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;
diff --git a/libs/hwui/renderthread/CanvasContext.h b/libs/hwui/renderthread/CanvasContext.h
index 917b00c..2e7b2f6 100644
--- a/libs/hwui/renderthread/CanvasContext.h
+++ b/libs/hwui/renderthread/CanvasContext.h
@@ -37,6 +37,7 @@
#include <SkSize.h>
#include <cutils/compiler.h>
#include <utils/Functor.h>
+#include <utils/Mutex.h>
#include <functional>
#include <future>
@@ -196,6 +197,10 @@
SkISize getNextFrameSize() const;
+ // Called when SurfaceStats are available.
+ static void onSurfaceStatsAvailable(void* context, ASurfaceControl* control,
+ ASurfaceControlStats* stats);
+
private:
CanvasContext(RenderThread& thread, bool translucent, RenderNode* rootRenderNode,
IContextFactory* contextFactory, std::unique_ptr<IRenderPipeline> renderPipeline);
@@ -212,6 +217,7 @@
void setupPipelineSurface();
SkRect computeDirtyRect(const Frame& frame, SkRect* dirty);
+ void finishFrame(FrameInfo* frameInfo);
// The same type as Frame.mWidth and Frame.mHeight
int32_t mLastFrameWidth = 0;
@@ -261,7 +267,12 @@
std::vector<sp<RenderNode>> mRenderNodes;
FrameInfo* mCurrentFrameInfo = nullptr;
- RingBuffer<std::pair<FrameInfo*, int64_t>, 4> mLast4FrameInfos;
+
+ // List of frames that are awaiting GPU completion reporting
+ RingBuffer<std::pair<FrameInfo*, int64_t>, 4> mLast4FrameInfos
+ GUARDED_BY(mLast4FrameInfosMutex);
+ std::mutex mLast4FrameInfosMutex;
+
std::string mName;
JankTracker mJankTracker;
FrameInfoVisualizer mProfiler;
@@ -276,6 +287,9 @@
std::unique_ptr<IRenderPipeline> mRenderPipeline;
std::vector<std::function<void(int64_t)>> mFrameCompleteCallbacks;
+
+ // If set to true, we expect that callbacks into onSurfaceStatsAvailable
+ bool mExpectSurfaceStats = false;
};
} /* namespace renderthread */
diff --git a/libs/hwui/renderthread/RenderProxy.cpp b/libs/hwui/renderthread/RenderProxy.cpp
index e14842f..b9568fc 100644
--- a/libs/hwui/renderthread/RenderProxy.cpp
+++ b/libs/hwui/renderthread/RenderProxy.cpp
@@ -215,6 +215,7 @@
void RenderProxy::dumpProfileInfo(int fd, int dumpFlags) {
mRenderThread.queue().runSync([&]() {
+ std::lock_guard lock(mRenderThread.getJankDataMutex());
mContext->profiler().dumpData(fd);
if (dumpFlags & DumpFlags::FrameStats) {
mContext->dumpFrames(fd);
@@ -234,6 +235,7 @@
uint32_t RenderProxy::frameTimePercentile(int percentile) {
return mRenderThread.queue().runSync([&]() -> auto {
+ std::lock_guard lock(mRenderThread.globalProfileData().getDataMutex());
return mRenderThread.globalProfileData()->findPercentile(percentile);
});
}
diff --git a/libs/hwui/renderthread/RenderThread.cpp b/libs/hwui/renderthread/RenderThread.cpp
index 2610186..5dc02e8 100644
--- a/libs/hwui/renderthread/RenderThread.cpp
+++ b/libs/hwui/renderthread/RenderThread.cpp
@@ -59,6 +59,26 @@
releaseFunc = (ASC_release) dlsym(handle_, "ASurfaceControl_release");
LOG_ALWAYS_FATAL_IF(releaseFunc == nullptr,
"Failed to find required symbol ASurfaceControl_release!");
+
+ registerListenerFunc = (ASC_registerSurfaceStatsListener) dlsym(handle_,
+ "ASurfaceControl_registerSurfaceStatsListener");
+ LOG_ALWAYS_FATAL_IF(registerListenerFunc == nullptr,
+ "Failed to find required symbol ASurfaceControl_registerSurfaceStatsListener!");
+
+ unregisterListenerFunc = (ASC_unregisterSurfaceStatsListener) dlsym(handle_,
+ "ASurfaceControl_unregisterSurfaceStatsListener");
+ LOG_ALWAYS_FATAL_IF(unregisterListenerFunc == nullptr,
+ "Failed to find required symbol ASurfaceControl_unregisterSurfaceStatsListener!");
+
+ getAcquireTimeFunc = (ASCStats_getAcquireTime) dlsym(handle_,
+ "ASurfaceControlStats_getAcquireTime");
+ LOG_ALWAYS_FATAL_IF(getAcquireTimeFunc == nullptr,
+ "Failed to find required symbol ASurfaceControlStats_getAcquireTime!");
+
+ getFrameNumberFunc = (ASCStats_getFrameNumber) dlsym(handle_,
+ "ASurfaceControlStats_getFrameNumber");
+ LOG_ALWAYS_FATAL_IF(getFrameNumberFunc == nullptr,
+ "Failed to find required symbol ASurfaceControlStats_getFrameNumber!");
}
void RenderThread::frameCallback(int64_t frameTimeNanos, void* data) {
@@ -146,7 +166,8 @@
, mFrameCallbackTaskPending(false)
, mRenderState(nullptr)
, mEglManager(nullptr)
- , mFunctorManager(WebViewFunctorManager::instance()) {
+ , mFunctorManager(WebViewFunctorManager::instance())
+ , mGlobalProfileData(mJankDataMutex) {
Properties::load();
start("RenderThread");
}
diff --git a/libs/hwui/renderthread/RenderThread.h b/libs/hwui/renderthread/RenderThread.h
index bb7c518..a7d1ba8 100644
--- a/libs/hwui/renderthread/RenderThread.h
+++ b/libs/hwui/renderthread/RenderThread.h
@@ -17,6 +17,7 @@
#ifndef RENDERTHREAD_H_
#define RENDERTHREAD_H_
+#include <surface_control_private.h>
#include <GrDirectContext.h>
#include <SkBitmap.h>
#include <cutils/compiler.h>
@@ -81,11 +82,22 @@
typedef void (*ASC_acquire)(ASurfaceControl* control);
typedef void (*ASC_release)(ASurfaceControl* control);
+typedef void (*ASC_registerSurfaceStatsListener)(ASurfaceControl* control, void* context,
+ ASurfaceControl_SurfaceStatsListener func);
+typedef void (*ASC_unregisterSurfaceStatsListener)(void* context,
+ ASurfaceControl_SurfaceStatsListener func);
+
+typedef int64_t (*ASCStats_getAcquireTime)(ASurfaceControlStats* stats);
+typedef uint64_t (*ASCStats_getFrameNumber)(ASurfaceControlStats* stats);
+
struct ASurfaceControlFunctions {
ASurfaceControlFunctions();
-
ASC_acquire acquireFunc;
ASC_release releaseFunc;
+ ASC_registerSurfaceStatsListener registerListenerFunc;
+ ASC_unregisterSurfaceStatsListener unregisterListenerFunc;
+ ASCStats_getAcquireTime getAcquireTimeFunc;
+ ASCStats_getFrameNumber getFrameNumberFunc;
};
class ChoreographerSource;
@@ -114,6 +126,7 @@
RenderState& renderState() const { return *mRenderState; }
EglManager& eglManager() const { return *mEglManager; }
ProfileDataContainer& globalProfileData() { return mGlobalProfileData; }
+ std::mutex& getJankDataMutex() { return mJankDataMutex; }
Readback& readback();
GrDirectContext* getGrContext() const { return mGrContext.get(); }
@@ -205,6 +218,7 @@
sp<VulkanManager> mVkManager;
ASurfaceControlFunctions mASurfaceControlFunctions;
+ std::mutex mJankDataMutex;
};
} /* namespace renderthread */