Adjust for pipeline stalls
Bug: 20853441
Calculating duration that crosses the UI-RT
sync point will now subtract out the time spent waiting
in queue under the assumption that this time will be
accounted for in the previous frame's metrics
Change-Id: Ia8213f4410638840613f5ae439e98dfb77532a6a
diff --git a/docs/html/preview/testing/performance.jd b/docs/html/preview/testing/performance.jd
index abb41c4..6f0a5f1 100644
--- a/docs/html/preview/testing/performance.jd
+++ b/docs/html/preview/testing/performance.jd
@@ -112,10 +112,10 @@
</p>
<pre class="noprettyprint">
-0,49762224585003,49762241251670,9223372036854775807,0,49762257627204,49762257646058,49762257969704,49762258002100,49762265541631,49762273951162,49762300914808,49762303675954,
-0,49762445152142,49762445152142,9223372036854775807,0,49762446678818,49762446705589,49762447268818,49762447388037,49762453551527,49762457134131,49762474889027,49762476150120,
-0,49762462118845,49762462118845,9223372036854775807,0,49762462595381,49762462619287,49762462919964,49762462968454,49762476194547,49762476483454,49762480214964,49762480911527,
-0,49762479085548,49762479085548,9223372036854775807,0,49762480066370,49762480099339,49762481013089,49762481085850,49762482232152,49762482478350,49762485657620,49762486116683,
+0,27965466202353,27965466202353,27965449758000,27965461202353,27965467153286,27965471442505,27965471925682,27965474025318,27965474588547,27965474860786,27965475078599,27965479796151,27965480589068,
+0,27965482993342,27965482993342,27965465835000,27965477993342,27965483807401,27965486875630,27965487288443,27965489520682,27965490184380,27965490568703,27965491408078,27965496119641,27965496619641,
+0,27965499784331,27965499784331,27965481404000,27965494784331,27965500785318,27965503736099,27965504201151,27965506776568,27965507298443,27965507515005,27965508405474,27965513495318,27965514061984,
+0,27965516575320,27965516575320,27965497155000,27965511575320,27965517697349,27965521276151,27965521734797,27965524350474,27965524884536,27965525160578,27965526020891,27965531371203,27965532114484,
</pre>
<p>
@@ -283,6 +283,22 @@
</ul>
</li>
+ <li>SYNC_QUEUED
+ <ul>
+ <li>The time at which a sync request was sent to the RenderThread.
+ </li>
+
+ <li>This marks the point at which a message to start the sync
+ phase was sent to the RenderThread. If the time between this and
+ SYNC_START is substantial (>0.1ms or so), it means that
+ the RenderThread was busy working on a different frame. Internally
+ this is used to differentiate between the frame doing too much work
+ and exceeding the 16ms budget and the frame being stalled due to
+ the previous frame exceeding the 16ms budget.
+ </li>
+ </ul>
+ </li>
+
<li>SYNC_START
<ul>
<li>The time at which the sync phase of the drawing started.
diff --git a/libs/hwui/FrameInfo.cpp b/libs/hwui/FrameInfo.cpp
index 85998f1..41e2233 100644
--- a/libs/hwui/FrameInfo.cpp
+++ b/libs/hwui/FrameInfo.cpp
@@ -30,6 +30,7 @@
"AnimationStart",
"PerformTraversalsStart",
"DrawStart",
+ "SyncQueued",
"SyncStart",
"IssueDrawCommandsStart",
"SwapBuffers",
diff --git a/libs/hwui/FrameInfo.h b/libs/hwui/FrameInfo.h
index 23339ce..f8013ab6 100644
--- a/libs/hwui/FrameInfo.h
+++ b/libs/hwui/FrameInfo.h
@@ -41,6 +41,8 @@
DrawStart,
// End of UI frame info
+ SyncQueued,
+
SyncStart,
IssueDrawCommandsStart,
SwapBuffers,
@@ -117,8 +119,7 @@
}
inline int64_t operator[](FrameInfoIndex index) const {
- if (index == FrameInfoIndex::NumIndexes) return 0;
- return mFrameInfo[static_cast<int>(index)];
+ return get(index);
}
inline int64_t operator[](int index) const {
@@ -127,10 +128,20 @@
}
inline int64_t duration(FrameInfoIndex start, FrameInfoIndex end) const {
- int64_t endtime = mFrameInfo[static_cast<int>(end)];
- int64_t starttime = mFrameInfo[static_cast<int>(start)];
+ int64_t endtime = get(end);
+ int64_t starttime = get(start);
int64_t gap = endtime - starttime;
gap = starttime > 0 ? gap : 0;
+ if (end > FrameInfoIndex::SyncQueued &&
+ start < FrameInfoIndex::SyncQueued) {
+ // Need to subtract out the time spent in a stalled state
+ // as this will be captured by the previous frame's info
+ int64_t offset = get(FrameInfoIndex::SyncStart)
+ - get(FrameInfoIndex::SyncQueued);
+ if (offset > 0) {
+ gap -= offset;
+ }
+ }
return gap > 0 ? gap : 0;
}
@@ -138,11 +149,16 @@
return duration(FrameInfoIndex::IntendedVsync, FrameInfoIndex::FrameCompleted);
}
-private:
inline int64_t& set(FrameInfoIndex index) {
return mFrameInfo[static_cast<int>(index)];
}
+ inline int64_t get(FrameInfoIndex index) const {
+ if (index == FrameInfoIndex::NumIndexes) return 0;
+ return mFrameInfo[static_cast<int>(index)];
+ }
+
+private:
int64_t mFrameInfo[static_cast<int>(FrameInfoIndex::NumIndexes)];
};
diff --git a/libs/hwui/FrameInfoVisualizer.cpp b/libs/hwui/FrameInfoVisualizer.cpp
index 7f9d9b9..b416615 100644
--- a/libs/hwui/FrameInfoVisualizer.cpp
+++ b/libs/hwui/FrameInfoVisualizer.cpp
@@ -189,7 +189,7 @@
// Set the bottom to the old top (build upwards)
rect[ri + 3] = rect[ri + 1];
// Move the top up by the duration
- rect[ri + 1] -= mVerticalUnit * duration(fi, start, end);
+ rect[ri + 1] -= mVerticalUnit * durationMS(fi, start, end);
}
}
@@ -253,10 +253,10 @@
}
mLastFrameLogged = mFrameSource[i][FrameInfoIndex::IntendedVsync];
fprintf(file, "\t%3.2f\t%3.2f\t%3.2f\t%3.2f\n",
- duration(i, FrameInfoIndex::IntendedVsync, FrameInfoIndex::SyncStart),
- duration(i, FrameInfoIndex::SyncStart, FrameInfoIndex::IssueDrawCommandsStart),
- duration(i, FrameInfoIndex::IssueDrawCommandsStart, FrameInfoIndex::SwapBuffers),
- duration(i, FrameInfoIndex::SwapBuffers, FrameInfoIndex::FrameCompleted));
+ durationMS(i, FrameInfoIndex::IntendedVsync, FrameInfoIndex::SyncStart),
+ durationMS(i, FrameInfoIndex::SyncStart, FrameInfoIndex::IssueDrawCommandsStart),
+ durationMS(i, FrameInfoIndex::IssueDrawCommandsStart, FrameInfoIndex::SwapBuffers),
+ durationMS(i, FrameInfoIndex::SwapBuffers, FrameInfoIndex::FrameCompleted));
}
fflush(file);
diff --git a/libs/hwui/FrameInfoVisualizer.h b/libs/hwui/FrameInfoVisualizer.h
index f1dc954..cf877c4 100644
--- a/libs/hwui/FrameInfoVisualizer.h
+++ b/libs/hwui/FrameInfoVisualizer.h
@@ -59,10 +59,8 @@
void drawGraph(OpenGLRenderer* canvas);
void drawThreshold(OpenGLRenderer* canvas);
- inline float duration(size_t index, FrameInfoIndex start, FrameInfoIndex end) {
- nsecs_t ns_start = mFrameSource[index][start];
- nsecs_t ns_end = mFrameSource[index][end];
- float duration = ((ns_end - ns_start) * 0.000001f);
+ inline float durationMS(size_t index, FrameInfoIndex start, FrameInfoIndex end) {
+ float duration = mFrameSource[index].duration(start, end) * 0.000001f;
// Clamp to large to avoid spiking off the top of the screen
duration = duration > 50.0f ? 50.0f : duration;
return duration > 0.0f ? duration : 0.0f;
diff --git a/libs/hwui/JankTracker.cpp b/libs/hwui/JankTracker.cpp
index 5c0801e..eb9b55f 100644
--- a/libs/hwui/JankTracker.cpp
+++ b/libs/hwui/JankTracker.cpp
@@ -31,7 +31,7 @@
"High input latency",
"Slow UI thread",
"Slow bitmap uploads",
- "Slow draw",
+ "Slow issue draw commands",
};
struct Comparison {
@@ -223,7 +223,7 @@
mData->jankFrameCount++;
for (int i = 0; i < NUM_BUCKETS; i++) {
- int64_t delta = frame[COMPARISONS[i].end] - frame[COMPARISONS[i].start];
+ int64_t delta = frame.duration(COMPARISONS[i].start, COMPARISONS[i].end);
if (delta >= mThresholds[i] && delta < IGNORE_EXCEEDING) {
mData->jankTypeCounts[i]++;
}
diff --git a/libs/hwui/renderthread/CanvasContext.cpp b/libs/hwui/renderthread/CanvasContext.cpp
index b88f30e..260fb6f 100644
--- a/libs/hwui/renderthread/CanvasContext.cpp
+++ b/libs/hwui/renderthread/CanvasContext.cpp
@@ -160,7 +160,7 @@
return info && ((*info)[FrameInfoIndex::Flags] & FrameInfoFlags::SkippedFrame);
}
-void CanvasContext::prepareTree(TreeInfo& info, int64_t* uiFrameInfo) {
+void CanvasContext::prepareTree(TreeInfo& info, int64_t* uiFrameInfo, int64_t syncQueued) {
mRenderThread.removeFrameCallback(this);
// If the previous frame was dropped we don't need to hold onto it, so
@@ -169,6 +169,7 @@
mCurrentFrameInfo = &mFrames.next();
}
mCurrentFrameInfo->importUiThreadInfo(uiFrameInfo);
+ mCurrentFrameInfo->set(FrameInfoIndex::SyncQueued) = syncQueued;
mCurrentFrameInfo->markSyncStart();
info.damageAccumulator = &mDamageAccumulator;
@@ -293,7 +294,7 @@
mRenderThread.timeLord().latestVsync());
TreeInfo info(TreeInfo::MODE_RT_ONLY, mRenderThread.renderState());
- prepareTree(info, frameInfo);
+ prepareTree(info, frameInfo, systemTime(CLOCK_MONOTONIC));
if (info.out.canDrawThisFrame) {
draw();
}
diff --git a/libs/hwui/renderthread/CanvasContext.h b/libs/hwui/renderthread/CanvasContext.h
index 10e66e9..f2fa9cd 100644
--- a/libs/hwui/renderthread/CanvasContext.h
+++ b/libs/hwui/renderthread/CanvasContext.h
@@ -78,7 +78,7 @@
void setOpaque(bool opaque);
void makeCurrent();
void processLayerUpdate(DeferredLayerUpdater* layerUpdater);
- void prepareTree(TreeInfo& info, int64_t* uiFrameInfo);
+ void prepareTree(TreeInfo& info, int64_t* uiFrameInfo, int64_t syncQueued);
void draw();
void destroy();
diff --git a/libs/hwui/renderthread/DrawFrameTask.cpp b/libs/hwui/renderthread/DrawFrameTask.cpp
index 008e297..6507ce8 100644
--- a/libs/hwui/renderthread/DrawFrameTask.cpp
+++ b/libs/hwui/renderthread/DrawFrameTask.cpp
@@ -69,6 +69,7 @@
LOG_ALWAYS_FATAL_IF(!mContext, "Cannot drawFrame with no CanvasContext!");
mSyncResult = kSync_OK;
+ mSyncQueued = systemTime(CLOCK_MONOTONIC);
postAndWait();
return mSyncResult;
@@ -119,7 +120,7 @@
mContext->processLayerUpdate(mLayers[i].get());
}
mLayers.clear();
- mContext->prepareTree(info, mFrameInfo);
+ mContext->prepareTree(info, mFrameInfo, mSyncQueued);
// This is after the prepareTree so that any pending operations
// (RenderNode tree state, prefetched layers, etc...) will be flushed.
diff --git a/libs/hwui/renderthread/DrawFrameTask.h b/libs/hwui/renderthread/DrawFrameTask.h
index 8039643..ebefcba 100644
--- a/libs/hwui/renderthread/DrawFrameTask.h
+++ b/libs/hwui/renderthread/DrawFrameTask.h
@@ -85,6 +85,7 @@
std::vector< sp<DeferredLayerUpdater> > mLayers;
int mSyncResult;
+ int64_t mSyncQueued;
int64_t mFrameInfo[UI_THREAD_FRAME_INFO_SIZE];
};
diff --git a/libs/hwui/tests/main.cpp b/libs/hwui/tests/main.cpp
index ceee953..80d7029 100644
--- a/libs/hwui/tests/main.cpp
+++ b/libs/hwui/tests/main.cpp
@@ -111,8 +111,6 @@
for (int i = 0; i < animation.getFrameCount(); i++) {
testContext.waitForVsync();
- // workaround b/20853441
- proxy->fence();
ATRACE_NAME("UI-Draw Frame");
nsecs_t vsync = systemTime(CLOCK_MONOTONIC);
UiFrameInfoBuilder(proxy->frameInfo())