Bug 1483245 - Add telemetry probes for amount of time spent on paint thread and the amount of tasks. r=jrmuizel
authorRyan Hunt <rhunt@eqrion.net>
Fri, 17 Aug 2018 15:22:34 -0500
changeset 432658 3c5aa35fa3d2674821a481ee46e67805b2e6b057
parent 432657 4841b3ddbacbb80dfd48c5c0b9737d6c33c7bcaa
child 432659 9f92f288b60876c75fddfddb2eba8ff685ed2b78
push id106826
push userrhunt@eqrion.net
push dateTue, 21 Aug 2018 20:32:35 +0000
treeherdermozilla-inbound@3c5aa35fa3d2 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersjrmuizel
bugs1483245
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 1483245 - Add telemetry probes for amount of time spent on paint thread and the amount of tasks. r=jrmuizel
gfx/layers/ipc/CompositorBridgeChild.cpp
gfx/layers/ipc/CompositorBridgeChild.h
toolkit/components/telemetry/Histograms.json
--- a/gfx/layers/ipc/CompositorBridgeChild.cpp
+++ b/gfx/layers/ipc/CompositorBridgeChild.cpp
@@ -87,16 +87,17 @@ CompositorBridgeChild::CompositorBridgeC
   , mResourceId(0)
   , mCanSend(false)
   , mActorDestroyed(false)
   , mFwdTransactionId(0)
   , mMessageLoop(MessageLoop::current())
   , mProcessToken(0)
   , mSectionAllocator(nullptr)
   , mPaintLock("CompositorBridgeChild.mPaintLock")
+  , mTotalAsyncPaints(0)
   , mOutstandingAsyncPaints(0)
   , mOutstandingAsyncEndTransaction(false)
   , mIsDelayingForAsyncPaints(false)
   , mSlowFlushCount(0)
   , mTotalFlushCount(0)
 {
   MOZ_ASSERT(NS_IsMainThread());
 }
@@ -1185,16 +1186,21 @@ CompositorBridgeChild::FlushAsyncPaints(
 
 void
 CompositorBridgeChild::NotifyBeginAsyncPaint(PaintTask* aTask)
 {
   MOZ_ASSERT(NS_IsMainThread());
 
   MonitorAutoLock lock(mPaintLock);
 
+  if (mTotalAsyncPaints == 0) {
+    mAsyncTransactionBegin = TimeStamp::Now();
+  }
+  mTotalAsyncPaints += 1;
+
   // We must not be waiting for paints or buffer copying to complete yet. This
   // would imply we started a new paint without waiting for a previous one, which
   // could lead to incorrect rendering or IPDL deadlocks.
   MOZ_ASSERT(!mIsDelayingForAsyncPaints);
 
   mOutstandingAsyncPaints++;
 
   // Mark texture clients that they are being used for async painting, and
@@ -1244,16 +1250,23 @@ CompositorBridgeChild::NotifyFinishedAsy
 
   if (mOutstandingAsyncSyncObject) {
     mOutstandingAsyncSyncObject->Synchronize();
     mOutstandingAsyncSyncObject = nullptr;
   }
 
   MonitorAutoLock lock(mPaintLock);
 
+  if (mTotalAsyncPaints > 0) {
+    float tenthMs = (TimeStamp::Now() - mAsyncTransactionBegin).ToMilliseconds() * 10;
+    Telemetry::Accumulate(Telemetry::GFX_OMTP_PAINT_TASK_COUNT, int32_t(mTotalAsyncPaints));
+    Telemetry::Accumulate(Telemetry::GFX_OMTP_PAINT_TIME, int32_t(tenthMs));
+    mTotalAsyncPaints = 0;
+  }
+
   // Since this should happen after ALL paints are done and
   // at the end of a transaction, this should always be true.
   MOZ_RELEASE_ASSERT(mOutstandingAsyncPaints == 0);
   MOZ_ASSERT(mOutstandingAsyncEndTransaction);
 
   mOutstandingAsyncEndTransaction = false;
 
   // It's possible that we painted so fast that the main thread never reached
--- a/gfx/layers/ipc/CompositorBridgeChild.h
+++ b/gfx/layers/ipc/CompositorBridgeChild.h
@@ -367,16 +367,22 @@ private:
   // TextureClients that must be kept alive during async painting. This
   // is only accessed on the main thread.
   nsTArray<RefPtr<TextureClient>> mTextureClientsForAsyncPaint;
 
   // Off-Main-Thread Painting state. This covers access to the OMTP-related
   // state below.
   Monitor mPaintLock;
 
+  // Contains the number of asynchronous paints that were queued since the
+  // beginning of the last async transaction, and the time stamp of when
+  // that was
+  size_t mTotalAsyncPaints;
+  TimeStamp mAsyncTransactionBegin;
+
   // Contains the number of outstanding asynchronous paints tied to a
   // PLayerTransaction on this bridge. This is R/W on both the main and paint
   // threads, and must be accessed within the paint lock.
   size_t mOutstandingAsyncPaints;
 
   // Whether we are waiting for an async paint end transaction
   bool mOutstandingAsyncEndTransaction;
   RefPtr<SyncObjectClient> mOutstandingAsyncSyncObject;
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -13719,26 +13719,46 @@
     "expires_in_version": "60",
     "kind": "exponential",
     "high": 300000,
     "n_buckets": 22,
     "keyed": true,
     "bug_numbers": [1341569],
     "description": "Milliseconds between starting to fill an autofill-eligible form field and submitting the form, keyed by the combination of form type and filling type."
   },
+  "GFX_OMTP_PAINT_TIME": {
+    "record_in_processes": ["content"],
+    "alert_emails": ["gfx-telemetry-alerts@mozilla.com", "rhunt@mozilla.com"],
+    "expires_in_version": "70",
+    "kind": "exponential",
+    "high": 10000,
+    "n_buckets": 50,
+    "description": "Amount of time in tenths of a millisecond from the beginning of the first async paint until all async paints are finished.",
+    "bug_numbers": [1483245]
+  },
   "GFX_OMTP_PAINT_WAIT_TIME": {
     "record_in_processes": ["content"],
     "alert_emails": ["gfx-telemetry-alerts@mozilla.com", "rhunt@mozilla.com"],
     "expires_in_version": "66",
     "kind": "exponential",
     "high": 200,
     "n_buckets": 50,
     "description": "Amount of time in milliseconds the main thread spends waiting for the paint thread to complete, if the time was greater than 200us.",
     "bug_numbers": [1386968]
   },
+  "GFX_OMTP_PAINT_TASK_COUNT": {
+    "record_in_processes": ["content"],
+    "alert_emails": ["gfx-telemetry-alerts@mozilla.com", "rhunt@mozilla.com"],
+    "expires_in_version": "70",
+    "kind": "exponential",
+    "high": 100,
+    "n_buckets": 25,
+    "description": "The amount of async paint tasks queued to the paint thread during a layer transaction.",
+    "bug_numbers": [1483245]
+  },
   "PREFERENCES_FILE_LOAD_TIME_US": {
     "record_in_processes": ["main", "content"],
     "expires_in_version": "62",
     "kind": "exponential",
     "high": 1000000,
     "n_buckets": 20,
     "keyed": true,
     "description": "The time (in microseconds) to load, parse and process each prefs file, keyed by filename.",