1800887 - Intermittent [tier 2] Exception: The test ran in chimera mode but we found no cold and warm browsertime JSONs. Cannot symbolicate profiles.

Status: RESOLVED FIXED

(Testing :: Raptor, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2022-11-16T12:44:09.502Z] 12:44:09     INFO -  perftest-output Info: PERFHERDER_DATA: {"framework": {"name": "browsertime"}, "suites": [{"name": "buzzfeed", "type": "pageload", "extraOptions": ["fission", "cold", "webrender"], "tags": ["fission", "cold", "webrender"], "lowerIsBetter": true, "unit": "ms", "alertThreshold": 2.0, "subtests": [{"name": "ContentfulSpeedIndex", "lowerIsBetter": true, "alertThreshold": 2.0, "unit": "ms", "shouldAlert": true, "replicates": [1514, 867, 902, 824, 853, 803, 854, 847, 844, 926, 910, 836, 839, 803, 795, 850, 822, 824, 810, 817, 779, 865, 880, 808, 890], "value": 844}, {"name": "FirstVisualChange", "lowerIsBetter": true, "alertThreshold": 2.0, "unit": "ms", "shouldAlert": true, "replicates": [1233, 666, 633, 666, 666, 600, 733, 666, 666, 666, 633, 666, 566, 600, 600, 633, 600, 600, 600, 600, 566, 666, 666, 600, 633], "value": 633}, {"name": "LastVisualChange", "lowerIsBetter": true, "alertThreshold": 2.0, "unit": "ms", "shouldAlert": true, "replicates": [2066, 1233, 1466, 1333, 1400, 1166, 1300, 1366, 1333, 1566, 1533, 1333, 1133, 1166, 1333, 1400, 1167, 1300, 1300, 1200, 1300, 1300, 1300, 1166, 1333], "value": 1300}, {"name": "PerceptualSpeedIndex", "lowerIsBetter": true, "alertThreshold": 2.0, "unit": "ms", "shouldAlert": true, "replicates": [1396, 803, 809, 793, 789, 734, 827, 796, 783, 836, 805, 781, 730, 728, 766, 773, 730, 749, 735, 741, 733, 786, 800, 727, 795], "value": 783}, {"name": "SpeedIndex", "lowerIsBetter": true, "alertThreshold": 2.0, "unit": "ms", "shouldAlert": true, "replicates": [1367, 795, 779, 760, 761, 711, 806, 776, 769, 824, 775, 756, 719, 708, 744, 745, 712, 732, 707, 713, 706, 758, 777, 713, 771], "value": 758}, {"name": "dcf", "lowerIsBetter": true, "alertThreshold": 2.0, "unit": "ms", "shouldAlert": false, "replicates": [1207, 640, 594, 574, 646, 583, 635, 647, 636, 765, 721, 662, 771, 753, 644, 761, 584, 576, 579, 574, 573, 628, 660, 734, 786], "value": 642.0}, {"name": "fcp", "lowerIsBetter": true, "alertThreshold": 2.0, "unit": "ms", "shouldAlert": true, "replicates": [1202, 642, 589, 632, 630, 576, 695, 632, 626, 612, 608, 647, 521, 577, 559, 592, 578, 560, 573, 556, 554, 607, 651, 560, 588], "value": 590.5}, {"name": "fnbpaint", "lowerIsBetter": true, "alertThreshold": 2.0, "unit": "ms", "shouldAlert": false, "replicates": [1204, 655, 591, 638, 643, 581, 715, 644, 634, 632, 626, 660, 536, 591, 584, 597, 580, 573, 577, 570, 569, 625, 658, 582, 613], "value": 605.0}, {"name": "loadtime", "lowerIsBetter": true, "alertThreshold": 2.0, "unit": "ms", "shouldAlert": true, "replicates": [2392, 1003, 1746, 1731, 1742, 987, 987, 1070, 1034, 1124, 1710, 1076, 980, 1551, 1055, 1259, 993, 1010, 1832, 1023, 1763, 1696, 1753, 994, 1096], "value": 1086.0}]}, {"name": "buzzfeed", "type": "pageload", "extraOptions": ["fission", "webrender", "warm"], "tags": ["fission", "webrender", "warm"], "lowerIsBetter": true, "unit": "ms", "alertThreshold": 2.0, "subtests": [{"name": "ContentfulSpeedIndex", "lowerIsBetter": true, "alertThreshold": 2.0, "unit": "ms", "shouldAlert": true, "replicates": [418, 451, 436, 416, 442, 466, 442, 472, 389, 472, 373, 425, 422, 457, 405, 406, 438, 409, 415, 461, 424, 403, 386, 438, 431], "value": 425}, {"name": "FirstVisualChange", "lowerIsBetter": true, "alertThreshold": 2.0, "unit": "ms", "shouldAlert": true, "replicates": [200, 233, 233, 200, 233, 233, 233, 233, 166, 233, 167, 200, 233, 233, 200, 200, 233, 233, 200, 233, 200, 200, 166, 200, 233], "value": 233}, {"name": "LastVisualChange", "lowerIsBetter": true, "alertThreshold": 2.0, "unit": "ms", "shouldAlert": true, "replicates": [966, 1100, 933, 966, 1033, 1000, 966, 1066, 933, 1100, 933, 1000, 1000, 966, 933, 966, 1100, 1033, 966, 1033, 933, 966, 933, 966, 966], "value": 966}, {"name": "PerceptualSpeedIndex", "lowerIsBetter": true, "alertThreshold": 2.0, "unit": "ms", "shouldAlert": true, "replicates": [336, 373, 359, 331, 363, 375, 360, 374, 307, 379, 307, 336, 360, 370, 334, 340, 369, 361, 334, 369, 337, 335, 308, 349, 362], "value": 359}, {"name": "SpeedIndex", "lowerIsBetter": true, "alertThreshold": 2.0, "unit": "ms", "shouldAlert": true, "replicates": [282, 315, 308, 280, 312, 317, 308, 316, 252, 321, 250, 283, 308, 316, 281, 281, 315, 309, 279, 316, 284, 279, 252, 288, 310], "value": 308}, {"name": "dcf", "lowerIsBetter": true, "alertThreshold": 2.0, "unit": "ms", "shouldAlert": false, "replicates": [439, 466, 459, 462, 440, 485, 465, 418, 465, 497, 530, 451, 509, 440, 438, 518, 460, 521, 449, 452, 414, 470, 458, 425, 512], "value": 461.0}, {"name": "fcp", "lowerIsBetter": true, "alertThreshold": 2.0, "unit": "ms", "shouldAlert": true, "replicates": [134, 134, 148, 129, 131, 150, 148, 144, 128, 151, 152, 133, 148, 148, 127, 149, 147, 154, 153, 168, 135, 153, 132, 129, 153], "value": 148.0}, {"name": "fnbpaint", "lowerIsBetter": true, "alertThreshold": 2.0, "unit": "ms", "shouldAlert": false, "replicates": [170, 184, 192, 179, 179, 194, 196, 188, 175, 200, 192, 171, 190, 199, 172, 191, 195, 193, 188, 201, 169, 190, 177, 182, 191], "value": 190.0}, {"name": "loadtime", "lowerIsBetter": true, "alertThreshold": 2.0, "unit": "ms", "shouldAlert": true, "replicates": [748, 785, 750, 744, 755, 797, 759, 802, 719, 857, 800, 747, 786, 791, 770, 789, 779, 769, 722, 801, 758, 766, 740, 828, 791], "value": 774.5}]}], "application": {"name": "firefox", "version": "109.0a1"}}
[task 2022-11-16T12:44:09.503Z] 12:44:09     INFO -  perftest-output Info: results can also be found locally at: C:\Users\task_1668599092\build\raptor.json
[task 2022-11-16T12:44:09.507Z] 12:44:09     INFO -  perftest-results-handler Info: Validating PERFHERDER_DATA against C:\Users\task_1668599092\mozharness\external_tools\performance-artifact-schema.json
[task 2022-11-16T12:44:09.512Z] 12:44:09     INFO -  perftest-results-handler Info: Writing video jobs and application data {'jobs': [{'browsertime_json_path': 'browsertime-results/buzzfeed/cold-browsertime.json', 'test_name': 'buzzfeed', 'tags': [], 'extra_options': ['fission', 'cold', 'webrender'], 'accept_zero_vismet': False}, {'browsertime_json_path': 'browsertime-results/buzzfeed/warm-browsertime.json', 'test_name': 'buzzfeed', 'tags': [], 'extra_options': ['fission', 'webrender', 'warm'], 'accept_zero_vismet': False}], 'application': {'name': 'firefox', 'version': '109.0a1'}, 'extra_options': ['fission', 'cold', 'webrender']} into C:\Users\task_1668599092\build\blobber_upload_dir\browsertime-results\jobs.json
[task 2022-11-16T12:44:09.512Z] 12:44:09     INFO -  raptor-perftest Info: Removing temporary directory: C:\Users\task_1668599092\AppData\Local\Temp\tmplufrrej7
[task 2022-11-16T12:44:09.675Z] 12:44:09    ERROR -  Traceback (most recent call last):
[task 2022-11-16T12:44:09.676Z] 12:44:09     INFO -    File "C:\Users\task_1668599092\build\tests\raptor\raptor\raptor.py", line 207, in <module>
[task 2022-11-16T12:44:09.676Z] 12:44:09     INFO -      main()
[task 2022-11-16T12:44:09.677Z] 12:44:09     INFO -    File "C:\Users\task_1668599092\build\tests\raptor\raptor\raptor.py", line 153, in main
[task 2022-11-16T12:44:09.677Z] 12:44:09     INFO -      success = raptor.run_tests(raptor_test_list, raptor_test_names)
[task 2022-11-16T12:44:09.677Z] 12:44:09     INFO -    File "C:\Users\task_1668599092\build\tests\raptor\raptor\perftest.py", line 478, in run_tests
[task 2022-11-16T12:44:09.678Z] 12:44:09     INFO -      return self.process_results(tests, test_names)
[task 2022-11-16T12:44:09.679Z] 12:44:09     INFO -    File "C:\Users\task_1668599092\build\tests\raptor\raptor\perftest.py", line 507, in process_results
[task 2022-11-16T12:44:09.679Z] 12:44:09     INFO -      self.gecko_profiler.symbolicate()
[task 2022-11-16T12:44:09.679Z] 12:44:09     INFO -    File "C:\Users\task_1668599092\build\tests\raptor\raptor\gecko_profile.py", line 221, in symbolicate
[task 2022-11-16T12:44:09.680Z] 12:44:09     INFO -      profiles = self.collect_profiles()
[task 2022-11-16T12:44:09.680Z] 12:44:09     INFO -    File "C:\Users\task_1668599092\build\tests\raptor\raptor\gecko_profile.py", line 173, in collect_profiles
[task 2022-11-16T12:44:09.680Z] 12:44:09     INFO -      "The test ran in chimera mode but we found no cold "
[task 2022-11-16T12:44:09.681Z] 12:44:09     INFO -  Exception: The test ran in chimera mode but we found no cold and warm browsertime JSONs. Cannot symbolicate profiles.
[task 2022-11-16T12:44:09.730Z] 12:44:09    ERROR - Return code: 1
[task 2022-11-16T12:44:09.730Z] 12:44:09  WARNING - setting return code to 1
[task 2022-11-16T12:44:09.730Z] 12:44:09     INFO - Copying Raptor results to upload dir:
[task 2022-11-16T12:44:09.731Z] 12:44:09     INFO - C:\Users\task_1668599092\build\blobber_upload_dir\perfherder-data.json
[task 2022-11-16T12:44:09.731Z] 12:44:09     INFO - Copying raptor results from C:\Users\task_1668599092\build\raptor.json to C:\Users\task_1668599092\build\blobber_upload_dir\perfherder-data.json
[task 2022-11-16T12:44:09.732Z] 12:44:09     INFO - Running post-action listener: _package_coverage_data
[task 2022-11-16T12:44:09.732Z] 12:44:09     INFO - Running post-action listener: _resource_record_post_action
[task 2022-11-16T12:44:09.732Z] 12:44:09     INFO - Running post-action listener: process_java_coverage_data
[task 2022-11-16T12:44:09.732Z] 12:44:09     INFO - Running post-action listener: stop_device
[task 2022-11-16T12:44:09.733Z] 12:44:09     INFO - [mozharness: 2022-11-16 12:44:09.732248Z] Finished run-tests step (success)
[task 2022-11-16T12:44:09.733Z] 12:44:09     INFO - Running post-run listener: _resource_record_post_run
[task 2022-11-16T12:44:09.877Z] 12:44:09     INFO - Total resource usage - Wall time: 1379s; CPU: 15%; Read bytes: 550254592; Write bytes: 2801563648; Read time: 12; Write time: 31
[task 2022-11-16T12:44:09.877Z] 12:44:09     INFO - TinderboxPrint: CPU usage<br/>15.1%
[task 2022-11-16T12:44:09.878Z] 12:44:09     INFO - TinderboxPrint: I/O read bytes / time<br/>550,254,592 / 12
[task 2022-11-16T12:44:09.878Z] 12:44:09     INFO - TinderboxPrint: I/O write bytes / time<br/>2,801,563,648 / 31
[task 2022-11-16T12:44:09.878Z] 12:44:09     INFO - TinderboxPrint: CPU idle<br/>9,364.1 (84.9%)
[task 2022-11-16T12:44:09.878Z] 12:44:09     INFO - TinderboxPrint: CPU system<br/>420.8 (3.8%)
[task 2022-11-16T12:44:09.878Z] 12:44:09     INFO - TinderboxPrint: CPU user<br/>1,241.8 (11.3%)
[task 2022-11-16T12:44:09.878Z] 12:44:09     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-11-16T12:44:09.879Z] 12:44:09     INFO - install - Wall time: 3s; CPU: 13%; Read bytes: 65536; Write bytes: 16392192; Read time: 0; Write time: 0
[task 2022-11-16T12:44:09.890Z] 12:44:09     INFO - run-tests - Wall time: 1376s; CPU: 15%; Read bytes: 550004736; Write bytes: 2785171456; Read time: 12; Write time: 31
[task 2022-11-16T12:44:10.255Z] 12:44:10  WARNING - returning nonzero exit status 1
[taskcluster 2022-11-16T12:44:10.305Z]    Exit Code: 1
[taskcluster 2022-11-16T12:44:10.305Z]    User Time: 0s
[taskcluster 2022-11-16T12:44:10.305Z]  Kernel Time: 0s
[taskcluster 2022-11-16T12:44:10.305Z]    Wall Time: 24m26.0631579s
[taskcluster 2022-11-16T12:44:10.305Z]       Result: FAILED
[taskcluster 2022-11-16T12:44:10.305Z] === Task Finished ===

Comment 1

[Iulian Moraru]

Hi Nazim! Can you please take a look at this? Could this be regressed by your recent changes in Bug 1788647?
Thank you!

Comment 2

[Intermittent Failures Robot]

6 failures in 3589 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 4
• mozilla-central: 2

Platform and build breakdown:

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

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

Comment 3

[Intermittent Failures Robot]

4 failures in 3888 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 4

Platform and build breakdown:

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

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

Comment 4

[Intermittent Failures Robot]

7 failures in 3938 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 6
• mozilla-central: 1

Platform and build breakdown:

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

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

Comment 5

[Greg Mierzwinski [:sparky]]

It looks like this is happening because we hit a test breaking failure, but then we continue to try to symbolicate the profiles but we can't/shouldn't because the data is bad. :canova, can you add some code to skip the symbolication when we fail in a test?

Comment 6

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

Sorry for not looking at it sooner. Sure, let me take a look.

Comment 7

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1
• autoland: 1

Platform and build breakdown:

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

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

Comment 8

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

Attachment: Bug 1800887 - Silently return early on symbolication if it's an extra profiler run r?#perftest

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/fe18f7bf4ac0
Silently return early on symbolication if it's an extra profiler run r=perftest-reviewers,sparky

Comment 10

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

https://hg.mozilla.org/mozilla-central/rev/fe18f7bf4ac0

Comment 11

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 2
• mozilla-beta: 2

Platform and build breakdown:

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

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