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

10 files changed, 38 insertions, 22 deletions

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 @@ const std::string FrameInfoNames[] = {
     "AnimationStart",
     "PerformTraversalsStart",
     "DrawStart",
+    "SyncQueued",
     "SyncStart",
     "IssueDrawCommandsStart",
     "SwapBuffers",
diff --git a/libs/hwui/FrameInfo.h b/libs/hwui/FrameInfo.h
index 23339ce..f8013ab 100644
--- a/libs/hwui/FrameInfo.h
+++ b/libs/hwui/FrameInfo.h
@@ -41,6 +41,8 @@ enum class FrameInfoIndex {
     DrawStart,
     // End of UI frame info
 
+    SyncQueued,
+
     SyncStart,
     IssueDrawCommandsStart,
     SwapBuffers,
@@ -117,8 +119,7 @@ public:
     }
 
     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 @@ public:
     }
 
     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 @@ public:
         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 @@ void FrameInfoVisualizer::nextBarSegment(FrameInfoIndex start, FrameInfoIndex en
         // 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 @@ void FrameInfoVisualizer::dumpData(int fd) {
         }
         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 @@ private:
     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 @@ static const char* JANK_TYPE_NAMES[] = {
         "High input latency",
         "Slow UI thread",
         "Slow bitmap uploads",
-        "Slow draw",
+        "Slow issue draw commands",
 };
 
 struct Comparison {
@@ -223,7 +223,7 @@ void JankTracker::addFrame(const FrameInfo& frame) {
     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 @@ static bool wasSkipped(FrameInfo* info) {
     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 @@ void CanvasContext::prepareTree(TreeInfo& info, int64_t* uiFrameInfo) {
         mCurrentFrameInfo = &mFrames.next();
     }
     mCurrentFrameInfo->importUiThreadInfo(uiFrameInfo);
+    mCurrentFrameInfo->set(FrameInfoIndex::SyncQueued) = syncQueued;
     mCurrentFrameInfo->markSyncStart();
 
     info.damageAccumulator = &mDamageAccumulator;
@@ -293,7 +294,7 @@ void CanvasContext::doFrame() {
                 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 @@ public:
     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 @@ int DrawFrameTask::drawFrame() {
     LOG_ALWAYS_FATAL_IF(!mContext, "Cannot drawFrame with no CanvasContext!");
 
     mSyncResult = kSync_OK;
+    mSyncQueued = systemTime(CLOCK_MONOTONIC);
     postAndWait();
 
     return mSyncResult;
@@ -119,7 +120,7 @@ bool DrawFrameTask::syncFrameState(TreeInfo& info) {
         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 @@ private:
     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 @@ public:
         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())