Bug 1387922 - Add log of start or fwd Transaction to on screen timing r=nical
authorsotaro <sotaro.ikeda.g@gmail.com>
Fri, 11 Aug 2017 10:57:21 +0900
changeset 374223 eba5c78cfe2cc3723c8cba1eaa5eea36e0d45383
parent 374222 6544c0f5a48914cc3f191432d55855c38af2430b
child 374224 a88ed8010517d597fd4fc94a124152575ca19f46
push id32318
push userkwierso@gmail.com
push dateFri, 11 Aug 2017 20:16:01 +0000
treeherdermozilla-central@80ff3f300e05 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersnical
bugs1387922
milestone57.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 1387922 - Add log of start or fwd Transaction to on screen timing r=nical
gfx/layers/LayersTypes.h
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/PWebRenderBridge.ipdl
gfx/layers/ipc/ShadowLayers.cpp
gfx/layers/wr/WebRenderBridgeChild.cpp
gfx/layers/wr/WebRenderBridgeChild.h
gfx/layers/wr/WebRenderBridgeParent.cpp
gfx/layers/wr/WebRenderBridgeParent.h
gfx/layers/wr/WebRenderLayerManager.cpp
gfx/webrender_bindings/RendererOGL.cpp
gfx/webrender_bindings/WebRenderTypes.h
--- a/gfx/layers/LayersTypes.h
+++ b/gfx/layers/LayersTypes.h
@@ -23,16 +23,18 @@
 #endif
 #define MOZ_LAYERS_LOG(_args)                             \
   MOZ_LOG(LayerManager::GetLog(), LogLevel::Debug, _args)
 #define MOZ_LAYERS_LOG_IF_SHADOWABLE(layer, _args)         \
   do { if (layer->AsShadowableLayer()) { MOZ_LOG(LayerManager::GetLog(), LogLevel::Debug, _args); } } while (0)
 
 #define INVALID_OVERLAY -1
 
+//#define ENABLE_FRAME_LATENCY_LOG
+
 namespace IPC {
 template <typename T> struct ParamTraits;
 } // namespace IPC
 
 namespace android {
 class MOZ_EXPORT GraphicBuffer;
 } // namespace android
 
--- a/gfx/layers/ipc/CompositorBridgeParent.cpp
+++ b/gfx/layers/ipc/CompositorBridgeParent.cpp
@@ -1252,16 +1252,18 @@ 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() == 1 || aInfo.id() > mPendingTransaction);
   mPendingTransaction = aInfo.id();
+  mTxnStartTime = aInfo.transactionStart();
+  mFwdTime = aInfo.fwdTime();
 
   if (root) {
     SetShadowProperties(root);
   }
   if (aInfo.scheduleComposite()) {
     ScheduleComposition();
     if (mPaused) {
       TimeStamp now = TimeStamp::Now();
@@ -1945,16 +1947,30 @@ CompositorBridgeParent::LayerTreeState::
 void
 CompositorBridgeParent::DidComposite(TimeStamp& aCompositeStart,
                                      TimeStamp& aCompositeEnd)
 {
   if (mWrBridge) {
     NotifyDidComposite(mWrBridge->FlushPendingTransactionIds(), aCompositeStart, aCompositeEnd);
   } else {
     NotifyDidComposite(mPendingTransaction, aCompositeStart, aCompositeEnd);
+#if defined(ENABLE_FRAME_LATENCY_LOG)
+    if (mPendingTransaction) {
+      if (mTxnStartTime) {
+        uint32_t latencyMs = round((aCompositeEnd - mTxnStartTime).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());
+        printf_stderr("From forwarding transaction to end of generate frame latencyMs %d this %p\n", latencyMs, this);
+      }
+    }
+    mTxnStartTime = TimeStamp();
+    mFwdTime = TimeStamp();
+#endif
     mPendingTransaction = 0;
   }
 }
 
 void
 CompositorBridgeParent::NotifyDidCompositeToPipeline(const wr::PipelineId& aPipelineId, const wr::Epoch& aEpoch, TimeStamp& aCompositeStart, TimeStamp& aCompositeEnd)
 {
   if (!mWrBridge || !mAsyncImageManager) {
--- a/gfx/layers/ipc/CompositorBridgeParent.h
+++ b/gfx/layers/ipc/CompositorBridgeParent.h
@@ -585,16 +585,18 @@ protected:
   RefPtr<WebRenderBridgeParent> mWrBridge;
   widget::CompositorWidget* mWidget;
   TimeStamp mTestTime;
   CSSToLayoutDeviceScale mScale;
   TimeDuration mVsyncRate;
   bool mIsTesting;
 
   uint64_t mPendingTransaction;
+  TimeStamp mTxnStartTime;
+  TimeStamp mFwdTime;
 
   bool mPaused;
 
   bool mUseExternalSurfaceSize;
   gfx::IntSize mEGLSurfaceSize;
 
   CompositorOptions mOptions;
 
--- a/gfx/layers/ipc/CrossProcessCompositorBridgeParent.cpp
+++ b/gfx/layers/ipc/CrossProcessCompositorBridgeParent.cpp
@@ -349,17 +349,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());
+  aLayerTree->SetPendingTransactionId(aInfo.id(), aInfo.transactionStart(), aInfo.fwdTime());
 }
 
 void
 CrossProcessCompositorBridgeParent::DidComposite(
   uint64_t aId,
   TimeStamp& aCompositeStart,
   TimeStamp& aCompositeEnd)
 {
@@ -370,20 +370,19 @@ CrossProcessCompositorBridgeParent::DidC
 void
 CrossProcessCompositorBridgeParent::DidCompositeLocked(
   uint64_t aId,
   TimeStamp& aCompositeStart,
   TimeStamp& aCompositeEnd)
 {
   sIndirectLayerTreesLock->AssertCurrentThreadOwns();
   if (LayerTransactionParent *layerTree = sIndirectLayerTrees[aId].mLayerTree) {
-    uint64_t transactionId = layerTree->GetPendingTransactionId();
+    uint64_t transactionId = layerTree->FlushTransactionId(aCompositeEnd);
     if (transactionId) {
       Unused << SendDidComposite(aId, transactionId, aCompositeStart, aCompositeEnd);
-      layerTree->SetPendingTransactionId(0);
     }
   } else if (WebRenderBridgeParent* wrbridge = sIndirectLayerTrees[aId].mWrBridge) {
     uint64_t transactionId = wrbridge->FlushPendingTransactionIds();
     if (transactionId) {
       Unused << SendDidComposite(aId, transactionId, aCompositeStart, aCompositeEnd);
     }
   }
 }
--- a/gfx/layers/ipc/LayerTransactionParent.cpp
+++ b/gfx/layers/ipc/LayerTransactionParent.cpp
@@ -948,16 +948,38 @@ LayerTransactionParent::DeallocShmem(ipc
   PLayerTransactionParent::DeallocShmem(aShmem);
 }
 
 bool LayerTransactionParent::IsSameProcess() const
 {
   return OtherPid() == base::GetCurrentProcId();
 }
 
+uint64_t
+LayerTransactionParent::FlushTransactionId(TimeStamp& aCompositeEnd)
+{
+#if defined(ENABLE_FRAME_LATENCY_LOG)
+  if (mPendingTransaction) {
+    if (mTxnStartTime) {
+      uint32_t latencyMs = round((aCompositeEnd - mTxnStartTime).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());
+      printf_stderr("From forwarding transaction to end of generate frame latencyMs %d this %p\n", latencyMs, this);
+    }
+  }
+  mTxnStartTime = TimeStamp();
+  mFwdTime = TimeStamp();
+#endif
+  uint64_t id = mPendingTransaction;
+  mPendingTransaction = 0;
+  return id;
+}
+
 void
 LayerTransactionParent::SendAsyncMessage(const InfallibleTArray<AsyncParentMessageData>& aMessage)
 {
   MOZ_ASSERT_UNREACHABLE("unexpected to be called");
 }
 
 void
 LayerTransactionParent::SendPendingAsyncMessages()
--- a/gfx/layers/ipc/LayerTransactionParent.h
+++ b/gfx/layers/ipc/LayerTransactionParent.h
@@ -78,17 +78,23 @@ public:
                                 ipc::SharedMemory::SharedMemoryType aType,
                                 ipc::Shmem* aShmem) override;
 
   virtual void DeallocShmem(ipc::Shmem& aShmem) override;
 
   virtual bool IsSameProcess() const override;
 
   const uint64_t& GetPendingTransactionId() { return mPendingTransaction; }
-  void SetPendingTransactionId(uint64_t aId) { mPendingTransaction = aId; }
+  void SetPendingTransactionId(uint64_t aId, const TimeStamp& aTxnStartTime, const TimeStamp& aFwdTime)
+  {
+    mPendingTransaction = aId;
+    mTxnStartTime = aTxnStartTime;
+    mFwdTime = aFwdTime;
+  }
+  uint64_t FlushTransactionId(TimeStamp& aCompositeEnd);
 
   // CompositableParentManager
   virtual void SendAsyncMessage(const InfallibleTArray<AsyncParentMessageData>& aMessage) override;
 
   virtual void SendPendingAsyncMessages() override;
 
   virtual void SetAboutToSendAsyncMessages() override;
 
@@ -194,16 +200,18 @@ 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;
 
   uint64_t mPendingTransaction;
+  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
   // hasn't yet propagated back to the child side and it might still
   // send us layer transactions.  We want to ignore those transactions
--- a/gfx/layers/ipc/LayersMessages.ipdlh
+++ b/gfx/layers/ipc/LayersMessages.ipdlh
@@ -571,16 +571,17 @@ struct TransactionInfo
   TargetConfig targetConfig;
   PluginWindowData[] plugins;
   bool isFirstPaint;
   FocusTarget focusTarget;
   bool scheduleComposite;
   uint32_t paintSequenceNumber;
   bool isRepeatTransaction;
   TimeStamp transactionStart;
+  TimeStamp fwdTime;
 };
 
 union MaybeTransform {
   Matrix4x4;
   void_t;
 };
 
 } // namespace
--- a/gfx/layers/ipc/PWebRenderBridge.ipdl
+++ b/gfx/layers/ipc/PWebRenderBridge.ipdl
@@ -52,20 +52,20 @@ parent:
                    SurfaceFormat aFormat, ByteBuffer aBytes);
   async DeleteImage(ImageKey aImageKey);
   async DeleteCompositorAnimations(uint64_t[] aIds);
   async AddRawFont(FontKey aFontKey, ByteBuffer aBytes, uint32_t aFontIndex);
   async DeleteFont(FontKey aFontKey);
   async DPBegin(IntSize aSize);
   async DPEnd(IntSize aSize, WebRenderParentCommand[] commands, OpDestroy[] toDestroy, uint64_t fwdTransactionId, uint64_t transactionId,
               LayoutSize aContentSize, ByteBuffer aDL, BuiltDisplayListDescriptor aDLDesc,
-              WebRenderScrollData aScrollData, IdNamespace aIdNamespace, TimeStamp fwdTime);
+              WebRenderScrollData aScrollData, IdNamespace aIdNamespace, TimeStamp txnStartTime, TimeStamp fwdTime);
   sync DPSyncEnd(IntSize aSize, WebRenderParentCommand[] commands, OpDestroy[] toDestroy, uint64_t fwdTransactionId, uint64_t transactionId,
                  LayoutSize aContentSize, ByteBuffer aDL, BuiltDisplayListDescriptor aDLDesc,
-                 WebRenderScrollData aScrollData, IdNamespace aIdNamespace, TimeStamp fwdTime);
+                 WebRenderScrollData aScrollData, IdNamespace aIdNamespace, TimeStamp txnStartTime, TimeStamp fwdTime);
   async ParentCommands(WebRenderParentCommand[] commands);
   sync DPGetSnapshot(PTexture texture);
   async AddPipelineIdForCompositable(PipelineId aImageId, CompositableHandle aHandle, bool aAsync);
   async RemovePipelineIdForCompositable(PipelineId aPipelineId);
   async AddExternalImageIdForCompositable(ExternalImageId aImageId, CompositableHandle aHandle);
   async RemoveExternalImageId(ExternalImageId aImageId);
   async SetLayerObserverEpoch(uint64_t layerObserverEpoch);
   async ClearCachedResources();
--- a/gfx/layers/ipc/ShadowLayers.cpp
+++ b/gfx/layers/ipc/ShadowLayers.cpp
@@ -733,16 +733,19 @@ ShadowLayerForwarder::EndTransaction(con
   info.id() = aId;
   info.plugins() = mPluginWindowData;
   info.isFirstPaint() = mIsFirstPaint;
   info.focusTarget() = mFocusTarget;
   info.scheduleComposite() = aScheduleComposite;
   info.paintSequenceNumber() = aPaintSequenceNumber;
   info.isRepeatTransaction() = aIsRepeatTransaction;
   info.transactionStart() = aTransactionStart;
+#if defined(ENABLE_FRAME_LATENCY_LOG)
+  info.fwdTime() = TimeStamp::Now();
+#endif
 
   TargetConfig targetConfig(mTxn->mTargetBounds,
                             mTxn->mTargetRotation,
                             mTxn->mTargetOrientation,
                             aRegionToClear);
   info.targetConfig() = targetConfig;
 
   if (!GetTextureForwarder()->IsSameProcess()) {
--- a/gfx/layers/wr/WebRenderBridgeChild.cpp
+++ b/gfx/layers/wr/WebRenderBridgeChild.cpp
@@ -97,37 +97,38 @@ WebRenderBridgeChild::ClearReadLocks()
   mReadLocks.Clear();
 }
 
 void
 WebRenderBridgeChild::DPEnd(wr::DisplayListBuilder &aBuilder,
                             const gfx::IntSize& aSize,
                             bool aIsSync,
                             uint64_t aTransactionId,
-                            const WebRenderScrollData& aScrollData)
+                            const WebRenderScrollData& aScrollData,
+                            const mozilla::TimeStamp& aTxnStartTime)
 {
   MOZ_ASSERT(!mDestroyed);
   MOZ_ASSERT(mIsInTransaction);
 
   wr::BuiltDisplayList dl;
   wr::LayoutSize contentSize;
   aBuilder.Finalize(contentSize, dl);
   ByteBuffer dlData(Move(dl.dl));
 
   TimeStamp fwdTime;
 #if defined(ENABLE_FRAME_LATENCY_LOG)
   fwdTime = TimeStamp::Now();
 #endif
 
   if (aIsSync) {
     this->SendDPSyncEnd(aSize, mParentCommands, mDestroyedActors, GetFwdTransactionId(), aTransactionId,
-                        contentSize, dlData, dl.dl_desc, aScrollData, mIdNamespace, fwdTime);
+                        contentSize, dlData, dl.dl_desc, aScrollData, mIdNamespace, aTxnStartTime, fwdTime);
   } else {
     this->SendDPEnd(aSize, mParentCommands, mDestroyedActors, GetFwdTransactionId(), aTransactionId,
-                    contentSize, dlData, dl.dl_desc, aScrollData, mIdNamespace, fwdTime);
+                    contentSize, dlData, dl.dl_desc, aScrollData, mIdNamespace, aTxnStartTime, fwdTime);
   }
 
   mParentCommands.Clear();
   mDestroyedActors.Clear();
   mIsInTransaction = false;
 }
 
 void
--- a/gfx/layers/wr/WebRenderBridgeChild.h
+++ b/gfx/layers/wr/WebRenderBridgeChild.h
@@ -58,17 +58,18 @@ public:
   explicit WebRenderBridgeChild(const wr::PipelineId& aPipelineId);
 
   void AddWebRenderParentCommand(const WebRenderParentCommand& aCmd);
   void AddWebRenderParentCommands(const nsTArray<WebRenderParentCommand>& aCommands);
 
   bool DPBegin(const  gfx::IntSize& aSize);
   void DPEnd(wr::DisplayListBuilder &aBuilder, const gfx::IntSize& aSize,
              bool aIsSync, uint64_t aTransactionId,
-             const WebRenderScrollData& aScrollData);
+             const WebRenderScrollData& aScrollData,
+             const mozilla::TimeStamp& aTxnStartTime);
   void ProcessWebRenderParentCommands();
 
   CompositorBridgeChild* GetCompositorBridgeChild();
 
   wr::PipelineId GetPipeline() { return mPipelineId; }
 
   // KnowsCompositor
   TextureForwarder* GetTextureForwarder() override;
--- a/gfx/layers/wr/WebRenderBridgeParent.cpp
+++ b/gfx/layers/wr/WebRenderBridgeParent.cpp
@@ -400,16 +400,17 @@ WebRenderBridgeParent::HandleDPEnd(const
                                  InfallibleTArray<OpDestroy>&& aToDestroy,
                                  const uint64_t& aFwdTransactionId,
                                  const uint64_t& aTransactionId,
                                  const wr::LayoutSize& aContentSize,
                                  const wr::ByteBuffer& dl,
                                  const wr::BuiltDisplayListDescriptor& dlDesc,
                                  const WebRenderScrollData& aScrollData,
                                  const wr::IdNamespace& aIdNamespace,
+                                 const TimeStamp& aTxnStartTime,
                                  const TimeStamp& aFwdTime)
 {
   AutoProfilerTracing tracing("Paint", "DPTransaction");
   UpdateFwdTransactionId(aFwdTransactionId);
   AutoClearReadLocks clearLocks(mReadLocks);
 
   if (mDestroyed) {
     for (const auto& op : aToDestroy) {
@@ -419,17 +420,17 @@ WebRenderBridgeParent::HandleDPEnd(const
   }
   // This ensures that destroy operations are always processed. It is not safe
   // to early-return from RecvDPEnd without doing so.
   AutoWebRenderBridgeParentAsyncMessageSender autoAsyncMessageSender(this, &aToDestroy);
 
   uint32_t wrEpoch = GetNextWrEpoch();
   ProcessWebRenderCommands(aSize, aCommands, wr::NewEpoch(wrEpoch),
                            aContentSize, dl, dlDesc, aIdNamespace);
-  HoldPendingTransactionId(wrEpoch, aTransactionId, aFwdTime);
+  HoldPendingTransactionId(wrEpoch, aTransactionId, aTxnStartTime, aFwdTime);
 
   mScrollData = aScrollData;
   UpdateAPZ();
 
   if (mIdNamespace != aIdNamespace) {
     // Pretend we composited since someone is wating for this event,
     // though DisplayList was not pushed to webrender.
     TimeStamp now = TimeStamp::Now();
@@ -514,44 +515,46 @@ WebRenderBridgeParent::RecvDPEnd(const g
                                  InfallibleTArray<OpDestroy>&& aToDestroy,
                                  const uint64_t& aFwdTransactionId,
                                  const uint64_t& aTransactionId,
                                  const wr::LayoutSize& aContentSize,
                                  const wr::ByteBuffer& dl,
                                  const wr::BuiltDisplayListDescriptor& dlDesc,
                                  const WebRenderScrollData& aScrollData,
                                  const wr::IdNamespace& aIdNamespace,
+                                 const TimeStamp& aTxnStartTime,
                                  const TimeStamp& aFwdTime)
 {
   if (mDestroyed) {
     return IPC_OK();
   }
   HandleDPEnd(aSize, Move(aCommands), Move(aToDestroy), aFwdTransactionId, aTransactionId,
-              aContentSize, dl, dlDesc, aScrollData, aIdNamespace, aFwdTime);
+              aContentSize, dl, dlDesc, aScrollData, aIdNamespace, aTxnStartTime, aFwdTime);
   return IPC_OK();
 }
 
 mozilla::ipc::IPCResult
 WebRenderBridgeParent::RecvDPSyncEnd(const gfx::IntSize &aSize,
                                      InfallibleTArray<WebRenderParentCommand>&& aCommands,
                                      InfallibleTArray<OpDestroy>&& aToDestroy,
                                      const uint64_t& aFwdTransactionId,
                                      const uint64_t& aTransactionId,
                                      const wr::LayoutSize& aContentSize,
                                      const wr::ByteBuffer& dl,
                                      const wr::BuiltDisplayListDescriptor& dlDesc,
                                      const WebRenderScrollData& aScrollData,
                                      const wr::IdNamespace& aIdNamespace,
+                                     const TimeStamp& aTxnStartTime,
                                      const TimeStamp& aFwdTime)
 {
   if (mDestroyed) {
     return IPC_OK();
   }
   HandleDPEnd(aSize, Move(aCommands), Move(aToDestroy), aFwdTransactionId, aTransactionId,
-              aContentSize, dl, dlDesc, aScrollData, aIdNamespace, aFwdTime);
+              aContentSize, dl, dlDesc, aScrollData, aIdNamespace, aTxnStartTime, aFwdTime);
   return IPC_OK();
 }
 
 mozilla::ipc::IPCResult
 WebRenderBridgeParent::RecvParentCommands(nsTArray<WebRenderParentCommand>&& aCommands)
 {
   if (mDestroyed) {
     return IPC_OK();
@@ -1145,27 +1148,30 @@ WebRenderBridgeParent::CompositeToTarget
   }
 
   if (scheduleComposite) {
     ScheduleComposition();
   }
 }
 
 void
-WebRenderBridgeParent::HoldPendingTransactionId(uint32_t aWrEpoch, uint64_t aTransactionId, const TimeStamp& aFwdTime)
+WebRenderBridgeParent::HoldPendingTransactionId(uint32_t aWrEpoch,
+                                                uint64_t aTransactionId,
+                                                const TimeStamp& aTxnStartTime,
+                                                const TimeStamp& aFwdTime)
 {
   // 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(aTransactionId == 1 || aTransactionId > LastPendingTransactionId());
   // Handle TransactionIdAllocator(RefreshDriver) change.
   if (aTransactionId == 1) {
     FlushPendingTransactionIds();
   }
-  mPendingTransactionIds.push(PendingTransactionId(wr::NewEpoch(aWrEpoch), aTransactionId, aFwdTime));
+  mPendingTransactionIds.push(PendingTransactionId(wr::NewEpoch(aWrEpoch), aTransactionId, aTxnStartTime, aFwdTime));
 }
 
 uint64_t
 WebRenderBridgeParent::LastPendingTransactionId()
 {
   uint64_t id = 0;
   if (!mPendingTransactionIds.empty()) {
     id = mPendingTransactionIds.back().mId;
@@ -1190,22 +1196,25 @@ WebRenderBridgeParent::FlushTransactionI
   uint64_t id = 0;
   while (!mPendingTransactionIds.empty()) {
     int64_t diff =
       static_cast<int64_t>(aEpoch.mHandle) - static_cast<int64_t>(mPendingTransactionIds.front().mEpoch.mHandle);
     if (diff < 0) {
       break;
     }
 #if defined(ENABLE_FRAME_LATENCY_LOG)
+    if (mPendingTransactionIds.front().mTxnStartTime) {
+      uint32_t latencyMs = round((aEndTime - mPendingTransactionIds.front().mTxnStartTime).ToMilliseconds());
+      printf_stderr("From transaction start to end of generate frame latencyMs %d this %p\n", latencyMs, this);
+    }
     if (mPendingTransactionIds.front().mFwdTime) {
       uint32_t latencyMs = round((aEndTime - mPendingTransactionIds.front().mFwdTime).ToMilliseconds());
-      printf_stderr("From EndTransaction to end of generate frame latencyMs %d this %p\n", latencyMs, this);
+      printf_stderr("From forwarding transaction to end of generate frame latencyMs %d this %p\n", latencyMs, this);
     }
 #endif
-
     id = mPendingTransactionIds.front().mId;
     mPendingTransactionIds.pop();
     if (diff == 0) {
       break;
     }
   }
   return id;
 }
--- a/gfx/layers/wr/WebRenderBridgeParent.h
+++ b/gfx/layers/wr/WebRenderBridgeParent.h
@@ -98,27 +98,29 @@ public:
                                     InfallibleTArray<OpDestroy>&& aToDestroy,
                                     const uint64_t& aFwdTransactionId,
                                     const uint64_t& aTransactionId,
                                     const wr::LayoutSize& aContentSize,
                                     const wr::ByteBuffer& dl,
                                     const wr::BuiltDisplayListDescriptor& dlDesc,
                                     const WebRenderScrollData& aScrollData,
                                     const wr::IdNamespace& aIdNamespace,
+                                    const TimeStamp& aTxnStartTime,
                                     const TimeStamp& aFwdTime) override;
   mozilla::ipc::IPCResult RecvDPSyncEnd(const gfx::IntSize& aSize,
                                         InfallibleTArray<WebRenderParentCommand>&& aCommands,
                                         InfallibleTArray<OpDestroy>&& aToDestroy,
                                         const uint64_t& aFwdTransactionId,
                                         const uint64_t& aTransactionId,
                                         const wr::LayoutSize& aContentSize,
                                         const wr::ByteBuffer& dl,
                                         const wr::BuiltDisplayListDescriptor& dlDesc,
                                         const WebRenderScrollData& aScrollData,
                                         const wr::IdNamespace& aIdNamespace,
+                                        const TimeStamp& aTxnStartTime,
                                         const TimeStamp& aFwdTime) override;
   mozilla::ipc::IPCResult RecvParentCommands(nsTArray<WebRenderParentCommand>&& commands) override;
   mozilla::ipc::IPCResult RecvDPGetSnapshot(PTextureParent* aTexture) override;
 
   mozilla::ipc::IPCResult RecvAddPipelineIdForCompositable(const wr::PipelineId& aPipelineIds,
                                                            const CompositableHandle& aHandle,
                                                            const bool& aAsync) override;
   mozilla::ipc::IPCResult RecvRemovePipelineIdForCompositable(const wr::PipelineId& aPipelineId) override;
@@ -165,17 +167,17 @@ public:
   // CompositableParentManager
   bool IsSameProcess() const override;
   base::ProcessId GetChildProcessId() override;
   void NotifyNotUsed(PTextureParent* aTexture, uint64_t aTransactionId) override;
   void SendAsyncMessage(const InfallibleTArray<AsyncParentMessageData>& aMessage) override;
   void SendPendingAsyncMessages() override;
   void SetAboutToSendAsyncMessages() override;
 
-  void HoldPendingTransactionId(uint32_t aWrEpoch, uint64_t aTransactionId, const TimeStamp& aFwdTime);
+  void HoldPendingTransactionId(uint32_t aWrEpoch, uint64_t aTransactionId, const TimeStamp& aTxnStartTime, const TimeStamp& aFwdTime);
   uint64_t LastPendingTransactionId();
   uint64_t FlushPendingTransactionIds();
   uint64_t FlushTransactionIdsForEpoch(const wr::Epoch& aEpoch, const TimeStamp& aEndTime);
 
   TextureFactoryIdentifier GetTextureFactoryIdentifier();
 
   void ExtractImageCompositeNotifications(nsTArray<ImageCompositeNotificationInfo>* aNotifications);
 
@@ -218,16 +220,17 @@ private:
                    InfallibleTArray<OpDestroy>&& aToDestroy,
                    const uint64_t& aFwdTransactionId,
                    const uint64_t& aTransactionId,
                    const wr::LayoutSize& aContentSize,
                    const wr::ByteBuffer& dl,
                    const wr::BuiltDisplayListDescriptor& dlDesc,
                    const WebRenderScrollData& aScrollData,
                    const wr::IdNamespace& aIdNamespace,
+                   const TimeStamp& aTxnStartTime,
                    const TimeStamp& aFwdTime);
   mozilla::ipc::IPCResult HandleShutdown();
 
   void AdvanceAnimations();
   void SampleAnimations(nsTArray<wr::WrOpacityProperty>& aOpacityArray,
                         nsTArray<wr::WrTransformProperty>& aTransformArray);
 
   CompositorBridgeParent* GetRootCompositorBridgeParent() const;
@@ -241,23 +244,25 @@ private:
   // Helper method to get an APZC reference from a scroll id. Uses the layers
   // id of this bridge, and may return null if the APZC wasn't found.
   already_AddRefed<AsyncPanZoomController> GetTargetAPZC(const FrameMetrics::ViewID& aId);
 
   uint32_t GetNextWrEpoch();
 
 private:
   struct PendingTransactionId {
-    PendingTransactionId(wr::Epoch aEpoch, uint64_t aId, const TimeStamp& aFwdTime)
+    PendingTransactionId(wr::Epoch aEpoch, uint64_t aId, const TimeStamp& aTxnStartTime, const TimeStamp& aFwdTime)
       : mEpoch(aEpoch)
       , mId(aId)
+      , mTxnStartTime(aTxnStartTime)
       , mFwdTime(aFwdTime)
     {}
     wr::Epoch mEpoch;
     uint64_t mId;
+    TimeStamp mTxnStartTime;
     TimeStamp mFwdTime;
   };
 
   CompositorBridgeParentBase* MOZ_NON_OWNING_REF mCompositorBridge;
   wr::PipelineId mPipelineId;
   RefPtr<widget::CompositorWidget> mWidget;
   RefPtr<wr::WebRenderAPI> mApi;
   RefPtr<AsyncImagePipelineManager> mAsyncImageManager;
--- a/gfx/layers/wr/WebRenderLayerManager.cpp
+++ b/gfx/layers/wr/WebRenderLayerManager.cpp
@@ -672,29 +672,30 @@ WebRenderLayerManager::EndTransactionInt
       mScrollData.SetIsFirstPaint();
       mIsFirstPaint = false;
     }
     mScrollData.SetPaintSequenceNumber(mPaintSequenceNumber);
   }
 
   bool sync = mTarget != nullptr;
   mLatestTransactionId = mTransactionIdAllocator->GetTransactionId(/*aThrottle*/ true);
+  TimeStamp transactionStart = mTransactionIdAllocator->GetTransactionStart();
 
   // Skip the synchronization for buffer since we also skip the painting during
   // device-reset status.
   if (!gfxPlatform::GetPlatform()->DidRenderingDeviceReset()) {
     if (WrBridge()->GetSyncObject() &&
         WrBridge()->GetSyncObject()->IsSyncObjectValid()) {
       WrBridge()->GetSyncObject()->Synchronize();
     }
   }
   {
     AutoProfilerTracing
       tracing("Paint", sync ? "ForwardDPTransactionSync":"ForwardDPTransaction");
-    WrBridge()->DPEnd(builder, size.ToUnknownSize(), sync, mLatestTransactionId, mScrollData);
+    WrBridge()->DPEnd(builder, size.ToUnknownSize(), sync, mLatestTransactionId, mScrollData, transactionStart);
   }
 
   MakeSnapshotIfRequired(size);
   mNeedsComposite = false;
 
   ClearDisplayItemLayers();
 
   // this may result in Layers being deleted, which results in
--- a/gfx/webrender_bindings/RendererOGL.cpp
+++ b/gfx/webrender_bindings/RendererOGL.cpp
@@ -4,16 +4,17 @@
  * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
 
 #include "RendererOGL.h"
 #include "GLContext.h"
 #include "GLContextProvider.h"
 #include "mozilla/gfx/Logging.h"
 #include "mozilla/layers/CompositorBridgeParent.h"
 #include "mozilla/layers/CompositorThread.h"
+#include "mozilla/layers/LayersTypes.h"
 #include "mozilla/webrender/RenderBufferTextureHost.h"
 #include "mozilla/webrender/RenderTextureHostOGL.h"
 #include "mozilla/widget/CompositorWidget.h"
 
 namespace mozilla {
 namespace wr {
 
 wr::WrExternalImage LockExternalImage(void* aObj, wr::WrExternalImageId aId, uint8_t aChannelIndex)
--- a/gfx/webrender_bindings/WebRenderTypes.h
+++ b/gfx/webrender_bindings/WebRenderTypes.h
@@ -12,18 +12,16 @@
 #include "mozilla/gfx/Types.h"
 #include "mozilla/gfx/Tools.h"
 #include "mozilla/layers/LayersTypes.h"
 #include "mozilla/Range.h"
 #include "Units.h"
 #include "RoundedRect.h"
 #include "nsStyleConsts.h"
 
-//#define ENABLE_FRAME_LATENCY_LOG
-
 namespace mozilla {
 namespace wr {
 
 typedef wr::WrWindowId WindowId;
 typedef wr::WrPipelineId PipelineId;
 typedef wr::WrImageKey ImageKey;
 typedef wr::WrFontKey FontKey;
 typedef wr::WrEpoch Epoch;