Bug 1350470 - Add telemetry to diagnose why the SetConnectivity IPC message is so slow to run r=billm draft
authorValentin Gosu <valentin.gosu@gmail.com>
Tue, 11 Apr 2017 18:14:03 +0300
changeset 561296 973339857c0da88a31573759c6447c09ae67c24e
parent 559608 731639fccc709a4dd95fed7e9dda88efb2227906
child 623939 4c2c7988b30825f4c8d1be91af3418db5e22fb6a
push id53692
push uservalentin.gosu@gmail.com
push dateWed, 12 Apr 2017 13:20:10 +0000
reviewersbillm
bugs1350470
milestone55.0a1
Bug 1350470 - Add telemetry to diagnose why the SetConnectivity IPC message is so slow to run r=billm MozReview-Commit-ID: Il4TGyYmsGI
browser/base/content/browser.js
netwerk/base/nsIOService.cpp
services/sync/modules/policies.js
toolkit/components/telemetry/Histograms.json
toolkit/mozapps/extensions/internal/XPIProvider.jsm
toolkit/mozapps/update/nsUpdateService.js
--- a/browser/base/content/browser.js
+++ b/browser/base/content/browser.js
@@ -6145,22 +6145,29 @@ var BrowserOffline = {
       return;
     }
 
     ioService.offline = !ioService.offline;
   },
 
   // nsIObserver
   observe(aSubject, aTopic, aState) {
+    let time = Date.now();
     if (aTopic != "network:offline-status-changed")
       return;
 
     // This notification is also received because of a loss in connectivity,
     // which we ignore by updating the UI to the current value of io.offline
     this._updateOfflineUI(Services.io.offline);
+
+    if (Services.appinfo.processType == Services.appinfo.PROCESS_TYPE_CONTENT) {
+      Services.telemetry
+              .getKeyedHistogramById("NETWORK_SENDCONNECTIVITY_TIME_MS")
+              .add("browser.js", Date.now() - time);
+    }
   },
 
   // BrowserOffline Implementation Methods
   _canGoOffline() {
     try {
       var cancelGoOffline = Cc["@mozilla.org/supports-PRBool;1"].createInstance(Ci.nsISupportsPRBool);
       Services.obs.notifyObservers(cancelGoOffline, "offline-requested", null);
 
--- a/netwerk/base/nsIOService.cpp
+++ b/netwerk/base/nsIOService.cpp
@@ -1158,22 +1158,26 @@ nsIOService::SetConnectivityInternal(boo
     }
     mConnectivity = aConnectivity;
 
     // This is used for PR_Connect PR_Close telemetry so it is important that
     // we have statistic about network change event even if we are offline.
     mLastConnectivityChange = PR_IntervalNow();
 
     if (mCaptivePortalService) {
+        mozilla::TimeStamp time = TimeStamp::Now();
         if (aConnectivity && !xpc::AreNonLocalConnectionsDisabled()) {
             // This will also trigger a captive portal check for the new network
             static_cast<CaptivePortalService*>(mCaptivePortalService.get())->Start();
         } else {
             static_cast<CaptivePortalService*>(mCaptivePortalService.get())->Stop();
         }
+        Telemetry::Accumulate(Telemetry::NETWORK_SENDCONNECTIVITY_TIME_MS,
+                              NS_LITERAL_CSTRING("nsIOService.cpp"),
+                              static_cast<uint32_t>((TimeStamp::Now() - time).ToMilliseconds()));
     }
 
     nsCOMPtr<nsIObserverService> observerService = services::GetObserverService();
     if (!observerService) {
         return NS_OK;
     }
     // This notification sends the connectivity to the child processes
     if (XRE_IsParentProcess()) {
--- a/services/sync/modules/policies.js
+++ b/services/sync/modules/policies.js
@@ -136,19 +136,25 @@ SyncScheduler.prototype = {
     switch (topic) {
       case "weave:engine:score:updated":
         if (Status.login == LOGIN_SUCCEEDED) {
           Utils.namedTimer(this.calculateScore, SCORE_UPDATE_DELAY, this,
                            "_scoreTimer");
         }
         break;
       case "network:offline-status-changed":
+        let time = Date.now();
         // Whether online or offline, we'll reschedule syncs
         this._log.trace("Network offline status change: " + data);
         this.checkSyncStatus();
+        if (Services.appinfo.processType == Services.appinfo.PROCESS_TYPE_CONTENT) {
+          Services.telemetry
+                  .getKeyedHistogramById("NETWORK_SENDCONNECTIVITY_TIME_MS")
+                  .add("policies.js", Date.now() - time);
+        }
         break;
       case "weave:service:sync:start":
         // Clear out any potentially pending syncs now that we're syncing
         this.clearSyncTriggers();
 
         // reset backoff info, if the server tells us to continue backing off,
         // we'll handle that later
         Status.resetBackoff();
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -3756,16 +3756,26 @@
     "kind": "linear",
     "low": 50,
     "high": 1000,
     "n_buckets": 10,
     "description": "Result of nsSocketTransportService::ProbeMaxCount()",
     "bug_numbers": [1260218],
     "alert_emails": ["necko@mozilla.com"]
   },
+  "NETWORK_SENDCONNECTIVITY_TIME_MS": {
+    "alert_emails": ["vgosu@mozilla.com"],
+    "bug_numbers": [1350470],
+    "expires_in_version": "56",
+    "kind": "exponential",
+    "high": 500,
+    "n_buckets": 20,
+    "keyed": true,
+    "description": "Measures the number of milliseconds we spend running code triggered by SendSetConnectivity. This probe is keyed on the name of the file running the code."
+  },
   "FIND_PLUGINS": {
     "alert_emails": ["perf-telemetry-alerts@mozilla.com"],
     "expires_in_version": "never",
     "kind": "exponential",
     "high": 3000,
     "n_buckets": 10,
     "description": "Time spent scanning filesystem for plugins (ms)"
   },
--- a/toolkit/mozapps/extensions/internal/XPIProvider.jsm
+++ b/toolkit/mozapps/extensions/internal/XPIProvider.jsm
@@ -6227,18 +6227,24 @@ class DownloadAddonInstall extends Addon
         this.channel.cancel(Cr.NS_BINDING_ABORTED);
       }
     } else {
       super.cancel();
     }
   }
 
   observe(aSubject, aTopic, aData) {
+    let time = Date.now();
     // Network is going offline
     this.cancel();
+    if (Services.appinfo.processType == Services.appinfo.PROCESS_TYPE_CONTENT) {
+      Services.telemetry
+              .getKeyedHistogramById("NETWORK_SENDCONNECTIVITY_TIME_MS")
+              .add("XPIProvider.jsm", Date.now() - time);
+    }
   }
 
   /**
    * Starts downloading the add-on's XPI file.
    */
   startDownload() {
     this.state = AddonManager.STATE_DOWNLOADING;
     if (!AddonManagerPrivate.callInstallListeners("onDownloadStarted",
--- a/toolkit/mozapps/update/nsUpdateService.js
+++ b/toolkit/mozapps/update/nsUpdateService.js
@@ -1906,17 +1906,23 @@ UpdateService.prototype = {
                                       APPID_TO_TOPIC[Services.appinfo.ID]);
         }
         // intentional fallthrough
       case "test-post-update-processing":
         // Clean up any extant updates
         this._postUpdateProcessing();
         break;
       case "network:offline-status-changed":
+        let time = Date.now();
         this._offlineStatusChanged(data);
+        if (Services.appinfo.processType == Services.appinfo.PROCESS_TYPE_CONTENT) {
+          Services.telemetry
+                  .getKeyedHistogramById("NETWORK_SENDCONNECTIVITY_TIME_MS")
+                  .add("nsUpdateService.js", Date.now() - time);
+        }
         break;
       case "nsPref:changed":
         if (data == PREF_APP_UPDATE_LOG) {
           gLogEnabled = getPref("getBoolPref", PREF_APP_UPDATE_LOG, false);
         }
         break;
       case "profile-change-net-teardown": // fall thru
       case "xpcom-shutdown":