Fix rendering crash in debug mode (fixes #14369)

wonder-sk · wonder-sk · commit 31c788d7f7cd · 2016-02-25T12:14:17.000+08:00
Introduced in b6de197 due to the use of static variables in a function that is called from multiple threads. Further changes to logging: - also works when sequential rendering is used - also works in release mode (to allow checking of rendering speed in normal QGIS release)
diff --git a/src/core/qgsmaprenderercustompainterjob.cpp b/src/core/qgsmaprenderercustompainterjob.cpp
@@ -200,6 +200,8 @@ void QgsMapRendererCustomPainterJob::futureFinished()
   mRenderingTime = mRenderingStart.elapsed();
   QgsDebugMsg( "QPAINTER futureFinished" );
 
+  logRenderingTime( mLayerJobs );
+
   // final cleanup
   cleanupJobs( mLayerJobs );
 
@@ -248,8 +250,15 @@ void QgsMapRendererCustomPainterJob::doRender()
     }
 
     if ( !job.cached )
+    {
+      QTime layerTime;
+      layerTime.start();
+
       job.renderer->render();
 
+      job.renderingTime = layerTime.elapsed();
+    }
+
     if ( job.img )
     {
       // If we flattened this layer for alternate blend modes, composite it now
diff --git a/src/core/qgsmaprendererjob.cpp b/src/core/qgsmaprendererjob.cpp
@@ -29,6 +29,7 @@
 #include "qgsmaplayerrenderer.h"
 #include "qgsmaplayerstylemanager.h"
 #include "qgsmaprenderercache.h"
+#include "qgsmessagelog.h"
 #include "qgspallabeling.h"
 #include "qgsvectorlayerrenderer.h"
 #include "qgsvectorlayer.h"
@@ -245,6 +246,7 @@ LayerRenderJobs QgsMapRendererJob::prepareJobs( QPainter* painter, QgsPalLabelin
     job.img = nullptr;
     job.blendMode = ml->blendMode();
     job.layerId = ml->id();
+    job.renderingTime = -1;
 
     job.context = QgsRenderContext::fromMapSettings( mSettings );
     job.context.setPainter( painter );
@@ -367,3 +369,22 @@ QImage QgsMapRendererJob::composeImage( const QgsMapSettings& settings, const La
   painter.end();
   return image;
 }
+
+void QgsMapRendererJob::logRenderingTime( const LayerRenderJobs& jobs )
+{
+  QSettings settings;
+  if ( !settings.value( "/Map/logCanvasRefreshEvent", false ).toBool() )
+    return;
+
+  QMultiMap<int, QString> elapsed;
+  Q_FOREACH ( const LayerRenderJob& job, jobs )
+    elapsed.insert( job.renderingTime, job.layerId );
+
+  QList<int> tt( elapsed.uniqueKeys() );
+  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" ) );
+}
diff --git a/src/core/qgsmaprendererjob.h b/src/core/qgsmaprendererjob.h
@@ -47,6 +47,7 @@ struct LayerRenderJob
   QPainter::CompositionMode blendMode;
   bool cached; // if true, img already contains cached image from previous rendering
   QString layerId;
+  int renderingTime; //!< time it took to render the layer in ms (it is -1 if not rendered or still rendering)
 };
 
 typedef QList<LayerRenderJob> LayerRenderJobs;
@@ -155,6 +156,9 @@ class CORE_EXPORT QgsMapRendererJob : public QObject
     //! @note not available in python bindings
     void cleanupJobs( LayerRenderJobs& jobs );
 
+    //! @note not available in python bindings
+    void logRenderingTime( const LayerRenderJobs& jobs );
+
     static QImage composeImage( const QgsMapSettings& settings, const LayerRenderJobs& jobs );
 
     bool needTemporaryImage( QgsMapLayer* ml );
diff --git a/src/core/qgsmaprendererparalleljob.cpp b/src/core/qgsmaprendererparalleljob.cpp
@@ -19,10 +19,8 @@
 #include "qgslogger.h"
 #include "qgsmaplayerrenderer.h"
 #include "qgspallabeling.h"
-#include "qgsmessagelog.h"
 
 #include <QtConcurrentMap>
-#include <QSettings>
 
 #define LABELING_V2
 
@@ -188,6 +186,8 @@ void QgsMapRendererParallelJob::renderLayersFinished()
   // compose final image
   mFinalImage = composeImage( mSettings, mLayerJobs );
 
+  logRenderingTime( mLayerJobs );
+
   cleanupJobs( mLayerJobs );
 
   QgsDebugMsg( "PARALLEL layers finished" );
@@ -227,22 +227,9 @@ 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" ) );
-    running << job.layerId;
-  }
-#endif
+  QgsDebugMsg( QString( "job %1 start (layer %2)" ).arg( reinterpret_cast< ulong >( &job ), 0, 16 ).arg( job.layerId ) );
 
   try
   {
@@ -261,30 +248,8 @@ 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 ) );
-
-  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
+  job.renderingTime = t.elapsed();
+  QgsDebugMsg( QString( "job %1 end [%2 ms] (layer %3)" ).arg( reinterpret_cast< ulong >( &job ), 0, 16 ).arg( job.renderingTime ).arg( job.layerId ) );
 }
 
 
