Filed by: ctuns [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=430525144&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Iq09_KLDQUizDxkNPbZukA/runs/0/artifacts/public/logs/live_backing.log
[task 2023-09-27T17:55:26.537Z] 17:55:26 INFO - PID 1456 | [#97] facebook.com-talos/tests/tp5n/facebook.com/www.facebook.com/Google.html Cycles:1 Average:137.50 Median:137.50 stddev:0.00 (0.0%)
[task 2023-09-27T17:55:26.537Z] 17:55:26 INFO - PID 1456 | Values: 137.5
[task 2023-09-27T17:55:26.537Z] 17:55:26 INFO - PID 1456 |
[task 2023-09-27T17:55:26.538Z] 17:55:26 INFO - PID 1456 | [#98] youtube.com-talos/tests/tp5n/youtube.com/www.youtube.com/music.html Cycles:1 Average:307.53 Median:307.53 stddev:0.00 (0.0%)
[task 2023-09-27T17:55:26.538Z] 17:55:26 INFO - PID 1456 | Values: 307.5
[task 2023-09-27T17:55:26.538Z] 17:55:26 INFO - PID 1456 |
[task 2023-09-27T17:55:26.538Z] 17:55:26 INFO - PID 1456 | [#99] people.com.cn-talos/tests/tp5n/people.com.cn/people.com.cn/index.html Cycles:1 Average:359.74 Median:359.74 stddev:0.00 (0.0%)
[task 2023-09-27T17:55:26.538Z] 17:55:26 INFO - PID 1456 | Values: 359.7
[task 2023-09-27T17:55:26.538Z] 17:55:26 INFO - PID 1456 | -------- Summary: end --------
[task 2023-09-27T17:55:26.538Z] 17:55:26 INFO - PID 1456 |
[task 2023-09-27T17:55:26.986Z] 17:55:26 INFO - PID 1456 | console.error: ({})
[task 2023-09-27T17:55:27.268Z] 17:55:27 INFO - TEST-INFO | 1456: exit 0
[task 2023-09-27T17:55:28.128Z] 17:55:28 INFO - The trace you have just captured "Z:\task_169583272327891\build\test.etl.kernel" may contain personally identifiable information, including but not necessarily limited to paths to files accessed, paths to registry accessed and process names. Exact information depends on the events that were logged. Please be aware of this when sharing out this trace with other people.
[task 2023-09-27T17:55:28.130Z] 17:55:28 INFO - The trace you have just captured "Z:\task_169583272327891\build\test.etl.user" may contain personally identifiable information, including but not necessarily limited to paths to files accessed, paths to registry accessed and process names. Exact information depends on the events that were logged. Please be aware of this when sharing out this trace with other people.
[task 2023-09-27T17:55:45.044Z] 17:55:45 INFO - Merged Etl: test.etl
[task 2023-09-27T18:05:04.829Z] 18:05:04 INFO - TEST-UNEXPECTED-FAIL : xperf: File 'c:\windows\system32\wsock32.dll' (normalized from 'C:\Windows\system32\wsock32.dll') was accessed and we were not expecting it. DiskReadCount: 2, DiskWriteCount: 0, DiskReadBytes: 73728, DiskWriteBytes: 0
[task 2023-09-27T18:05:04.834Z] 18:05:04 INFO - TEST-UNEXPECTED-FAIL : xperf: File 'c:\windows\system32\wintrust.dll' (normalized from 'C:\Windows\system32\wintrust.dll') was accessed and we were not expecting it. DiskReadCount: 2, DiskWriteCount: 0, DiskReadBytes: 32768, DiskWriteBytes: 0
[task 2023-09-27T18:05:04.834Z] 18:05:04 INFO - TEST-UNEXPECTED-FAIL : xperf: File 'c:\windows\system32\dbghelp.dll' (normalized from 'C:\Windows\system32\dbghelp.dll') was accessed and we were not expecting it. DiskReadCount: 14, DiskWriteCount: 0, DiskReadBytes: 196608, DiskWriteBytes: 0
[task 2023-09-27T18:05:04.834Z] 18:05:04 INFO - TEST-UNEXPECTED-FAIL : xperf: File 'c:\programdata\mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38' (normalized from 'C:\ProgramData\Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38') was accessed and we were not expecting it. DiskReadCount: 6, DiskWriteCount: 0, DiskReadBytes: 24576, DiskWriteBytes: 0
[task 2023-09-27T18:05:04.835Z] 18:05:04 INFO - TEST-UNEXPECTED-FAIL : xperf: File 'c:\programdata\mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38\updates' (normalized from 'C:\ProgramData\Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38\updates') was accessed and we were not expecting it. DiskReadCount: 2, DiskWriteCount: 0, DiskReadBytes: 8192, DiskWriteBytes: 0
[task 2023-09-27T18:05:04.835Z] 18:05:04 INFO - TEST-UNEXPECTED-FAIL : xperf: File 'c:\windows\system32\gdi32full.dll' (normalized from 'C:\Windows\system32\gdi32full.dll') was accessed and we were not expecting it. DiskReadCount: 2, DiskWriteCount: 0, DiskReadBytes: 8192, DiskWriteBytes: 0
[task 2023-09-27T18:05:04.836Z] 18:05:04 INFO - TEST-UNEXPECTED-FAIL : xperf: File '{profile}\cookies.sqlite-journal' (normalized from 'C:\Users\task_169583272327891\AppData\Local\Temp\tmpey4xtx07\profile\cookies.sqlite-journal') was accessed and we were not expecting it. DiskReadCount: 0, DiskWriteCount: 12, DiskReadBytes: 0, DiskWriteBytes: 132120
[task 2023-09-27T18:05:04.836Z] 18:05:04 INFO - TEST-UNEXPECTED-FAIL : xperf: File 'c:\windows\system32\devobj.dll' (normalized from 'C:\Windows\system32\devobj.dll') was accessed and we were not expecting it. DiskReadCount: 4, DiskWriteCount: 0, DiskReadBytes: 81920, DiskWriteBytes: 0
[task 2023-09-27T18:05:04.836Z] 18:05:04 INFO - TEST-UNEXPECTED-FAIL : xperf: File 'c:\windows\system32\windows.ui.immersive.dll' (normalized from 'C:\Windows\system32\Windows.UI.Immersive.dll') was accessed and we were not expecting it. DiskReadCount: 8, DiskWriteCount: 0, DiskReadBytes: 122880, DiskWriteBytes: 0
[task 2023-09-27T18:05:04.837Z] 18:05:04 INFO - TEST-UNEXPECTED-FAIL : xperf: File 'c:\windows\system32\imm32.dll' (normalized from 'C:\Windows\system32\imm32.dll') was accessed and we were not expecting it. DiskReadCount: 4, DiskWriteCount: 0, DiskReadBytes: 131072, DiskWriteBytes: 0
[task 2023-09-27T18:05:04.837Z] 18:05:04 INFO - TEST-UNEXPECTED-FAIL : xperf: File 'c:\windows\system32\directxdatabasehelper.dll' (normalized from 'C:\Windows\system32\directxdatabasehelper.dll') was accessed and we were not expecting it. DiskReadCount: 2, DiskWriteCount: 0, DiskReadBytes: 24576, DiskWriteBytes: 0
[task 2023-09-27T18:05:04.837Z] 18:05:04 INFO - TEST-UNEXPECTED-FAIL : xperf: File 'c:\windows\apppatch\directxapps.sdb' (normalized from 'C:\Windows\apppatch\DirectXApps.sdb') was accessed and we were not expecting it. DiskReadCount: 4, DiskWriteCount: 0, DiskReadBytes: 131072, DiskWriteBytes: 0
[task 2023-09-27T18:05:04.837Z] 18:05:04 INFO - TEST-UNEXPECTED-FAIL : xperf: File 'c:\windows\system32\msvcp140.dll' (normalized from 'C:\Windows\system32\msvcp140.dll') was accessed and we were not expecting it. DiskReadCount: 4, DiskWriteCount: 0, DiskReadBytes: 81920, DiskWriteBytes: 0
[task 2023-09-27T18:05:04.838Z] 18:05:04 INFO - TEST-UNEXPECTED-FAIL : xperf: File 'c:\windows\serviceprofiles\localservice\appdata\local\fontcache\~fontcache-fontface.dat' (normalized from 'C:\Windows\ServiceProfiles\LocalService\AppData\Local\FontCache\~FontCache-FontFace.dat') was accessed and we were not expecting it. DiskReadCount: 30, DiskWriteCount: 0, DiskReadBytes: 933888, DiskWriteBytes: 0
[task 2023-09-27T18:05:04.838Z] 18:05:04 INFO - TEST-UNEXPECTED-FAIL : xperf: File 'c:\windows\fonts\times.ttf' (normalized from 'C:\Windows\Fonts\times.ttf') was accessed and we were not expecting it. DiskReadCount: 4, DiskWriteCount: 0, DiskReadBytes: 131072, DiskWriteBytes: 0
[task 2023-09-27T18:05:07.001Z] 18:05:07 INFO - extending with xperf!
[task 2023-09-27T18:05:07.011Z] 18:05:07 INFO - mozcrash checking C:\Users\task_169583272327891\AppData\Local\Temp\tmpey4xtx07\profile\minidumps for minidumps...
[task 2023-09-27T18:05:07.011Z] 18:05:07 INFO - Detected a regression for tp5n
[task 2023-09-27T18:05:07.014Z] 18:05:07 INFO - TEST-UNEXPECTED-FAIL | tp5n | Talos has found a regression, if you have questions ask for help in matrix on the #perftest channel
[task 2023-09-27T18:05:07.014Z] 18:05:07 ERROR - Traceback (most recent call last):
[task 2023-09-27T18:05:07.014Z] 18:05:07 INFO - File "Z:\task_169583272327891\build\tests\talos\talos\run_tests.py", line 357, in run_tests
[task 2023-09-27T18:05:07.014Z] 18:05:07 INFO - talos_results.add(mytest.runTest(browser_config, test))
[task 2023-09-27T18:05:07.015Z] 18:05:07 INFO - File "Z:\task_169583272327891\build\tests\talos\talos\ttest.py", line 61, in runTest
[task 2023-09-27T18:05:07.015Z] 18:05:07 INFO - return self._runTest(browser_config, test_config, setup)
[task 2023-09-27T18:05:07.015Z] 18:05:07 INFO - File "Z:\task_169583272327891\build\tests\talos\talos\ttest.py", line 251, in _runTest
[task 2023-09-27T18:05:07.015Z] 18:05:07 INFO - raise TalosRegression(
[task 2023-09-27T18:05:07.015Z] 18:05:07 INFO - talos.utils.TalosRegression: Talos has found a regression, if you have questions ask for help in matrix on the #perftest channel
[task 2023-09-27T18:05:07.015Z] 18:05:07 INFO - TEST-INFO took 888261ms
[task 2023-09-27T18:05:07.015Z] 18:05:07 INFO - SUITE-END | took 888s
[task 2023-09-27T18:05:07.501Z] 18:05:07 INFO - Return code: 1
[task 2023-09-27T18:05:07.510Z] 18:05:07 WARNING - setting return code to 1
[task 2023-09-27T18:05:07.510Z] 18:05:07 INFO - Running post-action listener: _package_coverage_data
[task 2023-09-27T18:05:07.510Z] 18:05:07 INFO - Running post-action listener: _resource_record_post_action
[task 2023-09-27T18:05:07.510Z] 18:05:07 INFO - Running post-action listener: process_java_coverage_data
[task 2023-09-27T18:05:07.510Z] 18:05:07 INFO - [mozharness: 2023-09-27 18:05:07.510906Z] Finished run-tests step (success)
[task 2023-09-27T18:05:07.510Z] 18:05:07 INFO - Running post-run listener: _resource_record_post_run
[task 2023-09-27T18:05:07.626Z] 18:05:07 INFO - Total resource usage - Wall time: 916s; CPU: 24%; Read bytes: 2574250496; Write bytes: 6281748992; Read time: 123; Write time: 151
[task 2023-09-27T18:05:07.626Z] 18:05:07 INFO - TinderboxPrint: CPU usage<br/>23.9%
[task 2023-09-27T18:05:07.626Z] 18:05:07 INFO - TinderboxPrint: I/O read bytes / time<br/>2,574,250,496 / 123
[task 2023-09-27T18:05:07.626Z] 18:05:07 INFO - TinderboxPrint: I/O write bytes / time<br/>6,281,748,992 / 151
[task 2023-09-27T18:05:07.642Z] 18:05:07 INFO - TinderboxPrint: CPU idle<br/>5,574.5 (76.1%)
[task 2023-09-27T18:05:07.642Z] 18:05:07 INFO - TinderboxPrint: CPU system<br/>564.0 (7.7%)
[task 2023-09-27T18:05:07.642Z] 18:05:07 INFO - TinderboxPrint: CPU user<br/>1,185.9 (16.2%)
[task 2023-09-27T18:05:07.642Z] 18:05:07 INFO - install - Wall time: 27s; CPU: 17%; Read bytes: 7599104; Write bytes: 10289664; Read time: 0; Write time: 0
[task 2023-09-27T18:05:07.648Z] 18:05:07 INFO - run-tests - Wall time: 889s; CPU: 24%; Read bytes: 2565665280; Write bytes: 6270697472; Read time: 123; Write time: 151
[task 2023-09-27T18:05:07.829Z] 18:05:07 WARNING - returning nonzero exit status 1
[taskcluster 2023-09-27T18:05:07.908Z] Exit Code: 1
[taskcluster 2023-09-27T18:05:07.908Z] User Time: 0s
[taskcluster 2023-09-27T18:05:07.908Z] Kernel Time: 15.625ms
[taskcluster 2023-09-27T18:05:07.908Z] Wall Time: 19m37.3669586s
[taskcluster 2023-09-27T18:05:07.908Z] Result: FAILED
[taskcluster 2023-09-27T18:05:07.908Z] === Task Finished ===
[taskcluster 2023-09-27T18:05:07.908Z] Task Duration: 19m37.3690944s
[taskcluster 2023-09-27T18:05:08.268Z] Uploading artifact public/logs/localconfig.json from file Z:\task_169583272327891\logs\localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2024-09-26T14:51:51.771Z
[taskcluster 2023-09-27T18:05:09.190Z] Uploading artifact public/test_info/resource-usage.json from file Z:\task_169583272327891\build\blobber_upload_dir\resource-usage.json with content encoding "gzip", mime type "application/json" and expiry 2024-09-26T14:51:51.771Z
[taskcluster 2023-09-27T18:05:10.646Z] Uploading artifact public/test_info/xperf_errorsummary.log from file Z:\task_169583272327891\build\blobber_upload_dir\xperf_errorsummary.log with content encoding "gzip", mime type "text/plain" and expiry 2024-09-26T14:51:51.771Z
[taskcluster 2023-09-27T18:05:11.663Z] Uploading link artifact public/logs/live.log to artifact public/logs/live_backing.log with expiry 2024-09-26T14:51:51.771Z
[taskcluster:error] exit status 1
Description
•