From be3fba05e823f740f65b2679929347dc3dd282ad Mon Sep 17 00:00:00 2001
From: John Reck <jreck@google.com>
Date: Mon, 6 Jul 2015 13:49:58 -0700
Subject: 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
---
 docs/html/preview/testing/performance.jd | 24 ++++++++++++++++++++----
 libs/hwui/FrameInfo.cpp                  |  1 +
 libs/hwui/FrameInfo.h                    | 26 +++++++++++++++++++++-----
 libs/hwui/FrameInfoVisualizer.cpp        | 10 +++++-----
 libs/hwui/FrameInfoVisualizer.h          |  6 ++----
 libs/hwui/JankTracker.cpp                |  4 ++--
 libs/hwui/renderthread/CanvasContext.cpp |  5 +++--
 libs/hwui/renderthread/CanvasContext.h   |  2 +-
 libs/hwui/renderthread/DrawFrameTask.cpp |  3 ++-
 libs/hwui/renderthread/DrawFrameTask.h   |  1 +
 libs/hwui/tests/main.cpp                 |  2 --
 11 files changed, 58 insertions(+), 26 deletions(-)

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 @@ Number Slow draw: 23342
 </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 @@ Number Slow draw: 23342
     </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 (&gt;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 @@ 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())
-- 
cgit v1.1