Merge pull request #15267 from jherico/fix/tracing

Case 21930: Don't change OpenGL context state every frame

interface/src/Application.cpp

@@ -3981,6 +3981,15 @@ static void dumpEventQueue(QThread* thread) {
 }
 #endif // DEBUG_EVENT_QUEUE
 
+bool Application::notify(QObject * object, QEvent * event) {
+    if (thread() == QThread::currentThread()) {
+        PROFILE_RANGE_IF_LONGER(app, "notify", 2)
+        return QApplication::notify(object, event);
+    } 
+        
+    return QApplication::notify(object, event);
+}
+
 bool Application::event(QEvent* event) {
 
     if (_aboutToQuit) {

interface/src/Application.h

@@ -156,6 +156,7 @@ public:
     void updateCamera(RenderArgs& renderArgs, float deltaTime);
     void resizeGL();
 
+    bool notify(QObject *, QEvent *) override;
     bool event(QEvent* event) override;
     bool eventFilter(QObject* object, QEvent* event) override;
 

libraries/display-plugins/src/display-plugins/OpenGLDisplayPlugin.cpp

@@ -109,7 +109,6 @@ public:
         Q_ASSERT(_context);
         _context->makeCurrent();
         CHECK_GL_ERROR();
-        _context->doneCurrent();
         while (!_shutdown) {
             if (_pendingOtherThreadOperation) {
                 PROFILE_RANGE(render, "MainThreadOp")
@@ -129,6 +128,7 @@ public:
                     Lock lock(_mutex);
                     _condition.wait(lock, [&] { return _finishedOtherThreadOperation; });
                 }
+                _context->makeCurrent();
             }
 
             // Check for a new display plugin
@@ -140,18 +140,16 @@ public:
                     if (newPlugin != currentPlugin) {
                         // Deactivate the old plugin
                         if (currentPlugin != nullptr) {
-                            _context->makeCurrent();
                             currentPlugin->uncustomizeContext();
                             CHECK_GL_ERROR();
-                            _context->doneCurrent();
+                            // Force completion of all pending GL commands
+                            glFinish();
                         }
 
                         if (newPlugin) {
                             bool hasVsync = true;
                             QThread::setPriority(newPlugin->getPresentPriority());
                             bool wantVsync = newPlugin->wantVsync();
-                            _context->makeCurrent();
-                            CHECK_GL_ERROR();
 #if defined(Q_OS_MAC)
                             newPlugin->swapBuffers();
 #endif
@@ -163,7 +161,8 @@ public:
                             newPlugin->setVsyncEnabled(hasVsync);
                             newPlugin->customizeContext();
                             CHECK_GL_ERROR();
-                            _context->doneCurrent();
+                            // Force completion of all pending GL commands
+                            glFinish();
                         }
                         currentPlugin = newPlugin;
                         _newPluginQueue.pop();
@@ -180,7 +179,6 @@ public:
             }
 
             // Execute the frame and present it to the display device.
-            _context->makeCurrent();
             {
                 PROFILE_RANGE(render, "PluginPresent")
                 gl::globalLock();
@@ -188,9 +186,9 @@ public:
                 gl::globalRelease(false);
                 CHECK_GL_ERROR();
             }
-            _context->doneCurrent();
         }
 
+        _context->doneCurrent();
         Lock lock(_mutex);
         _context->moveToThread(qApp->thread());
         _shutdown = false;

libraries/shared/src/Profile.cpp

@@ -7,6 +7,7 @@
 //
 
 #include "Profile.h"
+#include <chrono>
 
 Q_LOGGING_CATEGORY(trace_app, "trace.app")
 Q_LOGGING_CATEGORY(trace_app_detail, "trace.app.detail")
@@ -41,14 +42,22 @@ static bool tracingEnabled() {
     return DependencyManager::isSet<tracing::Tracer>() && DependencyManager::get<tracing::Tracer>()->isEnabled();
 }
 
-Duration::Duration(const QLoggingCategory& category, const QString& name, uint32_t argbColor, uint64_t payload, const QVariantMap& baseArgs) : _name(name), _category(category) {
+DurationBase::DurationBase(const QLoggingCategory& category, const QString& name) : _name(name), _category(category) {
+}
+
+Duration::Duration(const QLoggingCategory& category,
+                   const QString& name,
+                   uint32_t argbColor,
+                   uint64_t payload,
+                   const QVariantMap& baseArgs) :
+    DurationBase(category, name) {
     if (tracingEnabled() && category.isDebugEnabled()) {
         QVariantMap args = baseArgs;
         args["nv_payload"] = QVariant::fromValue(payload);
         tracing::traceEvent(_category, _name, tracing::DurationBegin, "", args);
 
 #if defined(NSIGHT_TRACING)
-        nvtxEventAttributes_t eventAttrib { 0 };
+        nvtxEventAttributes_t eventAttrib{ 0 };
         eventAttrib.version = NVTX_VERSION;
         eventAttrib.size = NVTX_EVENT_ATTRIB_STRUCT_SIZE;
         eventAttrib.colorType = NVTX_COLOR_ARGB;
@@ -98,3 +107,17 @@ void Duration::endRange(const QLoggingCategory& category, uint64_t rangeId) {
 #endif
 }
 
+ConditionalDuration::ConditionalDuration(const QLoggingCategory& category, const QString& name, uint32_t minTime) :
+    DurationBase(category, name), _startTime(tracing::Tracer::now()), _minTime(minTime * USECS_PER_MSEC) {
+}
+
+ConditionalDuration::~ConditionalDuration() {
+    if (tracingEnabled() && _category.isDebugEnabled()) {
+        auto endTime = tracing::Tracer::now();
+        auto duration = endTime - _startTime;
+        if (duration >= _minTime) {
+            tracing::traceEvent(_category, _startTime, _name, tracing::DurationBegin);
+            tracing::traceEvent(_category, endTime, _name, tracing::DurationEnd);
+        }
+    }
+}

libraries/shared/src/Profile.h

@@ -37,17 +37,31 @@ Q_DECLARE_LOGGING_CATEGORY(trace_startup)
 Q_DECLARE_LOGGING_CATEGORY(trace_workload)
 Q_DECLARE_LOGGING_CATEGORY(trace_baker)
 
-class Duration {
+class DurationBase {
+
+protected:
+    DurationBase(const QLoggingCategory& category, const QString& name);
+    const QString _name;
+    const QLoggingCategory& _category;
+};
+
+class Duration : public DurationBase {
 public:
     Duration(const QLoggingCategory& category, const QString& name, uint32_t argbColor = 0xff0000ff, uint64_t payload = 0, const QVariantMap& args = QVariantMap());
     ~Duration();
 
     static uint64_t beginRange(const QLoggingCategory& category, const char* name, uint32_t argbColor);
     static void endRange(const QLoggingCategory& category, uint64_t rangeId);
+};
+
+class ConditionalDuration : public DurationBase {
+public:
+    ConditionalDuration(const QLoggingCategory& category, const QString& name, uint32_t minTime);
+    ~ConditionalDuration();
 
 private:
-    QString _name;
+    const int64_t _startTime;
-    const QLoggingCategory& _category;
+    const int64_t _minTime;
 };
 
 
@@ -95,6 +109,7 @@ inline void metadata(const QString& metadataType, const QVariantMap& args) {
 }
 
 #define PROFILE_RANGE(category, name) Duration profileRangeThis(trace_##category(), name);
+#define PROFILE_RANGE_IF_LONGER(category, name, ms) ConditionalDuration profileRangeThis(trace_##category(), name, ms);
 #define PROFILE_RANGE_EX(category, name, argbColor, payload, ...) Duration profileRangeThis(trace_##category(), name, argbColor, (uint64_t)payload, ##__VA_ARGS__);
 #define PROFILE_RANGE_BEGIN(category, rangeId, name, argbColor) rangeId = Duration::beginRange(trace_##category(), name, argbColor)
 #define PROFILE_RANGE_END(category, rangeId) Duration::endRange(trace_##category(), rangeId)

libraries/shared/src/Trace.cpp

@@ -176,6 +176,10 @@ void Tracer::serialize(const QString& filename) {
 #endif
 }
 
+int64_t Tracer::now() {
+    return std::chrono::duration_cast<std::chrono::microseconds>(p_high_resolution_clock::now().time_since_epoch()).count();
+}
+
 void Tracer::traceEvent(const QLoggingCategory& category,
     const QString& name, EventType type,
     qint64 timestamp, qint64 processID, qint64 threadID,
@@ -226,9 +230,17 @@ void Tracer::traceEvent(const QLoggingCategory& category,
         return;
     }
 
-    auto timestamp = std::chrono::duration_cast<std::chrono::microseconds>(p_high_resolution_clock::now().time_since_epoch()).count();
+    traceEvent(category, name, type, now(), id, args, extra);
+}
+
+void Tracer::traceEvent(const QLoggingCategory& category, 
+    const QString& name, EventType type, int64_t timestamp, const QString& id, 
+    const QVariantMap& args, const QVariantMap& extra) {
+    if (!_enabled && type != Metadata) {
+        return;
+    }
+
     auto processID = QCoreApplication::applicationPid();
     auto threadID = int64_t(QThread::currentThreadId());
-
     traceEvent(category, name, type, timestamp, processID, threadID, id, args, extra);
 }

libraries/shared/src/Trace.h

@@ -78,11 +78,18 @@ struct TraceEvent {
 
 class Tracer : public Dependency {
 public:
+    static int64_t now();
     void traceEvent(const QLoggingCategory& category, 
         const QString& name, EventType type,
         const QString& id = "", 
         const QVariantMap& args = QVariantMap(), const QVariantMap& extra = QVariantMap());
 
+    void traceEvent(const QLoggingCategory& category, 
+        const QString& name, EventType type,
+        int64_t timestamp,
+        const QString& id = "", 
+        const QVariantMap& args = QVariantMap(), const QVariantMap& extra = QVariantMap());
+
     void startTracing();
     void stopTracing();
     void serialize(const QString& file);
@@ -101,6 +108,16 @@ private:
     std::mutex _eventsMutex;
 };
 
+inline void traceEvent(const QLoggingCategory& category, int64_t timestamp, const QString& name, EventType type, const QString& id = "", const QVariantMap& args = {}, const QVariantMap& extra = {}) {
+    if (!DependencyManager::isSet<Tracer>()) {
+        return;
+    }
+    const auto& tracer = DependencyManager::get<Tracer>();
+    if (tracer) {
+        tracer->traceEvent(category, name, type, timestamp, id, args, extra);
+    }
+}
+
 inline void traceEvent(const QLoggingCategory& category, const QString& name, EventType type, const QString& id = "", const QVariantMap& args = {}, const QVariantMap& extra = {}) {
     if (!DependencyManager::isSet<Tracer>()) {
         return;