[feature] Add API for event tracing

This is more developer oriented feature to help with profiling, debugging and optimization - especially when dealing with multi-threaded code.
qgis · Nov 5, 2019 · a192268 · a192268
1 parent 60ee76b
commit a192268
Show file tree

Hide file tree

Showing 3 changed files with 231 additions and 0 deletions.
diff --git a/src/core/CMakeLists.txt b/src/core/CMakeLists.txt
@@ -227,6 +227,7 @@ SET(QGIS_CORE_SRCS
   qgseditformconfig.cpp
   qgsellipsoidutils.cpp
   qgserror.cpp
+  qgseventtracing.cpp
   qgsexpressioncontext.cpp
   qgsexpressionfieldbuffer.cpp
   qgsfeature.cpp
@@ -705,6 +706,7 @@ SET(QGIS_CORE_HDRS
   qgseditorwidgetsetup.h
   qgsellipsoidutils.h
   qgserror.h
+  qgseventtracing.h
   qgsexception.h
   qgsexpressioncontext.h
   qgsexpressioncontextgenerator.h

diff --git a/src/core/qgseventtracing.cpp b/src/core/qgseventtracing.cpp
@@ -0,0 +1,98 @@
+/***************************************************************************
+  qgseventtracing.cpp
+  --------------------------------------
+  Date                 : October 2019
+  Copyright            : (C) 2019 by Martin Dobias
+  Email                : wonder dot sk at gmail dot com
+ ***************************************************************************
+ *                                                                         *
+ *   This program is free software; you can redistribute it and/or modify  *
+ *   it under the terms of the GNU General Public License as published by  *
+ *   the Free Software Foundation; either version 2 of the License, or     *
+ *   (at your option) any later version.                                   *
+ *                                                                         *
+ ***************************************************************************/
+
+#include "qgseventtracing.h"
+
+#include <QFile>
+#include <QThread>
+
+/// @cond PRIVATE
+
+bool QgsEventTracing::sIsTracing = false;
+QElapsedTimer QgsEventTracing::sTracingTimer;
+QVector<QgsEventTracing::TraceItem> QgsEventTracing::sTraceEvents;
+QMutex QgsEventTracing::sTraceEventsMutex;
+
+
+bool QgsEventTracing::startTracing()
+{
+  if ( sIsTracing )
+    return false;
+
+  sIsTracing = true;
+  sTraceEventsMutex.lock();
+  sTracingTimer.start();
+  sTraceEvents.clear();
+  sTraceEvents.reserve( 1000 );
+  sTraceEventsMutex.unlock();
+  return true;
+}
+
+bool QgsEventTracing::stopTracing()
+{
+  if ( !sIsTracing )
+    return false;
+
+  sIsTracing = false;
+  sTracingTimer.invalidate();
+  return false;
+}
+
+bool QgsEventTracing::writeTrace( const QString &fileName )
+{
+  if ( sIsTracing )
+    return false;
+
+  QFile f( fileName );
+  if ( !f.open( QIODevice::WriteOnly ) )
+    return false;
+
+  f.write( "{\n\"traceEvents\": [\n" );
+
+  bool first = true;
+  for ( const auto &item : sTraceEvents )
+  {
+    if ( !first )
+      f.write( ",\n" );
+    else
+      first = false;
+    char t = item.type == Begin ? 'B' : ( item.type == End ? 'E' : 'I' );
+    QString msg = QString( "  {\"cat\": \"%1\", \"pid\": 1, \"tid\": %2, \"ts\": %3, \"ph\": \"%4\", \"name\": \"%5\" }" )
+                  .arg( item.category ).arg( item.threadId ).arg( item.timestamp ).arg( t ).arg( item.name );
+    f.write( msg.toUtf8() );
+  }
+
+  f.write( "\n]\n}\n" );
+  f.close();
+  return true;
+}
+
+void QgsEventTracing::addEvent( QgsEventTracing::EventType type, const QString &category, const QString &name )
+{
+  if ( !sIsTracing )
+    return;
+
+  sTraceEventsMutex.lock();
+  TraceItem item;
+  item.type = type;
+  item.timestamp = sTracingTimer.nsecsElapsed() / 1000;
+  item.threadId = reinterpret_cast<qint64>( QThread::currentThreadId() );
+  item.category = category;
+  item.name = name;
+  sTraceEvents.append( item );
+  sTraceEventsMutex.unlock();
+}
+
+///@endcond
diff --git a/src/core/qgseventtracing.h b/src/core/qgseventtracing.h
@@ -0,0 +1,131 @@
+/***************************************************************************
+  qgseventtracing.h
+  --------------------------------------
+  Date                 : October 2019
+  Copyright            : (C) 2019 by Martin Dobias
+  Email                : wonder dot sk at gmail dot com
+ ***************************************************************************
+ *                                                                         *
+ *   This program is free software; you can redistribute it and/or modify  *
+ *   it under the terms of the GNU General Public License as published by  *
+ *   the Free Software Foundation; either version 2 of the License, or     *
+ *   (at your option) any later version.                                   *
+ *                                                                         *
+ ***************************************************************************/
+
+#ifndef QGSEVENTTRACING_H
+#define QGSEVENTTRACING_H
+
+#include "qgis_core.h"
+
+#include <QMutex>
+#include <QElapsedTimer>
+#include <QString>
+#include <QVector>
+
+/// @cond PRIVATE
+
+//
+//  W A R N I N G
+//  -------------
+//
+// This file is not part of the QGIS API.  It exists purely as an
+// implementation detail.  This header file may change from version to
+// version without notice, or even be removed.
+//
+
+
+/**
+ * A utility class that provides event tracing functionality. When tracing
+ * is enabled, events from different threads can be recorded and stored
+ * in a JSON file. This helps understanding what is going on in multi-threaded
+ * environment of QGIS and trace some performance issues that are otherwise
+ * not that easy to spot in profiler output.
+ *
+ * Created traces can be viewed in Chrome/Chromium browser - simply set
+ * the URL to about:tracing and load the JSON file. There is also a tool
+ * called trace2html that turns the JSON file into a standalone HTML page
+ * that can be viewed anywhere.
+ *
+ * Trace viewer project is hosted here (created by Chrome developers):
+ * https://github.com/catapult-project/catapult/tree/master/tracing
+ *
+ * Event trace format specification:
+ * https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview
+ *
+ * The intended usage:
+ * 1. call startTracing()
+ * 2. repeatedly call addEvent()
+ * 3. call stopTracing() and writeTrace() to export the data to JSON
+ *
+ * \since QGIS 3.12
+ * \note not available in Python bindings
+ */
+class CORE_EXPORT QgsEventTracing
+{
+  public:
+    //! Type of the event that is being stored
+    enum EventType
+    {
+      Begin,    //!< Marks start of a duration event - should be paired with "End" event type
+      End,      //!< Marks end of a durection event - should be paired with "Begin" event type
+      Instant,  //!< Marks an instant event (which does not have any duration)
+    };
+
+    /**
+     * Starts tracing and clears buffers. Returns true on success (false if tracing is already running).
+     */
+    static bool startTracing();
+
+    /**
+     * Stops tracing. Returns true on success (false if tracing is already stopped).
+     */
+    static bool stopTracing();
+
+    /**
+     * Write captured trace to a JSON file. It is only possible to write trace when tracing has been stopped already.
+     */
+    static bool writeTrace( const QString &fileName );
+
+    /**
+     * Adds an event to the trace. Does nothing if tracing is not started.
+     * \note This method is thread-safe: it can be run from any thread.
+     */
+    static void addEvent( EventType type, const QString &category, const QString &name );
+
+    /**
+     * ScopedEvent can be used to trace a single function duration - the constructor adds a "begin" event
+     * and the destructor adds "end" event of the same name and category.
+     */
+    class ScopedEvent
+    {
+      public:
+        ScopedEvent( const QString &category, const QString &name ): mCat( category ), mName( name ) { addEvent( Begin, mCat, mName ); }
+        ~ScopedEvent() { addEvent( End, mCat, mName ); }
+      private:
+        QString mCat, mName;
+    };
+
+  private:
+    struct TraceItem
+    {
+      EventType type;
+      int threadId;
+      int timestamp;
+      QString category;
+      QString name;
+    };
+
+    //! Whether we are tracing right now
+    static bool sIsTracing;
+    //! High-precision timer to measure the elapsed time
+    static QElapsedTimer sTracingTimer;
+    //! Buffer of captured events in the current tracing session
+    static QVector<TraceItem> sTraceEvents;
+    //! Mutex to protect the buffer from being written to from multiple threads
+    static QMutex sTraceEventsMutex;
+};
+
+/// @endcond
+
+#endif // QGSEVENTTRACING_H