Bug 1652613 - record a telemetry event when we show the slow script notification warning, r=mconley

Differential Revision: https://phabricator.services.mozilla.com/D83922

browser/modules/ProcessHangMonitor.jsm

@@ -39,13 +39,19 @@ var ProcessHangMonitor = {
 
   /**
    * Collection of hang reports that haven't expired or been dismissed
-   * by the user. These are nsIHangReports.
+   * by the user. These are nsIHangReports. They are mapped to objects
+   * containing:
+   * - notificationTime: when (Cu.now()) we first showed a notification
+   * - waitCount: how often the user asked to wait for the script to finish
+   * - lastReportFromChild: when (Cu.now()) we last got hang info from the
+   *   child.
    */
-  _activeReports: new Set(),
+  _activeReports: new Map(),
 
   /**
    * Collection of hang reports that have been suppressed for a short
-   * period of time. Value is an nsITimer for when the wait time
+   * period of time. Value is an object like in _activeReports, but also
+   * including a `timer` prop, which is an nsITimer for when the wait time
    * expires.
    */
   _pausedReports: new Map(),
@@ -59,6 +65,7 @@ var ProcessHangMonitor = {
     Services.obs.addObserver(this, "quit-application-granted");
     Services.obs.addObserver(this, "xpcom-shutdown");
     Services.ww.registerNotification(this);
+    Services.telemetry.setEventRecordingEnabled("slow_script_warning", true);
   },
 
   /**
@@ -87,6 +94,7 @@ var ProcessHangMonitor = {
         report.endStartingDebugger();
       }
 
+      this._recordTelemetryForReport(report, "debugging");
       report.beginStartingDebugger();
 
       let svc = Cc["@mozilla.org/dom/slow-script-debug;1"].getService(
@@ -118,6 +126,7 @@ var ProcessHangMonitor = {
 
     switch (report.hangType) {
       case report.SLOW_SCRIPT:
+        this._recordTelemetryForReport(report, "user-aborted");
         this.terminateScript(win);
         break;
       case report.PLUGIN_HANG:
@@ -138,6 +147,7 @@ var ProcessHangMonitor = {
 
     switch (report.hangType) {
       case report.SLOW_SCRIPT:
+        this._recordTelemetryForReport(report, "user-aborted");
         this.terminateGlobal(win);
         break;
     }
@@ -147,9 +157,10 @@ var ProcessHangMonitor = {
    * Terminate whatever is causing this report, be it an add-on, page script,
    * or plug-in. This is done without updating any report notifications.
    */
-  stopHang(report) {
+  stopHang(report, endReason, backupInfo) {
     switch (report.hangType) {
       case report.SLOW_SCRIPT: {
+        this._recordTelemetryForReport(report, endReason, backupInfo);
         if (report.addonId) {
           report.terminateGlobal();
         } else {
@@ -173,6 +184,10 @@ var ProcessHangMonitor = {
     if (!report) {
       return;
     }
+    // Update the other info we keep.
+    let reportInfo = this._activeReports.get(report);
+    reportInfo.waitCount++;
+
     // Remove the report from the active list.
     this.removeActiveReport(report);
 
@@ -185,13 +200,13 @@ var ProcessHangMonitor = {
     let timer = Cc["@mozilla.org/timer;1"].createInstance(Ci.nsITimer);
     timer.initWithCallback(
       () => {
-        for (let [stashedReport, otherTimer] of this._pausedReports) {
-          if (otherTimer === timer) {
+        for (let [stashedReport, pausedInfo] of this._pausedReports) {
+          if (pausedInfo.timer === timer) {
             this.removePausedReport(stashedReport);
 
             // We're still hung, so move the report back to the active
             // list and update the UI.
-            this._activeReports.add(report);
+            this._activeReports.set(report, pausedInfo);
             this.updateWindows();
             break;
           }
@@ -201,7 +216,8 @@ var ProcessHangMonitor = {
       timer.TYPE_ONE_SHOT
     );
 
-    this._pausedReports.set(report, timer);
+    reportInfo.timer = timer;
+    this._pausedReports.set(report, reportInfo);
 
     // remove the browser notification associated with this hang
     this.updateWindows();
@@ -276,7 +292,7 @@ var ProcessHangMonitor = {
    */
   onQuitApplicationGranted() {
     this._shuttingDown = true;
-    this.stopAllHangs();
+    this.stopAllHangs("quit-application-granted");
     this.updateWindows();
   },
 
@@ -293,7 +309,7 @@ var ProcessHangMonitor = {
           // the hang.
         }
         if (!hungBrowserWindow || hungBrowserWindow == win) {
-          this.stopHang(report);
+          this.stopHang(report, "window-closed");
           return true;
         }
       } else if (report.hangType == report.PLUGIN_HANG) {
@@ -322,15 +338,15 @@ var ProcessHangMonitor = {
     this.updateWindows();
   },
 
-  stopAllHangs() {
+  stopAllHangs(endReason) {
     for (let report of this._activeReports) {
-      this.stopHang(report);
+      this.stopHang(report, endReason);
     }
 
-    this._activeReports = new Set();
+    this._activeReports = new Map();
 
     for (let [pausedReport] of this._pausedReports) {
-      this.stopHang(pausedReport);
+      this.stopHang(pausedReport, endReason);
       this.removePausedReport(pausedReport);
     }
   },
@@ -340,7 +356,7 @@ var ProcessHangMonitor = {
    */
   findActiveReport(browser) {
     let frameLoader = browser.frameLoader;
-    for (let report of this._activeReports) {
+    for (let report of this._activeReports.keys()) {
       if (report.isReportForBrowser(frameLoader)) {
         return report;
       }
@@ -361,6 +377,71 @@ var ProcessHangMonitor = {
     return null;
   },
 
+  /**
+   * Tell telemetry about the report.
+   */
+  _recordTelemetryForReport(report, endReason, backupInfo) {
+    let info =
+      this._activeReports.get(report) ||
+      this._pausedReports.get(report) ||
+      backupInfo;
+    if (!info) {
+      return;
+    }
+    try {
+      // Only report slow script hangs.
+      if (report.hangType != report.SLOW_SCRIPT) {
+        return;
+      }
+      let uri_type;
+      if (report.addonId) {
+        uri_type = "extension";
+      } else if (report.scriptFileName?.startsWith("debugger")) {
+        uri_type = "devtools";
+      } else {
+        try {
+          let url = new URL(report.scriptFileName);
+          if (url.protocol == "chrome:" || url.protocol == "resource:") {
+            uri_type = "browser";
+          } else {
+            uri_type = "content";
+          }
+        } catch (ex) {
+          Cu.reportError(ex);
+          uri_type = "unknown";
+        }
+      }
+      let uptime = 0;
+      if (info.notificationTime) {
+        uptime = Cu.now() - info.notificationTime;
+      }
+      uptime = "" + uptime;
+      // We combine the duration of the hang in the content process with the
+      // time since we were last told about the hang in the parent. This is
+      // not the same as the time we showed a notification, as we only do that
+      // for the currently selected browser. It's as messy as it is because
+      // there is no cross-process monotonically increasing timestamp we can
+      // use. :-(
+      let hangDuration =
+        report.hangDuration + Cu.now() - info.lastReportFromChild;
+      Services.telemetry.recordEvent(
+        "slow_script_warning",
+        "shown",
+        "content",
+        null,
+        {
+          end_reason: endReason,
+          hang_duration: "" + hangDuration,
+          uri_type,
+          uptime,
+          wait_count: "" + info.waitCount,
+        }
+      );
+    } catch (ex) {
+      Cu.reportError(ex);
+    }
+  },
+
   /**
    * Remove an active hang report from the active list and cancel the timer
    * associated with it.
@@ -375,10 +456,8 @@ var ProcessHangMonitor = {
    * associated with it.
    */
   removePausedReport(report) {
-    let timer = this._pausedReports.get(report);
-    if (timer) {
-      timer.cancel();
-    }
+    let info = this._pausedReports.get(report);
+    info?.timer?.cancel();
     this._pausedReports.delete(report);
   },
 
@@ -395,7 +474,7 @@ var ProcessHangMonitor = {
     // we have no opportunity to ask the user whether or not they want
     // to stop the hang or wait, so we'll opt for stopping the hang.
     if (!e.hasMoreElements()) {
-      this.stopAllHangs();
+      this.stopAllHangs("no-windows-left");
       return;
     }
 
@@ -418,6 +497,10 @@ var ProcessHangMonitor = {
     let report = this.findActiveReport(win.gBrowser.selectedBrowser);
 
     if (report) {
+      let info = this._activeReports.get(report);
+      if (info && !info.notificationTime) {
+        info.notificationTime = Cu.now();
+      }
       this.showNotification(win, report);
     } else {
       this.hideNotification(win);
@@ -566,13 +649,17 @@ var ProcessHangMonitor = {
    * before, show a notification for it in all open XUL windows.
    */
   reportHang(report) {
+    let now = Cu.now();
     if (this._shuttingDown) {
-      this.stopHang(report);
+      this.stopHang(report, "shutdown-in-progress", {
+        lastReportFromChild: now,
+      });
       return;
     }
 
     // If this hang was already reported reset the timer for it.
     if (this._activeReports.has(report)) {
+      this._activeReports.get(report).lastReportFromChild = now;
       // if this report is in active but doesn't have a notification associated
       // with it, display a notification.
       this.updateWindows();
@@ -581,6 +668,7 @@ var ProcessHangMonitor = {
 
     // If this hang was already reported and paused by the user ignore it.
     if (this._pausedReports.has(report)) {
+      this._pausedReports.get(report).lastReportFromChild = now;
       return;
     }
 
@@ -595,11 +683,16 @@ var ProcessHangMonitor = {
       Services.telemetry.getHistogramById("PLUGIN_HANG_NOTICE_COUNT").add();
     }
 
-    this._activeReports.add(report);
+    this._activeReports.set(report, {
+      lastReportFromChild: now,
+      waitCount: 0,
+    });
     this.updateWindows();
   },
 
   clearHang(report) {
+    this._recordTelemetryForReport(report, "cleared");
+
     this.removeActiveReport(report);
     this.removePausedReport(report);
     report.userCanceled();

toolkit/components/telemetry/Events.yaml

@@ -2271,6 +2271,32 @@ security.ui.certerror:
       has_sts: If the error page is for a site with HSTS headers or with a pinned key.
       panel_open: If the advanced panel was open at the time of the interaction.
 
+slow_script_warning:
+  shown:
+    bug_numbers:
+      - 1652613
+    description: >
+      Recorded when a slow script hang is resolved.
+    products:
+      - "firefox"
+    record_in_processes: ["main"]
+    release_channel_collection: opt-out
+    expiry_version: "85"
+    notification_emails:
+      - esmyth@mozilla.com
+      - gkruitbosch@mozilla.com
+    # Whether the hung script was for a content or browser process.
+    objects: [
+      "browser",
+      "content",
+    ]
+    extra_keys:
+      end_reason: Why the warning was hidden (user action, the process becoming responsive again, the browser quitting, etc.)
+      wait_count: How many times the user elected to wait.
+      hang_duration: How long we believe the hang continued (ms).
+      uri_type: The kind of script URL that hung.
+      uptime: How long the notification was up (ms).
+
 webrtc.ui:
   share_display:
     objects: