1688046 - Intermittent tools/profiler/tests/xpcshell/test_addProfilerMarker.js | xpcshell return code: 0 | - startTime should be the expected time - 132.594699 == 132.594

Status: RESOLVED FIXED

(Core :: Gecko Profiler, defect, P3)

Description

[Treeherder Bug Filer]

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

---

[task 2021-01-21T18:35:31.092Z] 18:35:31     INFO -  TEST-START | tools/profiler/tests/xpcshell/test_addProfilerMarker.js
[task 2021-01-21T18:35:31.282Z] 18:35:31  WARNING -  TEST-UNEXPECTED-FAIL | tools/profiler/tests/xpcshell/test_addProfilerMarker.js | xpcshell return code: 0
[task 2021-01-21T18:35:31.282Z] 18:35:31     INFO -  TEST-INFO took 167ms
[task 2021-01-21T18:35:31.282Z] 18:35:31     INFO -  >>>>>>>
[task 2021-01-21T18:35:31.282Z] 18:35:31     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2021-01-21T18:35:31.282Z] 18:35:31     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2021-01-21T18:35:31.282Z] 18:35:31     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2021-01-21T18:35:31.282Z] 18:35:31     INFO -  running event loop
[task 2021-01-21T18:35:31.283Z] 18:35:31     INFO -  tools/profiler/tests/xpcshell/test_addProfilerMarker.js | Starting
[task 2021-01-21T18:35:31.283Z] 18:35:31     INFO -  (xpcshell/head.js) | test pending (2)
[task 2021-01-21T18:35:31.283Z] 18:35:31     INFO -  "startTime used for markers with durations: 132.5947"
[task 2021-01-21T18:35:31.283Z] 18:35:31     INFO -  "Record markers without options object."
[task 2021-01-21T18:35:31.283Z] 18:35:31     INFO -  "Record markers providing the duration as the startTime property."
[task 2021-01-21T18:35:31.283Z] 18:35:31     INFO -  "Record markers to test the captureStack property."
[task 2021-01-21T18:35:31.283Z] 18:35:31     INFO -  "Record markers to test the category property"
[task 2021-01-21T18:35:31.283Z] 18:35:31     INFO -  "Capture the profile"
[task 2021-01-21T18:35:31.283Z] 18:35:31     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2021-01-21T18:35:31.283Z] 18:35:31     INFO -  "CONSOLE_MESSAGE: (info) No chrome package registered for chrome://branding/locale/brand.properties"
[task 2021-01-21T18:35:31.283Z] 18:35:31     INFO -  TEST-PASS | tools/profiler/tests/xpcshell/test_addProfilerMarker.js |  - Found 21 test markers in the captured profile - 21 == 21
[task 2021-01-21T18:35:31.284Z] 18:35:31     INFO -  "ChromeUtils.addProfilerMarker("test_addProfilerMarker0") -> ({name:"test_addProfilerMarker0", startTime:133.005268, endTime:0, phase:0, category:"JavaScript", data:(void 0)})"
[task 2021-01-21T18:35:31.284Z] 18:35:31     INFO -  TEST-PASS | tools/profiler/tests/xpcshell/test_addProfilerMarker.js |  - startTime should be a number - "number" == "number"
[task 2021-01-21T18:35:31.284Z] 18:35:31     INFO -  TEST-PASS | tools/profiler/tests/xpcshell/test_addProfilerMarker.js |  - startTime should be after the begining of the test - 133.005268 > 132.5947
[task 2021-01-21T18:35:31.284Z] 18:35:31     INFO -  TEST-PASS | tools/profiler/tests/xpcshell/test_addProfilerMarker.js |  - endTime should be a number - "number" == "number"
[task 2021-01-21T18:35:31.284Z] 18:35:31     INFO -  TEST-PASS | tools/profiler/tests/xpcshell/test_addProfilerMarker.js |  - endTime should be 0 - 0 == 0
[task 2021-01-21T18:35:31.284Z] 18:35:31     INFO -  TEST-PASS | tools/profiler/tests/xpcshell/test_addProfilerMarker.js |  - The data property should be undefined - "undefined" == "undefined"
[task 2021-01-21T18:35:31.284Z] 18:35:31     INFO -  "ChromeUtils.addProfilerMarker("test_addProfilerMarker1", 132.5947) -> ({name:"test_addProfilerMarker1", startTime:132.59469900000002, endTime:133.07497099999998, phase:1, category:"JavaScript", data:(void 0)})"
[task 2021-01-21T18:35:31.284Z] 18:35:31     INFO -  TEST-PASS | tools/profiler/tests/xpcshell/test_addProfilerMarker.js |  - startTime should be a number - "number" == "number"
[task 2021-01-21T18:35:31.284Z] 18:35:31  WARNING -  TEST-UNEXPECTED-FAIL | tools/profiler/tests/xpcshell/test_addProfilerMarker.js |  - startTime should be the expected time - 132.594699 == 132.5947
[task 2021-01-21T18:35:31.284Z] 18:35:31     INFO -  /Users/cltbld/tasks/task_1611252897/build/tests/xpcshell/tests/tools/profiler/tests/xpcshell/test_addProfilerMarker.js:expectDuration:38
[task 2021-01-21T18:35:31.284Z] 18:35:31     INFO -  /Users/cltbld/tasks/task_1611252897/build/tests/xpcshell/tests/tools/profiler/tests/xpcshell/test_addProfilerMarker.js:null:113
[task 2021-01-21T18:35:31.284Z] 18:35:31     INFO -  /Users/cltbld/tasks/task_1611252897/build/tests/xpcshell/tests/tools/profiler/tests/xpcshell/test_addProfilerMarker.js:null:179
[task 2021-01-21T18:35:31.284Z] 18:35:31     INFO -  /Users/cltbld/tasks/task_1611252897/build/tests/xpcshell/head.js:_do_main:239
[task 2021-01-21T18:35:31.285Z] 18:35:31     INFO -  /Users/cltbld/tasks/task_1611252897/build/tests/xpcshell/head.js:_execute_test:567
[task 2021-01-21T18:35:31.285Z] 18:35:31     INFO -  -e:null:1
[task 2021-01-21T18:35:31.285Z] 18:35:31     INFO -  exiting test
[task 2021-01-21T18:35:31.285Z] 18:35:31     INFO -  Unexpected exception NS_ERROR_ABORT:
[task 2021-01-21T18:35:31.285Z] 18:35:31     INFO -  _abort_failed_test@/Users/cltbld/tasks/task_1611252897/build/tests/xpcshell/head.js:827:20
[task 2021-01-21T18:35:31.285Z] 18:35:31     INFO -  do_report_result@/Users/cltbld/tasks/task_1611252897/build/tests/xpcshell/head.js:928:5
[task 2021-01-21T18:35:31.285Z] 18:35:31     INFO -  Assert<@/Users/cltbld/tasks/task_1611252897/build/tests/xpcshell/head.js:73:21
[task 2021-01-21T18:35:31.285Z] 18:35:31     INFO -  proto.report@resource://testing-common/Assert.jsm:233:10
[task 2021-01-21T18:35:31.285Z] 18:35:31     INFO -  equal@resource://testing-common/Assert.jsm:275:8
[task 2021-01-21T18:35:31.285Z] 18:35:31     INFO -  expectDuration@/Users/cltbld/tasks/task_1611252897/build/tests/xpcshell/tests/tools/profiler/tests/xpcshell/test_addProfilerMarker.js:38:10
[task 2021-01-21T18:35:31.285Z] 18:35:31     INFO -  @/Users/cltbld/tasks/task_1611252897/build/tests/xpcshell/tests/tools/profiler/tests/xpcshell/test_addProfilerMarker.js:113:19
[task 2021-01-21T18:35:31.285Z] 18:35:31     INFO -  @/Users/cltbld/tasks/task_1611252897/build/tests/xpcshell/tests/tools/profiler/tests/xpcshell/test_addProfilerMarker.js:179:31
[task 2021-01-21T18:35:31.285Z] 18:35:31     INFO -  _do_main@/Users/cltbld/tasks/task_1611252897/build/tests/xpcshell/head.js:239:6
[task 2021-01-21T18:35:31.285Z] 18:35:31     INFO -  _execute_test@/Users/cltbld/tasks/task_1611252897/build/tests/xpcshell/head.js:567:5
[task 2021-01-21T18:35:31.286Z] 18:35:31     INFO -  @-e:1:1
[task 2021-01-21T18:35:31.286Z] 18:35:31     INFO -  exiting test
[task 2021-01-21T18:35:31.286Z] 18:35:31     INFO -  <<<<<<<```

Comment 1

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

startTime should be the expected time - 132.594699 == 132.5947
This looks like bad rounding, and strictly comparing floating-point values after some processing can lead to false failures.

The test code does: Math.round(marker.startTime * 10 ** 6) / 10 ** 6, startTime, ...), with the global startTime being initialized to Math.round(Cu.now() * 10 ** 6) / 10 ** 6;.
So at first glance, this should always work, but my guess is that when going through multiple hoops (JS -> C++ -> JSON string -> JS), it may have been modified slightly, probably when converting between binary doubles and decimal JSON strings.

I'm thinking that maybe the initial startTime doesn't need to be rounded, and later equality tests should check for almost-equality, i.e., the difference should be small relative to the compared numbers, something like: Math.abs((a - b) / a) < 1 ** -6.

Florian, you wrote this test in bug 1674476, what do you think?
Please assign to yourself if you want to fix it, or to me if you don't have the time.

Comment 2

[BugBot [:suhaib / :marco/ :calixte]]

Set release status flags based on info from the regressing bug 1674476

Comment 3

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1
• comm-central: 1

Platform and build breakdown:

• macosx1014-64-qr: 1
  • opt: 1
• macosx1014-64-shippable: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1688046&startday=2021-01-18&endday=2021-01-24&tree=all

Comment 4

[Florian Quèze [:florian]]

Attachment: Bug 1688046 - Accept a rounding error of up to 1e-5 in floats used for timestamps in test_addProfilerMarker.js, r=gerald.

Comment 6

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/7c85440b7667
Accept a rounding error of up to 1e-5 in floats used for timestamps in test_addProfilerMarker.js, r=gerald.

Comment 7

[Andreea Pavel [:apavel]]

https://hg.mozilla.org/mozilla-central/rev/7c85440b7667

Comment 8

[BugBot [:suhaib / :marco/ :calixte]]

The patch landed in nightly and beta is affected.
:florian, is this bug important enough to require an uplift?
If not please set status_beta to wontfix.

For more information, please visit auto_nag documentation.

Comment 9

[Florian Quèze [:florian]]

It's a very low frequency intermittent failure, so I don't think it's worth uplifting; marking as wontfix. But it's also risk free as it's a test-only change, so if someone would like to uplift anyway, I don't mind.