Make GPU duration metrics more accurate for Vulkan

In the Vulkan pipeline, the GPU start time was measured to be when
swapBuffers starts. But the command queue has already been submitted at
this point, which means that the GPU work would already have begun. This
means that it's possible to measure a negative time since for very light
GPU workloads, the GPU fence can fire prior to CPU making it to
swapBuffers().

To compensate, instead measure from after skia completed submitting GPU
commands, until the GPU fence fires. Since it is theoretically possible
for GPU work to complete if the render thread gets descheduled
immediately after submitting the GPU, we also add some clamping to
ensure that the duration from command submission -> completion of GPU
work is nonnegative.

Bug: 230713131
Test: atest android.view.cts.FrameMetricsListenerTest
Change-Id: Ia30b7732eaab71e4e29766f788d5cd94ec63c38a

11 files changed, 108 insertions, 70 deletions

diff --git a/core/java/android/view/FrameMetrics.java b/core/java/android/view/FrameMetrics.java
index 3cffeb0578d4..380c1045aea8 100644
--- a/core/java/android/view/FrameMetrics.java
+++ b/core/java/android/view/FrameMetrics.java
@@ -254,8 +254,9 @@ public final class FrameMetrics {
         int GPU_COMPLETED = 19;
         int SWAP_BUFFERS_COMPLETED = 20;
         int DISPLAY_PRESENT_TIME = 21;
+        int COMMAND_SUBMISSION_COMPLETED = 22;
 
-        int FRAME_STATS_COUNT = 22; // must always be last and in sync with
+        int FRAME_STATS_COUNT = 23; // must always be last and in sync with
                                     // FrameInfoIndex::NumIndexes in libs/hwui/FrameInfo.h
     }
 
@@ -291,7 +292,7 @@ public final class FrameMetrics {
         // RESERVED VSYNC_TIMESTAMP
         0, 0,
         // GPU_DURATION
-        Index.SWAP_BUFFERS, Index.GPU_COMPLETED,
+        Index.COMMAND_SUBMISSION_COMPLETED, Index.GPU_COMPLETED,
         // DEADLINE
         Index.INTENDED_VSYNC, Index.FRAME_DEADLINE,
     };
diff --git a/libs/hwui/FrameInfo.cpp b/libs/hwui/FrameInfo.cpp
index fecf26906c04..8191f5e6a83a 100644
--- a/libs/hwui/FrameInfo.cpp
+++ b/libs/hwui/FrameInfo.cpp
@@ -20,19 +20,33 @@
 namespace android {
 namespace uirenderer {
 
-const std::array FrameInfoNames{
-        "Flags",               "FrameTimelineVsyncId",   "IntendedVsync",
-        "Vsync",               "InputEventId",           "HandleInputStart",
-        "AnimationStart",      "PerformTraversalsStart", "DrawStart",
-        "FrameDeadline",       "FrameInterval",          "FrameStartTime",
-        "SyncQueued",          "SyncStart",              "IssueDrawCommandsStart",
-        "SwapBuffers",         "FrameCompleted",         "DequeueBufferDuration",
-        "QueueBufferDuration", "GpuCompleted",           "SwapBuffersCompleted",
-        "DisplayPresentTime",
+const std::array FrameInfoNames{"Flags",
+                                "FrameTimelineVsyncId",
+                                "IntendedVsync",
+                                "Vsync",
+                                "InputEventId",
+                                "HandleInputStart",
+                                "AnimationStart",
+                                "PerformTraversalsStart",
+                                "DrawStart",
+                                "FrameDeadline",
+                                "FrameInterval",
+                                "FrameStartTime",
+                                "SyncQueued",
+                                "SyncStart",
+                                "IssueDrawCommandsStart",
+                                "SwapBuffers",
+                                "FrameCompleted",
+                                "DequeueBufferDuration",
+                                "QueueBufferDuration",
+                                "GpuCompleted",
+                                "SwapBuffersCompleted",
+                                "DisplayPresentTime",
+                                "CommandSubmissionCompleted"
 
 };
 
-static_assert(static_cast<int>(FrameInfoIndex::NumIndexes) == 22,
+static_assert(static_cast<int>(FrameInfoIndex::NumIndexes) == 23,
               "Must update value in FrameMetrics.java#FRAME_STATS_COUNT (and here)");
 
 void FrameInfo::importUiThreadInfo(int64_t* info) {
diff --git a/libs/hwui/FrameInfo.h b/libs/hwui/FrameInfo.h
index 540a88b16dc9..564ee4f53a54 100644
--- a/libs/hwui/FrameInfo.h
+++ b/libs/hwui/FrameInfo.h
@@ -58,6 +58,7 @@ enum class FrameInfoIndex {
     GpuCompleted,
     SwapBuffersCompleted,
     DisplayPresentTime,
+    CommandSubmissionCompleted,
 
     // Must be the last value!
     // Also must be kept in sync with FrameMetrics.java#FRAME_STATS_COUNT
diff --git a/libs/hwui/pipeline/skia/SkiaOpenGLPipeline.cpp b/libs/hwui/pipeline/skia/SkiaOpenGLPipeline.cpp
index 744739accb2c..2aca41e41905 100644
--- a/libs/hwui/pipeline/skia/SkiaOpenGLPipeline.cpp
+++ b/libs/hwui/pipeline/skia/SkiaOpenGLPipeline.cpp
@@ -16,8 +16,15 @@
 
 #include "SkiaOpenGLPipeline.h"
 
+#include <GrBackendSurface.h>
+#include <SkBlendMode.h>
+#include <SkImageInfo.h>
+#include <cutils/properties.h>
 #include <gui/TraceUtils.h>
+#include <strings.h>
+
 #include "DeferredLayerUpdater.h"
+#include "FrameInfo.h"
 #include "LayerDrawable.h"
 #include "LightingInfo.h"
 #include "SkiaPipeline.h"
@@ -27,17 +34,9 @@
 #include "renderstate/RenderState.h"
 #include "renderthread/EglManager.h"
 #include "renderthread/Frame.h"
+#include "renderthread/IRenderPipeline.h"
 #include "utils/GLUtils.h"
 
-#include <GLES3/gl3.h>
-
-#include <GrBackendSurface.h>
-#include <SkBlendMode.h>
-#include <SkImageInfo.h>
-
-#include <cutils/properties.h>
-#include <strings.h>
-
 using namespace android::uirenderer::renderthread;
 
 namespace android {
@@ -69,12 +68,11 @@ Frame SkiaOpenGLPipeline::getFrame() {
     return mEglManager.beginFrame(mEglSurface);
 }
 
-bool SkiaOpenGLPipeline::draw(const Frame& frame, const SkRect& screenDirty, const SkRect& dirty,
-                              const LightGeometry& lightGeometry,
-                              LayerUpdateQueue* layerUpdateQueue, const Rect& contentDrawBounds,
-                              bool opaque, const LightInfo& lightInfo,
-                              const std::vector<sp<RenderNode>>& renderNodes,
-                              FrameInfoVisualizer* profiler) {
+IRenderPipeline::DrawResult SkiaOpenGLPipeline::draw(
+        const Frame& frame, const SkRect& screenDirty, const SkRect& dirty,
+        const LightGeometry& lightGeometry, LayerUpdateQueue* layerUpdateQueue,
+        const Rect& contentDrawBounds, bool opaque, const LightInfo& lightInfo,
+        const std::vector<sp<RenderNode>>& renderNodes, FrameInfoVisualizer* profiler) {
     if (!isCapturingSkp()) {
         mEglManager.damageFrame(frame, dirty);
     }
@@ -129,7 +127,7 @@ bool SkiaOpenGLPipeline::draw(const Frame& frame, const SkRect& screenDirty, con
         dumpResourceCacheUsage();
     }
 
-    return true;
+    return {true, IRenderPipeline::DrawResult::kUnknownTime};
 }
 
 bool SkiaOpenGLPipeline::swapBuffers(const Frame& frame, bool drew, const SkRect& screenDirty,
diff --git a/libs/hwui/pipeline/skia/SkiaOpenGLPipeline.h b/libs/hwui/pipeline/skia/SkiaOpenGLPipeline.h
index fddd97f1c5b3..186998a01745 100644
--- a/libs/hwui/pipeline/skia/SkiaOpenGLPipeline.h
+++ b/libs/hwui/pipeline/skia/SkiaOpenGLPipeline.h
@@ -36,11 +36,14 @@ public:
 
     renderthread::MakeCurrentResult makeCurrent() override;
     renderthread::Frame getFrame() override;
-    bool draw(const renderthread::Frame& frame, const SkRect& screenDirty, const SkRect& dirty,
-              const LightGeometry& lightGeometry, LayerUpdateQueue* layerUpdateQueue,
-              const Rect& contentDrawBounds, bool opaque, const LightInfo& lightInfo,
-              const std::vector<sp<RenderNode> >& renderNodes,
-              FrameInfoVisualizer* profiler) override;
+    renderthread::IRenderPipeline::DrawResult draw(const renderthread::Frame& frame,
+                                                   const SkRect& screenDirty, const SkRect& dirty,
+                                                   const LightGeometry& lightGeometry,
+                                                   LayerUpdateQueue* layerUpdateQueue,
+                                                   const Rect& contentDrawBounds, bool opaque,
+                                                   const LightInfo& lightInfo,
+                                                   const std::vector<sp<RenderNode> >& renderNodes,
+                                                   FrameInfoVisualizer* profiler) override;
     GrSurfaceOrigin getSurfaceOrigin() override { return kBottomLeft_GrSurfaceOrigin; }
     bool swapBuffers(const renderthread::Frame& frame, bool drew, const SkRect& screenDirty,
                      FrameInfo* currentFrameInfo, bool* requireSwap) override;
diff --git a/libs/hwui/pipeline/skia/SkiaVulkanPipeline.cpp b/libs/hwui/pipeline/skia/SkiaVulkanPipeline.cpp
index 99fd463b0660..905d46e58014 100644
--- a/libs/hwui/pipeline/skia/SkiaVulkanPipeline.cpp
+++ b/libs/hwui/pipeline/skia/SkiaVulkanPipeline.cpp
@@ -16,7 +16,15 @@
 
 #include "SkiaVulkanPipeline.h"
 
+#include <GrDirectContext.h>
+#include <GrTypes.h>
+#include <SkSurface.h>
+#include <SkTypes.h>
+#include <cutils/properties.h>
 #include <gui/TraceUtils.h>
+#include <strings.h>
+#include <vk/GrVkTypes.h>
+
 #include "DeferredLayerUpdater.h"
 #include "LightingInfo.h"
 #include "Readback.h"
@@ -26,16 +34,7 @@
 #include "VkInteropFunctorDrawable.h"
 #include "renderstate/RenderState.h"
 #include "renderthread/Frame.h"
-
-#include <SkSurface.h>
-#include <SkTypes.h>
-
-#include <GrDirectContext.h>
-#include <GrTypes.h>
-#include <vk/GrVkTypes.h>
-
-#include <cutils/properties.h>
-#include <strings.h>
+#include "renderthread/IRenderPipeline.h"
 
 using namespace android::uirenderer::renderthread;
 
@@ -64,15 +63,14 @@ Frame SkiaVulkanPipeline::getFrame() {
     return vulkanManager().dequeueNextBuffer(mVkSurface);
 }
 
-bool SkiaVulkanPipeline::draw(const Frame& frame, const SkRect& screenDirty, const SkRect& dirty,
-                              const LightGeometry& lightGeometry,
-                              LayerUpdateQueue* layerUpdateQueue, const Rect& contentDrawBounds,
-                              bool opaque, const LightInfo& lightInfo,
-                              const std::vector<sp<RenderNode>>& renderNodes,
-                              FrameInfoVisualizer* profiler) {
+IRenderPipeline::DrawResult SkiaVulkanPipeline::draw(
+        const Frame& frame, const SkRect& screenDirty, const SkRect& dirty,
+        const LightGeometry& lightGeometry, LayerUpdateQueue* layerUpdateQueue,
+        const Rect& contentDrawBounds, bool opaque, const LightInfo& lightInfo,
+        const std::vector<sp<RenderNode>>& renderNodes, FrameInfoVisualizer* profiler) {
     sk_sp<SkSurface> backBuffer = mVkSurface->getCurrentSkSurface();
     if (backBuffer.get() == nullptr) {
-        return false;
+        return {false, -1};
     }
 
     // update the coordinates of the global light position based on surface rotation
@@ -94,9 +92,10 @@ bool SkiaVulkanPipeline::draw(const Frame& frame, const SkRect& screenDirty, con
         profiler->draw(profileRenderer);
     }
 
+    nsecs_t submissionTime = IRenderPipeline::DrawResult::kUnknownTime;
     {
         ATRACE_NAME("flush commands");
-        vulkanManager().finishFrame(backBuffer.get());
+        submissionTime = vulkanManager().finishFrame(backBuffer.get());
     }
     layerUpdateQueue->clear();
 
@@ -105,7 +104,7 @@ bool SkiaVulkanPipeline::draw(const Frame& frame, const SkRect& screenDirty, con
         dumpResourceCacheUsage();
     }
 
-    return true;
+    return {true, submissionTime};
 }
 
 bool SkiaVulkanPipeline::swapBuffers(const Frame& frame, bool drew, const SkRect& screenDirty,
diff --git a/libs/hwui/pipeline/skia/SkiaVulkanPipeline.h b/libs/hwui/pipeline/skia/SkiaVulkanPipeline.h
index 56d42e013f31..ada6af67d4a0 100644
--- a/libs/hwui/pipeline/skia/SkiaVulkanPipeline.h
+++ b/libs/hwui/pipeline/skia/SkiaVulkanPipeline.h
@@ -33,11 +33,14 @@ public:
 
     renderthread::MakeCurrentResult makeCurrent() override;
     renderthread::Frame getFrame() override;
-    bool draw(const renderthread::Frame& frame, const SkRect& screenDirty, const SkRect& dirty,
-              const LightGeometry& lightGeometry, LayerUpdateQueue* layerUpdateQueue,
-              const Rect& contentDrawBounds, bool opaque, const LightInfo& lightInfo,
-              const std::vector<sp<RenderNode> >& renderNodes,
-              FrameInfoVisualizer* profiler) override;
+    renderthread::IRenderPipeline::DrawResult draw(const renderthread::Frame& frame,
+                                                   const SkRect& screenDirty, const SkRect& dirty,
+                                                   const LightGeometry& lightGeometry,
+                                                   LayerUpdateQueue* layerUpdateQueue,
+                                                   const Rect& contentDrawBounds, bool opaque,
+                                                   const LightInfo& lightInfo,
+                                                   const std::vector<sp<RenderNode> >& renderNodes,
+                                                   FrameInfoVisualizer* profiler) override;
     GrSurfaceOrigin getSurfaceOrigin() override { return kTopLeft_GrSurfaceOrigin; }
     bool swapBuffers(const renderthread::Frame& frame, bool drew, const SkRect& screenDirty,
                      FrameInfo* currentFrameInfo, bool* requireSwap) override;
diff --git a/libs/hwui/renderthread/CanvasContext.cpp b/libs/hwui/renderthread/CanvasContext.cpp
index 122c77f3dadc..976117b9bbd4 100644
--- a/libs/hwui/renderthread/CanvasContext.cpp
+++ b/libs/hwui/renderthread/CanvasContext.cpp
@@ -512,9 +512,9 @@ nsecs_t CanvasContext::draw() {
 
     ATRACE_FORMAT("Drawing " RECT_STRING, SK_RECT_ARGS(dirty));
 
-    bool drew = mRenderPipeline->draw(frame, windowDirty, dirty, mLightGeometry, &mLayerUpdateQueue,
-                                      mContentDrawBounds, mOpaque, mLightInfo, mRenderNodes,
-                                      &(profiler()));
+    const auto drawResult = mRenderPipeline->draw(frame, windowDirty, dirty, mLightGeometry,
+                                                  &mLayerUpdateQueue, mContentDrawBounds, mOpaque,
+                                                  mLightInfo, mRenderNodes, &(profiler()));
 
     uint64_t frameCompleteNr = getFrameNumber();
 
@@ -534,8 +534,11 @@ nsecs_t CanvasContext::draw() {
 
     bool requireSwap = false;
     int error = OK;
-    bool didSwap =
-            mRenderPipeline->swapBuffers(frame, drew, windowDirty, mCurrentFrameInfo, &requireSwap);
+    bool didSwap = mRenderPipeline->swapBuffers(frame, drawResult.success, windowDirty,
+                                                mCurrentFrameInfo, &requireSwap);
+
+    mCurrentFrameInfo->set(FrameInfoIndex::CommandSubmissionCompleted) = std::max(
+            drawResult.commandSubmissionTime, mCurrentFrameInfo->get(FrameInfoIndex::SwapBuffers));
 
     mIsDirty = false;
 
@@ -753,7 +756,8 @@ void CanvasContext::onSurfaceStatsAvailable(void* context, int32_t surfaceContro
     if (frameInfo != nullptr) {
         frameInfo->set(FrameInfoIndex::FrameCompleted) = std::max(gpuCompleteTime,
                 frameInfo->get(FrameInfoIndex::SwapBuffersCompleted));
-        frameInfo->set(FrameInfoIndex::GpuCompleted) = gpuCompleteTime;
+        frameInfo->set(FrameInfoIndex::GpuCompleted) = std::max(
+                gpuCompleteTime, frameInfo->get(FrameInfoIndex::CommandSubmissionCompleted));
         std::scoped_lock lock(instance->mFrameMetricsReporterMutex);
         instance->mJankTracker.finishFrame(*frameInfo, instance->mFrameMetricsReporter, frameNumber,
                                            surfaceControlId);
diff --git a/libs/hwui/renderthread/IRenderPipeline.h b/libs/hwui/renderthread/IRenderPipeline.h
index aceb5a528fc8..ef58bc553c23 100644
--- a/libs/hwui/renderthread/IRenderPipeline.h
+++ b/libs/hwui/renderthread/IRenderPipeline.h
@@ -49,11 +49,21 @@ class IRenderPipeline {
 public:
     virtual MakeCurrentResult makeCurrent() = 0;
     virtual Frame getFrame() = 0;
-    virtual bool draw(const Frame& frame, const SkRect& screenDirty, const SkRect& dirty,
-                      const LightGeometry& lightGeometry, LayerUpdateQueue* layerUpdateQueue,
-                      const Rect& contentDrawBounds, bool opaque, const LightInfo& lightInfo,
-                      const std::vector<sp<RenderNode>>& renderNodes,
-                      FrameInfoVisualizer* profiler) = 0;
+
+    // Result of IRenderPipeline::draw
+    struct DrawResult {
+        // True if draw() succeeded, false otherwise
+        bool success = false;
+        // If drawing was successful, reports the time at which command
+        // submission occurred. -1 if this time is unknown.
+        static constexpr nsecs_t kUnknownTime = -1;
+        nsecs_t commandSubmissionTime = kUnknownTime;
+    };
+    virtual DrawResult draw(const Frame& frame, const SkRect& screenDirty, const SkRect& dirty,
+                            const LightGeometry& lightGeometry, LayerUpdateQueue* layerUpdateQueue,
+                            const Rect& contentDrawBounds, bool opaque, const LightInfo& lightInfo,
+                            const std::vector<sp<RenderNode>>& renderNodes,
+                            FrameInfoVisualizer* profiler) = 0;
     virtual bool swapBuffers(const Frame& frame, bool drew, const SkRect& screenDirty,
                              FrameInfo* currentFrameInfo, bool* requireSwap) = 0;
     virtual DeferredLayerUpdater* createTextureLayer() = 0;
diff --git a/libs/hwui/renderthread/VulkanManager.cpp b/libs/hwui/renderthread/VulkanManager.cpp
index a9ff2c60fdbe..718d4a16d5c8 100644
--- a/libs/hwui/renderthread/VulkanManager.cpp
+++ b/libs/hwui/renderthread/VulkanManager.cpp
@@ -494,7 +494,7 @@ static void destroy_semaphore(void* context) {
     }
 }
 
-void VulkanManager::finishFrame(SkSurface* surface) {
+nsecs_t VulkanManager::finishFrame(SkSurface* surface) {
     ATRACE_NAME("Vulkan finish frame");
     ALOGE_IF(mSwapSemaphore != VK_NULL_HANDLE || mDestroySemaphoreContext != nullptr,
              "finishFrame already has an outstanding semaphore");
@@ -530,6 +530,7 @@ void VulkanManager::finishFrame(SkSurface* surface) {
     GrDirectContext* context = GrAsDirectContext(surface->recordingContext());
     ALOGE_IF(!context, "Surface is not backed by gpu");
     context->submit();
+    const nsecs_t submissionTime = systemTime();
     if (semaphore != VK_NULL_HANDLE) {
         if (submitted == GrSemaphoresSubmitted::kYes) {
             mSwapSemaphore = semaphore;
@@ -558,6 +559,8 @@ void VulkanManager::finishFrame(SkSurface* surface) {
         }
     }
     skiapipeline::ShaderCache::get().onVkFrameFlushed(context);
+
+    return submissionTime;
 }
 
 void VulkanManager::swapBuffers(VulkanSurface* surface, const SkRect& dirtyRect) {
diff --git a/libs/hwui/renderthread/VulkanManager.h b/libs/hwui/renderthread/VulkanManager.h
index b816649edf6e..b8c2bdf112f8 100644
--- a/libs/hwui/renderthread/VulkanManager.h
+++ b/libs/hwui/renderthread/VulkanManager.h
@@ -84,7 +84,9 @@ public:
     void destroySurface(VulkanSurface* surface);
 
     Frame dequeueNextBuffer(VulkanSurface* surface);
-    void finishFrame(SkSurface* surface);
+    // Finishes the frame and submits work to the GPU
+    // Returns the estimated start time for intiating GPU work, -1 otherwise.
+    nsecs_t finishFrame(SkSurface* surface);
     void swapBuffers(VulkanSurface* surface, const SkRect& dirtyRect);
 
     // Inserts a wait on fence command into the Vulkan command buffer.