Ignore blocked-on-sf time for ADPF

Subtract out time spent blocked in dequeueBuffer. Also subtract out any
time UI spents waiting on render thread while render thread is blocked
dequeueBuffer, though this calculation is fairly crude.

Test: Checked bouncyball returns reasonable-ish numbers even when HWUI
      is ahead of surface flinger
Bug: 187556381
Change-Id: I368c446d93990ff8b7b645e30509405ba799c79c

libs/hwui/renderthread/CanvasContext.cpp

@@ -467,11 +467,11 @@ void CanvasContext::notifyFramePending() {
     mRenderThread.pushBackFrameCallback(this);
 }
 
-void CanvasContext::draw() {
+nsecs_t CanvasContext::draw() {
     if (auto grContext = getGrContext()) {
         if (grContext->abandoned()) {
             LOG_ALWAYS_FATAL("GrContext is abandoned/device lost at start of CanvasContext::draw");
-            return;
+            return 0;
         }
     }
     SkRect dirty;
@@ -486,7 +486,7 @@ void CanvasContext::draw() {
             std::invoke(func, mFrameNumber);
         }
         mFrameCompleteCallbacks.clear();
-        return;
+        return 0;
     }
 
     ScopedActiveContext activeContext(this);
@@ -616,6 +616,7 @@ void CanvasContext::draw() {
     }
 
     mRenderThread.cacheManager().onFrameCompleted();
+    return mCurrentFrameInfo->get(FrameInfoIndex::DequeueBufferDuration);
 }
 
 void CanvasContext::reportMetricsWithPresentTime() {

libs/hwui/renderthread/CanvasContext.h

@@ -127,7 +127,8 @@ public:
     void setColorMode(ColorMode mode);
     bool makeCurrent();
     void prepareTree(TreeInfo& info, int64_t* uiFrameInfo, int64_t syncQueued, RenderNode* target);
-    void draw();
+    // Returns the DequeueBufferDuration.
+    nsecs_t draw();
     void destroy();
 
     // IFrameCallback, Choreographer-driven frame callback entry point

libs/hwui/renderthread/DrawFrameTask.cpp

@@ -18,6 +18,7 @@
 
 #include <utils/Log.h>
 #include <utils/TraceUtils.h>
+#include <algorithm>
 
 #include "../DeferredLayerUpdater.h"
 #include "../DisplayList.h"
@@ -91,6 +92,7 @@ void DrawFrameTask::postAndWait() {
 void DrawFrameTask::run() {
     const int64_t vsyncId = mFrameInfo[static_cast<int>(FrameInfoIndex::FrameTimelineVsyncId)];
     ATRACE_FORMAT("DrawFrames %" PRId64, vsyncId);
+    nsecs_t syncDelayDuration = systemTime(SYSTEM_TIME_MONOTONIC) - mSyncQueued;
 
     bool canUnblockUiThread;
     bool canDrawThisFrame;
@@ -124,8 +126,9 @@ void DrawFrameTask::run() {
                 [callback, frameNr = context->getFrameNumber()]() { callback(frameNr); });
     }
 
+    nsecs_t dequeueBufferDuration = 0;
     if (CC_LIKELY(canDrawThisFrame)) {
-        context->draw();
+        dequeueBufferDuration = context->draw();
     } else {
         // wait on fences so tasks don't overlap next frame
         context->waitOnFences();
@@ -149,10 +152,14 @@ void DrawFrameTask::run() {
             mUpdateTargetWorkDuration(targetWorkDuration);
         }
         int64_t frameDuration = systemTime(SYSTEM_TIME_MONOTONIC) - frameStartTime;
-        if (frameDuration > kSanityCheckLowerBound && frameDuration < kSanityCheckUpperBound) {
-            mReportActualWorkDuration(frameDuration);
+        int64_t actualDuration = frameDuration -
+                                 (std::min(syncDelayDuration, mLastDequeueBufferDuration)) -
+                                 dequeueBufferDuration;
+        if (actualDuration > kSanityCheckLowerBound && actualDuration < kSanityCheckUpperBound) {
+            mReportActualWorkDuration(actualDuration);
         }
     }
+    mLastDequeueBufferDuration = dequeueBufferDuration;
 }
 
 bool DrawFrameTask::syncFrameState(TreeInfo& info) {

libs/hwui/renderthread/DrawFrameTask.h

@@ -110,6 +110,7 @@ private:
     std::function<void(int64_t)> mFrameCallback;
     std::function<void(int64_t)> mFrameCompleteCallback;
 
+    nsecs_t mLastDequeueBufferDuration = 0;
     nsecs_t mLastTargetWorkDuration = 0;
     std::function<void(int64_t)> mUpdateTargetWorkDuration;
     std::function<void(int64_t)> mReportActualWorkDuration;