Add recording of async events to the event tracer

qgis · Nov 22, 2019 · e86d283 · e86d283
1 parent ae92395
commit e86d283
Show file tree

Hide file tree

Showing 2 changed files with 58 additions and 12 deletions.
diff --git a/src/core/qgseventtracing.cpp b/src/core/qgseventtracing.cpp
@@ -15,6 +15,7 @@
 
 #include "qgseventtracing.h"
 
+#include <QCoreApplication>
 #include <QFile>
 #include <QThread>
 
@@ -23,10 +24,11 @@
 struct TraceItem
 {
   QgsEventTracing::EventType type;
-  int threadId;
-  int timestamp;
+  uint threadId;
+  qint64 timestamp;
   QString category;
   QString name;
+  QString id;
 };
 
 //! Whether we are tracing right now
@@ -68,6 +70,19 @@ bool QgsEventTracing::isTracingEnabled()
   return sIsTracing;
 }
 
+static char _eventTypeToChar( QgsEventTracing::EventType type )
+{
+  switch ( type )
+  {
+    case QgsEventTracing::Begin: return 'B';
+    case QgsEventTracing::End: return 'E';
+    case QgsEventTracing::Instant: return 'i';
+    case QgsEventTracing::AsyncBegin: return 'b';
+    case QgsEventTracing::AsyncEnd: return 'e';
+  }
+  return '?';
+}
+
 bool QgsEventTracing::writeTrace( const QString &fileName )
 {
   if ( sIsTracing )
@@ -86,10 +101,20 @@ bool QgsEventTracing::writeTrace( const QString &fileName )
       f.write( ",\n" );
     else
       first = false;
-    char t = item.type == Begin ? 'B' : ( item.type == End ? 'E' : 'i' );
-    QString msg = QStringLiteral( "  {\"cat\": \"%1\", \"pid\": 1, \"tid\": %2, \"ts\": %3, \"ph\": \"%4\", \"name\": \"%5\"%6 }" )
-                  .arg( item.category ).arg( item.threadId ).arg( item.timestamp ).arg( t ).arg( item.name )
-                  .arg( item.type == Instant ? QStringLiteral( ", \"s\": \"g\"" ) : QString() );
+    char t = _eventTypeToChar( item.type );
+    QString msg = QStringLiteral( "  {\"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 );
+
+    // for instant events we always set them as global (currently not supporting instant events at thread scope)
+    if ( item.type == Instant )
+      msg += QStringLiteral( ", \"s\": \"g\"" );
+
+    // async events also need to have ID associated
+    if ( item.type == AsyncBegin || item.type == AsyncEnd )
+      msg += QStringLiteral( ", \"id\": \"%1\"" ).arg( item.id );
+
+    msg += " }";
+
     f.write( msg.toUtf8() );
   }
 
@@ -98,7 +123,7 @@ bool QgsEventTracing::writeTrace( const QString &fileName )
   return true;
 }
 
-void QgsEventTracing::addEvent( QgsEventTracing::EventType type, const QString &category, const QString &name )
+void QgsEventTracing::addEvent( QgsEventTracing::EventType type, const QString &category, const QString &name, const QString &id )
 {
   if ( !sIsTracing )
     return;
@@ -107,9 +132,13 @@ void QgsEventTracing::addEvent( QgsEventTracing::EventType type, const QString &
   TraceItem item;
   item.type = type;
   item.timestamp = sTracingTimer()->nsecsElapsed() / 1000;
-  item.threadId = reinterpret_cast<qint64>( QThread::currentThreadId() );
+  if ( QThread::currentThread() == QCoreApplication::instance()->thread() )
+    item.threadId = 0;  // to make it show up first
+  else
+    item.threadId = static_cast<uint>( reinterpret_cast<quint64>( QThread::currentThreadId() ) );
   item.category = category;
   item.name = name;
+  item.id = id;
   sTraceEvents()->append( item );
   sTraceEventsMutex()->unlock();
 }

diff --git a/src/core/qgseventtracing.h b/src/core/qgseventtracing.h
@@ -49,6 +49,20 @@
  * called trace2html that turns the JSON file into a standalone HTML page
  * that can be viewed anywhere.
  *
+ * Currently we recognize these kinds of events:
+ * 1. Duration events - they provide a way to mark a duration of work within a thread.
+ *    Their duration is specified by begin and end timestamps. They can be nested
+ *    and the viewer will stack them. If you need durations that do not nest properly
+ *    (i.e. they only partially overlap), you should use Async events instead.
+ * 2. Instant events - they correspond to something that happens but has no duration
+ *    associated with it.
+ * 3. Async events - they are used to specify asynchronous operations. They also require
+ *    additional "id" parameter to group them into the same event tree.
+ *
+ * Duration events are for example to record run of a single function. Async events
+ * are useful for cases where e.g. main thread starts some work in background and there
+ * may be possible several such operations running in the background at the same time.
+ *
  * Trace viewer project is hosted here (created by Chrome developers):
  * https://github.com/catapult-project/catapult/tree/master/tracing
  *
@@ -69,9 +83,11 @@ class CORE_EXPORT QgsEventTracing
     //! 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)
+      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)
+      AsyncBegin,  //!< Marks start of an async event - should be paired with "AsyncEnd" event type
+      AsyncEnd,    //!< Marks end of an async event - should be paired with "AsyncBegin" event type
     };
 
     /**
@@ -96,9 +112,10 @@ class CORE_EXPORT QgsEventTracing
 
     /**
      * Adds an event to the trace. Does nothing if tracing is not started.
+     * The "id" parameter is only needed for Async events to group them into a single event tree.
      * \note This method is thread-safe: it can be run from any thread.
      */
-    static void addEvent( EventType type, const QString &category, const QString &name );
+    static void addEvent( EventType type, const QString &category, const QString &name, const QString &id = QString() );
 
     /**
      * ScopedEvent can be used to trace a single function duration - the constructor adds a "begin" event