Closed Bug 1682027 Opened 4 years ago Closed 16 days ago

High frequency results.MissingResultsError: Browsertime cycle missing ['paintTiming', 'first-contentful-paint'] measurement / Browsertime cycle missing ['largestContentfulPaint', 'renderTime'] measurement

Categories

(Testing :: Raptor, defect, P5)

defect

Tracking

(firefox123 disabled, firefox124 disabled)

RESOLVED INCOMPLETE
Tracking Status
firefox123 --- disabled
firefox124 --- disabled

People

(Reporter: intermittent-bug-filer, Assigned: afinder)

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell unknown])

Attachments

(2 files, 1 obsolete file)

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


[task 2020-12-11T17:29:00.502Z] 17:28:26     INFO -  perftest-results-handler Info: found browsertime results at /builds/task_160770594621467/workspace/build/blobber_upload_dir/browsertime-results/espn/browsertime.json
[task 2020-12-11T17:29:00.503Z] 17:28:26     INFO -  perftest-results-handler Info: parsing results from browsertime json
[task 2020-12-11T17:29:00.503Z] 17:28:26    ERROR -  Traceback (most recent call last):
[task 2020-12-11T17:29:00.503Z] 17:28:26     INFO -    File "/builds/task_160770594621467/workspace/build/tests/raptor/raptor/raptor.py", line 205, in <module>
[task 2020-12-11T17:29:00.503Z] 17:28:26     INFO -      main()
[task 2020-12-11T17:29:00.503Z] 17:28:26     INFO -    File "/builds/task_160770594621467/workspace/build/tests/raptor/raptor/raptor.py", line 151, in main
[task 2020-12-11T17:29:00.503Z] 17:28:26     INFO -      success = raptor.run_tests(raptor_test_list, raptor_test_names)
[task 2020-12-11T17:29:00.503Z] 17:28:26     INFO -    File "/builds/task_160770594621467/workspace/build/tests/raptor/raptor/browsertime/android.py", line 195, in run_tests
[task 2020-12-11T17:29:00.503Z] 17:28:26     INFO -      return super(BrowsertimeAndroid, self).run_tests(tests, test_names)
[task 2020-12-11T17:29:00.503Z] 17:28:26     INFO -    File "/builds/task_160770594621467/workspace/build/tests/raptor/raptor/perftest.py", line 399, in run_tests
[task 2020-12-11T17:29:00.503Z] 17:28:26     INFO -      return self.process_results(tests, test_names)
[task 2020-12-11T17:29:00.503Z] 17:28:26     INFO -    File "/builds/task_160770594621467/workspace/build/tests/raptor/raptor/perftest.py", line 427, in process_results
[task 2020-12-11T17:29:00.503Z] 17:28:26     INFO -      return self.results_handler.summarize_and_output(self.config, tests, test_names)
[task 2020-12-11T17:29:00.503Z] 17:28:26     INFO -    File "/builds/task_160770594621467/workspace/build/tests/raptor/raptor/results.py", line 720, in summarize_and_output
[task 2020-12-11T17:29:00.503Z] 17:28:26     INFO -      test.get("measure"),
[task 2020-12-11T17:29:00.503Z] 17:28:26     INFO -    File "/builds/task_160770594621467/workspace/build/tests/raptor/raptor/results.py", line 578, in parse_browsertime_json
[task 2020-12-11T17:29:00.503Z] 17:28:26     INFO -      raptor
[task 2020-12-11T17:29:00.503Z] 17:28:26     INFO -  results.MissingResultsError: Browsertime cycle missing ['paintTiming', 'first-contentful-paint'] measurement
[task 2020-12-11T17:29:00.503Z] 17:28:26    ERROR - Return code: 1
[task 2020-12-11T17:29:00.503Z] 17:28:26  WARNING - setting return code to 1```
Component: Performance → Raptor
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → INCOMPLETE
Status: REOPENED → RESOLVED
Closed: 4 years ago4 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 4 years ago3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 3 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago1 year ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 1 year ago1 year ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

Update

There have been 33 total failures within the last 7 days, all of them on Android 11.0 Samsung A51 AArch64 Shippable opt .

Recent log: https://treeherder.mozilla.org/logviewer?job_id=435721379&repo=autoland&lineNumber=3042

[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO -  raptor-perftest Info: Removing temporary directory: /tmp/tmpv4ybw7t3
[task 2023-11-10T02:21:05.909Z] 02:20:55    ERROR -  Traceback (most recent call last):
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO -    File "/builds/task_169958057011151/workspace/build/tests/raptor/raptor/raptor.py", line 186, in <module>
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO -      main()
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO -    File "/builds/task_169958057011151/workspace/build/tests/raptor/raptor/raptor.py", line 135, in main
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO -      success = raptor.run_tests(raptor_test_list, raptor_test_names)
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO -    File "/builds/task_169958057011151/workspace/build/tests/raptor/raptor/browsertime/android.py", line 257, in run_tests
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO -      return super(BrowsertimeAndroid, self).run_tests(tests, test_names)
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO -    File "/builds/task_169958057011151/workspace/build/tests/raptor/raptor/perftest.py", line 488, in run_tests
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO -      return self.process_results(tests, test_names)
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO -    File "/builds/task_169958057011151/workspace/build/tests/raptor/raptor/perftest.py", line 510, in process_results
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO -      res = self.results_handler.summarize_and_output(self.config, tests, test_names)
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO -    File "/builds/task_169958057011151/workspace/build/tests/raptor/raptor/results.py", line 1074, in summarize_and_output
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO -      for new_result in self.parse_browsertime_json(
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO -    File "/builds/task_169958057011151/workspace/build/tests/raptor/raptor/results.py", line 827, in parse_browsertime_json
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO -      raise MissingResultsError(
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO -  results.MissingResultsError: Browsertime cycle missing ['paintTiming', 'first-contentful-paint'] measurement
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO - Return code: 1
[task 2023-11-10T02:21:05.909Z] 02:20:55  WARNING - setting return code to 1
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO - Killing logcat pid 973.
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO - Copying Raptor results to upload dir:
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO - /builds/task_169958057011151/workspace/build/blobber_upload_dir/perfherder-data.json
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO - Copying raptor results from /builds/task_169958057011151/workspace/build/raptor.json to /builds/task_169958057011151/workspace/build/blobber_upload_dir/perfherder-data.json
[task 2023-11-10T02:21:05.909Z] 02:20:55 CRITICAL - Error copying results /builds/task_169958057011151/workspace/build/raptor.json to upload dir /builds/task_169958057011151/workspace/build/blobber_upload_dir/perfherder-data.json

Alex, can you help us assign this to someone?
Thank you.

Flags: needinfo?(afinder)
Whiteboard: [stockwell needswork:owner]

(In reply to Natalia Csoregi [:nataliaCs] from comment #56)

Update

There have been 33 total failures within the last 7 days, all of them on Android 11.0 Samsung A51 AArch64 Shippable opt .

Recent log: https://treeherder.mozilla.org/logviewer?job_id=435721379&repo=autoland&lineNumber=3042

[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO -  raptor-perftest Info: Removing temporary directory: /tmp/tmpv4ybw7t3
[task 2023-11-10T02:21:05.909Z] 02:20:55    ERROR -  Traceback (most recent call last):
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO -    File "/builds/task_169958057011151/workspace/build/tests/raptor/raptor/raptor.py", line 186, in <module>
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO -      main()
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO -    File "/builds/task_169958057011151/workspace/build/tests/raptor/raptor/raptor.py", line 135, in main
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO -      success = raptor.run_tests(raptor_test_list, raptor_test_names)
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO -    File "/builds/task_169958057011151/workspace/build/tests/raptor/raptor/browsertime/android.py", line 257, in run_tests
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO -      return super(BrowsertimeAndroid, self).run_tests(tests, test_names)
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO -    File "/builds/task_169958057011151/workspace/build/tests/raptor/raptor/perftest.py", line 488, in run_tests
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO -      return self.process_results(tests, test_names)
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO -    File "/builds/task_169958057011151/workspace/build/tests/raptor/raptor/perftest.py", line 510, in process_results
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO -      res = self.results_handler.summarize_and_output(self.config, tests, test_names)
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO -    File "/builds/task_169958057011151/workspace/build/tests/raptor/raptor/results.py", line 1074, in summarize_and_output
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO -      for new_result in self.parse_browsertime_json(
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO -    File "/builds/task_169958057011151/workspace/build/tests/raptor/raptor/results.py", line 827, in parse_browsertime_json
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO -      raise MissingResultsError(
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO -  results.MissingResultsError: Browsertime cycle missing ['paintTiming', 'first-contentful-paint'] measurement
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO - Return code: 1
[task 2023-11-10T02:21:05.909Z] 02:20:55  WARNING - setting return code to 1
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO - Killing logcat pid 973.
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO - Copying Raptor results to upload dir:
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO - /builds/task_169958057011151/workspace/build/blobber_upload_dir/perfherder-data.json
[task 2023-11-10T02:21:05.909Z] 02:20:55     INFO - Copying raptor results from /builds/task_169958057011151/workspace/build/raptor.json to /builds/task_169958057011151/workspace/build/blobber_upload_dir/perfherder-data.json
[task 2023-11-10T02:21:05.909Z] 02:20:55 CRITICAL - Error copying results /builds/task_169958057011151/workspace/build/raptor.json to upload dir /builds/task_169958057011151/workspace/build/blobber_upload_dir/perfherder-data.json

Alex, can you help us assign this to someone?
Thank you.

I'll take a look at this one starting on Monday. I'll log a separate defect for this. Thanks Natalia!

Planning to try and reproduce this locally on an A51, since these failures are mostly occurring on Android.

Flags: needinfo?(afinder)
Flags: needinfo?(afinder)

Managed to reproduce the issue in a try push. I haven't reproduced it locally yet. The exception seems to be raised here, in results.py. Currently looking into a way to fix the issue.

Flags: needinfo?(afinder)
Flags: needinfo?(afinder)

Update on the status of the investigation: it seems that the problem resides in parsing the cold-browsertime.json artifact file. Some of the nodes in the browserScripts.timings node are missing the paintTiming key, which contain the first-contentful-paint value. This happens around the moment when logging the following line: "Get visual metrics from the video". I looked at the attached artifact video files, but they don't seem to be corrupted. So, we can try a few solutions: disabling "run-visual-metrics" for the facebook essential tests on Android, or seeing if there are any VisualMetrics values at the browsertime repo that we can tweak to avoid the missing paintTiming values.

Flags: needinfo?(afinder)

it is all facebook, I wonder if re-recording might help

(In reply to Kash Shampur [:kshampur] ⌚EST from comment #64)

it is all facebook, I wonder if re-recording might help

Thanks for suggesting Kash! I'll try that as well.

Summary: Intermittent results.MissingResultsError: Browsertime cycle missing ['paintTiming', 'first-contentful-paint'] measurement → Intermittent results.MissingResultsError: Browsertime cycle missing ['paintTiming', 'first-contentful-paint'] measurement / Browsertime cycle missing ['largestContentfulPaint', 'renderTime'] measurement
Summary: Intermittent results.MissingResultsError: Browsertime cycle missing ['paintTiming', 'first-contentful-paint'] measurement / Browsertime cycle missing ['largestContentfulPaint', 'renderTime'] measurement → High frequency results.MissingResultsError: Browsertime cycle missing ['paintTiming', 'first-contentful-paint'] measurement / Browsertime cycle missing ['largestContentfulPaint', 'renderTime'] measurement

Submitted a try push with an increase in the post_startup_delay, but it's still failing. Also tried re-recording facebook for mobile, but it's failing in CI, even with only the facebook site targeted in pageload_sites.json. Currently looking into re-recording the site locally.

:afinder, do you have any updates on the re-recording?

Flags: needinfo?(afinder)

Hi sparky! I just received access to the 1Password vault to update the login test. I'll retry the re-recording today.

Flags: needinfo?(afinder)

I tried the re-recording, but I'm having issues with setting up the RAPTOR_LOGINS file for the recording.

Update

There have been 42 total failures within the last 7 days, all of them on Android 11.0 Samsung A51 AArch64 Shippable opt.

Recent log: https://treeherder.mozilla.org/logviewer?job_id=441810055&repo=autoland&lineNumber=2762

Whiteboard: [stockwell disable-recommended] → [stockwell disable-recommended][stockwell needswork]

Found how to set the RAPTOR_LOGINS json file in the environment variables for re-recording login tests, but I'll need to modify the content of the file to match the expected format in testing/performance/perftest_record.js. Will have a patch ready for review tomorrow with the re-recording.

Unfortunately, it looks like the account used for running the Facebook test has been locked since September 21, 2023. We won't be able to re-record the test without a valid, active Facebook account. Dave Hunt is currently looking into resolving the account issue.

:afinder, can you disable this test on the failing platform for now?

Flags: needinfo?(afinder)

(In reply to Greg Mierzwinski [:sparky] from comment #81)

:afinder, can you disable this test on the failing platform for now?

Will submit a patch for disabling them this week.

Flags: needinfo?(afinder)
Assignee: nobody → afinder
Attachment #9372299 - Attachment description: WIP: Bug 1682027 Disable Facebook Android Test r?#perftest → Bug 1682027 Disable Facebook Android Test r?#perftest
Pushed by afinder@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/ce67ec7f0570 Disable Facebook Android Test r=perftest-reviewers,sparky
Status: REOPENED → RESOLVED
Closed: 1 year ago10 months ago
Resolution: --- → FIXED
Target Milestone: --- → 123 Branch
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Attachment #9377761 - Flags: approval-mozilla-beta?

Uplift Approval Request

  • Explanation of risk level: This patch disables a test.
  • Code covered by automated testing: no
  • User impact if declined: None
  • Fix verified in Nightly: yes
  • Risk associated with taking this patch: None
  • Needs manual QE test: no
  • Steps to reproduce for manual QE testing: None
  • String changes made/needed: None
  • Is Android affected?: yes
Attachment #9377761 - Attachment is obsolete: true
Attachment #9377761 - Flags: approval-mozilla-beta?
Status: REOPENED → NEW
Target Milestone: 123 Branch → ---
Keywords: leave-open
Whiteboard: [stockwell disable-recommended][stockwell unknown] → [stockwell unknown]
Status: NEW → RESOLVED
Closed: 10 months ago16 days ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: