Bug 1368524 - Add a telemetry probe for how long we spend processing NotifyObservers callbacks, dr=bsmedberg, r=ehsan
authorMichael Layzell <michael@thelayzells.com>
Mon, 29 May 2017 15:42:42 -0400
changeset 413609 60b8fd06f8fb98d98f3aaa3e03b980291286842f
parent 413608 7060e3ad0b48542072d37fbdd9f014150dffe39f
child 413610 65c3ca9e63c0c85be91d5df2c06a806e1ad7436d
push id1490
push usermtabara@mozilla.com
push dateMon, 31 Jul 2017 14:08:16 +0000
treeherdermozilla-release@70e32e6bf15e [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersehsan
bugs1368524
milestone55.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 1368524 - Add a telemetry probe for how long we spend processing NotifyObservers callbacks, dr=bsmedberg, r=ehsan MozReview-Commit-ID: KWypjvFscVu
toolkit/components/telemetry/Histograms.json
xpcom/ds/nsObserverService.cpp
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -13342,10 +13342,22 @@
     "alert_emails": ["addons-dev-internal@mozilla.com"],
     "bug_numbers": [1353171],
     "expires_in_version": "60",
     "kind": "exponential",
     "releaseChannelCollection": "opt-out",
     "high": 50000,
     "n_buckets": 100,
     "description": "The amount of time it takes for a WebExtension to start up, from when the startup function is called to when the startup promise resolves."
+  },
+  "NOTIFY_OBSERVERS_LATENCY_MS": {
+    "record_in_processes": ["main", "content", "gpu"],
+    "alert_emails": ["michael@thelayzells.com"],
+    "bug_numbers": [1368524],
+    "expires_in_version": "60",
+    "kind": "exponential",
+    "low": 3,
+    "high": 512,
+    "n_buckets": 20,
+    "keyed": true,
+    "description": "Measures the number of milliseconds we spend synchronously notifying observers, keyed by topic. Note: only NotifyObservers calls which take over 500 microseconds are included in this probe."
   }
 }
--- a/xpcom/ds/nsObserverService.cpp
+++ b/xpcom/ds/nsObserverService.cpp
@@ -13,19 +13,24 @@
 #include "nsObserverService.h"
 #include "nsObserverList.h"
 #include "nsServiceManagerUtils.h"
 #include "nsThreadUtils.h"
 #include "nsEnumeratorUtils.h"
 #include "xpcpublic.h"
 #include "mozilla/net/NeckoCommon.h"
 #include "mozilla/Services.h"
+#include "mozilla/Telemetry.h"
+#include "mozilla/TimeStamp.h"
+#include "nsString.h"
 
 #define NOTIFY_GLOBAL_OBSERVERS
 
+static const uint32_t kMinTelemetryNotifyObserversLatencyMs = 1;
+
 // Log module for nsObserverService logging...
 //
 // To enable logging (see prlog.h for full details):
 //
 //    set MOZ_LOG=ObserverService:5
 //    set MOZ_LOG_FILE=service.log
 //
 // This enables LogLevel::Debug level information and places all output in
@@ -271,28 +276,37 @@ NS_IMETHODIMP nsObserverService::NotifyO
 {
   LOG(("nsObserverService::NotifyObservers(%s)", aTopic));
 
   NS_ENSURE_VALIDCALL
   if (NS_WARN_IF(!aTopic)) {
     return NS_ERROR_INVALID_ARG;
   }
 
+  mozilla::TimeStamp start = TimeStamp::Now();
+
   nsObserverList* observerList = mObserverTopicTable.GetEntry(aTopic);
   if (observerList) {
     observerList->NotifyObservers(aSubject, aTopic, aSomeData);
   }
 
 #ifdef NOTIFY_GLOBAL_OBSERVERS
   observerList = mObserverTopicTable.GetEntry("*");
   if (observerList) {
     observerList->NotifyObservers(aSubject, aTopic, aSomeData);
   }
 #endif
 
+  uint32_t latencyMs = round((TimeStamp::Now() - start).ToMilliseconds());
+  if (latencyMs >= kMinTelemetryNotifyObserversLatencyMs) {
+    Telemetry::Accumulate(Telemetry::NOTIFY_OBSERVERS_LATENCY_MS,
+                          nsDependentCString(aTopic),
+                          latencyMs);
+  }
+
   return NS_OK;
 }
 
 NS_IMETHODIMP
 nsObserverService::UnmarkGrayStrongObservers()
 {
   NS_ENSURE_VALIDCALL