Create RAII QgsScopedRuntimeProfile class and Python context manager

nyalldawson · nyalldawson · commit a913a6aa5aed · 2020-05-19T04:35:34.000+10:00
to ease logging of runtime profiles.

Now it's possible to do:

    with QgsRuntimeProfiler.profile('My operation'):
      # do something

to automatically handle everything required to log the operation runtime
diff --git a/python/core/__init__.py.in b/python/core/__init__.py.in
@@ -36,6 +36,7 @@ from .additions.qgsgeometry import _geometryNonZero, mapping_geometry
 from .additions.qgssettings import _qgssettings_enum_value, _qgssettings_set_enum_value, _qgssettings_flag_value
 from .additions.qgstaskwrapper import QgsTaskWrapper
 from .additions.readwritecontextentercategory import ReadWriteContextEnterCategory
+from .additions.runtimeprofiler import ScopedRuntimeProfileContextManager
 from .additions.validitycheck import check
 
 # Injections into classes
@@ -47,6 +48,7 @@ QgsProcessingFeatureSourceDefinition.__repr__ = processing_source_repr
 QgsProcessingOutputLayerDefinition.__repr__ = processing_output_layer_repr
 QgsProject.blockDirtying = ProjectDirtyBlocker
 QgsReadWriteContext.enterCategory = ReadWriteContextEnterCategory
+QgsRuntimeProfiler.profile = ScopedRuntimeProfileContextManager
 QgsSettings.enumValue = _qgssettings_enum_value
 QgsSettings.setEnumValue = _qgssettings_set_enum_value
 QgsSettings.flagValue = _qgssettings_flag_value
diff --git a/python/core/auto_generated/qgsruntimeprofiler.sip.in b/python/core/auto_generated/qgsruntimeprofiler.sip.in
@@ -81,6 +81,43 @@ The current total time collected in the profiler.
 
 };
 
+
+class QgsScopedRuntimeProfile
+{
+%Docstring
+
+Scoped object for logging of the runtime for a single operation or group of operations.
+
+This class automatically takes care of registering an operation in the :py:func:`QgsApplication.profiler()`
+registry upon construction, and recording of the elapsed runtime upon destruction.
+
+Python scripts should not use QgsScopedRuntimeProfile directly. Instead, use :py:func:`QgsRuntimeProfiler.profile()`
+.. code-block:: python
+
+       with QgsRuntimeProfiler.profile('My operation'):
+         # do something
+
+.. versionadded:: 3.14
+%End
+
+%TypeHeaderCode
+#include "qgsruntimeprofiler.h"
+%End
+  public:
+
+    QgsScopedRuntimeProfile( const QString &name );
+%Docstring
+Constructor for QgsScopedRuntimeProfile.
+
+Automatically registers the operation in the QgsApplication.profiler() instance
+and starts recording the run time of the operation.
+%End
+
+    ~QgsScopedRuntimeProfile();
+
+};
+
+
 /************************************************************************
  * This file has been generated automatically from                      *
  *                                                                      *
diff --git a/src/app/qgisapp.cpp b/src/app/qgisapp.cpp
@@ -14979,9 +14979,8 @@ void QgisApp::endProfile()
 
 void QgisApp::functionProfile( void ( QgisApp::*fnc )(), QgisApp *instance, const QString &name )
 {
-  startProfile( name );
+  QgsScopedRuntimeProfile profile( name );
   ( instance->*fnc )();
-  endProfile();
 }
 
 void QgisApp::mapCanvas_keyPressed( QKeyEvent *e )
diff --git a/src/app/qgspluginregistry.cpp b/src/app/qgspluginregistry.cpp
@@ -32,6 +32,7 @@
 #include "qgslogger.h"
 #include "qgsmessagelog.h"
 #include "qgsmessagebar.h"
+#include "qgsruntimeprofiler.h"
 
 #ifdef WITH_BINDINGS
 #include "qgspythonutils.h"
diff --git a/src/core/qgsruntimeprofiler.cpp b/src/core/qgsruntimeprofiler.cpp
@@ -96,10 +96,24 @@ void QgsRuntimeProfiler::clear()
 double QgsRuntimeProfiler::totalTime()
 {
   double total = 0;
-  QList<QPair<QString, double> >::const_iterator it = mProfileTimes.constBegin();
-  for ( ; it != mProfileTimes.constEnd(); ++it )
+  for ( auto it = mProfileTimes.constBegin(); it != mProfileTimes.constEnd(); ++it )
   {
-    total += ( *it ).second;
+    total += it->second;
   }
   return total;
 }
+
+
+//
+// QgsScopedRuntimeProfile
+//
+
+QgsScopedRuntimeProfile::QgsScopedRuntimeProfile( const QString &name )
+{
+  QgsApplication::profiler()->start( name );
+}
+
+QgsScopedRuntimeProfile::~QgsScopedRuntimeProfile()
+{
+  QgsApplication::profiler()->end();
+}
diff --git a/src/core/qgsruntimeprofiler.h b/src/core/qgsruntimeprofiler.h
@@ -95,4 +95,41 @@ class CORE_EXPORT QgsRuntimeProfiler
     QList< QPair< QString, double > > mProfileTimes;
 };
 
+
+/**
+ * \ingroup core
+ *
+ * Scoped object for logging of the runtime for a single operation or group of operations.
+ *
+ * This class automatically takes care of registering an operation in the QgsApplication::profiler()
+ * registry upon construction, and recording of the elapsed runtime upon destruction.
+ *
+ * Python scripts should not use QgsScopedRuntimeProfile directly. Instead, use QgsRuntimeProfiler.profile()
+ * \code{.py}
+ *   with QgsRuntimeProfiler.profile('My operation'):
+ *     # do something
+ * \endcode
+ *
+ * \since QGIS 3.14
+ */
+class CORE_EXPORT QgsScopedRuntimeProfile
+{
+  public:
+
+    /**
+     * Constructor for QgsScopedRuntimeProfile.
+     *
+     * Automatically registers the operation in the QgsApplication::profiler() instance
+     * and starts recording the run time of the operation.
+     */
+    QgsScopedRuntimeProfile( const QString &name );
+
+    /**
+     * Records the final runtime of the operation in the profiler instance.
+     */
+    ~QgsScopedRuntimeProfile();
+
+};
+
+
 #endif // QGSRUNTIMEPROFILER_H

Original file line number	Diff line number	Diff line change
`@@ -14979,9 +14979,8 @@ void QgisApp::endProfile()`
`14979`	`14979`
`14980`	`14980`	`void QgisApp::functionProfile( void ( QgisApp::fnc )(), QgisApp instance, const QString &name )`
`14981`	`14981`	`{`
`14982`		`- startProfile( name );`
	`14982`	`+ QgsScopedRuntimeProfile profile( name );`
`14983`	`14983`	`( instance->*fnc )();`
`14984`		`- endProfile();`
`14985`	`14984`	`}`
`14986`	`14985`
`14987`	`14986`	`void QgisApp::mapCanvas_keyPressed( QKeyEvent *e )`