1797782 - Extra profiler run is having issues with verbose mode

Status: NEW

(Testing :: Raptor, defect, P2)

Description

[Greg Mierzwinski [:sparky]]

See this try push which enables verbose mode: https://treeherder.mozilla.org/jobs?repo=try&selectedTaskRun=FvutzkKCRduYdu-5SwCNVw.0&revision=8c3816e90cb0d8667b805f0cef9e845a9d9e4142

It looks like the perf data is being obtained before the profiler step, and that we fail while symbolicating in verbose mode:

[task 2022-10-26T03:06:44.538Z] 03:06:44     INFO -  perftest-output Info: PERFHERDER_DATA: {"framework": {"name": "browsertime"}, "suites": [{"name": "reddit.2.12s", "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": [852, 831, 858, 735, 778, 804, 831, 844, 851, 790, 833, 900, 828, 829, 795, 779, 695, 813, 812, 780, 876, 714, 705, 764, 888], "value": 813}, {"name": "FirstVisualChange", "lowerIsBetter": true, "alertThreshold": 2.0, "unit": "ms", "shouldAlert": true, "replicates": [400, 440, 400, 280, 400, 400, 320, 400, 400, 320, 400, 400, 400, 400, 440, 360, 280, 360, 440, 360, 440, 320, 320, 360, 360], "value": 400}, {"name": "LastVisualChange", "lowerIsBetter": true, "alertThreshold": 2.0, "unit": "ms", "shouldAlert": true, "replicates": [7720, 7520, 7720, 7880, 7600, 7960, 7920, 7720, 7640, 7640, 7199, 8000, 7920, 7840, 7320, 7840, 7199, 7520, 7199, 7720, 7520, 7880, 7560, 7640, 7240], "value": 7640}, {"name": "PerceptualSpeedIndex", "lowerIsBetter": true, "alertThreshold": 2.0, "unit": "ms", "shouldAlert": true, "replicates": [727, 798, 734, 629, 691, 711, 780, 730, 753, 738, 726, 765, 722, 750, 709, 679, 622, 686, 737, 662, 770, 639, 664, 694, 748], "value": 726}, {"name": "SpeedIndex", "lowerIsBetter": true, "alertThreshold": 2.0, "unit": "ms", "shouldAlert": true, "replicates": [689, 742, 701, 585, 653, 679, 669, 683, 703, 667, 680, 725, 717, 678, 688, 629, 573, 651, 697, 610, 733, 599, 602, 643, 692], "value": 679}, {"name": "dcf", "lowerIsBetter": true, "alertThreshold": 2.0, "unit": "ms", "shouldAlert": false, "replicates": [642, 641, 739, 811, 803, 858, 775, 743, 631, 922, 767, 976, 936, 677, 737, 824, 608, 781, 659, 774, 921, 830, 727, 770, 851], "value": 774.5}, {"name": "fcp", "lowerIsBetter": true, "alertThreshold": 2.0, "unit": "ms", "shouldAlert": true, "replicates": [354, 339, 320, 230, 311, 343, 268, 329, 358, 307, 350, 342, 365, 339, 357, 314, 223, 307, 350, 316, 354, 282, 231, 287, 328], "value": 324.0}, {"name": "fnbpaint", "lowerIsBetter": true, "alertThreshold": 2.0, "unit": "ms", "shouldAlert": false, "replicates": [361, 346, 344, 237, 343, 344, 269, 352, 364, 308, 352, 344, 372, 341, 358, 336, 240, 329, 357, 324, 361, 289, 232, 304, 334], "value": 342.0}, {"name": "loadtime", "lowerIsBetter": true, "alertThreshold": 2.0, "unit": "ms", "shouldAlert": true, "replicates": [2720, 2769, 2754, 2843, 3243, 2943, 3094, 2708, 3004, 2944, 2726, 3086, 2994, 2807, 2945, 2678, 2801, 2786, 2841, 2911, 2983, 2753, 2789, 2563, 2762], "value": 2824.0}]}, {"name": "reddit.2.12s", "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": [442, 438, 402, 350, 318, 389, 343, 461, 453, 327, 483, 458, 353, 266, 392, 501, 468, 345, 269, 470, 458, 284, 437, 257, 436], "value": 402}, {"name": "FirstVisualChange", "lowerIsBetter": true, "alertThreshold": 2.0, "unit": "ms", "shouldAlert": true, "replicates": [320, 320, 280, 240, 200, 240, 240, 320, 360, 200, 360, 320, 240, 160, 280, 400, 360, 240, 160, 360, 280, 160, 320, 160, 320], "value": 280}, {"name": "LastVisualChange", "lowerIsBetter": true, "alertThreshold": 2.0, "unit": "ms", "shouldAlert": true, "replicates": [1880, 2120, 2040, 1680, 1600, 1800, 1800, 1880, 1400, 1720, 2040, 1880, 1800, 1520, 2040, 1640, 1800, 1320, 1920, 2040, 2000, 1480, 1840, 1520, 2120], "value": 1800}, {"name": "PerceptualSpeedIndex", "lowerIsBetter": true, "alertThreshold": 2.0, "unit": "ms", "shouldAlert": true, "replicates": [480, 509, 434, 383, 347, 431, 390, 496, 474, 359, 542, 485, 396, 303, 466, 556, 514, 373, 353, 505, 501, 322, 492, 292, 516], "value": 466}, {"name": "SpeedIndex", "lowerIsBetter": true, "alertThreshold": 2.0, "unit": "ms", "shouldAlert": true, "replicates": [432, 450, 387, 348, 309, 371, 354, 442, 443, 311, 485, 442, 351, 267, 409, 549, 505, 333, 295, 463, 436, 277, 441, 257, 457], "value": 409}, {"name": "dcf", "lowerIsBetter": true, "alertThreshold": 2.0, "unit": "ms", "shouldAlert": false, "replicates": [400, 421, 366, 400, 307, 337, 336, 457, 374, 285, 408, 414, 336, 329, 385, 410, 341, 304, 305, 417, 441, 339, 410, 280, 435], "value": 370.0}, {"name": "fcp", "lowerIsBetter": true, "alertThreshold": 2.0, "unit": "ms", "shouldAlert": true, "replicates": [343, 341, 309, 290, 214, 261, 275, 351, 359, 224, 352, 332, 242, 209, 285, 393, 373, 231, 217, 357, 340, 198, 306, 223, 360], "value": 298.0}, {"name": "fnbpaint", "lowerIsBetter": true, "alertThreshold": 2.0, "unit": "ms", "shouldAlert": false, "replicates": [353, 352, 319, 315, 238, 262, 285, 360, 373, 235, 360, 343, 263, 216, 300, 409, 379, 232, 218, 358, 349, 208, 329, 234, 361], "value": 317.0}, {"name": "loadtime", "lowerIsBetter": true, "alertThreshold": 2.0, "unit": "ms", "shouldAlert": true, "replicates": [1813, 2169, 2010, 1751, 1647, 1753, 1765, 1845, 1787, 1859, 2058, 1681, 1747, 1751, 2014, 1959, 1865, 1674, 1912, 2009, 1803, 1420, 1751, 1720, 2070], "value": 1795.0}]}], "application": {"name": "firefox", "version": "107.0a1"}}
[task 2022-10-26T03:06:44.538Z] 03:06:44     INFO -  perftest-output Info: results can also be found locally at: /opt/worker/tasks/task_166675178455006/build/raptor.json
[task 2022-10-26T03:06:44.539Z] 03:06:44     INFO -  perftest-results-handler Info: Validating PERFHERDER_DATA against /opt/worker/tasks/task_166675178455006/mozharness/external_tools/performance-artifact-schema.json
[task 2022-10-26T03:06:44.539Z] 03:06:44     INFO -  perftest-results-handler Info: Writing video jobs and application data {'jobs': [{'browsertime_json_path': 'browsertime-results/reddit/cold-browsertime.json', 'test_name': 'reddit', 'tags': [], 'extra_options': ['fission', 'cold', 'webrender'], 'accept_zero_vismet': False}, {'browsertime_json_path': 'browsertime-results/reddit/warm-browsertime.json', 'test_name': 'reddit', 'tags': [], 'extra_options': ['fission', 'webrender', 'warm'], 'accept_zero_vismet': False}], 'application': {'name': 'firefox', 'version': '107.0a1'}, 'extra_options': ['fission', 'cold', 'webrender']} into /opt/worker/tasks/task_166675178455006/build/blobber_upload_dir/browsertime-results/jobs.json
[task 2022-10-26T03:06:44.540Z] 03:06:44     INFO -  raptor-gecko-profile Info: Found 2 profiles: [{'path': '/opt/worker/tasks/task_166675178455006/build/blobber_upload_dir/browsertime-results/reddit/profiling/pages/www_reddit_com/r/technology/comments/9sqwyh/we_posed_as_100_senators_to_run_ads_on_facebook/data/geckoProfile-1.json.gz', 'type': 'cold'}, {'path': '/opt/worker/tasks/task_166675178455006/build/blobber_upload_dir/browsertime-results/reddit/profiling/pages/www_reddit_com/r/technology/comments/9sqwyh/we_posed_as_100_senators_to_run_ads_on_facebook/query-6bc054f4/data/geckoProfile-1.json.gz', 'type': 'cold'}]
[task 2022-10-26T03:06:44.540Z] 03:06:44     INFO -  profiler Retrieving symbol zip from https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/P1Hs2jvWTWGg55IQyDd2hQ/artifacts/public/build/target.crashreporter-symbols.zip...
[task 2022-10-26T03:07:23.636Z] 03:07:23     INFO -  raptor-gecko-profile Info: Opening profile at /opt/worker/tasks/task_166675178455006/build/blobber_upload_dir/browsertime-results/reddit/profiling/pages/www_reddit_com/r/technology/comments/9sqwyh/we_posed_as_100_senators_to_run_ads_on_facebook/data/geckoProfile-1.json.gz
[task 2022-10-26T03:07:24.053Z] 03:07:24     INFO -  raptor-gecko-profile Info: Symbolicating profile from /opt/worker/tasks/task_166675178455006/build/blobber_upload_dir/browsertime-results/reddit/profiling/pages/www_reddit_com/r/technology/comments/9sqwyh/we_posed_as_100_senators_to_run_ads_on_facebook/data/geckoProfile-1.json.gz
[task 2022-10-26T03:07:24.067Z] 03:07:24     INFO -  profiler Need to fetch PDB file for XUL A6535AEA49293BF2B56007B47C71EBB80
[task 2022-10-26T03:07:24.067Z] 03:07:24     INFO -  profiler Parsing SYM file at /var/folders/fn/jpjnpp817tg6r6w_7zq4f_0c000014/T/tmpxty4_z6k/XUL/A6535AEA49293BF2B56007B47C71EBB80/XUL.sym
[task 2022-10-26T03:07:33.123Z] 03:07:33     INFO -  profiler Found 358596 unique entries from 11376 PUBLIC lines, 347220 FUNC lines
[task 2022-10-26T03:07:33.171Z] 03:07:33     INFO -  profiler Storing libSymbolMap under [XUL][A6535AEA49293BF2B56007B47C71EBB80]
[task 2022-10-26T03:07:33.171Z] 03:07:33     INFO -  profiler Cache occupancy before MaybeEvict: 0/2000000
[task 2022-10-26T03:07:33.171Z] 03:07:33     INFO -  profiler 358596 symbols in cache after fetching symbol file
[task 2022-10-26T03:07:33.171Z] 03:07:33     INFO -  profiler Need to fetch PDB file for CoreVideo 5314E70D325F3E9899FC00FDF520747E0
[task 2022-10-26T03:07:33.172Z] 03:07:33     INFO -  profiler Error opening file /var/folders/fn/jpjnpp817tg6r6w_7zq4f_0c000014/T/tmpxty4_z6k/CoreVideo/5314E70D325F3E9899FC00FDF520747E0/CoreVideo.sym: [Errno 2] No such file or directory: '/var/folders/fn/jpjnpp817tg6r6w_7zq4f_0c000014/T/tmpxty4_z6k/CoreVideo/5314E70D325F3E9899FC00FDF520747E0/CoreVideo.sym'
[task 2022-10-26T03:07:33.172Z] 03:07:33     INFO -  profiler Error opening file /var/folders/fn/jpjnpp817tg6r6w_7zq4f_0c000014/T/tmpdliaqfry/CoreVideo/5314E70D325F3E9899FC00FDF520747E0/CoreVideo.sym: [Errno 2] No such file or directory: '/var/folders/fn/jpjnpp817tg6r6w_7zq4f_0c000014/T/tmpdliaqfry/CoreVideo/5314E70D325F3E9899FC00FDF520747E0/CoreVideo.sym'
[task 2022-10-26T03:07:33.173Z] 03:07:33     INFO -  profiler Error opening file /var/folders/fn/jpjnpp817tg6r6w_7zq4f_0c000014/T/tmpxty4_z6k/CoreVideo/5314E70D325F3E9899FC00FDF520747E0/CoreVideo.nmsym: [Errno 2] No such file or directory: '/var/folders/fn/jpjnpp817tg6r6w_7zq4f_0c000014/T/tmpxty4_z6k/CoreVideo/5314E70D325F3E9899FC00FDF520747E0/CoreVideo.nmsym'
[task 2022-10-26T03:07:33.173Z] 03:07:33     INFO -  profiler Error opening file /var/folders/fn/jpjnpp817tg6r6w_7zq4f_0c000014/T/tmpdliaqfry/CoreVideo/5314E70D325F3E9899FC00FDF520747E0/CoreVideo.nmsym: [Errno 2] No such file or directory: '/var/folders/fn/jpjnpp817tg6r6w_7zq4f_0c000014/T/tmpdliaqfry/CoreVideo/5314E70D325F3E9899FC00FDF520747E0/CoreVideo.nmsym'
[task 2022-10-26T03:07:33.173Z] 03:07:33     INFO -  profiler No matching sym files, tried ['FIREFOX', 'WINDOWS']