also log rendering times of individual layers when debugging output is

enabled
qgis · Feb 19, 2016 · b6de197 · b6de197
1 parent 2973c1d
commit b6de197
Showing 1 changed file with 38 additions and 1 deletion.
diff --git a/src/core/qgsmaprendererparalleljob.cpp b/src/core/qgsmaprendererparalleljob.cpp
@@ -19,8 +19,10 @@
 #include "qgslogger.h"
 #include "qgsmaplayerrenderer.h"
 #include "qgspallabeling.h"
+#include "qgsmessagelog.h"
 
 #include <QtConcurrentMap>
+#include <QSettings>
 
 #define LABELING_V2
 
@@ -225,9 +227,23 @@ void QgsMapRendererParallelJob::renderLayerStatic( LayerRenderJob& job )
   if ( job.cached )
     return;
 
+#ifdef QGISDEBUG
+  static QSet<QString> running;
+  static QMultiMap<int, QString> elapsed;
+
+  QSettings settings;
+  bool log = settings.value( "/Map/logCanvasRefreshEvent", false ).toBool();
+
   QTime t;
   t.start();
   QgsDebugMsg( QString( "job %1 start" ).arg( reinterpret_cast< ulong >( &job ), 0, 16 ) );
+  if ( log )
+  {
+    QgsMessageLog::logMessage( tr( "Layer %1 job started" ).arg( job.layerId ), tr( "Rendering" ) );
+    Q_ASSERT( !running.contains( job.layerId ) );
+    running << job.layerId;
+  }
+#endif
 
   try
   {
@@ -246,9 +262,30 @@ void QgsMapRendererParallelJob::renderLayerStatic( LayerRenderJob& job )
     QgsDebugMsg( "Caught unhandled unknown exception" );
   }
 
+#ifdef QGISDEBUG
   int tt = t.elapsed();
+
   QgsDebugMsg( QString( "job %1 end [%2 ms]" ).arg( reinterpret_cast< ulong >( &job ), 0, 16 ).arg( tt ) );
-  Q_UNUSED( tt );
+
+  if ( log )
+  {
+    running.remove( job.layerId );
+    elapsed.insert( tt, job.layerId );
+
+    QgsMessageLog::logMessage( tr( "Layer %1 job ended (%2 ms; still running:%3)" ).arg( job.layerId ).arg( tt ).arg( QStringList( running.values() ).join( ", " ) ), tr( "Rendering" ) );
+    if ( running.isEmpty() )
+    {
+      QList<int> tt( elapsed.keys() );
+      qSort( tt.begin(), tt.end(), qGreater<int>() );
+      Q_FOREACH ( int t, tt )
+      {
+        QgsMessageLog::logMessage( tr( "%1 ms: %2" ).arg( t ).arg( QStringList( elapsed.values( t ) ).join( ", " ) ), tr( "Rendering" ) );
+      }
+      QgsMessageLog::logMessage( "---", tr( "Rendering" ) );
+      elapsed.clear();
+    }
+  }
+#endif
 }