Bug 1470528 - Implement CONTENT_FRAME_TIME for the non-webrender codepath. r=sotaro, data-review=francois

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 --HG-- extra : rebase_source : 29ebd6a85dd49ee263d50e3674eec4957ac5f12a extra : histedit_source : 1aa9f4f31b5bff6736e0c0e576a5611880d0ab33
2018-06-26 13:40:10 -05:00 · 2018-06-26 13:40:10 -05:00 · 73970a1f68
--- a/gfx/layers/client/ClientLayerManager.cpp
+++ b/gfx/layers/client/ClientLayerManager.cpp
@ -436,9 +436,15 @@ ClientLayerManager::EndTransaction(DrawPaintedLayerCallback aCallback,
  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();
@ -755,12 +761,7 @@ ClientLayerManager::ForwardTransaction(bool aScheduleComposite)
  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);
@ -770,7 +771,8 @@ ClientLayerManager::ForwardTransaction(bool aScheduleComposite)
  bool sent = false;
  bool ok = mForwarder->EndTransaction(
    mRegionToClear, mLatestTransactionId, aScheduleComposite,
-    mPaintSequenceNumber, mIsRepeatTransaction, transactionStart,
+    mPaintSequenceNumber, mIsRepeatTransaction,
+    refreshStart, mTransactionStart,
    &sent);
  if (ok) {
    if (sent) {
--- a/gfx/layers/ipc/CompositorBridgeParent.cpp
+++ b/gfx/layers/ipc/CompositorBridgeParent.cpp
@ -1328,6 +1328,7 @@ CompositorBridgeParent::ShadowLayersUpdated(LayerTransactionParent* aLayerTree,
  // 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();

@ -1636,14 +1637,14 @@ CompositorBridgeParent::AllocPLayerTransactionParent(const nsTArray<LayersBacken

  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;
 }
@ -2131,15 +2132,16 @@ CompositorBridgeParent::DidComposite(TimeStamp& aCompositeStart,
    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
--- a/gfx/layers/ipc/CompositorBridgeParent.h
+++ b/gfx/layers/ipc/CompositorBridgeParent.h
@ -601,6 +601,7 @@ protected:
  TimeDuration mVsyncRate;

  TransactionId mPendingTransaction;
+  TimeStamp mRefreshStartTime;
  TimeStamp mTxnStartTime;
  TimeStamp mFwdTime;

--- a/gfx/layers/ipc/CrossProcessCompositorBridgeParent.cpp
+++ b/gfx/layers/ipc/CrossProcessCompositorBridgeParent.cpp
@ -94,14 +94,15 @@ CrossProcessCompositorBridgeParent::AllocPLayerTransactionParent(
    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;
 }
@ -372,7 +373,7 @@ CrossProcessCompositorBridgeParent::ShadowLayersUpdated(
    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
--- a/gfx/layers/ipc/LayerTransactionParent.cpp
+++ b/gfx/layers/ipc/LayerTransactionParent.cpp
@ -26,6 +26,7 @@
 #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
@ -48,13 +49,15 @@ namespace layers {
 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)
@ -935,20 +938,29 @@ bool LayerTransactionParent::IsSameProcess() const
 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;
--- a/gfx/layers/ipc/LayerTransactionParent.h
+++ b/gfx/layers/ipc/LayerTransactionParent.h
@ -48,7 +48,8 @@ public:
  LayerTransactionParent(HostLayerManager* aManager,
                         CompositorBridgeParentBase* aBridge,
                         CompositorAnimationStorage* aAnimStorage,
-                         LayersId aId);
+                         LayersId aId,
+                         TimeDuration aVsyncRate);

 protected:
  ~LayerTransactionParent();
@ -79,9 +80,13 @@ public:
  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;
  }
@ -196,7 +201,10 @@ private:
  uint64_t mChildEpoch;
  uint64_t mParentEpoch;

+  TimeDuration mVsyncRate;
+
  TransactionId mPendingTransaction;
+  TimeStamp mRefreshStartTime;
  TimeStamp mTxnStartTime;
  TimeStamp mFwdTime;

--- a/gfx/layers/ipc/LayersMessages.ipdlh
+++ b/gfx/layers/ipc/LayersMessages.ipdlh
@ -560,6 +560,7 @@ struct TransactionInfo
  bool scheduleComposite;
  uint32_t paintSequenceNumber;
  bool isRepeatTransaction;
+  TimeStamp refreshStart;
  TimeStamp transactionStart;
  TimeStamp fwdTime;
 };
--- a/gfx/layers/ipc/ShadowLayers.cpp
+++ b/gfx/layers/ipc/ShadowLayers.cpp
@ -599,6 +599,7 @@ ShadowLayerForwarder::EndTransaction(const nsIntRegion& aRegionToClear,
                                     bool aScheduleComposite,
                                     uint32_t aPaintSequenceNumber,
                                     bool aIsRepeatTransaction,
+                                     const mozilla::TimeStamp& aRefreshStart,
                                     const mozilla::TimeStamp& aTransactionStart,
                                     bool* aSent)
 {
@ -740,6 +741,7 @@ ShadowLayerForwarder::EndTransaction(const nsIntRegion& aRegionToClear,
  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();
--- a/gfx/layers/ipc/ShadowLayers.h
+++ b/gfx/layers/ipc/ShadowLayers.h
@ -257,6 +257,7 @@ public:
                      bool aScheduleComposite,
                      uint32_t aPaintSequenceNumber,
                      bool aIsRepeatTransaction,
+                      const mozilla::TimeStamp& aRefreshStart,
                      const mozilla::TimeStamp& aTransactionStart,
                      bool* aSent);

--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@ -12801,6 +12801,16 @@
    "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"],