commit 472cfdd8400641ad88f4d36487a6525fea693396
parent 9ee356d4f4b015f72f6e4568e5cc741aa74809a6
Author: iulian moraru <imoraru@mozilla.com>
Date: Tue, 7 Oct 2025 05:28:15 +0300
Revert "Bug 1992477, Bug 1992181 - replay the logs of failures that happened in parallel, without failing the treeherder jobs, r=jmaher." for causing xpcshell failures on test_ExperimentManager_prefs.
This reverts commit 71e9bf363fd74835bf0bc7c81158f1179cb2960a.
Revert "Bug 1992181 - show 'artifact' markers for files found in the upload dir when stopping the resource monitor, r=ahal."
This reverts commit aad0350f350f4b6bdeb88bb0a09402cacfa534e0.
Revert "Bug 1992181 - Include 'process_output' structured log messages in resource usage profiles, r=ahal."
This reverts commit 0009d2b54a739c12351c91b17d078d6a9013f5a5.
Revert "Bug 1992181 - Resource usage profiles should show test_status and log messages, r=ahal."
This reverts commit d550c4e679b642116e3a3272a16df3637918ae2a.
Diffstat:
5 files changed, 23 insertions(+), 230 deletions(-)
diff --git a/testing/mozbase/mozlog/mozlog/handlers/resourcehandler.py b/testing/mozbase/mozlog/mozlog/handlers/resourcehandler.py
@@ -53,11 +53,7 @@ class ResourceHandler(LogHandler):
def test_end(self, data):
SystemResourceMonitor.end_test(data)
- def test_status(self, data):
- SystemResourceMonitor.test_status(data)
-
def log(self, data):
- SystemResourceMonitor.test_status(data)
-
- def process_output(self, data):
- SystemResourceMonitor.test_status(data)
+ level = data.get("level").upper()
+ time = self.resources.convert_to_monotonic_time(data.get("time") / 1000)
+ SystemResourceMonitor.record_marker(level, time, time, data.get("message"))
diff --git a/testing/mozbase/mozsystemmonitor/mozsystemmonitor/resourcemonitor.py b/testing/mozbase/mozsystemmonitor/mozsystemmonitor/resourcemonitor.py
@@ -404,16 +404,13 @@ class SystemResourceMonitor:
self.start_time = time.monotonic()
SystemResourceMonitor.instance = self
- def stop(self, upload_dir=None):
+ def stop(self):
"""Stop measuring system-wide CPU resource utilization.
You should call this if and only if you have called start(). You should
always pair a stop() with a start().
Currently, data is not available until you call stop().
-
- Args:
- upload_dir: Optional path to upload directory for artifact markers.
"""
if not self._process:
self._stopped = True
@@ -507,48 +504,17 @@ class SystemResourceMonitor:
SystemResourceUsage.instance = None
self.end_time = time.monotonic()
- # Add event markers for files in upload directory
- if upload_dir is None:
- upload_dir = os.environ.get("UPLOAD_DIR") or os.environ.get(
- "MOZ_UPLOAD_DIR"
- )
- if upload_dir and os.path.isdir(upload_dir):
- try:
- for filename in os.listdir(upload_dir):
- filepath = os.path.join(upload_dir, filename)
- if os.path.isfile(filepath):
- stat = os.stat(filepath)
- timestamp = self.convert_to_monotonic_time(stat.st_mtime)
- marker_data = {
- "type": "Artifact",
- "filename": filename,
- "size": stat.st_size,
- }
- self.events.append((timestamp, "artifact", marker_data))
- except Exception as e:
- warnings.warn(f"Failed to scan upload directory: {e}")
-
# Methods to record events alongside the monitored data.
@staticmethod
- def record_event(name, timestamp=None, data=None):
+ def record_event(name):
"""Record an event as occuring now.
Events are actions that occur at a specific point in time. If you are
looking for an action that has a duration, see the phase API below.
-
- Args:
- name: Name of the event (string)
- timestamp: Optional timestamp (monotonic time). If not provided, uses current time.
- data: Optional marker payload dictionary (e.g., {"type": "TestStatus", ...})
"""
if SystemResourceMonitor.instance:
- if timestamp is None:
- timestamp = time.monotonic()
- if data:
- SystemResourceMonitor.instance.events.append((timestamp, name, data))
- else:
- SystemResourceMonitor.instance.events.append((timestamp, name))
+ SystemResourceMonitor.instance.events.append((time.monotonic(), name))
@staticmethod
def record_marker(name, start, end, data):
@@ -646,8 +612,6 @@ class SystemResourceMonitor:
if status in ("SKIP", "TIMEOUT"):
marker_data["color"] = "yellow"
- if message:
- marker_data["message"] = message
elif status in ("CRASH", "ERROR"):
marker_data["color"] = "red"
elif expected is None and not will_retry:
@@ -658,60 +622,6 @@ class SystemResourceMonitor:
SystemResourceMonitor.instance.record_marker("test", start, end, marker_data)
- @staticmethod
- def test_status(data):
- """Record a test_status/log/process_output event.
-
- Args:
- data: Dictionary containing test_status/log/process_output data including:
- - "action": the action type
- - "test": test name (optional)
- - "subtest": subtest name (optional, only for test_status/log)
- - "status" or "level": status for test_status/log
- - "time": timestamp in milliseconds
- - "message" or "data": optional message
- """
- if not SystemResourceMonitor.instance:
- return
-
- time_sec = data["time"] / 1000
- timestamp = SystemResourceMonitor.instance.convert_to_monotonic_time(time_sec)
-
- action = data.get("action")
- marker_data = {"type": "TestStatus"}
-
- if action == "process_output":
- # Process output uses "output" as marker name
- marker_name = "output"
- message = data.get("data")
- else:
- # test_status and log actions
- status = (data.get("status") or data.get("level")).upper()
- marker_name = status
-
- # Determine color based on status
- if status == "PASS":
- marker_data["color"] = "green"
- elif status == "FAIL":
- marker_data["color"] = "orange"
- elif status == "ERROR":
- marker_data["color"] = "red"
-
- subtest = data.get("subtest")
- if subtest:
- marker_data["subtest"] = subtest
-
- message = data.get("message")
-
- test_name = data.get("test")
- if test_name:
- marker_data["test"] = test_name
-
- if message:
- marker_data["message"] = message
-
- SystemResourceMonitor.record_event(marker_name, timestamp, marker_data)
-
@contextmanager
def phase(self, name):
"""Context manager for recording an active phase."""
@@ -1120,7 +1030,7 @@ class SystemResourceMonitor:
{
"name": "Test",
"tooltipLabel": "{marker.data.name}",
- "tableLabel": "{marker.data.status} — {marker.data.test}",
+ "tableLabel": "{marker.data.test} — {marker.data.status}",
"chartLabel": "{marker.data.name}",
"display": ["marker-chart", "marker-table"],
"colorField": "color",
@@ -1147,61 +1057,12 @@ class SystemResourceMonitor:
"format": "string",
},
{
- "key": "message",
- "label": "Message",
- "format": "string",
- },
- {
"key": "color",
"hidden": True,
},
],
},
{
- "name": "TestStatus",
- "tableLabel": "{marker.data.message} — {marker.data.test} {marker.data.subtest}",
- "display": ["marker-chart", "marker-table"],
- "colorField": "color",
- "data": [
- {
- "key": "message",
- "label": "Message",
- "format": "string",
- },
- {
- "key": "test",
- "label": "Test Name",
- "format": "string",
- },
- {
- "key": "subtest",
- "label": "Subtest",
- "format": "string",
- },
- {
- "key": "color",
- "hidden": True,
- },
- ],
- },
- {
- "name": "Artifact",
- "tableLabel": "{marker.data.filename} — {marker.data.size}",
- "display": ["marker-chart", "marker-table"],
- "data": [
- {
- "key": "filename",
- "label": "Filename",
- "format": "string",
- },
- {
- "key": "size",
- "label": "Size",
- "format": "bytes",
- },
- ],
- },
- {
"name": "Mem",
"tooltipLabel": "{marker.name}",
"display": [],
@@ -1562,27 +1423,14 @@ class SystemResourceMonitor:
add_marker(get_string_index(name), start, end, markerData, TASK_CATEGORY, 3)
if self.events:
event_string_index = get_string_index("Event")
- for event in self.events:
- if len(event) == 3:
- # Event with payload: (time, name, data)
- event_time, name, data = event
- add_marker(
- get_string_index(name),
- event_time,
- None,
- data,
- OTHER_CATEGORY,
- 3,
- )
- elif len(event) == 2:
- # Simple event: (time, text)
- event_time, text = event
+ for event_time, text in self.events:
+ if text:
add_marker(
event_string_index,
event_time,
None,
{"type": "Text", "text": text},
- OTHER_CATEGORY,
+ TASK_CATEGORY,
3,
)
diff --git a/testing/mozharness/mozharness/base/python.py b/testing/mozharness/mozharness/base/python.py
@@ -880,14 +880,12 @@ class ResourceMonitoringMixin(PerfherderResourceOptionsMixin):
if not self._resource_monitor:
return
- # Get upload directory to pass to stop() for artifact markers
- upload_dir = self.query_abs_dirs()["abs_blob_upload_dir"]
-
- self._resource_monitor.stop(upload_dir=upload_dir)
+ self._resource_monitor.stop()
self._log_resource_usage()
# Upload a JSON file containing the raw resource data.
try:
+ upload_dir = self.query_abs_dirs()["abs_blob_upload_dir"]
if not os.path.exists(upload_dir):
os.makedirs(upload_dir)
with open(os.path.join(upload_dir, "resource-usage.json"), "w") as fh:
diff --git a/testing/mozharness/mozharness/mozilla/structuredlog.py b/testing/mozharness/mozharness/mozilla/structuredlog.py
@@ -106,12 +106,6 @@ class StructuredOutputParser(OutputParser):
SystemResourceMonitor.begin_test(data)
elif action == "test_end":
SystemResourceMonitor.end_test(data)
- elif action == "test_status":
- SystemResourceMonitor.test_status(data)
- elif action == "log":
- SystemResourceMonitor.test_status(data)
- elif action == "process_output":
- SystemResourceMonitor.test_status(data)
elif action == "suite_start":
SystemResourceMonitor.begin_marker("suite", data["source"])
elif action == "suite_end":
@@ -120,6 +114,8 @@ class StructuredOutputParser(OutputParser):
SystemResourceMonitor.begin_marker("test", data["name"])
elif action == "group_end":
SystemResourceMonitor.end_marker("test", data["name"])
+ if line.startswith("TEST-UNEXPECTED-FAIL"):
+ SystemResourceMonitor.record_event(line)
if action in ("log", "process_output"):
if action == "log":
diff --git a/testing/xpcshell/runxpcshelltests.py b/testing/xpcshell/runxpcshelltests.py
@@ -433,7 +433,6 @@ class XPCShellTestThread(Thread):
expected="TIMEOUT",
message="Test timed out",
)
- self.log_full_output(mark_failures_as_expected=True)
else:
result = "TIMEOUT"
if self.timeoutAsPass:
@@ -711,15 +710,12 @@ class XPCShellTestThread(Thread):
line = line.decode("utf-8")
return line
- def log_line(self, line, time=None):
+ def log_line(self, line):
"""Log a line of output (either a parser json object or text output from
the test process"""
if isinstance(line, (str, bytes)):
line = self.fix_text_output(line).rstrip("\r\n")
- kwargs = {"command": self.command, "test": self.test_object["id"]}
- if time is not None:
- kwargs["time"] = time
- self.log.process_output(self.proc_ident, line, **kwargs)
+ self.log.process_output(self.proc_ident, line, command=self.command)
else:
if "message" in line:
line["message"] = self.fix_text_output(line["message"])
@@ -731,41 +727,14 @@ class XPCShellTestThread(Thread):
line["thread"] = current_thread().name
self.log.log_raw(line)
- def log_full_output(self, mark_failures_as_expected=False):
- """Logs any buffered output from the test process, and clears the buffer.
-
- Args:
- mark_failures_as_expected: If True, failures will be marked as expected
- (TEST-EXPECTED-FAIL instead of TEST-UNEXPECTED-FAIL). This is used
- when a test will be retried.
- """
+ def log_full_output(self):
+ """Logs any buffered output from the test process, and clears the buffer."""
if not self.output_lines:
return
- self.log.info(f">>>>>>> Begin of full log for {self.test_object['id']}")
- for timestamp, line in self.output_lines:
- if isinstance(line, dict):
- # Always ensure the 'test' field is present for resource usage profiles
- if "test" not in line:
- line["test"] = self.test_object["id"]
-
- if mark_failures_as_expected:
- if line.get("action") == "test_status" and "expected" in line:
- # Ensure the 'expected' field matches the 'status' to avoid failing the job
- line["expected"] = line.get("status")
- elif line.get("action") == "log" and line.get("level") == "ERROR":
- # Convert ERROR log to test_status so it gets colored
- # properly without causing a test failure.
- line["action"] = "test_status"
- line["status"] = "ERROR"
- line["expected"] = "ERROR"
- line["subtest"] = ""
- del line["level"]
- self.log_line(line)
- else:
- # For text lines, we need to provide the timestamp that was
- # recorded when appending the message to self.output_lines
- self.log_line(line, time=timestamp)
- self.log.info(f"<<<<<<< End of full log for {self.test_object['id']}")
+ self.log.info(">>>>>>>")
+ for line in self.output_lines:
+ self.log_line(line)
+ self.log.info("<<<<<<<")
self.output_lines = []
def report_message(self, message):
@@ -773,15 +742,7 @@ class XPCShellTestThread(Thread):
if self.verbose:
self.log_line(message)
else:
- # Store timestamp only for string messages (dicts already have timestamps)
- # We need valid timestamps to replay messages correctly in resource
- # usage profiles.
- import time
-
- timestamp = (
- int(time.time() * 1000) if isinstance(message, (str, bytes)) else None
- )
- self.output_lines.append((timestamp, message))
+ self.output_lines.append(message)
def process_line(self, line_string):
"""Parses a single line of output, determining its significance and
@@ -2415,9 +2376,6 @@ class XPCShellTests:
if test.retry or test.is_alive():
# if the join call timed out, test.is_alive => True
self.try_again_list.append(test.test_object)
- # Print the failure output now, marking failures as expected
- # since we'll retry sequentially
- test.log_full_output(mark_failures_as_expected=True)
continue
# did the test encounter any exception?
if test.exception:
@@ -2457,9 +2415,6 @@ class XPCShellTests:
self.test_ended(test)
if (test.failCount > 0 or test.passCount <= 0) and test.retry:
self.try_again_list.append(test.test_object)
- # Print the failure output now, marking failures as expected
- # since we'll retry sequentially
- test.log_full_output(mark_failures_as_expected=True)
continue
self.addTestResults(test)
# did the test encounter any exception?
