Bug 1505858. Record full paint time before waiting for composite in telemetry. r=mattwoodrow
authorJeff Muizelaar <jrmuizel@gmail.com>
Fri, 16 Nov 2018 05:26:10 +0000
changeset 503163 236208271581e0605523c1f2121671a7c9931674
parent 503162 4ae022f59b1227d16bdf67bc7c46661ff1441e18
child 503164 9135ee87f8d9cc7b6257ca3d84976d433200f600
push id10290
push userffxbld-merge
push dateMon, 03 Dec 2018 16:23:23 +0000
treeherdermozilla-beta@700bed2445e6 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersmattwoodrow
bugs1505858
milestone65.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 1505858. Record full paint time before waiting for composite in telemetry. r=mattwoodrow Differential Revision: https://phabricator.services.mozilla.com/D11953
gfx/layers/ipc/CrossProcessCompositorBridgeParent.cpp
gfx/layers/wr/WebRenderBridgeParent.cpp
toolkit/components/telemetry/Histograms.json
--- a/gfx/layers/ipc/CrossProcessCompositorBridgeParent.cpp
+++ b/gfx/layers/ipc/CrossProcessCompositorBridgeParent.cpp
@@ -362,16 +362,36 @@ 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->SendObserveLayersUpdate(id, aLayerTree->GetChildEpoch(), true);
   }
 
+  auto endTime = TimeStamp::Now();
+#ifdef MOZ_GECKO_PROFILER
+  if (profiler_is_active()) {
+    class ContentBuildPayload : public ProfilerMarkerPayload {
+      public:
+        ContentBuildPayload(const mozilla::TimeStamp& aStartTime, const mozilla::TimeStamp& aEndTime)
+          : ProfilerMarkerPayload(aStartTime, aEndTime)
+        {}
+        virtual void StreamPayload(SpliceableJSONWriter& aWriter, const TimeStamp& aProcessStartTime, UniqueStacks& aUniqueStacks) override {
+          StreamCommonProps("CONTENT_FULL_PAINT_TIME", aWriter, aProcessStartTime, aUniqueStacks);
+        }
+    };
+    profiler_add_marker_for_thread(profiler_current_thread_id(), "CONTENT_FULL_PAINT_TIME", MakeUnique<ContentBuildPayload>(aInfo.transactionStart(),
+                                                                                                                       endTime));
+  }
+#endif
+  Telemetry::Accumulate(Telemetry::CONTENT_FULL_PAINT_TIME,
+                        static_cast<uint32_t>((endTime - aInfo.transactionStart()).ToMilliseconds()));
+
+
   aLayerTree->SetPendingTransactionId(aInfo.id(), aInfo.refreshStart(), aInfo.transactionStart(), aInfo.fwdTime());
 }
 
 void
 CrossProcessCompositorBridgeParent::DidComposite(
   LayersId aId,
   TimeStamp& aCompositeStart,
   TimeStamp& aCompositeEnd)
--- a/gfx/layers/wr/WebRenderBridgeParent.cpp
+++ b/gfx/layers/wr/WebRenderBridgeParent.cpp
@@ -192,16 +192,62 @@ public:
   }
 protected:
   RefPtr<CompositorBridgeParentBase> mBridge;
   LayersId mLayersId;
   LayersObserverEpoch mObserverEpoch;
   bool mIsActive;
 };
 
+class SceneBuiltNotification: public wr::NotificationHandler {
+public:
+  explicit SceneBuiltNotification(TimeStamp aTxnStartTime)
+  : mTxnStartTime(aTxnStartTime)
+  {}
+
+  virtual void Notify(wr::Checkpoint) override {
+    auto startTime = this->mTxnStartTime;
+    CompositorThreadHolder::Loop()->PostTask(
+      NS_NewRunnableFunction("SceneBuiltNotificationRunnable", [startTime]() {
+        auto endTime = TimeStamp::Now();
+#ifdef MOZ_GECKO_PROFILER
+        if (profiler_is_active()) {
+          class ContentFullPaintPayload : public ProfilerMarkerPayload
+          {
+          public:
+            ContentFullPaintPayload(const mozilla::TimeStamp& aStartTime,
+                                    const mozilla::TimeStamp& aEndTime)
+              : ProfilerMarkerPayload(aStartTime, aEndTime)
+            {
+            }
+            virtual void StreamPayload(SpliceableJSONWriter& aWriter,
+                                       const TimeStamp& aProcessStartTime,
+                                       UniqueStacks& aUniqueStacks) override
+            {
+              StreamCommonProps("CONTENT_FULL_PAINT_TIME",
+                                aWriter,
+                                aProcessStartTime,
+                                aUniqueStacks);
+            }
+          };
+
+          profiler_add_marker_for_thread(profiler_current_thread_id(),
+                                         "CONTENT_FULL_PAINT_TIME",
+                                         MakeUnique<ContentFullPaintPayload>(startTime, endTime));
+        }
+#endif
+        Telemetry::Accumulate(Telemetry::CONTENT_FULL_PAINT_TIME,
+                              static_cast<uint32_t>((endTime - startTime).ToMilliseconds()));
+      }));
+  }
+protected:
+  TimeStamp mTxnStartTime;
+};
+
+
 class WebRenderBridgeParent::ScheduleSharedSurfaceRelease final
   : public wr::NotificationHandler
 {
 public:
   ScheduleSharedSurfaceRelease()
   { }
 
   void Add(const wr::ExternalImageId& aId)
@@ -931,16 +977,23 @@ WebRenderBridgeParent::RecvSetDisplayLis
           mCompositorBridge,
           GetLayersId(),
           mChildLayersObserverEpoch,
           true
         )
       );
     }
 
+    txn.Notify(
+      wr::Checkpoint::SceneBuilt,
+      MakeUnique<SceneBuiltNotification>(
+        aTxnStartTime
+      )
+    );
+
     mApi->SendTransaction(txn);
 
     // We will schedule generating a frame after the scene
     // build is done, so we don't need to do it here.
   } else if (observeLayersUpdate) {
     mCompositorBridge->ObserveLayersUpdate(GetLayersId(), mChildLayersObserverEpoch, true);
   }
 
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -13049,16 +13049,27 @@
     "bug_numbers": [1309442, 1489524],
     "expires_in_version": "never",
     "releaseChannelCollection": "opt-out",
     "kind": "exponential",
     "high": 1000,
     "n_buckets": 50,
     "description": "Time spent in the paint pipeline for content in milliseconds."
   },
+  "CONTENT_FULL_PAINT_TIME": {
+    "record_in_processes": ["main", "content"],
+    "alert_emails": ["gfx-telemetry-alerts@mozilla.com", "jmuizelaar@mozilla.com", "dbolter@mozilla.com"],
+    "bug_numbers": [1505858],
+    "expires_in_version": "never",
+    "releaseChannelCollection": "opt-out",
+    "kind": "exponential",
+    "high": 1000,
+    "n_buckets": 50,
+    "description": "Time spent in the paint pipeline until it's ready for composition in milliseconds."
+  },
   "CONTENT_FRAME_TIME": {
     "record_in_processes": ["main", "gpu"],
     "alert_emails": ["gfx-telemetry-alerts@mozilla.com", "rhunt@mozilla.com"],
     "bug_numbers": [1470528],
     "expires_in_version": "66",
     "kind": "exponential",
     "high": 5000,
     "n_buckets": 50,