Add timer query support to TracePerfTests.

This can allow us to get some profiling measurements on ANGLE vs a
native driver. We correlate host times with GL times using the blocking
timestamp query. We also time RenderPasses/FBO switches using the
trace instrumentation we added in an earlier patch combined with timer
queries.

Not currently instrumented for the current tests. We'll need to re-run
capture to get the callbacks working correctly.

Bug: angleproject:4433
Change-Id: I8f61774a3a090ac9460a378d34715a72954d1331
Reviewed-on: https://chromium-review.googlesource.com/c/angle/angle/+/2080597
Reviewed-by: Cody Northrop <[email protected]>
Commit-Queue: Jamie Madill <[email protected]>

Author: null77

src/tests/perf_tests/ANGLEPerfTest.cpp

@@ -116,10 +116,7 @@ void UpdateTraceEventDuration(angle::PlatformMethods *platform,
 
 double MonotonicallyIncreasingTime(angle::PlatformMethods *platform)
 {
-    // Move the time origin to the first call to this function, to avoid generating unnecessarily
-    // large timestamps.
-    static double origin = angle::GetCurrentTime();
-    return angle::GetCurrentTime() - origin;
+    return GetHostTimeSeconds();
 }
 
 void DumpTraceEventsToJSONFile(const std::vector<TraceEvent> &traceEvents,
@@ -174,6 +171,16 @@ ANGLE_MAYBE_UNUSED void KHRONOS_APIENTRY DebugMessageCallback(GLenum source,
 }
 }  // anonymous namespace
 
+TraceEvent::TraceEvent(char phaseIn,
+                       const char *categoryNameIn,
+                       const char *nameIn,
+                       double timestampIn)
+    : phase(phaseIn), categoryName(categoryNameIn), name{}, timestamp(timestampIn)
+{
+    ASSERT(strlen(nameIn) < kMaxNameLen);
+    strcpy(name, nameIn);
+}
+
 ANGLEPerfTest::ANGLEPerfTest(const std::string &name,
                              const std::string &backend,
                              const std::string &story,
@@ -394,9 +401,9 @@ ANGLERenderTest::ANGLERenderTest(const std::string &name, const RenderTestParams
                     testParams.story(),
                     OneFrame() ? 1 : testParams.iterationsPerStep),
       mTestParams(testParams),
+      mIsTimestampQueryAvailable(false),
       mGLWindow(nullptr),
-      mOSWindow(nullptr),
-      mIsTimestampQueryAvailable(false)
+      mOSWindow(nullptr)
 {
     // Force fast tests to make sure our slowest bots don't time out.
     if (OneFrame())
@@ -592,6 +599,24 @@ void ANGLERenderTest::endInternalTraceEvent(const char *name)
     }
 }
 
+void ANGLERenderTest::beginGLTraceEvent(const char *name, double hostTimeSec)
+{
+    if (gEnableTrace)
+    {
+        mTraceEventBuffer.emplace_back(TRACE_EVENT_PHASE_BEGIN, gTraceCategories[1].name, name,
+                                       hostTimeSec);
+    }
+}
+
+void ANGLERenderTest::endGLTraceEvent(const char *name, double hostTimeSec)
+{
+    if (gEnableTrace)
+    {
+        mTraceEventBuffer.emplace_back(TRACE_EVENT_PHASE_END, gTraceCategories[1].name, name,
+                                       hostTimeSec);
+    }
+}
+
 void ANGLERenderTest::step()
 {
     beginInternalTraceEvent("step");
@@ -714,3 +739,14 @@ std::vector<TraceEvent> &ANGLERenderTest::getTraceEventBuffer()
 {
     return mTraceEventBuffer;
 }
+
+namespace angle
+{
+double GetHostTimeSeconds()
+{
+    // Move the time origin to the first call to this function, to avoid generating unnecessarily
+    // large timestamps.
+    static double origin = angle::GetCurrentTime();
+    return angle::GetCurrentTime() - origin;
+}
+}  // namespace angle

src/tests/perf_tests/ANGLEPerfTest.h

@@ -43,14 +43,13 @@ class Event;
 struct TraceEvent final
 {
     TraceEvent() {}
+    TraceEvent(char phaseIn, const char *categoryNameIn, const char *nameIn, double timestampIn);
 
-    TraceEvent(char phaseIn, const char *categoryNameIn, const char *nameIn, double timestampIn)
-        : phase(phaseIn), categoryName(categoryNameIn), name(nameIn), timestamp(timestampIn)
-    {}
+    static constexpr uint32_t kMaxNameLen = 64;
 
     char phase               = 0;
     const char *categoryName = nullptr;
-    const char *name         = nullptr;
+    char name[kMaxNameLen]   = {};
     double timestamp         = 0;
 };
 
@@ -148,6 +147,10 @@ class ANGLERenderTest : public ANGLEPerfTest
 
     void beginInternalTraceEvent(const char *name);
     void endInternalTraceEvent(const char *name);
+    void beginGLTraceEvent(const char *name, double hostTimeSec);
+    void endGLTraceEvent(const char *name, double hostTimeSec);
+
+    bool mIsTimestampQueryAvailable;
 
   private:
     void SetUp() override;
@@ -165,7 +168,6 @@ class ANGLERenderTest : public ANGLEPerfTest
     angle::PlatformMethods mPlatformMethods;
     ConfigParameters mConfigParams;
 
-    bool mIsTimestampQueryAvailable;
     GLuint mTimestampQuery;
 
     // Trace event record that can be output.
@@ -201,4 +203,10 @@ ParamsT Passthrough(const ParamsT &input)
     return input;
 }
 }  // namespace params
+
+namespace angle
+{
+// Returns the time of the host since the application started in seconds.
+double GetHostTimeSeconds();
+}  // namespace angle
 #endif  // PERF_TESTS_ANGLE_PERF_TEST_H_

src/tests/perf_tests/DrawCallPerfParams.h

@@ -54,6 +54,14 @@ ParamsT GL(const ParamsT &in)
     return out;
 }
 
+template <typename ParamsT>
+ParamsT GL3(const ParamsT &in)
+{
+    ParamsT out       = in;
+    out.eglParameters = angle::egl_platform::OPENGL_OR_GLES(3, 0);
+    return out;
+}
+
 template <typename ParamsT>
 ParamsT Vulkan(const ParamsT &in)
 {

src/tests/perf_tests/TracePerfTest.cpp

@@ -28,6 +28,7 @@ using namespace egl_platform;
 
 namespace
 {
+void FramebufferChangeCallback(void *userData, GLenum target, GLuint framebuffer);
 
 enum class TracePerfTestID
 {
@@ -99,9 +100,34 @@ class TracePerfTest : public ANGLERenderTest, public ::testing::WithParamInterfa
     void destroyBenchmark() override;
     void drawBenchmark() override;
 
+    void onFramebufferChange(GLenum target, GLuint framebuffer);
+
     uint32_t mStartFrame;
     uint32_t mEndFrame;
     std::function<void(uint32_t)> mReplayFunc;
+
+    double getHostTimeFromGLTime(GLint64 glTime);
+
+  private:
+    struct QueryInfo
+    {
+        GLuint beginTimestampQuery;
+        GLuint endTimestampQuery;
+        GLuint framebuffer;
+    };
+
+    struct TimeSample
+    {
+        GLint64 glTime;
+        double hostTime;
+    };
+
+    void sampleTime();
+
+    // For tracking RenderPass/FBO change timing.
+    QueryInfo mCurrentQuery = {};
+    std::vector<QueryInfo> mRunningQueries;
+    std::vector<TimeSample> mTimeline;
 };
 
 TracePerfTest::TracePerfTest()
@@ -157,19 +183,153 @@ void TracePerfTest::initializeBenchmark()
 
 void TracePerfTest::destroyBenchmark() {}
 
+void TracePerfTest::sampleTime()
+{
+    if (mIsTimestampQueryAvailable)
+    {
+        GLint64 glTime;
+        // glGetInteger64vEXT is exported by newer versions of the timer query extensions.
+        // Unfortunately only the core EP is exposed by some desktop drivers (e.g. NVIDIA).
+        if (glGetInteger64vEXT)
+        {
+            glGetInteger64vEXT(GL_TIMESTAMP_EXT, &glTime);
+        }
+        else
+        {
+            glGetInteger64v(GL_TIMESTAMP_EXT, &glTime);
+        }
+        mTimeline.push_back({glTime, angle::GetHostTimeSeconds()});
+    }
+}
+
 void TracePerfTest::drawBenchmark()
 {
+    // Add a time sample from GL and the host.
+    sampleTime();
+
     startGpuTimer();
 
     for (uint32_t frame = mStartFrame; frame < mEndFrame; ++frame)
     {
+        char frameName[32];
+        sprintf(frameName, "Frame %u", frame);
+        beginInternalTraceEvent(frameName);
+
         mReplayFunc(frame);
         getGLWindow()->swap();
+
+        endInternalTraceEvent(frameName);
+    }
+
+    // Process any running queries once per iteration.
+    for (size_t queryIndex = 0; queryIndex < mRunningQueries.size();)
+    {
+        const QueryInfo &query = mRunningQueries[queryIndex];
+
+        GLuint endResultAvailable = 0;
+        glGetQueryObjectuivEXT(query.endTimestampQuery, GL_QUERY_RESULT_AVAILABLE,
+                               &endResultAvailable);
+
+        if (endResultAvailable == GL_TRUE)
+        {
+            char fboName[32];
+            sprintf(fboName, "FBO %u", query.framebuffer);
+
+            GLint64 beginTimestamp = 0;
+            glGetQueryObjecti64vEXT(query.beginTimestampQuery, GL_QUERY_RESULT, &beginTimestamp);
+            glDeleteQueriesEXT(1, &query.beginTimestampQuery);
+            double beginHostTime = getHostTimeFromGLTime(beginTimestamp);
+            beginGLTraceEvent(fboName, beginHostTime);
+
+            GLint64 endTimestamp = 0;
+            glGetQueryObjecti64vEXT(query.endTimestampQuery, GL_QUERY_RESULT, &endTimestamp);
+            glDeleteQueriesEXT(1, &query.endTimestampQuery);
+            double endHostTime = getHostTimeFromGLTime(endTimestamp);
+            endGLTraceEvent(fboName, endHostTime);
+
+            mRunningQueries.erase(mRunningQueries.begin() + queryIndex);
+        }
+        else
+        {
+            queryIndex++;
+        }
     }
 
     stopGpuTimer();
 }
 
+// Converts a GL timestamp into a host-side CPU time aligned with "GetHostTimeSeconds".
+// This check is necessary to line up sampled trace events in a consistent timeline.
+// Uses a linear interpolation from a series of samples. We do a blocking call to sample
+// both host and GL time once per swap. We then find the two closest GL timestamps and
+// interpolate the host times between them to compute our result. If we are past the last
+// GL timestamp we sample a new data point pair.
+double TracePerfTest::getHostTimeFromGLTime(GLint64 glTime)
+{
+    // Find two samples to do a lerp.
+    size_t firstSampleIndex = mTimeline.size() - 1;
+    while (firstSampleIndex > 0)
+    {
+        if (mTimeline[firstSampleIndex].glTime < glTime)
+        {
+            break;
+        }
+        firstSampleIndex--;
+    }
+
+    // Add an extra sample if we're missing an ending sample.
+    if (firstSampleIndex == mTimeline.size() - 1)
+    {
+        sampleTime();
+    }
+
+    const TimeSample &start = mTimeline[firstSampleIndex];
+    const TimeSample &end   = mTimeline[firstSampleIndex + 1];
+
+    // Note: we have observed in some odd cases later timestamps producing values that are
+    // smaller than preceding timestamps. This bears further investigation.
+
+    // Compute the scaling factor for the lerp.
+    double glDelta = static_cast<double>(glTime - start.glTime);
+    double glRange = static_cast<double>(end.glTime - start.glTime);
+    double t       = glDelta / glRange;
+
+    // Lerp(t1, t2, t)
+    double hostRange = end.hostTime - start.hostTime;
+    return mTimeline[firstSampleIndex].hostTime + hostRange * t;
+}
+
+// Callback from the perf tests.
+void TracePerfTest::onFramebufferChange(GLenum target, GLuint framebuffer)
+{
+    if (!mIsTimestampQueryAvailable)
+        return;
+
+    if (target != GL_FRAMEBUFFER && target != GL_DRAW_FRAMEBUFFER)
+        return;
+
+    // We have at most one active timestamp query at a time. This code will end the current query
+    // and immediately start a new one.
+    if (mCurrentQuery.beginTimestampQuery != 0)
+    {
+        glGenQueriesEXT(1, &mCurrentQuery.endTimestampQuery);
+        glQueryCounterEXT(mCurrentQuery.endTimestampQuery, GL_TIMESTAMP_EXT);
+        mRunningQueries.push_back(mCurrentQuery);
+        mCurrentQuery = {};
+    }
+
+    ASSERT(mCurrentQuery.beginTimestampQuery == 0);
+
+    glGenQueriesEXT(1, &mCurrentQuery.beginTimestampQuery);
+    glQueryCounterEXT(mCurrentQuery.beginTimestampQuery, GL_TIMESTAMP_EXT);
+    mCurrentQuery.framebuffer = framebuffer;
+}
+
+ANGLE_MAYBE_UNUSED void FramebufferChangeCallback(void *userData, GLenum target, GLuint framebuffer)
+{
+    reinterpret_cast<TracePerfTest *>(userData)->onFramebufferChange(target, framebuffer);
+}
+
 TEST_P(TracePerfTest, Run)
 {
     run();

src/tests/test_utils/angle_test_configs.cpp

@@ -398,6 +398,15 @@ EGLPlatformParameters OPENGL_OR_GLES()
 #endif
 }
 
+EGLPlatformParameters OPENGL_OR_GLES(EGLint major, EGLint minor)
+{
+#if defined(ANGLE_PLATFORM_ANDROID)
+    return OPENGLES(major, minor);
+#else
+    return OPENGL(major, minor);
+#endif
+}
+
 EGLPlatformParameters OPENGL_OR_GLES_NULL()
 {
 #if defined(ANGLE_PLATFORM_ANDROID)

src/tests/test_utils/angle_test_configs.h

@@ -109,6 +109,7 @@ EGLPlatformParameters OPENGLES(EGLint major, EGLint minor);
 EGLPlatformParameters OPENGLES_NULL();
 
 EGLPlatformParameters OPENGL_OR_GLES();
+EGLPlatformParameters OPENGL_OR_GLES(EGLint major, EGLint minor);
 EGLPlatformParameters OPENGL_OR_GLES_NULL();
 
 EGLPlatformParameters VULKAN();