Bug 1510853 - Add CONTENT_FRAME_TIME_REASON. r=jrmuizel, data-review=chutten

MozReview-Commit-ID: 9RV9ZkHXZTR

Differential Revision: https://phabricator.services.mozilla.com/D13351

--HG--
extra : moz-landing-system : lando

gfx/layers/client/ClientLayerManager.cpp

@@ -681,6 +681,9 @@ void ClientLayerManager::ForwardTransaction(bool aScheduleComposite) {
   mLatestTransactionId =
       mTransactionIdAllocator->GetTransactionId(!mIsRepeatTransaction);
   TimeStamp refreshStart = mTransactionIdAllocator->GetTransactionStart();
+  if (!refreshStart) {
+    refreshStart = mTransactionStart;
+  }
 
   if (gfxPrefs::AlwaysPaint() && XRE_IsContentProcess()) {
     mForwarder->SendPaintTime(mLatestTransactionId, mLastPaintTime);

gfx/layers/ipc/CompositorBridgeParent.cpp

@@ -671,11 +671,12 @@ void CompositorBridgeParent::PauseComposition() {
     TimeStamp now = TimeStamp::Now();
     if (mCompositor) {
       mCompositor->Pause();
-      DidComposite(now, now);
+      DidComposite(VsyncId(), now, now);
     } else if (mWrBridge) {
       mWrBridge->Pause();
       NotifyPipelineRendered(mWrBridge->PipelineId(),
-                             mWrBridge->GetCurrentEpoch(), now, now, now);
+                             mWrBridge->GetCurrentEpoch(), VsyncId(), now, now,
+                             now);
     }
   }
 
@@ -899,7 +900,7 @@ void CompositorBridgeParent::CompositeToTarget(VsyncId aId, DrawTarget* aTarget,
 
   if (!CanComposite()) {
     TimeStamp end = TimeStamp::Now();
-    DidComposite(start, end);
+    DidComposite(aId, start, end);
     return;
   }
 
@@ -993,7 +994,7 @@ void CompositorBridgeParent::CompositeToTarget(VsyncId aId, DrawTarget* aTarget,
 
   if (!aTarget) {
     TimeStamp end = TimeStamp::Now();
-    DidComposite(start, end);
+    DidComposite(aId, start, end);
   }
 
   // We're not really taking advantage of the stored composite-again-time here.
@@ -1246,7 +1247,7 @@ void CompositorBridgeParent::ShadowLayersUpdated(
     ScheduleComposition();
     if (mPaused) {
       TimeStamp now = TimeStamp::Now();
-      DidComposite(now, now);
+      DidComposite(VsyncId(), now, now);
     }
   }
   mLayerManager->NotifyShadowTreeTransaction();
@@ -1284,7 +1285,7 @@ bool CompositorBridgeParent::SetTestSampleTime(const LayersId& aId,
       CancelCurrentCompositeTask();
       // Pretend we composited in case someone is wating for this event.
       TimeStamp now = TimeStamp::Now();
-      DidComposite(now, now);
+      DidComposite(VsyncId(), now, now);
     }
   }
 
@@ -1314,7 +1315,7 @@ void CompositorBridgeParent::ApplyAsyncProperties(
       CancelCurrentCompositeTask();
       // Pretend we composited in case someone is waiting for this event.
       TimeStamp now = TimeStamp::Now();
-      DidComposite(now, now);
+      DidComposite(VsyncId(), now, now);
     }
   }
 }
@@ -1684,8 +1685,8 @@ mozilla::ipc::IPCResult CompositorBridgeParent::RecvAdoptChild(
         GetAnimationStorage(), mWrBridge->GetTextureFactoryIdentifier());
     // Pretend we composited, since parent CompositorBridgeParent was replaced.
     TimeStamp now = TimeStamp::Now();
-    NotifyPipelineRendered(childWrBridge->PipelineId(), newEpoch, now, now,
+    NotifyPipelineRendered(childWrBridge->PipelineId(), newEpoch, VsyncId(),
-                           now);
+                           now, now, now);
   }
 
   if (oldApzUpdater) {
@@ -1976,19 +1977,14 @@ CompositorBridgeParent::LayerTreeState::InProcessSharingController() const {
   return mParent;
 }
 
-void CompositorBridgeParent::DidComposite(LayersId aId,
+void CompositorBridgeParent::DidComposite(const VsyncId& aId,
                                           TimeStamp& aCompositeStart,
                                           TimeStamp& aCompositeEnd) {
-  MOZ_ASSERT(aId == mRootLayerTreeID);
-  DidComposite(aCompositeStart, aCompositeEnd);
-}
-
-void CompositorBridgeParent::DidComposite(TimeStamp& aCompositeStart,
-                                          TimeStamp& aCompositeEnd) {
   if (mWrBridge) {
     MOZ_ASSERT(false);  // This should never get called for a WR compositor
   } else {
-    NotifyDidComposite(mPendingTransaction, aCompositeStart, aCompositeEnd);
+    NotifyDidComposite(mPendingTransaction, aId, aCompositeStart,
+                       aCompositeEnd);
 #if defined(ENABLE_FRAME_LATENCY_LOG)
     if (mPendingTransaction.IsValid()) {
       if (mRefreshStartTime) {
@@ -2017,8 +2013,9 @@ void CompositorBridgeParent::DidComposite(TimeStamp& aCompositeStart,
 
 void CompositorBridgeParent::NotifyPipelineRendered(
     const wr::PipelineId& aPipelineId, const wr::Epoch& aEpoch,
-    TimeStamp& aCompositeStart, TimeStamp& aRenderStart,
+    const VsyncId& aCompositeStartId, TimeStamp& aCompositeStart,
-    TimeStamp& aCompositeEnd, wr::RendererStats* aStats) {
+    TimeStamp& aRenderStart, TimeStamp& aCompositeEnd,
+    wr::RendererStats* aStats) {
   if (!mWrBridge || !mAsyncImageManager) {
     return;
   }
@@ -2033,7 +2030,8 @@ void CompositorBridgeParent::NotifyPipelineRendered(
 
     if (!mPaused) {
       TransactionId transactionId = mWrBridge->FlushTransactionIdsForEpoch(
-          aEpoch, aCompositeStart, aRenderStart, aCompositeEnd, uiController);
+          aEpoch, aCompositeStartId, aCompositeStart, aRenderStart,
+          aCompositeEnd, uiController);
       Unused << SendDidComposite(LayersId{0}, transactionId, aCompositeStart,
                                  aCompositeEnd);
 
@@ -2052,8 +2050,8 @@ void CompositorBridgeParent::NotifyPipelineRendered(
     wrBridge->RemoveEpochDataPriorTo(aEpoch);
     if (!mPaused) {
       TransactionId transactionId = wrBridge->FlushTransactionIdsForEpoch(
-          aEpoch, aCompositeStart, aRenderStart, aCompositeEnd, uiController,
+          aEpoch, aCompositeStartId, aCompositeStart, aRenderStart,
-          aStats, &stats);
+          aCompositeEnd, uiController, aStats, &stats);
       Unused << wrBridge->GetCompositorBridge()->SendDidComposite(
           wrBridge->GetLayersId(), transactionId, aCompositeStart,
           aCompositeEnd);
@@ -2071,6 +2069,7 @@ CompositorBridgeParent::GetAsyncImagePipelineManager() const {
 }
 
 void CompositorBridgeParent::NotifyDidComposite(TransactionId aTransactionId,
+                                                VsyncId aId,
                                                 TimeStamp& aCompositeStart,
                                                 TimeStamp& aCompositeEnd) {
   MOZ_ASSERT(
@@ -2088,13 +2087,13 @@ void CompositorBridgeParent::NotifyDidComposite(TransactionId aTransactionId,
   }
 
   MonitorAutoLock lock(*sIndirectLayerTreesLock);
-  ForEachIndirectLayerTree(
+  ForEachIndirectLayerTree([&](LayerTreeState* lts,
-      [&](LayerTreeState* lts, const LayersId& aLayersId) -> void {
+                               const LayersId& aLayersId) -> void {
-        if (lts->mCrossProcessParent && lts->mParent == this) {
+    if (lts->mCrossProcessParent && lts->mParent == this) {
-          CrossProcessCompositorBridgeParent* cpcp = lts->mCrossProcessParent;
+      CrossProcessCompositorBridgeParent* cpcp = lts->mCrossProcessParent;
-          cpcp->DidCompositeLocked(aLayersId, aCompositeStart, aCompositeEnd);
+      cpcp->DidCompositeLocked(aLayersId, aId, aCompositeStart, aCompositeEnd);
-        }
+    }
-      });
+  });
 }
 
 void CompositorBridgeParent::InvalidateRemoteLayers() {

gfx/layers/ipc/CompositorBridgeParent.h

@@ -147,9 +147,6 @@ class CompositorBridgeParentBase : public PCompositorBridgeParent,
                                    LayersObserverEpoch aEpoch,
                                    bool aActive) = 0;
 
-  virtual void DidComposite(LayersId aId, TimeStamp& aCompositeStart,
-                            TimeStamp& aCompositeEnd) = 0;
-
   // HostIPCAllocator
   base::ProcessId GetChildProcessId() override;
   void NotifyNotUsed(PTextureParent* aTexture,
@@ -314,6 +311,7 @@ class CompositorBridgeParent final : public CompositorBridgeParentBase,
   void NotifyWebRenderContextPurge();
   void NotifyPipelineRendered(const wr::PipelineId& aPipelineId,
                               const wr::Epoch& aEpoch,
+                              const VsyncId& aCompositeStartId,
                               TimeStamp& aCompositeStart,
                               TimeStamp& aRenderStart, TimeStamp& aCompositeEnd,
                               wr::RendererStats* aStats = nullptr);
@@ -628,11 +626,10 @@ class CompositorBridgeParent final : public CompositorBridgeParentBase,
    */
   bool CanComposite();
 
-  void DidComposite(LayersId aId, TimeStamp& aCompositeStart,
+  void DidComposite(const VsyncId& aId, TimeStamp& aCompositeStart,
-                    TimeStamp& aCompositeEnd) override;
+                    TimeStamp& aCompositeEnd);
-  void DidComposite(TimeStamp& aCompositeStart, TimeStamp& aCompositeEnd);
 
-  void NotifyDidComposite(TransactionId aTransactionId,
+  void NotifyDidComposite(TransactionId aTransactionId, VsyncId aId,
                           TimeStamp& aCompositeStart, TimeStamp& aCompositeEnd);
 
   // The indirect layer tree lock must be held before calling this function.

gfx/layers/ipc/CrossProcessCompositorBridgeParent.cpp

@@ -394,17 +394,13 @@ void CrossProcessCompositorBridgeParent::ShadowLayersUpdated(
       aInfo.transactionStart(), aInfo.url(), aInfo.fwdTime());
 }
 
-void CrossProcessCompositorBridgeParent::DidComposite(
-    LayersId aId, TimeStamp& aCompositeStart, TimeStamp& aCompositeEnd) {
-  MonitorAutoLock lock(*sIndirectLayerTreesLock);
-  DidCompositeLocked(aId, aCompositeStart, aCompositeEnd);
-}
-
 void CrossProcessCompositorBridgeParent::DidCompositeLocked(
-    LayersId aId, TimeStamp& aCompositeStart, TimeStamp& aCompositeEnd) {
+    LayersId aId, const VsyncId& aVsyncId, TimeStamp& aCompositeStart,
+    TimeStamp& aCompositeEnd) {
   sIndirectLayerTreesLock->AssertCurrentThreadOwns();
   if (LayerTransactionParent* layerTree = sIndirectLayerTrees[aId].mLayerTree) {
-    TransactionId transactionId = layerTree->FlushTransactionId(aCompositeEnd);
+    TransactionId transactionId =
+        layerTree->FlushTransactionId(aVsyncId, aCompositeEnd);
     if (transactionId.IsValid()) {
       Unused << SendDidComposite(aId, transactionId, aCompositeStart,
                                  aCompositeEnd);

gfx/layers/ipc/CrossProcessCompositorBridgeParent.h

@@ -137,10 +137,8 @@ class CrossProcessCompositorBridgeParent final
   // Use DidCompositeLocked if you already hold a lock on
   // sIndirectLayerTreesLock; Otherwise use DidComposite, which would request
   // the lock automatically.
-  void DidCompositeLocked(LayersId aId, TimeStamp& aCompositeStart,
+  void DidCompositeLocked(LayersId aId, const VsyncId& aVsyncId,
-                          TimeStamp& aCompositeEnd);
+                          TimeStamp& aCompositeStart, TimeStamp& aCompositeEnd);
-  void DidComposite(LayersId aId, TimeStamp& aCompositeStart,
-                    TimeStamp& aCompositeEnd) override;
 
   PTextureParent* AllocPTextureParent(
       const SurfaceDescriptor& aSharedData, const ReadLockDescriptor& aReadLock,

gfx/layers/ipc/LayerTransactionParent.cpp

@@ -39,6 +39,8 @@
 #include "mozilla/layers/TextureHost.h"
 #include "mozilla/layers/AsyncCompositionManager.h"
 
+using mozilla::Telemetry::LABELS_CONTENT_FRAME_TIME_REASON;
+
 namespace mozilla {
 namespace layers {
 
@@ -884,12 +886,49 @@ bool LayerTransactionParent::IsSameProcess() const {
 }
 
 TransactionId LayerTransactionParent::FlushTransactionId(
-    TimeStamp& aCompositeEnd) {
+    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.
+    latencyMs = (aCompositeEnd - mRefreshStartTime).ToMilliseconds();
+    latencyNorm = latencyMs / mVsyncRate.ToMilliseconds();
+    fracLatencyNorm = lround(latencyNorm * 100.0);
+    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)

gfx/layers/ipc/LayerTransactionParent.h

@@ -84,7 +84,8 @@ class LayerTransactionParent final : public PLayerTransactionParent,
     mTxnURL = aURL;
     mFwdTime = aFwdTime;
   }
-  TransactionId FlushTransactionId(TimeStamp& aCompositeEnd);
+  TransactionId FlushTransactionId(const VsyncId& aId,
+                                   TimeStamp& aCompositeEnd);
 
   // CompositableParentManager
   void SendAsyncMessage(

gfx/layers/wr/WebRenderBridgeParent.cpp

@@ -35,6 +35,8 @@
 #include "mozilla/webrender/RenderThread.h"
 #include "mozilla/widget/CompositorWidget.h"
 
+using mozilla::Telemetry::LABELS_CONTENT_FRAME_TIME_REASON;
+
 #ifdef MOZ_GECKO_PROFILER
 #include "ProfilerMarkerPayload.h"
 #endif
@@ -955,7 +957,8 @@ mozilla::ipc::IPCResult WebRenderBridgeParent::RecvSetDisplayList(
     // though DisplayList was not pushed to webrender.
     if (CompositorBridgeParent* cbp = GetRootCompositorBridgeParent()) {
       TimeStamp now = TimeStamp::Now();
-      cbp->NotifyPipelineRendered(mPipelineId, wrEpoch, now, now, now);
+      cbp->NotifyPipelineRendered(mPipelineId, wrEpoch, VsyncId(), now, now,
+                                  now);
     }
   }
 
@@ -1076,7 +1079,8 @@ mozilla::ipc::IPCResult WebRenderBridgeParent::RecvEmptyTransaction(
     MOZ_ASSERT(mPendingTransactionIds.size() == 1);
     if (CompositorBridgeParent* cbp = GetRootCompositorBridgeParent()) {
       TimeStamp now = TimeStamp::Now();
-      cbp->NotifyPipelineRendered(mPipelineId, mWrEpoch, now, now, now);
+      cbp->NotifyPipelineRendered(mPipelineId, mWrEpoch, VsyncId(), now, now,
+                                  now);
     }
   }
 
@@ -1218,7 +1222,7 @@ void WebRenderBridgeParent::FlushFrameGeneration() {
     mCompositorScheduler->CancelCurrentCompositeTask();
     // Update timestamp of scheduler for APZ and animation.
     mCompositorScheduler->UpdateLastComposeTime();
-    MaybeGenerateFrame(/* aForceGenerateFrame */ true);
+    MaybeGenerateFrame(VsyncId(), /* aForceGenerateFrame */ true);
   }
 }
 
@@ -1679,7 +1683,7 @@ void WebRenderBridgeParent::CompositeToTarget(VsyncId aId,
     }
     return;
   }
-  MaybeGenerateFrame(/* aForceGenerateFrame */ false);
+  MaybeGenerateFrame(aId, /* aForceGenerateFrame */ false);
 }
 
 TimeDuration WebRenderBridgeParent::GetVsyncInterval() const {
@@ -1691,7 +1695,8 @@ TimeDuration WebRenderBridgeParent::GetVsyncInterval() const {
   return TimeDuration();
 }
 
-void WebRenderBridgeParent::MaybeGenerateFrame(bool aForceGenerateFrame) {
+void WebRenderBridgeParent::MaybeGenerateFrame(VsyncId aId,
+                                               bool aForceGenerateFrame) {
   // This function should only get called in the root WRBP
   MOZ_ASSERT(IsRootWebRenderBridgeParent());
 
@@ -1739,7 +1744,7 @@ void WebRenderBridgeParent::MaybeGenerateFrame(bool aForceGenerateFrame) {
 
   SetAPZSampleTime();
 
-  wr::RenderThread::Get()->IncPendingFrameCount(mApi->GetId(), start);
+  wr::RenderThread::Get()->IncPendingFrameCount(mApi->GetId(), aId, start);
 
 #if defined(ENABLE_FRAME_LATENCY_LOG)
   auto startTime = TimeStamp::Now();
@@ -1782,10 +1787,10 @@ void WebRenderBridgeParent::NotifySceneBuiltForEpoch(
 }
 
 TransactionId WebRenderBridgeParent::FlushTransactionIdsForEpoch(
-    const wr::Epoch& aEpoch, const TimeStamp& aCompositeStartTime,
+    const wr::Epoch& aEpoch, const VsyncId& aCompositeStartId,
-    const TimeStamp& aRenderStartTime, const TimeStamp& aEndTime,
+    const TimeStamp& aCompositeStartTime, const TimeStamp& aRenderStartTime,
-    UiCompositorControllerParent* aUiController, wr::RendererStats* aStats,
+    const TimeStamp& aEndTime, UiCompositorControllerParent* aUiController,
-    nsTArray<FrameStats>* aOutputStats) {
+    wr::RendererStats* aStats, nsTArray<FrameStats>* aOutputStats) {
   TransactionId id{0};
   while (!mPendingTransactionIds.empty()) {
     const auto& transactionId = mPendingTransactionIds.front();
@@ -1822,6 +1827,50 @@ TransactionId WebRenderBridgeParent::FlushTransactionIdsForEpoch(
       }
 #endif
 
+      // Record CONTENT_FRAME_TIME_REASON.
+      //
+      // This uses the refresh start time (CONTENT_FRAME_TIME uses the start of
+      // display list building), since that includes layout/style time, and 200
+      // should correlate more closely with missing a vsync.
+      //
+      // 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.
+      latencyMs = (aEndTime - transactionId.mRefreshStartTime).ToMilliseconds();
+      latencyNorm = latencyMs / mVsyncRate.ToMilliseconds();
+      fracLatencyNorm = lround(latencyNorm * 100.0);
+      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) {
+          // 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 (fracLatencyNorm > 200) {
         aOutputStats->AppendElement(FrameStats(
             transactionId.mId, aCompositeStartTime, aRenderStartTime, aEndTime,

gfx/layers/wr/WebRenderBridgeParent.h

@@ -181,9 +181,9 @@ class WebRenderBridgeParent final : public PWebRenderBridgeParent,
       const bool aIsFirstPaint, const bool aUseForTelemetry = true);
   TransactionId LastPendingTransactionId();
   TransactionId FlushTransactionIdsForEpoch(
-      const wr::Epoch& aEpoch, const TimeStamp& aCompositeStartTime,
+      const wr::Epoch& aEpoch, const VsyncId& aCompositeStartId,
-      const TimeStamp& aRenderStartTime, const TimeStamp& aEndTime,
+      const TimeStamp& aCompositeStartTime, const TimeStamp& aRenderStartTime,
-      UiCompositorControllerParent* aUiController,
+      const TimeStamp& aEndTime, UiCompositorControllerParent* aUiController,
       wr::RendererStats* aStats = nullptr,
       nsTArray<FrameStats>* aOutputStats = nullptr);
   void NotifySceneBuiltForEpoch(const wr::Epoch& aEpoch,
@@ -316,7 +316,7 @@ class WebRenderBridgeParent final : public PWebRenderBridgeParent,
   void FlushFrameGeneration();
   void FlushFramePresentation();
 
-  void MaybeGenerateFrame(bool aForceGenerateFrame);
+  void MaybeGenerateFrame(VsyncId aId, bool aForceGenerateFrame);
 
  private:
   struct PendingTransactionId {

gfx/webrender_bindings/RenderThread.cpp

@@ -244,6 +244,7 @@ void RenderThread::HandleFrame(wr::WindowId aWindowId, bool aRender) {
   }
 
   TimeStamp startTime;
+  VsyncId startId;
 
   bool hadSlowFrame;
   {  // scope lock
@@ -253,11 +254,13 @@ void RenderThread::HandleFrame(wr::WindowId aWindowId, bool aRender) {
     WindowInfo* info = it->second;
     MOZ_ASSERT(info->mPendingCount > 0);
     startTime = info->mStartTimes.front();
+    startId = info->mStartIds.front();
     hadSlowFrame = info->mHadSlowFrame;
     info->mHadSlowFrame = false;
   }
 
-  UpdateAndRender(aWindowId, startTime, aRender, /* aReadbackSize */ Nothing(),
+  UpdateAndRender(aWindowId, startId, startTime, aRender,
+                  /* aReadbackSize */ Nothing(),
                   /* aReadbackBuffer */ Nothing(), hadSlowFrame);
   FrameRenderingComplete(aWindowId);
 }
@@ -304,6 +307,7 @@ void RenderThread::RunEvent(wr::WindowId aWindowId,
 
 static void NotifyDidRender(layers::CompositorBridgeParent* aBridge,
                             RefPtr<WebRenderPipelineInfo> aInfo,
+                            VsyncId aCompositeStartId,
                             TimeStamp aCompositeStart, TimeStamp aRenderStart,
                             TimeStamp aEnd, bool aRender,
                             RendererStats aStats) {
@@ -317,13 +321,9 @@ static void NotifyDidRender(layers::CompositorBridgeParent* aBridge,
   auto info = aInfo->Raw();
 
   for (uintptr_t i = 0; i < info.epochs.length; i++) {
-    aBridge->NotifyPipelineRendered(info.epochs.data[i].pipeline_id,
+    aBridge->NotifyPipelineRendered(
-                                    info.epochs.data[i].epoch, aCompositeStart,
+        info.epochs.data[i].pipeline_id, info.epochs.data[i].epoch,
-                                    aRenderStart, aEnd, &aStats);
+        aCompositeStartId, aCompositeStart, aRenderStart, aEnd, &aStats);
-  }
-
-  if (aBridge->GetWrBridge()) {
-    aBridge->GetWrBridge()->CompositeIfNeeded();
   }
 }
 
@@ -336,6 +336,7 @@ static void NotifyDidStartRender(layers::CompositorBridgeParent* aBridge) {
 }
 
 void RenderThread::UpdateAndRender(wr::WindowId aWindowId,
+                                   const VsyncId& aStartId,
                                    const TimeStamp& aStartTime, bool aRender,
                                    const Maybe<gfx::IntSize>& aReadbackSize,
                                    const Maybe<Range<uint8_t>>& aReadbackBuffer,
@@ -374,8 +375,8 @@ void RenderThread::UpdateAndRender(wr::WindowId aWindowId,
 
   layers::CompositorThreadHolder::Loop()->PostTask(
       NewRunnableFunction("NotifyDidRenderRunnable", &NotifyDidRender,
-                          renderer->GetCompositorBridge(), info, aStartTime,
+                          renderer->GetCompositorBridge(), info, aStartId,
-                          start, end, aRender, stats));
+                          aStartTime, start, end, aRender, stats));
 
   if (rendered) {
     // Wait for GPU after posting NotifyDidRender, since the wait is not
@@ -463,6 +464,7 @@ void RenderThread::SetDestroyed(wr::WindowId aWindowId) {
 }
 
 void RenderThread::IncPendingFrameCount(wr::WindowId aWindowId,
+                                        const VsyncId& aStartId,
                                         const TimeStamp& aStartTime) {
   MutexAutoLock lock(mFrameCountMapLock);
   auto it = mWindowInfos.find(AsUint64(aWindowId));
@@ -472,6 +474,7 @@ void RenderThread::IncPendingFrameCount(wr::WindowId aWindowId,
   }
   it->second->mPendingCount++;
   it->second->mStartTimes.push(aStartTime);
+  it->second->mStartIds.push(aStartId);
 }
 
 void RenderThread::DecPendingFrameCount(wr::WindowId aWindowId) {
@@ -495,6 +498,7 @@ void RenderThread::DecPendingFrameCount(wr::WindowId aWindowId) {
   mozilla::Telemetry::AccumulateTimeDelta(mozilla::Telemetry::COMPOSITE_TIME,
                                           info->mStartTimes.front());
   info->mStartTimes.pop();
+  info->mStartIds.pop();
 }
 
 void RenderThread::IncRenderingFrameCount(wr::WindowId aWindowId) {
@@ -529,6 +533,7 @@ void RenderThread::FrameRenderingComplete(wr::WindowId aWindowId) {
   mozilla::Telemetry::AccumulateTimeDelta(mozilla::Telemetry::COMPOSITE_TIME,
                                           info->mStartTimes.front());
   info->mStartTimes.pop();
+  info->mStartIds.pop();
 }
 
 void RenderThread::NotifySlowFrame(wr::WindowId aWindowId) {

gfx/webrender_bindings/RenderThread.h

@@ -21,6 +21,7 @@
 #include "mozilla/webrender/WebRenderTypes.h"
 #include "mozilla/layers/SynchronousTask.h"
 #include "GLContext.h"
+#include "mozilla/VsyncDispatcher.h"
 
 #include <list>
 #include <queue>
@@ -168,8 +169,9 @@ class RenderThread final {
   void RunEvent(wr::WindowId aWindowId, UniquePtr<RendererEvent> aCallBack);
 
   /// Can only be called from the render thread.
-  void UpdateAndRender(wr::WindowId aWindowId, const TimeStamp& aStartTime,
+  void UpdateAndRender(wr::WindowId aWindowId, const VsyncId& aStartId,
-                       bool aRender, const Maybe<gfx::IntSize>& aReadbackSize,
+                       const TimeStamp& aStartTime, bool aRender,
+                       const Maybe<gfx::IntSize>& aReadbackSize,
                        const Maybe<Range<uint8_t>>& aReadbackBuffer,
                        bool aHadSlowFrame);
 
@@ -200,7 +202,7 @@ class RenderThread final {
   /// Can be called from any thread.
   bool TooManyPendingFrames(wr::WindowId aWindowId);
   /// Can be called from any thread.
-  void IncPendingFrameCount(wr::WindowId aWindowId,
+  void IncPendingFrameCount(wr::WindowId aWindowId, const VsyncId& aStartId,
                             const TimeStamp& aStartTime);
   /// Can be called from any thread.
   void DecPendingFrameCount(wr::WindowId aWindowId);
@@ -266,6 +268,7 @@ class RenderThread final {
     // One entry in this queue for each pending frame, so the length
     // should always equal mPendingCount
     std::queue<TimeStamp> mStartTimes;
+    std::queue<VsyncId> mStartIds;
     bool mHadSlowFrame = false;
   };
 

gfx/webrender_bindings/WebRenderAPI.cpp

@@ -372,8 +372,9 @@ void WebRenderAPI::Readback(const TimeStamp& aStartTime, gfx::IntSize size,
     ~Readback() { MOZ_COUNT_DTOR(Readback); }
 
     virtual void Run(RenderThread& aRenderThread, WindowId aWindowId) override {
-      aRenderThread.UpdateAndRender(aWindowId, mStartTime, /* aRender */ true,
+      aRenderThread.UpdateAndRender(aWindowId, VsyncId(), mStartTime,
-                                    Some(mSize), Some(mBuffer), false);
+                                    /* aRender */ true, Some(mSize),
+                                    Some(mBuffer), false);
       layers::AutoCompleteTask complete(mTask);
     }
 

toolkit/components/telemetry/Histograms.json

@@ -13211,6 +13211,15 @@
     "n_buckets": 50,
     "description": "The time, in percentage of a vsync interval, spent from beginning a paint in the content process until that frame is presented in the compositor by WebRender, excluding time spent uploading any content"
   },
+  "CONTENT_FRAME_TIME_REASON": {
+    "record_in_processes": ["main", "gpu"],
+    "alert_emails": ["gfx-telemetry-alerts@mozilla.com", "mwoodrow@mozilla.com"],
+    "bug_numbers": [1510853],
+    "expires_in_version": "73",
+    "kind": "categorical",
+    "description": "The reason that CONTENT_FRAME_TIME recorded a slow (>200) result, if any.",
+    "labels": ["OnTime", "NoVsync", "MissedComposite", "SlowComposite"]
+  },
   "CONTENT_LARGE_PAINT_PHASE_WEIGHT": {
     "record_in_processes": ["main", "content"],
     "alert_emails": ["gfx-telemetry-alerts@mozilla.com", "mwoodrow@mozilla.com"],