Bug 2050049 - Dump and report a profile when an xpcshell test is about to time out, r=ahal.

Arm the profiler's scheduled off-main-thread dump (scheduleDumpToFile) shortly
before the harness timeout fires, so a test wedged in a synchronous run -- where
the main-thread nsITimer in head.js could never fire -- still leaves a profile.

The harness picks the artifact path, giving a retried run a _retry suffix (and a
numeric counter on collision) so it doesn't overwrite an earlier run's profile,
and reports the written file via a structured test_status so it becomes a
FAIL-named TestStatus marker the dashboards read and is downgraded to expected
on a retried run.

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

Author: fqueze

testing/xpcshell/head.js

@@ -632,26 +632,21 @@ function _execute_test() {
     PerTestCoverageUtils.beforeTestSync();
   }
 
-  let timer;
-  if (
-    _Services.profiler.IsActive() &&
-    !_Services.env.exists("MOZ_PROFILER_SHUTDOWN") &&
-    _Services.env.exists("MOZ_UPLOAD_DIR") &&
-    _Services.env.exists("MOZ_TEST_TIMEOUT_INTERVAL")
-  ) {
-    timer = _Cc["@mozilla.org/timer;1"].createInstance(Ci.nsITimer);
-    timer.initWithCallback(
-      function upload_test_timeout_profile() {
-        ChromeUtils.addProfilerMarker(
-          "xpcshell-test",
-          { category: "Test", startTime },
-          _TEST_NAME
-        );
-        _do_upload_profile();
-      },
-      parseInt(_Services.env.get("MOZ_TEST_TIMEOUT_INTERVAL")) * 1000 * 0.9, // Keep 10% of the time to gather the profile.
-      timer.TYPE_ONE_SHOT
-    );
+  // If we don't finish before the harness's timeout, the profiler writes a
+  // profile from its sampler thread, so a test that wedges its main thread
+  // (e.g. a long synchronous run that never returns to the event loop) still
+  // leaves a profile. Unlike a main-thread nsITimer this fires regardless of
+  // what the main thread is doing. The harness picks the output path (in
+  // MOZ_TEST_TIMEOUT_PROFILE_PATH) and reports the written file when it times
+  // the test out.
+  let scheduledProfileDump = false;
+  let timeoutProfilePath = _Services.env.get("MOZ_TEST_TIMEOUT_PROFILE_PATH");
+  if (timeoutProfilePath && _Services.profiler.IsActive()) {
+    // Keep 10% of the time to write the profile before the harness kills us.
+    let delaySeconds =
+      parseInt(_Services.env.get("MOZ_TEST_TIMEOUT_INTERVAL")) * 0.9;
+    _Services.profiler.scheduleDumpToFile(delaySeconds, timeoutProfilePath);
+    scheduledProfileDump = true;
   }
 
   try {
@@ -798,8 +793,8 @@ function _execute_test() {
     _PromiseTestUtils.uninit();
   }
 
-  if (timer) {
-    timer.cancel();
+  if (scheduledProfileDump) {
+    _Services.profiler.cancelScheduledDump();
   }
 
   // If MOZ_PROFILER_SHUTDOWN is set, the profiler got started from --profiler

testing/xpcshell/runxpcshelltests.py

@@ -187,6 +187,9 @@ def __init__(
             # Retry in CI, but report results without retry when run locally to
             # avoid confusion and ease local debugging.
             self.retry = os.environ.get("MOZ_AUTOMATION") is not None
+        # True only for the re-run of a test that failed the first time, so it
+        # can name artifacts differently from the initial run.
+        self.is_retry = kwargs.get("is_retry", False)
         self.verbose = verbose
         self.usingTSan = usingTSan
         self.usingCrashReporter = usingCrashReporter
@@ -454,6 +457,29 @@ def testTimeout(self, proc):
         if self.timeout_factor > 1:
             extra = {"timeoutfactor": self.timeout_factor}
 
+        # If the profiler dumped a profile from its sampler thread before we
+        # killed the wedged process (scheduled by head.js via scheduleDumpToFile
+        # since the main thread can't write one once it stops returning to the
+        # event loop), report it here as a structured test_status, logged while
+        # the test is still in progress so the artifact is linked to this test.
+        # A structured message (unlike a raw log line) is downgraded to expected
+        # on a retried run, and is recorded as a FAIL marker in the
+        # resource-usage profile the dashboards read.
+        profile_name = self.timeout_profile_name
+        upload_dir = self.env.get("MOZ_UPLOAD_DIR")
+        if (
+            profile_name
+            and upload_dir
+            and os.path.isfile(os.path.join(upload_dir, profile_name))
+        ):
+            self.log.test_status(
+                self.test_object["id"],
+                "",
+                "FAIL",
+                expected="FAIL" if (self.retry or self.timeoutAsPass) else expected,
+                message=f"Test timed out; profile uploaded in {profile_name}",
+            )
+
         if self.retry:
             self.log.test_end(
                 self.test_object["id"],
@@ -990,11 +1016,41 @@ def run_test(self):
 
         testTimeoutInterval = self.harness_timeout * self.timeout_factor
 
+        self.timeout_profile_name = None
         if not self.interactive and not self.debuggerInfo and not self.jsDebuggerInfo:
             self.timer = Timer(testTimeoutInterval, lambda: self.testTimeout(proc))
             self.timer.start()
             self.env["MOZ_TEST_TIMEOUT_INTERVAL"] = str(testTimeoutInterval)
 
+            # When the profiler runs by default, have it dump a profile from its
+            # sampler thread shortly before this timeout fires (armed by
+            # head.js), so a test wedged in a synchronous run (where the main
+            # thread can never write one) still leaves a profile. We pick the
+            # artifact name here so the retry of a test that timed out doesn't
+            # overwrite the initial run's profile: the retry gets a "_retry"
+            # suffix, and a numeric counter is only added on an actual name
+            # collision (the same test listed in two manifests). The suffixes go
+            # before the test extension so the name still ends in e.g.
+            # ".js.json" as Treeherder expects. testTimeout reports this name.
+            upload_dir = self.env.get("MOZ_UPLOAD_DIR")
+            if (
+                upload_dir
+                and self.env.get("MOZ_PROFILER_STARTUP")
+                and "MOZ_PROFILER_SHUTDOWN" not in self.env
+            ):
+                root, ext = os.path.splitext(os.path.basename(name))
+                if self.is_retry:
+                    root += "_retry"
+                filename = f"profile_{root}{ext}.json"
+                i = 2
+                while os.path.exists(os.path.join(upload_dir, filename)):
+                    filename = f"profile_{root}-{i}{ext}.json"
+                    i += 1
+                self.timeout_profile_name = filename
+                self.env["MOZ_TEST_TIMEOUT_PROFILE_PATH"] = os.path.join(
+                    upload_dir, filename
+                )
+
         proc = None
         process_output = None
 
@@ -2568,6 +2624,7 @@ def runTestList(
 
         try_again_kwargs = kwargs.copy()
         try_again_kwargs["retry"] = False
+        try_again_kwargs["is_retry"] = True
         for test_object in self.try_again_list:
             test = testClass(
                 test_object,