[feature] Add runtime profiler class to profile code

python/core/core.sip

@@ -122,6 +122,7 @@
 %Include qgsrenderchecker.sip
 %Include qgsrendercontext.sip
 %Include qgsrunprocess.sip
+%Include qgsruntimeprofiler.sip
 %Include qgsscalecalculator.sip
 %Include qgsscaleexpression.sip
 %Include qgsscaleutils.sip

python/core/qgsruntimeprofiler.sip

@@ -0,0 +1,56 @@
+class QgsRuntimeProfiler
+{
+%TypeHeaderCode
+#include <qgsruntimeprofiler.h>
+%End
+  public:
+    /**
+     * @brief Instance of the run time profiler. To use the main profiler
+     * use this instance.
+     * @return The instance of the run time profiler
+     */
+    QgsRuntimeProfiler();
+
+    /**
+     * @brief Begin the group for the profiler. Groups will append {GroupName}/ to the
+     * front of the profile tag set using start.
+     * @param name The name of the group.
+     */
+    static QgsRuntimeProfiler * instance();
+
+    /**
+     * @brief Begin the group for the profiler. Groups will append {GroupName}/ to the
+     * front of the profile tag set using start.
+     * @param name The name of the group.
+     */
+    void beginGroup( const QString& name );
+
+    /**
+     * @brief End the current active group.
+     */
+    void endGroup();
+
+    /**
+     * @brief Start a profile event with the given name.
+     * @param name The name of the profile event. Will have the name of
+     * the active group appened after ending.
+     */
+    void start( const QString& name );
+
+    /**
+     * @brief End the current profile event.
+     */
+    void end();
+
+    /**
+     * @brief clear Clear all profile data.
+     */
+    void clear();
+
+    /**
+     * @brief The current total time collected in the profiler.
+     * @return The current total time collected in the profiler.
+     */
+    double totalTime();
+
+};

src/app/qgisapp.cpp

@@ -587,14 +587,20 @@ QgisApp::QgisApp( QSplashScreen *splash, bool restorePlugins, bool skipVersionCh
   }
 
   smInstance = this;
+  profiler = QgsRuntimeProfiler::instance();
 
   namSetup();
 
   // load GUI: actions, menus, toolbars
+  profiler->beginGroup( "qgisapp" );
+  profiler->beginGroup( "startup" );
+  startProfile( "Setting up UI" );
   setupUi( this );
+  endProfile();
 
   //////////
 
+  startProfile( "Checking database" );
   mSplash->showMessage( tr( "Checking database" ), Qt::AlignHCenter | Qt::AlignBottom );
   qApp->processEvents();
   // Do this early on before anyone else opens it and prevents us copying it
@@ -603,7 +609,9 @@ QgisApp::QgisApp( QSplashScreen *splash, bool restorePlugins, bool skipVersionCh
   {
     QMessageBox::critical( this, tr( "Private qgis.db" ), dbError );
   }
+  endProfile();
 
+  startProfile( "Initializing authentication" );
   mSplash->showMessage( tr( "Initializing authentication" ), Qt::AlignHCenter | Qt::AlignBottom );
   qApp->processEvents();
   QgsAuthManager::instance()->init( QgsApplication::pluginPath() );
@@ -611,9 +619,12 @@ QgisApp::QgisApp( QSplashScreen *splash, bool restorePlugins, bool skipVersionCh
   {
     masterPasswordSetup();
   }
+  endProfile();
 
   // Create the themes folder for the user
+  startProfile( "Creating theme folder" );
   QgsApplication::createThemeFolder();
+  endProfile();
 
   mSplash->showMessage( tr( "Reading settings" ), Qt::AlignHCenter | Qt::AlignBottom );
   qApp->processEvents();
@@ -623,11 +634,13 @@ QgisApp::QgisApp( QSplashScreen *splash, bool restorePlugins, bool skipVersionCh
 
   QSettings settings;
 
+  startProfile( "Building style sheet" );
   // set up stylesheet builder and apply saved or default style options
   mStyleSheetBuilder = new QgisAppStyleSheet( this );
   connect( mStyleSheetBuilder, SIGNAL( appStyleSheetChanged( const QString& ) ),
            this, SLOT( setAppStyleSheet( const QString& ) ) );
   mStyleSheetBuilder->buildStyleSheet( mStyleSheetBuilder->defaultOptions() );
+  endProfile();
 
   QWidget *centralWidget = this->centralWidget();
   QGridLayout *centralLayout = new QGridLayout( centralWidget );
@@ -635,6 +648,7 @@ QgisApp::QgisApp( QSplashScreen *splash, bool restorePlugins, bool skipVersionCh
   centralLayout->setContentsMargins( 0, 0, 0, 0 );
 
   // "theMapCanvas" used to find this canonical instance later
+  startProfile( "Creating map canvas" );
   mMapCanvas = new QgsMapCanvas( centralWidget, "theMapCanvas" );
   connect( mMapCanvas, SIGNAL( messageEmitted( const QString&, const QString&, QgsMessageBar::MessageLevel ) ),
            this, SLOT( displayMessage( const QString&, const QString&, QgsMessageBar::MessageLevel ) ) );
@@ -646,11 +660,15 @@ QgisApp::QgisApp( QSplashScreen *splash, bool restorePlugins, bool skipVersionCh
   int myGreen = settings.value( "/qgis/default_canvas_color_green", 255 ).toInt();
   int myBlue = settings.value( "/qgis/default_canvas_color_blue", 255 ).toInt();
   mMapCanvas->setCanvasColor( QColor( myRed, myGreen, myBlue ) );
+  endProfile();
 
   // what type of project to auto-open
   mProjOpen = settings.value( "/qgis/projOpenAtLaunch", 0 ).toInt();
 
+
+  startProfile( "Welcome page" );
   mWelcomePage = new QgsWelcomePage( skipVersionCheck );
+  endProfile();
 
   mCentralContainer = new QStackedWidget;
   mCentralContainer->insertWidget( 0, mMapCanvas );
@@ -663,59 +681,75 @@ QgisApp::QgisApp( QSplashScreen *splash, bool restorePlugins, bool skipVersionCh
   mCentralContainer->setCurrentIndex( mProjOpen ? 0 : 1 );
 
   // a bar to warn the user with non-blocking messages
+  startProfile( "Message bar" );
   mInfoBar = new QgsMessageBar( centralWidget );
   mInfoBar->setSizePolicy( QSizePolicy::Minimum, QSizePolicy::Fixed );
   centralLayout->addWidget( mInfoBar, 0, 0, 1, 1 );
+  endProfile();
 
+  startProfile( "User input dock" );
   // User Input Dock Widget
   mUserInputDockWidget = new QgsUserInputDockWidget( this );
   mUserInputDockWidget->setObjectName( "UserInputDockWidget" );
+  endProfile();
 
   //set the focus to the map canvas
   mMapCanvas->setFocus();
 
+  startProfile( "Layer tree" );
   mLayerTreeView = new QgsLayerTreeView( this );
   mLayerTreeView->setObjectName( "theLayerTreeView" ); // "theLayerTreeView" used to find this canonical instance later
+  endProfile();
 
   // create undo widget
+  startProfile( "Undo dock" );
   mUndoDock = new QDockWidget( tr( "Undo/Redo Panel" ), this );
   mUndoWidget = new QgsUndoWidget( mUndoDock, mMapCanvas );
   mUndoWidget->setObjectName( "Undo" );
   mUndoDock->setWidget( mUndoWidget );
   mUndoDock->setObjectName( "undo/redo dock" );
+  endProfile();
 
   // Advanced Digitizing dock
+  startProfile( "Advanced digitize panel" );
   mAdvancedDigitizingDockWidget = new QgsAdvancedDigitizingDockWidget( mMapCanvas, this );
   mAdvancedDigitizingDockWidget->setObjectName( "AdvancedDigitizingTools" );
+  endProfile();
 
   // Statistical Summary dock
+  startProfile( "Stats dock" );
   mStatisticalSummaryDockWidget = new QgsStatisticalSummaryDockWidget( this );
   mStatisticalSummaryDockWidget->setObjectName( "StatistalSummaryDockWidget" );
+  endProfile();
 
   // Bookmarks dock
+  startProfile( "Bookmarks widget" );
   mBookMarksDockWidget = new QgsBookmarks( this );
   mBookMarksDockWidget->setObjectName( "BookmarksDockWidget" );
+  endProfile();
 
+  startProfile( "Snapping utils" );
   mSnappingUtils = new QgsMapCanvasSnappingUtils( mMapCanvas, this );
   mMapCanvas->setSnappingUtils( mSnappingUtils );
   connect( QgsProject::instance(), SIGNAL( snapSettingsChanged() ), mSnappingUtils, SLOT( readConfigFromProject() ) );
   connect( this, SIGNAL( projectRead() ), mSnappingUtils, SLOT( readConfigFromProject() ) );
+  endProfile();
 
-  createActions();
-  createActionGroups();
-  createMenus();
-  createToolBars();
-  createStatusBar();
-  createCanvasTools();
+  functionProfile( &QgisApp::createActions, this, "Create actions" );
+  functionProfile( &QgisApp::createActionGroups, this, "Create action group" );
+  functionProfile( &QgisApp::createMenus, this, "Create menus" );
+  functionProfile( &QgisApp::createToolBars, this, "Toolbars" );
+  functionProfile( &QgisApp::createStatusBar, this, "Status bar" );
+  functionProfile( &QgisApp::createCanvasTools, this, "Create canvas tools" );
   mMapCanvas->freeze();
-  initLayerTreeView();
-  createOverview();
-  createMapTips();
-  createDecorations();
-  readSettings();
-  updateRecentProjectPaths();
-  updateProjectFromTemplates();
-  legendLayerSelectionChanged();
+  functionProfile( &QgisApp::initLayerTreeView, this, "Init Layer tree view" );
+  functionProfile( &QgisApp::createOverview, this, "Create overview" );
+  functionProfile( &QgisApp::createMapTips, this, "Create map tips" );
+  functionProfile( &QgisApp::createDecorations, this, "Create decorations" );
+  functionProfile( &QgisApp::readSettings, this, "Read settings" );
+  functionProfile( &QgisApp::updateRecentProjectPaths, this, "Update recent project paths" );
+  functionProfile( &QgisApp::updateProjectFromTemplates, this, "Update project from templates" );
+  functionProfile( &QgisApp::legendLayerSelectionChanged, this, "Legend layer selection changed" );
   mSaveRollbackInProgress = false;
 
   QFileSystemWatcher* projectsTemplateWatcher = new QFileSystemWatcher( this );
@@ -725,11 +759,14 @@ QgisApp::QgisApp( QSplashScreen *splash, bool restorePlugins, bool skipVersionCh
   connect( projectsTemplateWatcher, SIGNAL( directoryChanged( QString ) ), this, SLOT( updateProjectFromTemplates() ) );
 
   // initialize the plugin manager
+  startProfile( "Plugin manager" );
   mPluginManager = new QgsPluginManager( this, restorePlugins );
+  endProfile();
 
   addDockWidget( Qt::LeftDockWidgetArea, mUndoDock );
   mUndoDock->hide();
 
+  startProfile( "Map Style dock" );
   mMapStylingDock = new QDockWidget( this );
   mMapStylingDock->setWindowTitle( tr( "Map Styling" ) );
   mMapStylingDock->setObjectName( "MapStyling" );
@@ -740,9 +777,12 @@ QgisApp::QgisApp( QSplashScreen *splash, bool restorePlugins, bool skipVersionCh
 
   addDockWidget( Qt::RightDockWidgetArea, mMapStylingDock );
   mMapStylingDock->hide();
+  endProfile();
 
+  startProfile( "Snapping dialog" );
   mSnappingDialog = new QgsSnappingDialog( this, mMapCanvas );
   mSnappingDialog->setObjectName( "SnappingOption" );
+  endProfile();
 
   mBrowserWidget = new QgsBrowserDockWidget( tr( "Browser Panel" ), this );
   mBrowserWidget->setObjectName( "Browser" );
@@ -864,11 +904,13 @@ QgisApp::QgisApp( QSplashScreen *splash, bool restorePlugins, bool skipVersionCh
 
   if ( mPythonUtils && mPythonUtils->isEnabled() )
   {
+    startProfile( "initPluginInstaller" );
     // initialize the plugin installer to start fetching repositories in background
     QgsPythonRunner::run( "import pyplugin_installer" );
     QgsPythonRunner::run( "pyplugin_installer.initPluginInstaller()" );
     // enable Python in the Plugin Manager and pass the PythonUtils to it
     mPluginManager->setPythonUtils( mPythonUtils );
+    endProfile();
   }
   else if ( mActionShowPythonDialog )
   {
@@ -911,10 +953,14 @@ QgisApp::QgisApp( QSplashScreen *splash, bool restorePlugins, bool skipVersionCh
   //
   mSplash->showMessage( tr( "Restoring window state" ), Qt::AlignHCenter | Qt::AlignBottom );
   qApp->processEvents();
+  startProfile( "Restore window state" );
   restoreWindowState();
+  endProfile();
 
   // do main window customization - after window state has been restored, before the window is shown
+  startProfile( "Update customiziation on main window" );
   QgsCustomization::instance()->updateMainWindow( mToolbarMenu );
+  endProfile();
 
   mSplash->showMessage( tr( "QGIS Ready!" ), Qt::AlignHCenter | Qt::AlignBottom );
 
@@ -936,8 +982,10 @@ QgisApp::QgisApp( QSplashScreen *splash, bool restorePlugins, bool skipVersionCh
 
   mFullScreenMode = false;
   mPrevScreenModeMaximized = false;
+  startProfile( "Show main window" );
   show();
   qApp->processEvents();
+  endProfile();
 
   mMapCanvas->freeze( false );
   mMapCanvas->clearExtentHistory(); // reset zoomnext/zoomlast
@@ -994,7 +1042,9 @@ QgisApp::QgisApp( QSplashScreen *splash, bool restorePlugins, bool skipVersionCh
   // notify user if authentication system is disabled
   ( void )QgsAuthGuiUtils::isDisabled( messageBar() );
 
+  startProfile( "New project" );
   fileNewBlank(); // prepare empty project, also skips any default templates from loading
+  endProfile();
 
   // request notification of FileOpen events (double clicking a file icon in Mac OS X Finder)
   // should come after fileNewBlank to ensure project is properly set up to receive any data source files
@@ -1004,6 +1054,19 @@ QgisApp::QgisApp( QSplashScreen *splash, bool restorePlugins, bool skipVersionCh
 #ifdef ANDROID
   toggleFullScreen();
 #endif
+  profiler->endGroup();
+  profiler->endGroup();
+
+  QgsDebugMsg( "PROFILE TIMES" );
+  QgsDebugMsg( QString( "PROFILE TIMES TOTAL - %1 " ).arg( profiler->totalTime() ) );
+  QList<QPair<QString, double> >::const_iterator it = profiler->profileTimes().constBegin();
+  for ( ; it != profiler->profileTimes().constEnd(); ++it )
+  {
+    QString name = ( *it ).first;
+    double time = ( *it ).second;
+    QgsDebugMsg( QString( " - %1 - %2" ).arg( name ).arg( time ) );
+  }
+
 } // QgisApp ctor
 
 QgisApp::QgisApp()
@@ -10960,6 +11023,23 @@ void QgisApp::keyPressEvent( QKeyEvent * e )
   }
 }
 
+void QgisApp::startProfile( const QString& name )
+{
+  profiler->start( name );
+}
+
+void QgisApp::endProfile()
+{
+  profiler->end();
+}
+
+void QgisApp::functionProfile( void ( QgisApp::*fnc )(), QgisApp* instance, QString name )
+{
+  startProfile( name );
+  ( instance->*fnc )();
+  endProfile();
+}
+
 void QgisApp::mapCanvas_keyPressed( QKeyEvent *e )
 {
   // Delete selected features when it is possible and KeyEvent was not managed by current MapTool

src/app/qgisapp.h

@@ -118,6 +118,7 @@ class QgsDiagramProperties;
 #include "qgsmessagebar.h"
 #include "qgsbookmarks.h"
 #include "qgswelcomepageitemsmodel.h"
+#include "qgsruntimeprofiler.h"
 
 
 #include "ui_qgisapp.h"
@@ -1374,6 +1375,12 @@ class APP_EXPORT QgisApp : public QMainWindow, private Ui::MainWindow
     void layerSavedAs( QgsMapLayer* l, const QString& path );
 
   private:
+    void startProfile( const QString &name );
+    void endProfile();
+    void functionProfile( void ( QgisApp::*fnc )(), QgisApp *instance, QString name );
+
+    QgsRuntimeProfiler* profiler;
+
     /** This method will open a dialog so the user can select GDAL sublayers to load
      * @returns true if any items were loaded
      */

src/core/CMakeLists.txt

@@ -186,6 +186,7 @@ SET(QGIS_CORE_SRCS
   qgsrendercontext.cpp
   qgsrulebasedlabeling.cpp
   qgsrunprocess.cpp
+  qgsruntimeprofiler.cpp
   qgsscalecalculator.cpp
   qgsscaleexpression.cpp
   qgsscaleutils.cpp
@@ -693,6 +694,7 @@ SET(QGIS_CORE_HDRS
   qgsrelation.h
   qgsrenderchecker.h
   qgsrendercontext.h
+  qgsruntimeprofiler.h
   qgsscalecalculator.h
   qgsscaleexpression.h
   qgsscaleutils.h

src/core/qgsruntimeprofiler.cpp

@@ -0,0 +1,73 @@
+#include "qgsruntimeprofiler.h"
+#include "qgslogger.h"
+
+
+QgsRuntimeProfiler* QgsRuntimeProfiler::mInstance = nullptr;
+
+QgsRuntimeProfiler* QgsRuntimeProfiler::instance()
+{
+  if ( !mInstance )
+    mInstance = new QgsRuntimeProfiler();
+  return mInstance;
+}
+
+QgsRuntimeProfiler::QgsRuntimeProfiler()
+{
+
+}
+
+void QgsRuntimeProfiler::beginGroup( const QString &name )
+{
+  mGroupStack.push( name );
+  if ( !name.isEmpty() )
+  {
+    mGroupPrefix += name;
+    mGroupPrefix += QLatin1Char( '/' );
+  }
+}
+
+void QgsRuntimeProfiler::endGroup()
+{
+  if ( mGroupStack.isEmpty() )
+  {
+    qWarning( "QSettings::endGroup: No matching beginGroup()" );
+    return;
+  }
+
+  QString group = mGroupStack.pop();
+  int len = group.size();
+  if ( len > 0 )
+    mGroupPrefix.truncate( mGroupPrefix.size() - ( len + 1 ) );
+}
+
+void QgsRuntimeProfiler::start( const QString &name )
+{
+  mProfileTime.restart();
+  mCurrentName = name;
+}
+
+void QgsRuntimeProfiler::end()
+{
+  QString name = mCurrentName;
+  name.prepend( mGroupPrefix );
+  double timing =  mProfileTime.elapsed() / 1000.0;
+  mProfileTimes.append( QPair<QString, double>( name, timing ) );
+  QString message =  QString( "PROFILE: %1 - %2" ).arg( name ).arg( timing );
+  QgsDebugMsg( message );
+}
+
+void QgsRuntimeProfiler::clear()
+{
+  mProfileTimes.clear();
+}
+
+double QgsRuntimeProfiler::totalTime()
+{
+  double total = 0;
+  QList<QPair<QString, double> >::const_iterator it = mProfileTimes.constBegin();
+  for ( ; it != mProfileTimes.constEnd(); ++it )
+  {
+    total += ( *it ).second;
+  }
+  return total;
+}

src/core/qgsruntimeprofiler.h

@@ -0,0 +1,77 @@
+#ifndef QGSRUNTIMEPROFILER_H
+#define QGSRUNTIMEPROFILER_H
+
+#include <QTime>
+#include <QPair>
+#include <QStack>
+
+
+class CORE_EXPORT QgsRuntimeProfiler
+{
+  public:
+    /**
+     * @brief Instance of the run time profiler. To use the main profiler
+     * use this instance.
+     * @return The instance of the run time profiler
+     */
+    QgsRuntimeProfiler();
+
+    /**
+     * @brief Begin the group for the profiler. Groups will append {GroupName}/ to the
+     * front of the profile tag set using start.
+     * @param name The name of the group.
+     */
+    static QgsRuntimeProfiler * instance();
+
+    /**
+     * @brief Begin the group for the profiler. Groups will append {GroupName}/ to the
+     * front of the profile tag set using start.
+     * @param name The name of the group.
+     */
+    void beginGroup( const QString& name );
+
+    /**
+     * @brief End the current active group.
+     */
+    void endGroup();
+
+    /**
+     * @brief Start a profile event with the given name.
+     * @param name The name of the profile event. Will have the name of
+     * the active group appened after ending.
+     */
+    void start( const QString& name );
+
+    /**
+     * @brief End the current profile event.
+     */
+    void end();
+
+    /**
+     * @brief Return all the current profile times.
+     * @return A list of profile event names and times.
+     */
+    const QList<QPair<QString, double>> profileTimes()  { return mProfileTimes; }
+
+    /**
+     * @brief clear Clear all profile data.
+     */
+    void clear();
+
+    /**
+     * @brief The current total time collected in the profiler.
+     * @return The current total time collected in the profiler.
+     */
+    double totalTime();
+
+  private:
+    static QgsRuntimeProfiler* mInstance;
+
+    QString mGroupPrefix;
+    QStack<QString> mGroupStack;
+    QTime mProfileTime;
+    QString mCurrentName;
+    QList<QPair<QString, double>> mProfileTimes;
+};
+
+#endif // QGSRUNTIMEPROFILER_H