Bug 1517980. Have CONTENT_FRAME_TIME_REASON correspond to CONTENT_FRAME_TIME_VSYNC. r=mattwoodrow
authorJeff Muizelaar <jrmuizel@gmail.com>
Sat, 05 Jan 2019 23:10:20 +0000
changeset 509750 f55412c54286167462200b2d240236b16156cfae
parent 509749 3b215a981675793f6b0ebe4daab9c5c6b897df20
child 509751 9aa94abacb927c5803092a774659bd7644cc46cb
push id10547
push userffxbld-merge
push dateMon, 21 Jan 2019 13:03:58 +0000
treeherdermozilla-beta@24ec1916bffe [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersmattwoodrow
bugs1517980
milestone66.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1517980. Have CONTENT_FRAME_TIME_REASON correspond to CONTENT_FRAME_TIME_VSYNC. r=mattwoodrow CONTENT_FRAME_TIME_VSYNC is more meaningful metric because it actually starts at the beginning of the vsync making it easier to reason about missing frames. It makes more sense for CONTENT_FRAME_TIME_REASON wants to use this same starting point. Differential Revision: https://phabricator.services.mozilla.com/D15790
gfx/layers/ipc/LayerTransactionParent.cpp
gfx/layers/wr/WebRenderBridgeParent.cpp
--- a/gfx/layers/ipc/LayerTransactionParent.cpp
+++ b/gfx/layers/ipc/LayerTransactionParent.cpp
@@ -887,56 +887,56 @@ bool LayerTransactionParent::IsSameProce
 TransactionId LayerTransactionParent::FlushTransactionId(
     const VsyncId& aId, TimeStamp& aCompositeEnd) {
   if (mId.IsValid() && mPendingTransaction.IsValid() && !mVsyncRate.IsZero()) {
     double latencyMs = (aCompositeEnd - mTxnStartTime).ToMilliseconds();
     double latencyNorm = latencyMs / mVsyncRate.ToMilliseconds();
     int32_t fracLatencyNorm = lround(latencyNorm * 100.0);
     Telemetry::Accumulate(Telemetry::CONTENT_FRAME_TIME, fracLatencyNorm);
 
-    // Record CONTENT_FRAME_TIME_REASON. See
-    // WebRenderBridgeParent::FlushTransactionIdsForEpoch for more details.
-    //
-    // Note that deseralizing a layers update (RecvUpdate) can delay the receipt
-    // of the composite vsync message
-    // (CompositorBridgeParent::CompositeToTarget), since they're using the same
-    // thread. This can mean that compositing might start significantly late,
-    // but this code will still detect it as having successfully started on the
-    // right vsync (which is somewhat correct). We'd now have reduced time left
-    // in the vsync interval to finish compositing, so the chances of a missed
-    // frame increases. This is effectively including the RecvUpdate work as
-    // part of the 'compositing' phase for this metric, but it isn't included in
-    // COMPOSITE_TIME, and *is* included in CONTENT_FULL_PAINT_TIME.
-    if (fracLatencyNorm < 200) {
-      // Success
-      Telemetry::AccumulateCategorical(
-          LABELS_CONTENT_FRAME_TIME_REASON::OnTime);
-    } else {
-      if (mTxnVsyncId == VsyncId() || aId == VsyncId() || mTxnVsyncId >= aId) {
-        // Vsync ids are nonsensical, possibly something got trigged from
-        // outside vsync?
-        Telemetry::AccumulateCategorical(
-            LABELS_CONTENT_FRAME_TIME_REASON::NoVsync);
-      } else if (aId - mTxnVsyncId > 1) {
-        // Composite started late (and maybe took too long as well)
-        Telemetry::AccumulateCategorical(
-            LABELS_CONTENT_FRAME_TIME_REASON::MissedComposite);
-      } else {
-        // Composite start on time, but must have taken too long.
-        Telemetry::AccumulateCategorical(
-            LABELS_CONTENT_FRAME_TIME_REASON::SlowComposite);
-      }
-    }
-
     if (!(mTxnVsyncId == VsyncId()) && mVsyncStartTime) {
       latencyMs = (aCompositeEnd - mVsyncStartTime).ToMilliseconds();
       latencyNorm = latencyMs / mVsyncRate.ToMilliseconds();
       fracLatencyNorm = lround(latencyNorm * 100.0);
       Telemetry::Accumulate(Telemetry::CONTENT_FRAME_TIME_VSYNC,
                             fracLatencyNorm);
+
+      // Record CONTENT_FRAME_TIME_REASON. See
+      // WebRenderBridgeParent::FlushTransactionIdsForEpoch for more details.
+      //
+      // Note that deseralizing a layers update (RecvUpdate) can delay the receipt
+      // of the composite vsync message
+      // (CompositorBridgeParent::CompositeToTarget), since they're using the same
+      // thread. This can mean that compositing might start significantly late,
+      // but this code will still detect it as having successfully started on the
+      // right vsync (which is somewhat correct). We'd now have reduced time left
+      // in the vsync interval to finish compositing, so the chances of a missed
+      // frame increases. This is effectively including the RecvUpdate work as
+      // part of the 'compositing' phase for this metric, but it isn't included in
+      // COMPOSITE_TIME, and *is* included in CONTENT_FULL_PAINT_TIME.
+      if (fracLatencyNorm < 200) {
+        // Success
+        Telemetry::AccumulateCategorical(
+            LABELS_CONTENT_FRAME_TIME_REASON::OnTime);
+      } else {
+        if (mTxnVsyncId == VsyncId() || aId == VsyncId() || mTxnVsyncId >= aId) {
+          // Vsync ids are nonsensical, possibly something got trigged from
+          // outside vsync?
+          Telemetry::AccumulateCategorical(
+              LABELS_CONTENT_FRAME_TIME_REASON::NoVsync);
+        } else if (aId - mTxnVsyncId > 1) {
+          // Composite started late (and maybe took too long as well)
+          Telemetry::AccumulateCategorical(
+              LABELS_CONTENT_FRAME_TIME_REASON::MissedComposite);
+        } else {
+          // Composite start on time, but must have taken too long.
+          Telemetry::AccumulateCategorical(
+              LABELS_CONTENT_FRAME_TIME_REASON::SlowComposite);
+        }
+      }
     }
   }
 
 #if defined(ENABLE_FRAME_LATENCY_LOG)
   if (mPendingTransaction.IsValid()) {
     if (mRefreshStartTime) {
       int32_t latencyMs =
           lround((aCompositeEnd - mRefreshStartTime).ToMilliseconds());
--- a/gfx/layers/wr/WebRenderBridgeParent.cpp
+++ b/gfx/layers/wr/WebRenderBridgeParent.cpp
@@ -1974,75 +1974,75 @@ TransactionId WebRenderBridgeParent::Flu
       if (aStats) {
         latencyMs -= (double(aStats->gpu_cache_upload_time) / 1000000.0);
         latencyNorm = latencyMs / mVsyncRate.ToMilliseconds();
         fracLatencyNorm = lround(latencyNorm * 100.0);
       }
       Telemetry::Accumulate(Telemetry::CONTENT_FRAME_TIME_WITHOUT_UPLOAD,
                             fracLatencyNorm);
 
-      // Record CONTENT_FRAME_TIME_REASON.
-      //
-      // Also of note is that when the root WebRenderBridgeParent decides to
-      // skip a composite (due to the Renderer being busy), that won't notify
-      // child WebRenderBridgeParents. That failure will show up as the
-      // composite starting late (since it did), but it's really a fault of a
-      // slow composite on the previous frame, not a slow
-      // CONTENT_FULL_PAINT_TIME. It would be nice to have a separate bucket for
-      // this category (scene was ready on the next vsync, but we chose not to
-      // composite), but I can't find a way to locate the right child
-      // WebRenderBridgeParents from the root. WebRender notifies us of the
-      // child pipelines contained within a render, after it finishes, but I
-      // can't see how to query what child pipeline would have been rendered,
-      // when we choose to not do it.
-      if (fracLatencyNorm < 200) {
-        // Success
-        Telemetry::AccumulateCategorical(
-            LABELS_CONTENT_FRAME_TIME_REASON::OnTime);
-      } else {
-        if (transactionId.mVsyncId == VsyncId() ||
-            aCompositeStartId == VsyncId() ||
-            transactionId.mVsyncId >= aCompositeStartId) {
-          // Vsync ids are nonsensical, possibly something got trigged from
-          // outside vsync?
-          Telemetry::AccumulateCategorical(
-              LABELS_CONTENT_FRAME_TIME_REASON::NoVsync);
-        } else if (aCompositeStartId - transactionId.mVsyncId > 1) {
-          auto fullPaintTime =
-              transactionId.mSceneBuiltTime
-                  ? transactionId.mSceneBuiltTime - transactionId.mTxnStartTime
-                  : TimeDuration::FromMilliseconds(0);
-          // Composite started late (and maybe took too long as well)
-          if (fullPaintTime >= TimeDuration::FromMilliseconds(20)) {
-            Telemetry::AccumulateCategorical(
-                LABELS_CONTENT_FRAME_TIME_REASON::MissedCompositeLong);
-          } else if (fullPaintTime >= TimeDuration::FromMilliseconds(10)) {
-            Telemetry::AccumulateCategorical(
-                LABELS_CONTENT_FRAME_TIME_REASON::MissedCompositeMid);
-          } else if (fullPaintTime >= TimeDuration::FromMilliseconds(5)) {
-            Telemetry::AccumulateCategorical(
-                LABELS_CONTENT_FRAME_TIME_REASON::MissedCompositeLow);
-          } else {
-            Telemetry::AccumulateCategorical(
-                LABELS_CONTENT_FRAME_TIME_REASON::MissedComposite);
-          }
-        } else {
-          // Composite start on time, but must have taken too long.
-          Telemetry::AccumulateCategorical(
-              LABELS_CONTENT_FRAME_TIME_REASON::SlowComposite);
-        }
-      }
-
       if (!(transactionId.mVsyncId == VsyncId()) &&
           transactionId.mVsyncStartTime) {
         latencyMs = (aEndTime - transactionId.mVsyncStartTime).ToMilliseconds();
         latencyNorm = latencyMs / mVsyncRate.ToMilliseconds();
         fracLatencyNorm = lround(latencyNorm * 100.0);
         Telemetry::Accumulate(Telemetry::CONTENT_FRAME_TIME_VSYNC,
                               fracLatencyNorm);
+
+        // Record CONTENT_FRAME_TIME_REASON.
+        //
+        // Also of note is that when the root WebRenderBridgeParent decides to
+        // skip a composite (due to the Renderer being busy), that won't notify
+        // child WebRenderBridgeParents. That failure will show up as the
+        // composite starting late (since it did), but it's really a fault of a
+        // slow composite on the previous frame, not a slow
+        // CONTENT_FULL_PAINT_TIME. It would be nice to have a separate bucket for
+        // this category (scene was ready on the next vsync, but we chose not to
+        // composite), but I can't find a way to locate the right child
+        // WebRenderBridgeParents from the root. WebRender notifies us of the
+        // child pipelines contained within a render, after it finishes, but I
+        // can't see how to query what child pipeline would have been rendered,
+        // when we choose to not do it.
+        if (fracLatencyNorm < 200) {
+          // Success
+          Telemetry::AccumulateCategorical(
+              LABELS_CONTENT_FRAME_TIME_REASON::OnTime);
+        } else {
+          if (transactionId.mVsyncId == VsyncId() ||
+              aCompositeStartId == VsyncId() ||
+              transactionId.mVsyncId >= aCompositeStartId) {
+            // Vsync ids are nonsensical, possibly something got trigged from
+            // outside vsync?
+            Telemetry::AccumulateCategorical(
+                LABELS_CONTENT_FRAME_TIME_REASON::NoVsync);
+          } else if (aCompositeStartId - transactionId.mVsyncId > 1) {
+            auto fullPaintTime =
+                transactionId.mSceneBuiltTime
+                    ? transactionId.mSceneBuiltTime - transactionId.mTxnStartTime
+                    : TimeDuration::FromMilliseconds(0);
+            // Composite started late (and maybe took too long as well)
+            if (fullPaintTime >= TimeDuration::FromMilliseconds(20)) {
+              Telemetry::AccumulateCategorical(
+                  LABELS_CONTENT_FRAME_TIME_REASON::MissedCompositeLong);
+            } else if (fullPaintTime >= TimeDuration::FromMilliseconds(10)) {
+              Telemetry::AccumulateCategorical(
+                  LABELS_CONTENT_FRAME_TIME_REASON::MissedCompositeMid);
+            } else if (fullPaintTime >= TimeDuration::FromMilliseconds(5)) {
+              Telemetry::AccumulateCategorical(
+                  LABELS_CONTENT_FRAME_TIME_REASON::MissedCompositeLow);
+            } else {
+              Telemetry::AccumulateCategorical(
+                  LABELS_CONTENT_FRAME_TIME_REASON::MissedComposite);
+            }
+          } else {
+            // Composite start on time, but must have taken too long.
+            Telemetry::AccumulateCategorical(
+                LABELS_CONTENT_FRAME_TIME_REASON::SlowComposite);
+          }
+        }
       }
     }
 
 #if defined(ENABLE_FRAME_LATENCY_LOG)
     if (transactionId.mRefreshStartTime) {
       int32_t latencyMs =
           lround((aEndTime - transactionId.mRefreshStartTime).ToMilliseconds());
       printf_stderr(