GPU async timing instrumentation via MX_TRACE_ASYNC

source/MaterialXRenderGlsl/CMakeLists.txt

@@ -18,14 +18,18 @@ elseif(UNIX)
     find_package(OpenGL REQUIRED)
 endif()
 
+set(RENDERGLSL_MTLX_MODULES MaterialXRenderHw MaterialXGenGlsl)
+if(MATERIALX_BUILD_PERFETTO_TRACING)
+    list(APPEND RENDERGLSL_MTLX_MODULES MaterialXTrace)
+endif()
+
 mx_add_library(MaterialXRenderGlsl
     SOURCE_FILES
         ${materialx_source}
     HEADER_FILES
         ${materialx_headers}
     MTLX_MODULES
-        MaterialXRenderHw
-        MaterialXGenGlsl
+        ${RENDERGLSL_MTLX_MODULES}
     EXPORT_DEFINE
         MATERIALX_RENDERGLSL_EXPORTS
     ADD_OBJECTIVE_C_CODE)

source/MaterialXRenderGlsl/GlslRenderer.cpp

@@ -12,9 +12,54 @@
 #include <MaterialXRenderHw/SimpleWindow.h>
 #include <MaterialXRender/TinyObjLoader.h>
 #include <MaterialXGenHw/HwConstants.h>
+#include <MaterialXTrace/Tracing.h>
 
 MATERIALX_NAMESPACE_BEGIN
 
+#ifdef MATERIALX_BUILD_PERFETTO_TRACING
+namespace
+{
+
+/// RAII wrapper around a GL_TIME_ELAPSED query. On destruction, reads the
+/// result (blocking until the GPU is done) and emits an async trace event.
+class GpuTimerScope
+{
+  public:
+    GpuTimerScope()
+    {
+        // Timer queries require OpenGL 3.3, while macOS may fall back to a 3.2 core profile.
+        if (GLAD_GL_VERSION_3_3 && Tracing::Dispatcher::getInstance().isEnabled())
+        {
+            glGenQueries(1, &_query);
+            glBeginQuery(GL_TIME_ELAPSED, _query);
+        }
+    }
+
+    ~GpuTimerScope()
+    {
+        if (!_query)
+            return;
+
+        glEndQuery(GL_TIME_ELAPSED);
+        // Reading GL_QUERY_RESULT blocks until the GPU work is done,
+        // so the GPU slice can safely end "now".
+        GLuint64 gpuDurationNs = 0;
+        glGetQueryObjectui64v(_query, GL_QUERY_RESULT, &gpuDurationNs);
+        glDeleteQueries(1, &_query);
+        MX_TRACE_ASYNC_ENDING_NOW(Tracing::GPU_ASYNC_TRACK, Tracing::Category::Render,
+                                  "GPU Frame", gpuDurationNs);
+    }
+
+    GpuTimerScope(const GpuTimerScope&) = delete;
+    GpuTimerScope& operator=(const GpuTimerScope&) = delete;
+
+  private:
+    GLuint _query = 0;
+};
+
+} // anonymous namespace
+#endif
+
 //
 // GlslRenderer methods
 //
@@ -161,6 +206,10 @@ void GlslRenderer::render()
     glDepthFunc(GL_LESS);
     glClear(GL_COLOR_BUFFER_BIT | GL_DEPTH_BUFFER_BIT);
 
+#ifdef MATERIALX_BUILD_PERFETTO_TRACING
+    GpuTimerScope gpuTimer;
+#endif
+
     try
     {
         // Bind program and input parameters

source/MaterialXTrace/PerfettoSink.cpp

@@ -7,6 +7,7 @@
 
 #ifdef MATERIALX_BUILD_PERFETTO_TRACING
 
+#include <cstdint>
 #include <fstream>
 #include <mutex>
 
@@ -31,6 +32,99 @@ MATERIALX_NAMESPACE_BEGIN
 namespace Tracing
 {
 
+// ---------------------------------------------------------------------------
+// Per-category Perfetto operations.
+//
+// Perfetto trace macros require compile-time category string literals, so
+// we stamp out a thin ops struct per category and dispatch through a generic
+// lambda.  Adding a new Category means adding one DEFINE line and one switch
+// case in withCategory() below.
+// ---------------------------------------------------------------------------
+namespace
+{
+
+// A Perfetto track that carries its display name, in the spirit of
+// perfetto::CounterTrack. Perfetto writes a track's descriptor on its first
+// use per trace sequence by calling Serialize() on the static track type, so
+// no up-front registration via SetTrackDescriptor is needed.
+class NamedTrack : public perfetto::Track
+{
+  public:
+    explicit NamedTrack(const AsyncTrack& track) :
+        perfetto::Track(track.id),
+        _name(track.name)
+    {
+    }
+
+    perfetto::protos::gen::TrackDescriptor Serialize() const
+    {
+        auto desc = perfetto::Track::Serialize();
+        desc.set_name(_name);
+        return desc;
+    }
+
+    void Serialize(perfetto::protos::pbzero::TrackDescriptor* desc) const
+    {
+        auto bytes = Serialize().SerializeAsString();
+        desc->AppendRawProtoBytes(bytes.data(), bytes.size());
+    }
+
+  private:
+    const char* _name;
+};
+
+#define MX_DEFINE_PERFETTO_OPS(Name, perfettoCategory)                           \
+struct Name                                                                      \
+{                                                                                \
+    static void beginEvent(const char* name)                                     \
+    {                                                                            \
+        TRACE_EVENT_BEGIN(perfettoCategory, nullptr,                              \
+            [&](perfetto::EventContext ctx) { ctx.event()->set_name(name); });    \
+    }                                                                            \
+    static void endEvent()                                                       \
+    {                                                                            \
+        TRACE_EVENT_END(perfettoCategory);                                       \
+    }                                                                            \
+    static void counter(perfetto::CounterTrack track, double value)              \
+    {                                                                            \
+        TRACE_COUNTER(perfettoCategory, track, value);                           \
+    }                                                                            \
+    static void asyncBegin(const NamedTrack& track, uint64_t startNs,            \
+                           const char* name)                                     \
+    {                                                                            \
+        TRACE_EVENT_BEGIN(perfettoCategory, nullptr, track, startNs,             \
+            [&](perfetto::EventContext ctx) { ctx.event()->set_name(name); });   \
+    }                                                                            \
+    static void asyncEnd(const NamedTrack& track, uint64_t endNs)                \
+    {                                                                            \
+        TRACE_EVENT_END(perfettoCategory, track, endNs);                         \
+    }                                                                            \
+};
+
+MX_DEFINE_PERFETTO_OPS(RenderOps,    "mx.render")
+MX_DEFINE_PERFETTO_OPS(ShaderGenOps, "mx.shadergen")
+MX_DEFINE_PERFETTO_OPS(OptimizeOps,  "mx.optimize")
+MX_DEFINE_PERFETTO_OPS(MaterialOps,  "mx.material")
+
+#undef MX_DEFINE_PERFETTO_OPS
+
+/// Dispatch a generic callable by category.  The callable receives a
+/// category-ops tag whose static methods wrap the Perfetto trace macros.
+template<typename Fn>
+void withCategory(Category category, Fn&& fn)
+{
+    switch (category)
+    {
+        case Category::Render:    fn(RenderOps{}); break;
+        case Category::ShaderGen: fn(ShaderGenOps{}); break;
+        case Category::Optimize:  fn(OptimizeOps{}); break;
+        case Category::Material:  fn(MaterialOps{}); break;
+        default: break;
+    }
+}
+
+} // anonymous namespace
+
 PerfettoSink::PerfettoSink(std::string outputPath, size_t bufferSizeKb)
     : _outputPath(std::move(outputPath))
 {
@@ -77,82 +171,36 @@ PerfettoSink::~PerfettoSink()
 
 void PerfettoSink::beginEvent(Category category, const char* name)
 {
-    // Perfetto requires compile-time category names for TRACE_EVENT macros.
-    // Switch on the enum lets the compiler optimize to a jump table.
-    switch (category)
-    {
-        case Category::Render:
-            TRACE_EVENT_BEGIN("mx.render", nullptr, [&](perfetto::EventContext ctx) {
-                ctx.event()->set_name(name);
-            });
-            break;
-        case Category::ShaderGen:
-            TRACE_EVENT_BEGIN("mx.shadergen", nullptr, [&](perfetto::EventContext ctx) {
-                ctx.event()->set_name(name);
-            });
-            break;
-        case Category::Optimize:
-            TRACE_EVENT_BEGIN("mx.optimize", nullptr, [&](perfetto::EventContext ctx) {
-                ctx.event()->set_name(name);
-            });
-            break;
-        case Category::Material:
-            TRACE_EVENT_BEGIN("mx.material", nullptr, [&](perfetto::EventContext ctx) {
-                ctx.event()->set_name(name);
-            });
-            break;
-        default:
-            // Fallback for any future categories
-            TRACE_EVENT_BEGIN("mx.render", nullptr, [&](perfetto::EventContext ctx) {
-                ctx.event()->set_name(name);
-            });
-            break;
-    }
+    withCategory(category, [name](auto ops) {
+        decltype(ops)::beginEvent(name);
+    });
 }
 
 void PerfettoSink::endEvent(Category category)
 {
-    switch (category)
-    {
-        case Category::Render:
-            TRACE_EVENT_END("mx.render");
-            break;
-        case Category::ShaderGen:
-            TRACE_EVENT_END("mx.shadergen");
-            break;
-        case Category::Optimize:
-            TRACE_EVENT_END("mx.optimize");
-            break;
-        case Category::Material:
-            TRACE_EVENT_END("mx.material");
-            break;
-        default:
-            TRACE_EVENT_END("mx.render");
-            break;
-    }
+    withCategory(category, [](auto ops) {
+        decltype(ops)::endEvent();
+    });
 }
 
 void PerfettoSink::counter(Category category, const char* name, double value)
 {
-    auto track = perfetto::CounterTrack(name);
-    switch (category)
-    {
-        case Category::Render:
-            TRACE_COUNTER("mx.render", track, value);
-            break;
-        case Category::ShaderGen:
-            TRACE_COUNTER("mx.shadergen", track, value);
-            break;
-        case Category::Optimize:
-            TRACE_COUNTER("mx.optimize", track, value);
-            break;
-        case Category::Material:
-            TRACE_COUNTER("mx.material", track, value);
-            break;
-        default:
-            TRACE_COUNTER("mx.render", track, value);
-            break;
-    }
+    withCategory(category, [name, value](auto ops) {
+        decltype(ops)::counter(perfetto::CounterTrack(name), value);
+    });
+}
+
+void PerfettoSink::asyncEventEndingNow(const AsyncTrack& track, Category category,
+                                       const char* eventName, uint64_t durationNs)
+{
+    NamedTrack perfTrack(track);
+    uint64_t endNs = perfetto::TrackEvent::GetTraceTimeNs();
+    uint64_t startNs = endNs - durationNs;
+
+    withCategory(category, [&](auto ops) {
+        decltype(ops)::asyncBegin(perfTrack, startNs, eventName);
+        decltype(ops)::asyncEnd(perfTrack, endNs);
+    });
 }
 
 void PerfettoSink::setThreadName(const char* name)

source/MaterialXTrace/PerfettoSink.h

@@ -70,6 +70,8 @@ class PerfettoSink : public Sink
     void beginEvent(Category category, const char* name) override;
     void endEvent(Category category) override;
     void counter(Category category, const char* name, double value) override;
+    void asyncEventEndingNow(const AsyncTrack& track, Category category,
+                             const char* eventName, uint64_t durationNs) override;
     void setThreadName(const char* name) override;
 
   private: