Collect diagnostics on paint times for the compositor overlay. (bug 1352151 part 1, r=mattwoodrow)

--HG--
extra : rebase_source : f30dc11079add3f1019777b1c85cc5c5a5f0596b

gfx/layers/client/ClientLayerManager.cpp

@@ -316,6 +316,11 @@ ClientLayerManager::EndTransactionInternal(DrawPaintedLayerCallback aCallback,
   PaintTelemetry::AutoRecord record(PaintTelemetry::Metric::Rasterization);
   GeckoProfilerTracingRAII tracer("Paint", "Rasterize");
 
+  Maybe<TimeStamp> startTime;
+  if (gfxPrefs::LayersDrawFPS()) {
+    startTime = Some(TimeStamp::Now());
+  }
+
 #ifdef WIN32
   if (aCallbackData) {
     // Content processes don't get OnPaint called. So update here whenever we
@@ -384,6 +389,11 @@ ClientLayerManager::EndTransactionInternal(DrawPaintedLayerCallback aCallback,
     FrameLayerBuilder::InvalidateAllLayers(this);
   }
 
+  if (startTime) {
+    PaintTiming& pt = mForwarder->GetPaintTiming();
+    pt.rasterMs() = (TimeStamp::Now() - startTime.value()).ToMilliseconds();
+  }
+
   return !mTransactionIncomplete;
 }
 

gfx/layers/client/ClientLayerManager.h

@@ -240,6 +240,16 @@ public:
   virtual already_AddRefed<PersistentBufferProvider>
   CreatePersistentBufferProvider(const gfx::IntSize& aSize, gfx::SurfaceFormat aFormat) override;
 
+  static PaintTiming* MaybeGetPaintTiming(LayerManager* aManager) {
+    if (!aManager) {
+      return nullptr;
+    }
+    if (ClientLayerManager* lm = aManager->AsClientLayerManager()) {
+      return &lm->AsShadowForwarder()->GetPaintTiming();
+    }
+    return nullptr;
+  }
+
 protected:
   enum TransactionPhase {
     PHASE_NONE, PHASE_CONSTRUCTION, PHASE_DRAWING, PHASE_FORWARD

gfx/layers/composite/Diagnostics.cpp

@@ -0,0 +1,81 @@
+/* -*- Mode: C++; tab-width: 20; indent-tabs-mode: nil; c-basic-offset: 2 -*-
+ * This Source Code Form is subject to the terms of the Mozilla Public
+ * License, v. 2.0. If a copy of the MPL was not distributed with this
+ * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
+
+#include "Diagnostics.h"
+#include "mozilla/layers/LayersMessages.h"
+#include "nsPrintfCString.h"
+
+namespace mozilla {
+namespace layers {
+
+float
+TimedMetric::Average() const
+{
+  // We take at most 2 seconds of history.
+  TimeStamp latest = TimeStamp::Now();
+  float total = 0.0f;
+  size_t count = 0;
+  for (auto iter = mHistory.rbegin(); iter != mHistory.rend(); iter++) {
+    if ((latest - iter->second).ToSeconds() > 2.0f) {
+      break;
+    }
+    total += iter->first;
+    count++;
+  }
+
+  if (!count) {
+    return 0.0f;
+  }
+  return total / float(count);
+}
+
+Diagnostics::Diagnostics()
+ : mCompositeFps("Compositor"),
+   mTransactionFps("LayerTransactions")
+{
+}
+
+void
+Diagnostics::RecordPaintTimes(const PaintTiming& aPaintTimes)
+{
+  mDlbMs.Add(aPaintTimes.dlMs());
+  mFlbMs.Add(aPaintTimes.flbMs());
+  mRasterMs.Add(aPaintTimes.rasterMs());
+  mSerializeMs.Add(aPaintTimes.serializeMs());
+  mSendMs.Add(aPaintTimes.sendMs());
+}
+
+std::string
+Diagnostics::GetFrameOverlayString()
+{
+  TimeStamp now = TimeStamp::Now();
+  unsigned fps = unsigned(mCompositeFps.AddFrameAndGetFps(now));
+  unsigned txnFps = unsigned(mTransactionFps.GetFPS(now));
+
+  // DL  = nsDisplayListBuilder
+  // FLB = FrameLayerBuilder
+  // R   = ClientLayerManager::EndTransaction
+  // CP  = ShadowLayerForwarder::EndTransaction (txn build)
+  // TX  = LayerTransactionChild::SendUpdate (IPDL serialize+send)
+  // UP  = LayerTransactionParent::RecvUpdate (IPDL deserialize, update, APZ update)
+  // CC_BUILD = Container prepare/composite frame building
+  // CC_EXEC  = Container render/composite drawing
+  nsPrintfCString line1("FPS: %d (TXN: %d)", fps, txnFps);
+  nsPrintfCString line2("CC_BUILD: %0.1f CC_EXEC: %0.1f",
+    mPrepareMs.Average(),
+    mCompositeMs.Average());
+  nsPrintfCString line3("DL: %0.1f FLB: %0.1f R: %0.1f CP: %0.1f TX: %0.1f UP: %0.1f",
+    mDlbMs.Average(),
+    mFlbMs.Average(),
+    mRasterMs.Average(),
+    mSerializeMs.Average(),
+    mSendMs.Average(),
+    mUpdateMs.Average());
+
+  return std::string(line1.get()) + ", " + std::string(line2.get()) + "\n" + std::string(line3.get());
+}
+
+} // namespace layers
+} // namespace mozilla

gfx/layers/composite/Diagnostics.h

@@ -0,0 +1,96 @@
+/* -*- Mode: C++; tab-width: 20; indent-tabs-mode: nil; c-basic-offset: 2 -*-
+ * This Source Code Form is subject to the terms of the Mozilla Public
+ * License, v. 2.0. If a copy of the MPL was not distributed with this
+ * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
+
+#ifndef mozilla_gfx_layers_composite_Diagnostics_h
+#define mozilla_gfx_layers_composite_Diagnostics_h
+
+#include "FPSCounter.h"
+#include "gfxPrefs.h"
+#include "mozilla/TimeStamp.h"
+#include <deque>
+#include <string>
+#include <utility>
+
+namespace mozilla {
+namespace layers {
+
+class PaintTiming;
+
+class TimedMetric
+{
+  typedef std::pair<float, TimeStamp> Entry;
+
+public:
+  void Add(float aValue) {
+    if (mHistory.size() > kMaxHistory) {
+      mHistory.pop_front();
+    }
+    mHistory.push_back(Entry(aValue, TimeStamp::Now()));
+  }
+
+  float Average() const;
+
+private:
+  static const size_t kMaxHistory = 60;
+
+  std::deque<Entry> mHistory;
+};
+
+class Diagnostics
+{
+public:
+  Diagnostics();
+
+  void RecordPaintTimes(const PaintTiming& aPaintTimes);
+  void RecordUpdateTime(float aValue) {
+    mUpdateMs.Add(aValue);
+  }
+  void RecordPrepareTime(float aValue) {
+    mPrepareMs.Add(aValue);
+  }
+  void RecordCompositeTime(float aValue) {
+    mCompositeMs.Add(aValue);
+  }
+  void AddTxnFrame() {
+    mTransactionFps.AddFrame(TimeStamp::Now());
+  }
+
+  std::string GetFrameOverlayString();
+
+  class Record {
+  public:
+    Record() {
+      if (gfxPrefs::LayersDrawFPS()) {
+        mStart = TimeStamp::Now();
+      }
+    }
+    bool Recording() const {
+      return !mStart.IsNull();
+    }
+    float Duration() const {
+      return (TimeStamp::Now() - mStart).ToMilliseconds();
+    }
+
+  private:
+    TimeStamp mStart;
+  };
+
+private:
+  FPSCounter mCompositeFps;
+  FPSCounter mTransactionFps;
+  TimedMetric mDlbMs;
+  TimedMetric mFlbMs;
+  TimedMetric mRasterMs;
+  TimedMetric mSerializeMs;
+  TimedMetric mSendMs;
+  TimedMetric mUpdateMs;
+  TimedMetric mPrepareMs;
+  TimedMetric mCompositeMs;
+};
+
+} // namespace layers
+} // namespace mozilla
+
+#endif // mozilla_gfx_layers_composite_Diagnostics_h

gfx/layers/composite/LayerManagerComposite.cpp

@@ -10,6 +10,7 @@
 #include "ColorLayerComposite.h"        // for ColorLayerComposite
 #include "CompositableHost.h"           // for CompositableHost
 #include "ContainerLayerComposite.h"    // for ContainerLayerComposite, etc
+#include "Diagnostics.h"
 #include "FPSCounter.h"                 // for FPSState, FPSCounter
 #include "FrameMetrics.h"               // for FrameMetrics
 #include "GeckoProfiler.h"              // for profiler_set_frame_number, etc
@@ -124,6 +125,19 @@ HostLayerManager::HostLayerManager()
 HostLayerManager::~HostLayerManager()
 {}
 
+void
+HostLayerManager::RecordPaintTimes(const PaintTiming& aTiming)
+{
+  mDiagnostics->RecordPaintTimes(aTiming);
+}
+
+void
+HostLayerManager::RecordUpdateTime(float aValue)
+{
+  mDiagnostics->RecordUpdateTime(aValue);
+}
+
+
 /**
  * LayerManagerComposite
  */
@@ -136,6 +150,7 @@ LayerManagerComposite::LayerManagerComposite(Compositor* aCompositor)
 , mGeometryChanged(true)
 {
   mTextRenderer = new TextRenderer(aCompositor);
+  mDiagnostics = MakeUnique<Diagnostics>();
   MOZ_ASSERT(aCompositor);
 
 #ifdef USE_SKIA
@@ -925,8 +940,21 @@ LayerManagerComposite::Render(const nsIntRegion& aInvalidRegion, const nsIntRegi
   }
 
   // Render our layers.
-  RootLayer()->Prepare(ViewAs<RenderTargetPixel>(clipRect, PixelCastJustification::RenderTargetIsParentLayerForRoot));
-  RootLayer()->RenderLayer(clipRect.ToUnknownRect(), Nothing());
+  {
+    Diagnostics::Record record;
+    RootLayer()->Prepare(ViewAs<RenderTargetPixel>(clipRect, PixelCastJustification::RenderTargetIsParentLayerForRoot));
+    if (record.Recording()) {
+      mDiagnostics->RecordPrepareTime(record.Duration());
+    }
+  }
+  // Execute draw commands.
+  {
+    Diagnostics::Record record;
+    RootLayer()->RenderLayer(clipRect.ToUnknownRect(), Nothing());
+    if (record.Recording()) {
+      mDiagnostics->RecordCompositeTime(record.Duration());
+    }
+  }
   RootLayer()->Cleanup();
 
   if (!mRegionToClear.IsEmpty()) {

gfx/layers/composite/LayerManagerComposite.h

@@ -52,6 +52,7 @@ class CanvasLayerComposite;
 class ColorLayerComposite;
 class Compositor;
 class ContainerLayerComposite;
+class Diagnostics;
 struct EffectChain;
 class ImageLayer;
 class ImageLayerComposite;
@@ -169,6 +170,9 @@ public:
     return false;
   }
 
+  void RecordPaintTimes(const PaintTiming& aTiming);
+  void RecordUpdateTime(float aValue);
+
   TimeStamp GetCompositionTime() const {
     return mCompositionTime;
   }
@@ -196,6 +200,7 @@ protected:
   // true if the last frame was deemed 'too complicated' to be rendered.
   float mWarningLevel;
   mozilla::TimeStamp mWarnTime;
+  UniquePtr<Diagnostics> mDiagnostics;
 
   bool mWindowOverlayChanged;
   TimeDuration mLastPaintTime;

gfx/layers/ipc/CompositorBridgeParent.h

@@ -147,6 +147,10 @@ public:
                            uint32_t aApzcId) override;
   bool StopSharingMetrics(FrameMetrics::ViewID aScrollId,
                           uint32_t aApzcId) override;
+
+  virtual bool IsRemote() const {
+    return false;
+  }
 };
 
 class CompositorBridgeParent final : public CompositorBridgeParentBase

gfx/layers/ipc/CrossProcessCompositorBridgeParent.h

@@ -161,6 +161,10 @@ public:
 
   void ObserveLayerUpdate(uint64_t aLayersId, uint64_t aEpoch, bool aActive) override;
 
+  bool IsRemote() const override {
+    return true;
+  }
+
 protected:
   void OnChannelConnected(int32_t pid) override {
     mCompositorThreadHolder = CompositorThreadHolder::GetSingleton();

gfx/layers/ipc/LayerTransactionParent.cpp

@@ -149,9 +149,7 @@ LayerTransactionParent::RecvUpdate(const TransactionInfo& aInfo)
   PROFILER_LABEL("LayerTransactionParent", "RecvUpdate",
     js::ProfileEntry::Category::GRAPHICS);
 
-#ifdef COMPOSITOR_PERFORMANCE_WARNING
   TimeStamp updateStart = TimeStamp::Now();
-#endif
 
   MOZ_LAYERS_LOG(("[ParentSide] received txn with %" PRIuSIZE " edits", aInfo.cset().Length()));
 
@@ -506,6 +504,8 @@ LayerTransactionParent::RecvUpdate(const TransactionInfo& aInfo)
                     OtherPid(),
                     latency.ToMilliseconds());
     }
+
+    mLayerManager->RecordUpdateTime((TimeStamp::Now() - updateStart).ToMilliseconds());
   }
 
   return IPC_OK();
@@ -1026,5 +1026,17 @@ LayerTransactionParent::RecvReleaseCompositable(const CompositableHandle& aHandl
   return IPC_OK();
 }
 
+mozilla::ipc::IPCResult
+LayerTransactionParent::RecvRecordPaintTimes(const PaintTiming& aTiming)
+{
+  // Currently we only add paint timings for remote layers. In the future
+  // we could be smarter and use paint timings from the UI process, either
+  // as a separate overlay or if no remote layers are attached.
+  if (mLayerManager && mCompositorBridge->IsRemote()) {
+    mLayerManager->RecordPaintTimes(aTiming);
+  }
+  return IPC_OK();
+}
+
 } // namespace layers
 } // namespace mozilla

gfx/layers/ipc/LayerTransactionParent.h

@@ -140,6 +140,7 @@ protected:
   virtual mozilla::ipc::IPCResult RecvRequestProperty(const nsString& aProperty, float* aValue) override;
   virtual mozilla::ipc::IPCResult RecvSetConfirmedTargetAPZC(const uint64_t& aBlockId,
                                                              nsTArray<ScrollableLayerGuid>&& aTargets) override;
+  virtual mozilla::ipc::IPCResult RecvRecordPaintTimes(const PaintTiming& aTiming) override;
 
   bool SetLayerAttributes(const OpSetLayerAttributes& aOp);
 

gfx/layers/ipc/LayersMessages.ipdlh

@@ -534,6 +534,14 @@ union AsyncParentMessageData {
   OpNotifyNotUsed;
 };
 
+struct PaintTiming {
+  float serializeMs;
+  float sendMs;
+  float dlMs;
+  float flbMs;
+  float rasterMs;
+};
+
 struct TransactionInfo
 {
   Edit[] cset;

gfx/layers/ipc/PLayerTransaction.ipdl

@@ -122,6 +122,8 @@ parent:
   // input event.
   async SetConfirmedTargetAPZC(uint64_t aInputBlockId, ScrollableLayerGuid[] aTargets);
 
+  async RecordPaintTimes(PaintTiming timing);
+
   async Shutdown();
 child:
   async __delete__();

gfx/layers/ipc/ShadowLayers.cpp

@@ -15,6 +15,7 @@
 #include "RenderTrace.h"                // for RenderTraceScope
 #include "gfx2DGlue.h"                  // for Moz2D transition helpers
 #include "gfxPlatform.h"                // for gfxImageFormat, gfxPlatform
+#include "gfxPrefs.h"
 //#include "gfxSharedImageSurface.h"      // for gfxSharedImageSurface
 #include "ipc/IPCMessageUtils.h"        // for gfxContentType, null_t
 #include "IPDLActor.h"
@@ -586,6 +587,11 @@ ShadowLayerForwarder::EndTransaction(const nsIntRegion& aRegionToClear,
     return false;
   }
 
+  Maybe<TimeStamp> startTime;
+  if (gfxPrefs::LayersDrawFPS()) {
+    startTime = Some(TimeStamp::Now());
+  }
+
   GetCompositorBridgeChild()->WillEndTransaction();
 
   MOZ_ASSERT(aId);
@@ -724,6 +730,11 @@ ShadowLayerForwarder::EndTransaction(const nsIntRegion& aRegionToClear,
     PlatformSyncBeforeUpdate();
   }
 
+  if (startTime) {
+    mPaintTiming.serializeMs() = (TimeStamp::Now() - startTime.value()).ToMilliseconds();
+    startTime = Some(TimeStamp::Now());
+  }
+
   for (ReadLockVector& locks : mTxn->mReadLocks) {
     if (locks.Length()) {
       if (!mShadowManager->SendInitReadLocks(locks)) {
@@ -740,6 +751,11 @@ ShadowLayerForwarder::EndTransaction(const nsIntRegion& aRegionToClear,
     return false;
   }
 
+  if (startTime) {
+    mPaintTiming.sendMs() = (TimeStamp::Now() - startTime.value()).ToMilliseconds();
+    mShadowManager->SendRecordPaintTimes(mPaintTiming);
+  }
+
   *aSent = true;
   mIsFirstPaint = false;
   mPaintSyncId = 0;

gfx/layers/ipc/ShadowLayers.h

@@ -392,6 +392,10 @@ public:
     return NS_IsMainThread();
   }
 
+  PaintTiming& GetPaintTiming() {
+    return mPaintTiming;
+  }
+
   // Returns true if aSurface wraps a Shmem.
   static bool IsShmem(SurfaceDescriptor* aSurface);
 
@@ -442,6 +446,7 @@ private:
   UniquePtr<ActiveResourceTracker> mActiveResourceTracker;
   uint64_t mNextLayerHandle;
   nsDataHashtable<nsUint64HashKey, CompositableClient*> mCompositables;
+  PaintTiming mPaintTiming;
 };
 
 class CompositableClient;

gfx/layers/moz.build

@@ -316,6 +316,7 @@ UNIFIED_SOURCES += [
     'composite/CompositableHost.cpp',
     'composite/ContainerLayerComposite.cpp',
     'composite/ContentHost.cpp',
+    'composite/Diagnostics.cpp',
     'composite/FPSCounter.cpp',
     'composite/FrameUniformityData.cpp',
     'composite/GPUVideoTextureHost.cpp',

layout/base/nsLayoutUtils.cpp

@@ -3672,6 +3672,14 @@ nsLayoutUtils::PaintFrame(nsRenderingContext* aRenderingContext, nsIFrame* aFram
     }
 
     builder.LeavePresShell(aFrame, &list);
+
+    if (!record.GetStart().IsNull() && gfxPrefs::LayersDrawFPS()) {
+      if (RefPtr<LayerManager> lm = builder.GetWidgetLayerManager()) {
+        if (PaintTiming* pt = ClientLayerManager::MaybeGetPaintTiming(lm)) {
+          pt->dlMs() = (TimeStamp::Now() - record.GetStart()).ToMilliseconds();
+        }
+      }
+    }
   }
 
   Telemetry::AccumulateTimeDelta(Telemetry::PAINT_BUILD_DISPLAYLIST_TIME,

layout/painting/nsDisplayList.cpp

@@ -83,6 +83,7 @@
 #include "nsCSSProps.h"
 #include "nsPluginFrame.h"
 #include "nsSVGMaskFrame.h"
+#include "ClientLayerManager.h"
 #include "mozilla/layers/WebRenderBridgeChild.h"
 #include "mozilla/layers/WebRenderLayerManager.h"
 #include "mozilla/layers/WebRenderDisplayItemLayer.h"
@@ -2115,9 +2116,16 @@ already_AddRefed<LayerManager> nsDisplayList::PaintRoot(nsDisplayListBuilder* aB
 
     {
       PaintTelemetry::AutoRecord record(PaintTelemetry::Metric::Layerization);
+
       root = layerBuilder->
         BuildContainerLayerFor(aBuilder, layerManager, frame, nullptr, this,
                                containerParameters, nullptr);
+
+      if (!record.GetStart().IsNull() && gfxPrefs::LayersDrawFPS()) {
+        if (PaintTiming* pt = ClientLayerManager::MaybeGetPaintTiming(layerManager)) {
+          pt->flbMs() = (TimeStamp::Now() - record.GetStart()).ToMilliseconds();
+        }
+      }
     }
 
     if (!root) {

layout/painting/nsDisplayList.h

@@ -4922,6 +4922,10 @@ class PaintTelemetry
    public:
     explicit AutoRecord(Metric aMetric);
     ~AutoRecord();
+
+    TimeStamp GetStart() const {
+      return mStart;
+    }
    private:
     Metric mMetric;
     mozilla::TimeStamp mStart;