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
This commit is contained in:
Alec Mouri
2022-05-27 22:03:11 +00:00
parent d7df1b2804
commit 3afb3972f4
11 changed files with 108 additions and 70 deletions

View File

@@ -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,
};

View File

@@ -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) {

View File

@@ -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

View File

@@ -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,

View File

@@ -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;

View File

@@ -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,

View File

@@ -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;

View File

@@ -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);

View File

@@ -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;

View File

@@ -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) {

View File

@@ -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.