Add GPU completion to FrameMetrics (1/3)
- Add SurfaceStatsCallback to TransactionCompletedListener
- Register a callback in RenderProxy to be called when we have
surface stats from SF via the BLAST callback.
- Instead of finishing a frame for frame metrics reporting
immediately, wait until BLAST callback fires, note GPU completion
time and finish frame.
- Expose GPU_COMPLETION in FrameMetrics
- Modify TOTAL_DURATION to also include GPU_COMPLETION
Test: FrameMetricsListenerTest
Fixes: 171046219
Change-Id: I16fa1d80cfc4e7a5527c18fec7e885409f17ee4d
diff --git a/libs/hwui/renderthread/CanvasContext.cpp b/libs/hwui/renderthread/CanvasContext.cpp
index 9543d47..b760db2 100644
--- a/libs/hwui/renderthread/CanvasContext.cpp
+++ b/libs/hwui/renderthread/CanvasContext.cpp
@@ -178,12 +178,16 @@
if (surfaceControl == mSurfaceControl) return;
auto funcs = mRenderThread.getASurfaceControlFunctions();
+
if (mSurfaceControl != nullptr) {
+ funcs.unregisterListenerFunc(this, &onSurfaceStatsAvailable);
funcs.releaseFunc(mSurfaceControl);
}
mSurfaceControl = surfaceControl;
+ mExpectSurfaceStats = surfaceControl != nullptr;
if (mSurfaceControl != nullptr) {
funcs.acquireFunc(mSurfaceControl);
+ funcs.registerListenerFunc(surfaceControl, this, &onSurfaceStatsAvailable);
}
}
@@ -332,8 +336,8 @@
// just keep using the previous frame's structure instead
if (!wasSkipped(mCurrentFrameInfo)) {
mCurrentFrameInfo = mJankTracker.startFrame();
- mLast4FrameInfos.next().first = mCurrentFrameInfo;
}
+
mCurrentFrameInfo->importUiThreadInfo(uiFrameInfo);
mCurrentFrameInfo->set(FrameInfoIndex::SyncQueued) = syncQueued;
mCurrentFrameInfo->markSyncStart();
@@ -538,17 +542,14 @@
}
mCurrentFrameInfo->set(FrameInfoIndex::DequeueBufferDuration) = swap.dequeueDuration;
mCurrentFrameInfo->set(FrameInfoIndex::QueueBufferDuration) = swap.queueDuration;
- mLast4FrameInfos[-1].second = frameCompleteNr;
mHaveNewSurface = false;
mFrameNumber = -1;
} else {
mCurrentFrameInfo->set(FrameInfoIndex::DequeueBufferDuration) = 0;
mCurrentFrameInfo->set(FrameInfoIndex::QueueBufferDuration) = 0;
- mLast4FrameInfos[-1].second = -1;
}
- // TODO: Use a fence for real completion?
- mCurrentFrameInfo->markFrameCompleted();
+ mCurrentFrameInfo->markSwapBuffersCompleted();
#if LOG_FRAMETIME_MMA
float thisFrame = mCurrentFrameInfo->duration(FrameInfoIndex::IssueDrawCommandsStart,
@@ -572,30 +573,73 @@
mFrameCompleteCallbacks.clear();
}
- mJankTracker.finishFrame(*mCurrentFrameInfo);
- if (CC_UNLIKELY(mFrameMetricsReporter.get() != nullptr)) {
- mFrameMetricsReporter->reportFrameMetrics(mCurrentFrameInfo->data());
- }
-
- if (mLast4FrameInfos.size() == mLast4FrameInfos.capacity()) {
- // By looking 4 frames back, we guarantee all SF stats are available. There are at
- // most 3 buffers in BufferQueue. Surface object keeps stats for the last 8 frames.
- FrameInfo* forthBehind = mLast4FrameInfos.front().first;
- int64_t composedFrameId = mLast4FrameInfos.front().second;
- nsecs_t acquireTime = -1;
- if (mNativeSurface) {
- native_window_get_frame_timestamps(mNativeSurface->getNativeWindow(), composedFrameId,
- nullptr, &acquireTime, nullptr, nullptr, nullptr,
- nullptr, nullptr, nullptr, nullptr);
+ if (requireSwap) {
+ if (mExpectSurfaceStats) {
+ std::lock_guard lock(mLast4FrameInfosMutex);
+ std::pair<FrameInfo*, int64_t>& next = mLast4FrameInfos.next();
+ next.first = mCurrentFrameInfo;
+ next.second = frameCompleteNr;
+ } else {
+ mCurrentFrameInfo->markFrameCompleted();
+ mCurrentFrameInfo->set(FrameInfoIndex::GpuCompleted)
+ = mCurrentFrameInfo->get(FrameInfoIndex::FrameCompleted);
+ finishFrame(mCurrentFrameInfo);
}
- // Ignore default -1, NATIVE_WINDOW_TIMESTAMP_INVALID and NATIVE_WINDOW_TIMESTAMP_PENDING
- forthBehind->set(FrameInfoIndex::GpuCompleted) = acquireTime > 0 ? acquireTime : -1;
- mJankTracker.finishGpuDraw(*forthBehind);
}
mRenderThread.cacheManager().onFrameCompleted();
}
+void CanvasContext::finishFrame(FrameInfo* frameInfo) {
+
+ // TODO (b/169858044): Consolidate this into a single call.
+ mJankTracker.finishFrame(*frameInfo);
+ mJankTracker.finishGpuDraw(*frameInfo);
+
+ // TODO (b/169858044): Move this into JankTracker to adjust deadline when queue is
+ // double-stuffed.
+ if (CC_UNLIKELY(mFrameMetricsReporter.get() != nullptr)) {
+ mFrameMetricsReporter->reportFrameMetrics(frameInfo->data());
+ }
+}
+
+void CanvasContext::onSurfaceStatsAvailable(void* context, ASurfaceControl* control,
+ ASurfaceControlStats* stats) {
+
+ CanvasContext* instance = static_cast<CanvasContext*>(context);
+
+ const ASurfaceControlFunctions& functions =
+ instance->mRenderThread.getASurfaceControlFunctions();
+
+ nsecs_t gpuCompleteTime = functions.getAcquireTimeFunc(stats);
+ uint64_t frameNumber = functions.getFrameNumberFunc(stats);
+
+ FrameInfo* frameInfo = nullptr;
+ {
+ std::lock_guard(instance->mLast4FrameInfosMutex);
+ for (size_t i = 0; i < instance->mLast4FrameInfos.size(); i++) {
+ if (instance->mLast4FrameInfos[i].second == frameNumber) {
+ frameInfo = instance->mLast4FrameInfos[i].first;
+ break;
+ }
+ }
+ }
+ if (frameInfo != nullptr) {
+ if (gpuCompleteTime == -1) {
+ gpuCompleteTime = frameInfo->get(FrameInfoIndex::SwapBuffersCompleted);
+ }
+ if (gpuCompleteTime < frameInfo->get(FrameInfoIndex::SwapBuffers)) {
+ // TODO (b/180488606): Investigate why this can happen for first frames.
+ ALOGW("Impossible GPU complete time swapBuffers=%" PRIi64 " gpuComplete=%" PRIi64,
+ frameInfo->get(FrameInfoIndex::SwapBuffers), gpuCompleteTime);
+ gpuCompleteTime = frameInfo->get(FrameInfoIndex::SwapBuffersCompleted);
+ }
+ frameInfo->set(FrameInfoIndex::FrameCompleted) = gpuCompleteTime;
+ frameInfo->set(FrameInfoIndex::GpuCompleted) = gpuCompleteTime;
+ instance->finishFrame(frameInfo);
+ }
+}
+
// Called by choreographer to do an RT-driven animation
void CanvasContext::doFrame() {
if (!mRenderPipeline->isSurfaceReady()) return;