Bug 1470528 - Implement CONTENT_FRAME_TIME for the non-webrender codepath. r=sotaro
☠☠ backed out by 6e5891e3bbd2 ☠ ☠
authorRyan Hunt <rhunt@eqrion.net>
Tue, 26 Jun 2018 13:40:10 -0500
changeset 424924 e438548991db2848923dddd391912141814752c7
parent 424923 f859daf8d8d9356eb2c51811d724403d56574639
child 424925 90513daef576e637053b3f0c745933455ff5eb0f
push id34227
push userrgurzau@mozilla.com
push dateWed, 04 Jul 2018 09:59:03 +0000
treeherdermozilla-central@cc3401e78e8b [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewerssotaro
bugs1470528
milestone63.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 1470528 - Implement CONTENT_FRAME_TIME for the non-webrender codepath. r=sotaro This commit adds the CONTENT_FRAME_TIME metric which tracks the time from the beginning of a paint in the content process until it is presented in the compositor. There is existing logging for frame latency which tracks from the beginning of a refresh tick until the frame is presented. This is undesirable for this probe as javascript and layout can run in this time period. So this probe uses the existing infrastructure for logging frame latency, but uses a start time from BeginTransaction in layer manager. MozReview-Commit-ID: 5z9LS3tsZTY
gfx/layers/client/ClientLayerManager.cpp
gfx/layers/ipc/CompositorBridgeParent.cpp
gfx/layers/ipc/CompositorBridgeParent.h
gfx/layers/ipc/CrossProcessCompositorBridgeParent.cpp
gfx/layers/ipc/LayerTransactionParent.cpp
gfx/layers/ipc/LayerTransactionParent.h
gfx/layers/ipc/LayersMessages.ipdlh
gfx/layers/ipc/ShadowLayers.cpp
gfx/layers/ipc/ShadowLayers.h
toolkit/components/telemetry/Histograms.json
--- a/gfx/layers/client/ClientLayerManager.cpp
+++ b/gfx/layers/client/ClientLayerManager.cpp
@@ -431,19 +431,25 @@ ClientLayerManager::EndTransaction(DrawP
     mWidget->PrepareWindowEffects();
   }
   EndTransactionInternal(aCallback, aCallbackData, aFlags);
   ForwardTransaction(!(aFlags & END_NO_REMOTE_COMPOSITE));
 
   if (mRepeatTransaction) {
     mRepeatTransaction = false;
     mIsRepeatTransaction = true;
+
+    // BeginTransaction will reset the transaction start time, but we
+    // would like to keep the original time for telemetry purposes.
+    TimeStamp transactionStart = mTransactionStart;
     if (BeginTransaction()) {
+      mTransactionStart = transactionStart;
       ClientLayerManager::EndTransaction(aCallback, aCallbackData, aFlags);
     }
+
     mIsRepeatTransaction = false;
   } else {
     MakeSnapshotIfRequired();
   }
 
   mInTransaction = false;
   mTransactionStart = TimeStamp();
 }
@@ -750,32 +756,28 @@ ClientLayerManager::ForwardTransaction(b
     PaintThread::Get()->EndLayerTransaction(syncObject);
   } else if (syncObject) {
     syncObject->Synchronize();
   }
 
   mPhase = PHASE_FORWARD;
 
   mLatestTransactionId = mTransactionIdAllocator->GetTransactionId(!mIsRepeatTransaction);
-  TimeStamp transactionStart;
-  if (!mTransactionIdAllocator->GetTransactionStart().IsNull()) {
-    transactionStart = mTransactionIdAllocator->GetTransactionStart();
-  } else {
-    transactionStart = mTransactionStart;
-  }
+  TimeStamp refreshStart = mTransactionIdAllocator->GetTransactionStart();
 
   if (gfxPrefs::AlwaysPaint() && XRE_IsContentProcess()) {
     mForwarder->SendPaintTime(mLatestTransactionId, mLastPaintTime);
   }
 
   // forward this transaction's changeset to our LayerManagerComposite
   bool sent = false;
   bool ok = mForwarder->EndTransaction(
     mRegionToClear, mLatestTransactionId, aScheduleComposite,
-    mPaintSequenceNumber, mIsRepeatTransaction, transactionStart,
+    mPaintSequenceNumber, mIsRepeatTransaction,
+    refreshStart, mTransactionStart,
     &sent);
   if (ok) {
     if (sent) {
       mNeedsComposite = false;
     }
   } else if (HasShadowManager()) {
     NS_WARNING("failed to forward Layers transaction");
   }
--- a/gfx/layers/ipc/CompositorBridgeParent.cpp
+++ b/gfx/layers/ipc/CompositorBridgeParent.cpp
@@ -1323,16 +1323,17 @@ CompositorBridgeParent::ShadowLayersUpda
     }
   }
 
   // The transaction ID might get reset to 1 if the page gets reloaded, see
   // https://bugzilla.mozilla.org/show_bug.cgi?id=1145295#c41
   // Otherwise, it should be continually increasing.
   MOZ_ASSERT(aInfo.id() == TransactionId{1} || aInfo.id() > mPendingTransaction);
   mPendingTransaction = aInfo.id();
+  mRefreshStartTime = aInfo.refreshStart();
   mTxnStartTime = aInfo.transactionStart();
   mFwdTime = aInfo.fwdTime();
 
   if (root) {
     SetShadowProperties(root);
   }
   if (aInfo.scheduleComposite()) {
     ScheduleComposition();
@@ -1631,24 +1632,24 @@ CompositorBridgeParent::AllocPLayerTrans
                                                      const LayersId& aId)
 {
   MOZ_ASSERT(!aId.IsValid());
 
   InitializeLayerManager(aBackendHints);
 
   if (!mLayerManager) {
     NS_WARNING("Failed to initialise Compositor");
-    LayerTransactionParent* p = new LayerTransactionParent(/* aManager */ nullptr, this, /* aAnimStorage */ nullptr, mRootLayerTreeID);
+    LayerTransactionParent* p = new LayerTransactionParent(/* aManager */ nullptr, this, /* aAnimStorage */ nullptr, mRootLayerTreeID, mVsyncRate);
     p->AddIPDLReference();
     return p;
   }
 
   mCompositionManager = new AsyncCompositionManager(this, mLayerManager);
 
-  LayerTransactionParent* p = new LayerTransactionParent(mLayerManager, this, GetAnimationStorage(), mRootLayerTreeID);
+  LayerTransactionParent* p = new LayerTransactionParent(mLayerManager, this, GetAnimationStorage(), mRootLayerTreeID, mVsyncRate);
   p->AddIPDLReference();
   return p;
 }
 
 bool
 CompositorBridgeParent::DeallocPLayerTransactionParent(PLayerTransactionParent* actor)
 {
   static_cast<LayerTransactionParent*>(actor)->ReleaseIPDLReference();
@@ -2126,25 +2127,26 @@ CompositorBridgeParent::DidComposite(Tim
                                      TimeStamp& aCompositeEnd)
 {
   if (mWrBridge) {
     NotifyDidComposite(mWrBridge->FlushPendingTransactionIds(), aCompositeStart, aCompositeEnd);
   } else {
     NotifyDidComposite(mPendingTransaction, aCompositeStart, aCompositeEnd);
 #if defined(ENABLE_FRAME_LATENCY_LOG)
     if (mPendingTransaction.IsValid()) {
-      if (mTxnStartTime) {
-        uint32_t latencyMs = round((aCompositeEnd - mTxnStartTime).ToMilliseconds());
+      if (mRefreshStartTime) {
+        int32_t latencyMs = lround((aCompositeEnd - mRefreshStartTime).ToMilliseconds());
         printf_stderr("From transaction start to end of generate frame latencyMs %d this %p\n", latencyMs, this);
       }
       if (mFwdTime) {
-        uint32_t latencyMs = round((aCompositeEnd - mFwdTime).ToMilliseconds());
+        int32_t latencyMs = lround((aCompositeEnd - mFwdTime).ToMilliseconds());
         printf_stderr("From forwarding transaction to end of generate frame latencyMs %d this %p\n", latencyMs, this);
       }
     }
+    mRefreshStartTime = TimeStamp();
     mTxnStartTime = TimeStamp();
     mFwdTime = TimeStamp();
 #endif
     mPendingTransaction = TransactionId{0};
   }
 }
 
 void
--- a/gfx/layers/ipc/CompositorBridgeParent.h
+++ b/gfx/layers/ipc/CompositorBridgeParent.h
@@ -596,16 +596,17 @@ protected:
   RefPtr<AsyncImagePipelineManager> mAsyncImageManager;
   RefPtr<WebRenderBridgeParent> mWrBridge;
   widget::CompositorWidget* mWidget;
   Maybe<TimeStamp> mTestTime;
   CSSToLayoutDeviceScale mScale;
   TimeDuration mVsyncRate;
 
   TransactionId mPendingTransaction;
+  TimeStamp mRefreshStartTime;
   TimeStamp mTxnStartTime;
   TimeStamp mFwdTime;
 
   bool mPaused;
 
   bool mUseExternalSurfaceSize;
   gfx::IntSize mEGLSurfaceSize;
 
--- a/gfx/layers/ipc/CrossProcessCompositorBridgeParent.cpp
+++ b/gfx/layers/ipc/CrossProcessCompositorBridgeParent.cpp
@@ -89,24 +89,25 @@ CrossProcessCompositorBridgeParent::Allo
   if (sIndirectLayerTrees.end() != itr) {
     state = &itr->second;
   }
 
   if (state && state->mLayerManager) {
     state->mCrossProcessParent = this;
     HostLayerManager* lm = state->mLayerManager;
     CompositorAnimationStorage* animStorage = state->mParent ? state->mParent->GetAnimationStorage() : nullptr;
-    LayerTransactionParent* p = new LayerTransactionParent(lm, this, animStorage, aId);
+    TimeDuration vsyncRate = state->mParent ? state->mParent->GetVsyncInterval() : TimeDuration();
+    LayerTransactionParent* p = new LayerTransactionParent(lm, this, animStorage, aId, vsyncRate);
     p->AddIPDLReference();
     sIndirectLayerTrees[aId].mLayerTree = p;
     return p;
   }
 
   NS_WARNING("Created child without a matching parent?");
-  LayerTransactionParent* p = new LayerTransactionParent(/* aManager */ nullptr, this, /* aAnimStorage */ nullptr, aId);
+  LayerTransactionParent* p = new LayerTransactionParent(/* aManager */ nullptr, this, /* aAnimStorage */ nullptr, aId, TimeDuration());
   p->AddIPDLReference();
   return p;
 }
 
 bool
 CrossProcessCompositorBridgeParent::DeallocPLayerTransactionParent(PLayerTransactionParent* aLayers)
 {
   LayerTransactionParent* slp = static_cast<LayerTransactionParent*>(aLayers);
@@ -367,17 +368,17 @@ CrossProcessCompositorBridgeParent::Shad
   }
 
   if (aLayerTree->ShouldParentObserveEpoch()) {
     // Note that we send this through the window compositor, since this needs
     // to reach the widget owning the tab.
     Unused << state->mParent->SendObserveLayerUpdate(id, aLayerTree->GetChildEpoch(), true);
   }
 
-  aLayerTree->SetPendingTransactionId(aInfo.id(), aInfo.transactionStart(), aInfo.fwdTime());
+  aLayerTree->SetPendingTransactionId(aInfo.id(), aInfo.refreshStart(), aInfo.transactionStart(), aInfo.fwdTime());
 }
 
 void
 CrossProcessCompositorBridgeParent::DidComposite(
   LayersId aId,
   TimeStamp& aCompositeStart,
   TimeStamp& aCompositeEnd)
 {
--- a/gfx/layers/ipc/LayerTransactionParent.cpp
+++ b/gfx/layers/ipc/LayerTransactionParent.cpp
@@ -21,16 +21,17 @@
 #include "mozilla/layers/ImageBridgeParent.h" // for ImageBridgeParent
 #include "mozilla/layers/ImageLayerComposite.h"
 #include "mozilla/layers/LayerManagerComposite.h"
 #include "mozilla/layers/LayersMessages.h"  // for EditReply, etc
 #include "mozilla/layers/LayersTypes.h"  // for MOZ_LAYERS_LOG
 #include "mozilla/layers/TextureHostOGL.h"  // for TextureHostOGL
 #include "mozilla/layers/PaintedLayerComposite.h"
 #include "mozilla/mozalloc.h"           // for operator delete, etc
+#include "mozilla/Telemetry.h"
 #include "mozilla/Unused.h"
 #include "nsCoord.h"                    // for NSAppUnitsToFloatPixels
 #include "nsISupportsImpl.h"            // for Layer::Release, etc
 #include "nsLayoutUtils.h"              // for nsLayoutUtils
 #include "nsMathUtils.h"                // for NS_round
 #include "nsPoint.h"                    // for nsPoint
 #include "nsTArray.h"                   // for nsTArray, nsTArray_Impl, etc
 #include "TreeTraversal.h"              // for ForEachNode
@@ -43,23 +44,25 @@ using mozilla::layout::RenderFrameParent
 namespace mozilla {
 namespace layers {
 
 //--------------------------------------------------
 // LayerTransactionParent
 LayerTransactionParent::LayerTransactionParent(HostLayerManager* aManager,
                                                CompositorBridgeParentBase* aBridge,
                                                CompositorAnimationStorage* aAnimStorage,
-                                               LayersId aId)
+                                               LayersId aId,
+                                               TimeDuration aVsyncRate)
   : mLayerManager(aManager)
   , mCompositorBridge(aBridge)
   , mAnimStorage(aAnimStorage)
   , mId(aId)
   , mChildEpoch(0)
   , mParentEpoch(0)
+  , mVsyncRate(aVsyncRate)
   , mPendingTransaction{0}
   , mDestroyed(false)
   , mIPCOpen(false)
 {
   MOZ_ASSERT(mId.IsValid());
 }
 
 LayerTransactionParent::~LayerTransactionParent()
@@ -954,30 +957,39 @@ LayerTransactionParent::DeallocShmem(ipc
 bool LayerTransactionParent::IsSameProcess() const
 {
   return OtherPid() == base::GetCurrentProcId();
 }
 
 TransactionId
 LayerTransactionParent::FlushTransactionId(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);
+  }
+
 #if defined(ENABLE_FRAME_LATENCY_LOG)
   if (mPendingTransaction.IsValid()) {
-    if (mTxnStartTime) {
-      uint32_t latencyMs = round((aCompositeEnd - mTxnStartTime).ToMilliseconds());
+    if (mRefreshStartTime) {
+      int32_t latencyMs = lround((aCompositeEnd - mRefreshStartTime).ToMilliseconds());
       printf_stderr("From transaction start to end of generate frame latencyMs %d this %p\n", latencyMs, this);
     }
     if (mFwdTime) {
-      uint32_t latencyMs = round((aCompositeEnd - mFwdTime).ToMilliseconds());
+      int32_t latencyMs = lround((aCompositeEnd - mFwdTime).ToMilliseconds());
       printf_stderr("From forwarding transaction to end of generate frame latencyMs %d this %p\n", latencyMs, this);
     }
   }
+#endif
+
+  mRefreshStartTime = TimeStamp();
   mTxnStartTime = TimeStamp();
   mFwdTime = TimeStamp();
-#endif
   TransactionId id = mPendingTransaction;
   mPendingTransaction = TransactionId{0};
   return id;
 }
 
 void
 LayerTransactionParent::SendAsyncMessage(const InfallibleTArray<AsyncParentMessageData>& aMessage)
 {
--- a/gfx/layers/ipc/LayerTransactionParent.h
+++ b/gfx/layers/ipc/LayerTransactionParent.h
@@ -43,17 +43,18 @@ class LayerTransactionParent final : pub
   typedef InfallibleTArray<Edit> EditArray;
   typedef InfallibleTArray<OpDestroy> OpDestroyArray;
   typedef InfallibleTArray<PluginWindowData> PluginsArray;
 
 public:
   LayerTransactionParent(HostLayerManager* aManager,
                          CompositorBridgeParentBase* aBridge,
                          CompositorAnimationStorage* aAnimStorage,
-                         LayersId aId);
+                         LayersId aId,
+                         TimeDuration aVsyncRate);
 
 protected:
   ~LayerTransactionParent();
 
 public:
   void Destroy();
 
   void SetLayerManager(HostLayerManager* aLayerManager, CompositorAnimationStorage* aAnimStorage);
@@ -74,19 +75,23 @@ public:
                         ipc::SharedMemory::SharedMemoryType aType,
                         ipc::Shmem* aShmem) override;
 
   void DeallocShmem(ipc::Shmem& aShmem) override;
 
   bool IsSameProcess() const override;
 
   const TransactionId& GetPendingTransactionId() { return mPendingTransaction; }
-  void SetPendingTransactionId(TransactionId aId, const TimeStamp& aTxnStartTime, const TimeStamp& aFwdTime)
+  void SetPendingTransactionId(TransactionId aId,
+                               const TimeStamp& aRefreshStartTime,
+                               const TimeStamp& aTxnStartTime,
+                               const TimeStamp& aFwdTime)
   {
     mPendingTransaction = aId;
+    mRefreshStartTime = aRefreshStartTime;
     mTxnStartTime = aTxnStartTime;
     mFwdTime = aFwdTime;
   }
   TransactionId FlushTransactionId(TimeStamp& aCompositeEnd);
 
   // CompositableParentManager
   void SendAsyncMessage(const InfallibleTArray<AsyncParentMessageData>& aMessage) override;
 
@@ -191,17 +196,20 @@ private:
 
   // These fields keep track of the latest epoch values in the child and the
   // parent. mChildEpoch is the latest epoch value received from the child.
   // mParentEpoch is the latest epoch value that we have told TabParent about
   // (via ObserveLayerUpdate).
   uint64_t mChildEpoch;
   uint64_t mParentEpoch;
 
+  TimeDuration mVsyncRate;
+
   TransactionId mPendingTransaction;
+  TimeStamp mRefreshStartTime;
   TimeStamp mTxnStartTime;
   TimeStamp mFwdTime;
 
   // When the widget/frame/browser stuff in this process begins its
   // destruction process, we need to Disconnect() all the currently
   // live shadow layers, because some of them might be orphaned from
   // the layer tree.  This happens in Destroy() above.  After we
   // Destroy() ourself, there's a window in which that information
--- a/gfx/layers/ipc/LayersMessages.ipdlh
+++ b/gfx/layers/ipc/LayersMessages.ipdlh
@@ -567,16 +567,17 @@ struct TransactionInfo
   TransactionId id;
   TargetConfig targetConfig;
   PluginWindowData[] plugins;
   bool isFirstPaint;
   FocusTarget focusTarget;
   bool scheduleComposite;
   uint32_t paintSequenceNumber;
   bool isRepeatTransaction;
+  TimeStamp refreshStart;
   TimeStamp transactionStart;
   TimeStamp fwdTime;
 };
 
 union MaybeTransform {
   Matrix4x4;
   void_t;
 };
--- a/gfx/layers/ipc/ShadowLayers.cpp
+++ b/gfx/layers/ipc/ShadowLayers.cpp
@@ -599,16 +599,17 @@ ShadowLayerForwarder::SendPaintTime(Tran
 }
 
 bool
 ShadowLayerForwarder::EndTransaction(const nsIntRegion& aRegionToClear,
                                      TransactionId aId,
                                      bool aScheduleComposite,
                                      uint32_t aPaintSequenceNumber,
                                      bool aIsRepeatTransaction,
+                                     const mozilla::TimeStamp& aRefreshStart,
                                      const mozilla::TimeStamp& aTransactionStart,
                                      bool* aSent)
 {
   *aSent = false;
 
   TransactionInfo info;
 
   MOZ_ASSERT(IPCOpen(), "no manager to forward to");
@@ -740,16 +741,17 @@ ShadowLayerForwarder::EndTransaction(con
   info.fwdTransactionId() = GetFwdTransactionId();
   info.id() = aId;
   info.plugins() = mPluginWindowData;
   info.isFirstPaint() = mIsFirstPaint;
   info.focusTarget() = mFocusTarget;
   info.scheduleComposite() = aScheduleComposite;
   info.paintSequenceNumber() = aPaintSequenceNumber;
   info.isRepeatTransaction() = aIsRepeatTransaction;
+  info.refreshStart() = aRefreshStart;
   info.transactionStart() = aTransactionStart;
 #if defined(ENABLE_FRAME_LATENCY_LOG)
   info.fwdTime() = TimeStamp::Now();
 #endif
 
   TargetConfig targetConfig(mTxn->mTargetBounds,
                             mTxn->mTargetRotation,
                             mTxn->mTargetOrientation,
--- a/gfx/layers/ipc/ShadowLayers.h
+++ b/gfx/layers/ipc/ShadowLayers.h
@@ -253,16 +253,17 @@ public:
    * |aReplies| are directions from the LayerManagerComposite to the
    * caller of EndTransaction().
    */
   bool EndTransaction(const nsIntRegion& aRegionToClear,
                       TransactionId aId,
                       bool aScheduleComposite,
                       uint32_t aPaintSequenceNumber,
                       bool aIsRepeatTransaction,
+                      const mozilla::TimeStamp& aRefreshStart,
                       const mozilla::TimeStamp& aTransactionStart,
                       bool* aSent);
 
   /**
    * Set an actor through which layer updates will be pushed.
    */
   void SetShadowManager(PLayerTransactionChild* aShadowManager);
 
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -12796,16 +12796,26 @@
     "alert_emails": ["mwoodrow@mozilla.com","gfx-telemetry-alerts@mozilla.com"],
     "bug_numbers": [1309442],
     "expires_in_version": "66",
     "kind": "exponential",
     "high": 1000,
     "n_buckets": 50,
     "description": "Time spent in the paint pipeline for content in milliseconds."
   },
+  "CONTENT_FRAME_TIME": {
+    "record_in_processes": ["main", "gpu"],
+    "alert_emails": ["rhunt@mozilla.com","gfx-telemetry-alerts@mozilla.com"],
+    "bug_numbers": [1470528],
+    "expires_in_version": "66",
+    "kind": "exponential",
+    "high": 5000,
+    "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."
+  },
   "CONTENT_LARGE_PAINT_PHASE_WEIGHT": {
     "record_in_processes": ["main", "content"],
     "alert_emails": ["mwoodrow@mozilla.com","gfx-telemetry-alerts@mozilla.com"],
     "bug_numbers": [1309442],
     "expires_in_version": "66",
     "keyed": true,
     "keys": ["dl", "flb", "fr", "r"],
     "kind": "linear",