1804399 - Intermittent [tier 2] Btime KeyError: 'files' | followed by Return code: 1 (search in log, the failure line might not appear in treeherder UI)

Status: RESOLVED FIXED

(Testing :: Raptor, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: imoraru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=398860592&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/VYVMBZOPSYK5wVDLCAa81Q/runs/0/artifacts/public/logs/live_backing.log

---

[task 2022-12-07T06:08:00.602Z] 06:08:00     INFO -  perftest-results-handler Info: Validating PERFHERDER_DATA against C:\Users\task_1670366980\mozharness\external_tools\performance-artifact-schema.json
[task 2022-12-07T06:08:00.607Z] 06:08:00     INFO -  perftest-results-handler Info: Writing video jobs and application data {'jobs': [{'browsertime_json_path': 'browsertime-results/reddit-billgates-post-1/browsertime.json', 'test_name': 'reddit-billgates-post-1', 'tags': ['interactive'], 'extra_options': ['fission', 'cold', 'webrender'], 'accept_zero_vismet': True}], 'application': {'name': 'firefox', 'version': '109.0a1'}, 'extra_options': ['fission', 'cold', 'webrender']} into C:\Users\task_1670366980\build\blobber_upload_dir\browsertime-results\jobs.json
[task 2022-12-07T06:08:00.608Z] 06:08:00     INFO -  raptor-perftest Info: Removing temporary directory: C:\Users\task_1670366980\AppData\Local\Temp\tmpq8w607vd
[task 2022-12-07T06:08:00.799Z] 06:08:00    ERROR -  Traceback (most recent call last):
[task 2022-12-07T06:08:00.799Z] 06:08:00     INFO -    File "C:\Users\task_1670366980\build\tests\raptor\raptor\raptor.py", line 206, in <module>
[task 2022-12-07T06:08:00.800Z] 06:08:00     INFO -      main()
[task 2022-12-07T06:08:00.800Z] 06:08:00     INFO -    File "C:\Users\task_1670366980\build\tests\raptor\raptor\raptor.py", line 152, in main
[task 2022-12-07T06:08:00.800Z] 06:08:00     INFO -      success = raptor.run_tests(raptor_test_list, raptor_test_names)
[task 2022-12-07T06:08:00.801Z] 06:08:00     INFO -    File "C:\Users\task_1670366980\build\tests\raptor\raptor\perftest.py", line 480, in run_tests
[task 2022-12-07T06:08:00.801Z] 06:08:00     INFO -      return self.process_results(tests, test_names)
[task 2022-12-07T06:08:00.801Z] 06:08:00     INFO -    File "C:\Users\task_1670366980\build\tests\raptor\raptor\perftest.py", line 509, in process_results
[task 2022-12-07T06:08:00.802Z] 06:08:00     INFO -      self.gecko_profiler.symbolicate()
[task 2022-12-07T06:08:00.802Z] 06:08:00     INFO -    File "C:\Users\task_1670366980\build\tests\raptor\raptor\gecko_profile.py", line 221, in symbolicate
[task 2022-12-07T06:08:00.802Z] 06:08:00     INFO -      profiles = self.collect_profiles()
[task 2022-12-07T06:08:00.802Z] 06:08:00     INFO -    File "C:\Users\task_1670366980\build\tests\raptor\raptor\gecko_profile.py", line 195, in collect_profiles
[task 2022-12-07T06:08:00.803Z] 06:08:00     INFO -      for rel_profile_path in entry["files"]["geckoProfiles"]:
[task 2022-12-07T06:08:00.803Z] 06:08:00     INFO -  KeyError: 'files'
[task 2022-12-07T06:08:00.858Z] 06:08:00    ERROR - Return code: 1
[task 2022-12-07T06:08:00.858Z] 06:08:00  WARNING - setting return code to 1
[task 2022-12-07T06:08:00.858Z] 06:08:00     INFO - Copying Raptor results to upload dir:
[task 2022-12-07T06:08:00.858Z] 06:08:00     INFO - C:\Users\task_1670366980\build\blobber_upload_dir\perfherder-data.json
[task 2022-12-07T06:08:00.858Z] 06:08:00     INFO - Copying raptor results from C:\Users\task_1670366980\build\raptor.json to C:\Users\task_1670366980\build\blobber_upload_dir\perfherder-data.json
[task 2022-12-07T06:08:00.860Z] 06:08:00     INFO - Running post-action listener: _package_coverage_data
[task 2022-12-07T06:08:00.860Z] 06:08:00     INFO - Running post-action listener: _resource_record_post_action
[task 2022-12-07T06:08:00.860Z] 06:08:00     INFO - Running post-action listener: process_java_coverage_data
[task 2022-12-07T06:08:00.860Z] 06:08:00     INFO - Running post-action listener: stop_device
[task 2022-12-07T06:08:00.860Z] 06:08:00     INFO - [mozharness: 2022-12-07 06:08:00.860417Z] Finished run-tests step (success)
[task 2022-12-07T06:08:00.860Z] 06:08:00     INFO - Running post-run listener: _resource_record_post_run
[task 2022-12-07T06:08:00.979Z] 06:08:00     INFO - Total resource usage - Wall time: 834s; CPU: 12%; Read bytes: 184550400; Write bytes: 1313560064; Read time: 1; Write time: 9
[task 2022-12-07T06:08:00.979Z] 06:08:00     INFO - TinderboxPrint: CPU usage<br/>12.4%
[task 2022-12-07T06:08:00.979Z] 06:08:00     INFO - TinderboxPrint: I/O read bytes / time<br/>184,550,400 / 1
[task 2022-12-07T06:08:00.980Z] 06:08:00     INFO - TinderboxPrint: I/O write bytes / time<br/>1,313,560,064 / 9
[task 2022-12-07T06:08:00.980Z] 06:08:00     INFO - TinderboxPrint: CPU idle<br/>5,850.3 (87.6%)
[task 2022-12-07T06:08:00.980Z] 06:08:00     INFO - TinderboxPrint: CPU system<br/>192.7 (2.9%)
[task 2022-12-07T06:08:00.980Z] 06:08:00     INFO - TinderboxPrint: CPU user<br/>630.6 (9.4%)
[task 2022-12-07T06:08:00.980Z] 06:08:00     INFO - install-chromium-distribution - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2022-12-07T06:08:00.981Z] 06:08:00     INFO - install - Wall time: 3s; CPU: 13%; Read bytes: 32768; Write bytes: 24576; Read time: 0; Write time: 0
[task 2022-12-07T06:08:00.987Z] 06:08:00     INFO - run-tests - Wall time: 832s; CPU: 12%; Read bytes: 184374272; Write bytes: 1294865920; Read time: 1; Write time: 9
[task 2022-12-07T06:08:01.207Z] 06:08:01  WARNING - returning nonzero exit status 1
[taskcluster 2022-12-07T06:08:01.252Z]    Exit Code: 1
[taskcluster 2022-12-07T06:08:01.252Z]    User Time: 0s
[taskcluster 2022-12-07T06:08:01.252Z]  Kernel Time: 15.625ms
[taskcluster 2022-12-07T06:08:01.252Z]    Wall Time: 15m35.0032654s
[taskcluster 2022-12-07T06:08:01.252Z]       Result: FAILED
[taskcluster 2022-12-07T06:08:01.252Z] === Task Finished ===
[taskcluster 2022-12-07T06:08:01.252Z] Task Duration: 15m35.0032654s

Comment 1

[Greg Mierzwinski [:sparky]]

:canova, this failure is caused by the gecko-profiling run failing, could you look into it? It looks like we're still trying to go through our files even if they might not exist.

Comment 2

[Greg Mierzwinski [:sparky]]

(see comment above)

Comment 3

[Intermittent Failures Robot]

37 failures in 3510 pushes (0.011 failures/push) were associated with this bug in the last 7 days.

This is the #40 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• mozilla-central: 11
• autoland: 26

Platform and build breakdown:

• windows10-64-shippable-qr: 37
  • opt: 37

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1804399&startday=2022-12-05&endday=2022-12-11&tree=all

Comment 4

[Nazım Can Altınova [:canova][:canaltinova on phabricator]]

Attachment: Bug 1804399 - Do not throw an error in case there isn't a captured profile r?#perftest

Depends on D164658

Comment 5

[Nazım Can Altınova [:canova][:canaltinova on phabricator]]

Attachment: Bug 1804399 - Do not check the profiling directory inside _is_extra_profiler_run and gracefully fail later r?#perftest

Previously we were checing if there is a profiling directory to decide that
it's an extra profiler run. But actually this is incorrect because it can still
be an extra profiler run with a failed output. So we skip checking that
directory while deciding if it's a profiler run, and add an additional check to
see if this step is failed.

Depends on D164661

Comment 6

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/f90b55a71fa2
Do not throw an error in case there isn't a captured profile r=perftest-reviewers,sparky
https://hg.mozilla.org/integration/autoland/rev/ed1bf9574d1f
Do not check the profiling directory inside _is_extra_profiler_run and gracefully fail later r=perftest-reviewers,sparky

Comment 7

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

https://hg.mozilla.org/mozilla-central/rev/f90b55a71fa2
https://hg.mozilla.org/mozilla-central/rev/ed1bf9574d1f

Comment 8

[Intermittent Failures Robot]

18 failures in 3558 pushes (0.005 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 9
• mozilla-central: 7
• toolchains: 2

Platform and build breakdown:

• windows10-64-shippable-qr: 18
  • opt: 18

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1804399&startday=2022-12-12&endday=2022-12-18&tree=all