1571171 - Perma [tier 2] tools/profiler/tests/xpcshell/test_merged_stacks.js | - The stack contains a few frame labels, as well as the JS functions that we called. - false == true

Status: RESOLVED FIXED

(Core :: Gecko Profiler, defect, P2)

Description

[Treeherder Bug Filer]

Filed by: opoprus [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=259720261&repo=mozilla-inbound
Full log: https://queue.taskcluster.net/v1/task/auH17HpTR_KNDaFaSRP5vQ/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://queue.taskcluster.net/v1/task/auH17HpTR_KNDaFaSRP5vQ/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

---

[task 2019-08-03T00:10:03.042Z] 00:10:03 INFO - TEST-START | tools/profiler/tests/xpcshell/test_merged_stacks.js
[task 2019-08-03T00:10:04.168Z] 00:10:04 WARNING - TEST-UNEXPECTED-FAIL | tools/profiler/tests/xpcshell/test_merged_stacks.js | xpcshell return code: 0
[task 2019-08-03T00:10:04.169Z] 00:10:04 INFO - TEST-INFO took 1127ms
[task 2019-08-03T00:10:04.169Z] 00:10:04 INFO - >>>>>>>
[task 2019-08-03T00:10:04.170Z] 00:10:04 INFO - PID 10429 | *** You are running in chaos test mode. See ChaosMode.h. ***
[task 2019-08-03T00:10:04.170Z] 00:10:04 INFO - (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2019-08-03T00:10:04.171Z] 00:10:04 INFO - (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2019-08-03T00:10:04.171Z] 00:10:04 INFO - (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2019-08-03T00:10:04.171Z] 00:10:04 INFO - running event loop
[task 2019-08-03T00:10:04.172Z] 00:10:04 INFO - "CONSOLE_MESSAGE: (info) No chrome package registered for chrome://branding/locale/brand.properties"
[task 2019-08-03T00:10:04.172Z] 00:10:04 INFO - tools/profiler/tests/xpcshell/test_merged_stacks.js | Starting
[task 2019-08-03T00:10:04.173Z] 00:10:04 INFO - (xpcshell/head.js) | test pending (2)
[task 2019-08-03T00:10:04.173Z] 00:10:04 INFO - (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2019-08-03T00:10:04.174Z] 00:10:04 INFO - PID 10429 | console.log: "Actual stack: " ["(root)", "xpcshell argument processing", "0x7f6b91df2e74", "0x7f6b9641a0b9", "0x7f6b963d2b7c", "0x7f6b963d2a0a", "js::RunScript", "0x7f6b94e64d0e", "0x7f6b94e660c2", "0x7f6b966261a6", "0x31aac439548e", "0x7f6b82a4fe8f", "0x31aac4397797", "0x7f6b9504e739", "0x7f6b94e78f68", "js::RunScript", "0x7f6b94e64d0e", "0x7f6b94e6eb15", "0x7f6b94e78fef", "0x7f6b94bab02e", "0x7f6b94ba9d58", "0x7f6b970afb85", "0x7f6b951cdf83", "0x7f6b94b360e5", "0x7f6b94b3577d", "0x7f6b962e3054", "0x563094fbd028", "0x7f6b9929fb1e"]
[task 2019-08-03T00:10:04.174Z] 00:10:04 INFO - PID 10429 | console.log: "Expected to contain: " ["(root)", "/^0x[0-9a-f]+$/", "/^0x[0-9a-f]+$/", "js::RunScript", "/^0x[0-9a-f]+$/", "/^0x[0-9a-f]+$/", "/^functionA \\(.+test_merged_stacks\\.js:\\d+:\\d+\\)$/", "/^functionB \\(.+test_merged_stacks\\.js:\\d+:\\d+\\)$/", "/^functionC \\(.+test_merged_stacks\\.js:\\d+:\\d+\\)$/", "/^0x[0-9a-f]+$/", "/^0x[0-9a-f]+$/"]
[task 2019-08-03T00:10:04.175Z] 00:10:04 INFO - "Could not find a match for: "/^functionA \(.+test_merged_stacks\.js:\d+:\d+\)$/""
[task 2019-08-03T00:10:04.175Z] 00:10:04 WARNING - TEST-UNEXPECTED-FAIL | tools/profiler/tests/xpcshell/test_merged_stacks.js | - The stack contains a few frame labels, as well as the JS functions that we called. - false == true
[task 2019-08-03T00:10:04.176Z] 00:10:04 INFO - /builds/worker/workspace/build/tests/xpcshell/tests/tools/profiler/tests/xpcshell/test_merged_stacks.js:null:34
[task 2019-08-03T00:10:04.176Z] 00:10:04 INFO - exiting test
[task 2019-08-03T00:10:04.177Z] 00:10:04 INFO - Unexpected exception NS_ERROR_ABORT:
[task 2019-08-03T00:10:04.177Z] 00:10:04 INFO - _abort_failed_test@/builds/worker/workspace/build/tests/xpcshell/head.js:788:20
[task 2019-08-03T00:10:04.178Z] 00:10:04 INFO - do_report_result@/builds/worker/workspace/build/tests/xpcshell/head.js:889:23
[task 2019-08-03T00:10:04.178Z] 00:10:04 INFO - Assert<@/builds/worker/workspace/build/tests/xpcshell/head.js:66:21
[task 2019-08-03T00:10:04.178Z] 00:10:04 INFO - proto.report@resource://testing-common/Assert.jsm:233:10
[task 2019-08-03T00:10:04.179Z] 00:10:04 INFO - proto.ok@resource://testing-common/Assert.jsm:259:10
[task 2019-08-03T00:10:04.179Z] 00:10:04 INFO - expectStackToContain@/builds/worker/workspace/build/tests/xpcshell/tests/tools/profiler/tests/xpcshell/head_profiler.js:143:16
[task 2019-08-03T00:10:04.180Z] 00:10:04 INFO - @/builds/worker/workspace/build/tests/xpcshell/tests/tools/profiler/tests/xpcshell/test_merged_stacks.js:34:23
[task 2019-08-03T00:10:04.180Z] 00:10:04 INFO - async*run_next_test/_run_next_test/<@/builds/worker/workspace/build/tests/xpcshell/head.js:1564:35
[task 2019-08-03T00:10:04.180Z] 00:10:04 INFO - _run_next_test@/builds/worker/workspace/build/tests/xpcshell/head.js:1564:38
[task 2019-08-03T00:10:04.181Z] 00:10:04 INFO - run@/builds/worker/workspace/build/tests/xpcshell/head.js:732:17
[task 2019-08-03T00:10:04.181Z] 00:10:04 INFO - _do_main@/builds/worker/workspace/build/tests/xpcshell/head.js:245:6
[task 2019-08-03T00:10:04.181Z] 00:10:04 INFO - _execute_test@/builds/worker/workspace/build/tests/xpcshell/head.js:572:13
[task 2019-08-03T00:10:04.182Z] 00:10:04 INFO - @-e:1:14
[task 2019-08-03T00:10:04.182Z] 00:10:04 INFO - exiting test
[task 2019-08-03T00:10:04.182Z] 00:10:04 INFO - PID 10429 | JavaScript error: resource://testing-common/PromiseTestUtils.jsm, line 112: uncaught exception: Object
[task 2019-08-03T00:10:04.183Z] 00:10:04 INFO - <<<<<<<

Comment 1

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

Greg, could you please have a look?

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 2
• mozilla-inbound: 1
• autoland: 1
• try: 5

Platform breakdown:

• linux64: 2
• linux64-shippable: 4
• macosx1014-64-shippable: 1
• linux64-shippable-qr: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1571171&startday=2019-07-29&endday=2019-08-04&tree=all

Comment 3

[Greg Tatum [:gregtatum]]

This is failing because we are missing some JavaScript frames in the stack, and there are only native frames. This is either a bug where JS frames are not created, or a case where we just happen to collect a stack where there is no JavaScript stack frame present. To fix the latter, I can rewrite the test to keep on collecting a sample for N iterations, until a JS frame is present. It would also be helpful to actually symbolicate to double verify those symbols aren't an error case.

[
  "(root)",
  "xpcshell argument processing",
  "0x7f6b91df2e74",
  "0x7f6b9641a0b9",
  "0x7f6b963d2b7c",
  "0x7f6b963d2a0a",
  "js::RunScript",
  "0x7f6b94e64d0e",
  "0x7f6b94e660c2",
  "0x7f6b966261a6",
  "0x31aac439548e",
  "0x7f6b82a4fe8f",
  "0x31aac4397797",
  "0x7f6b9504e739",
  "0x7f6b94e78f68",
  "js::RunScript",
  "0x7f6b94e64d0e",
  "0x7f6b94e6eb15",
  "0x7f6b94e78fef",
  "0x7f6b94bab02e",
  "0x7f6b94ba9d58",
  "0x7f6b970afb85",
  "0x7f6b951cdf83",
  "0x7f6b94b360e5",
  "0x7f6b94b3577d",
  "0x7f6b962e3054",
  "0x563094fbd028",
  "0x7f6b9929fb1e"
]

Comment 4

[Greg Tatum [:gregtatum]]

I could not reproduce this on macOS, it makes me concerned that it's a bug.

Comment 5

[Greg Tatum [:gregtatum]]

I was able to reproduce this pretty consistently locally on an artifact Linux optimized build, but not on an artifact Linux debug build.

Comment 6

[Greg Tatum [:gregtatum]]

Looks like this is failing due to my use of an async function during my sample check. I'm going to rewrite things and see if it clears it up.

Comment 7

[Greg Tatum [:gregtatum]]

Attachment: Bug 1571171 - Make test helper doAtLeastOnePeriodicSample non-async; r?canaltinova

Comment 8

[Greg Tatum [:gregtatum]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=409f3f7395046cf2c8d30ba4c999c55c2d6f0811

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/757856705ec4
Make test helper doAtLeastOnePeriodicSample non-async; r=canaltinova

Comment 10

[Andrei Ciure[:aciure]]

https://hg.mozilla.org/mozilla-central/rev/757856705ec4

Comment 11

[Noemi Erli[:noemi_erli]]

This is failing again:
https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&selectedJob=260325865&resultStatus=testfailed%2Cbusted%2Cexception&revision=4ba2efc86669143d4ce3e31c6d8c180a0dbf28bf&searchStr=xpcshell

Comment 12

[Greg Tatum [:gregtatum]]

This is a different failure, and looks like a bug in the profiler where stack walking fails. I believe this is Bug 1434402 where we fail to stackwalk through Ion code.

[
  "(root)",
  "xpcshell argument processing",
  "js::RunScript",
  "js::RunScript",
  "XPCWrappedJS method call",
  "js::RunScript",
  "functionA (/builds/worker/workspace/build/tests/xpcshell/tests/tools/profiler/tests/xpcshell/test_merged_stacks.js:65:9)",
  "functionB (/builds/worker/workspace/build/tests/xpcshell/tests/tools/profiler/tests/xpcshell/test_merged_stacks.js:69:9)",
  "functionC (/builds/worker/workspace/build/tests/xpcshell/tests/tools/profiler/tests/xpcshell/test_merged_stacks.js:73:15)",
  "doAtLeastOnePeriodicSample (/builds/worker/workspace/build/tests/xpcshell/tests/tools/profiler/tests/xpcshell/head_profiler.js:91:9)",
  "getProfileSampleCount (/builds/worker/workspace/build/tests/xpcshell/tests/tools/profiler/tests/xpcshell/head_profiler.js:92:11)",
  "0x55c037c3ba03",
  "0x7f19af0cbaf8"
]

I'm not confident I'm going to be able to reproduce this locally. I'd be curious to see what the failure rate looks like here.

A potential fix would be attempt to de-optimize the function. If I recall correctly, putting a debugger statement in a function ensures that it will never be optimized, so perhaps that could be band-aid to make this not fail, although this is a failure case.

Comment 13

[Intermittent Failures Robot]

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

** 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:

• try: 11
• mozilla-central: 2
• autoland: 21
• mozilla-inbound: 3

Platform breakdown:

• linux64-devedition: 1
• linux64: 28
• macosx1014-64: 2
• macosx1014-64-shippable: 3
• linux64-shippable: 2
• linux64-shippable-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1571171&startday=2019-08-05&endday=2019-08-11&tree=all

Comment 14

[Intermittent Failures Robot]

36 failures in 4839 pushes (0.007 failures/push) were associated with this bug in the last 7 days.

** 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:

• autoland: 26
• mozilla-central: 6
• mozilla-inbound: 4

Platform breakdown:

• linux64: 36

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1571171&startday=2019-08-12&endday=2019-08-18&tree=all

Comment 15

[Intermittent Failures Robot]

1 failures in 5073 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform breakdown:

• linux64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1571171&startday=2019-08-19&endday=2019-08-25&tree=all

Comment 16

[Intermittent Failures Robot]

1 failures in 5047 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 1

Platform breakdown:

• windows10-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1571171&startday=2019-08-26&endday=2019-09-01&tree=all

Comment 17

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 7

Platform breakdown:

• linux1804-64-ccov: 7

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1571171&startday=2020-04-20&endday=2020-04-26&tree=all

Comment 18

[Alexandru Michis [:malexandru]]

This started permafailing on central since this push:
https://hg.mozilla.org/mozilla-central/pushloghtml?changeset=be13cb1076bc1923240b3ec450cf177d2b4ad42b

https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&group_state=expanded&searchStr=linux%2C18.04%2Cx64%2Cccov%2Copt%2Cxpcshell%2Ctests%2Ctest-linux1804-64-ccov%2Fopt-xpcshell-e10s&fromchange=1d081d5764889cc2eb45369104a374728ad979f3&tochange=be13cb1076bc1923240b3ec450cf177d2b4ad42b&selectedTaskRun=aYbIC49bTQO_AumLa8QXvQ-0

Greg, could you please take a look?

Comment 19

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

(In reply to Alexandru Michis [:malexandru] from comment #18)

This started permafailing on central since this push:
https://hg.mozilla.org/mozilla-central/pushloghtml?changeset=be13cb1076bc1923240b3ec450cf177d2b4ad42b

This push switches to the new profile buffer code, so it may be my fault! I'll have a look...

Comment 20

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

The new chunk-based buffer takes the requested size as-is, and cuts it in (at least) 4 chunks. The test sets the buffer capacity to a low number, which is too small for a chunk to hold the full stack samples (which are presumably bigger on the ccov build).

I will add a generic clamping mechanism, to ensure that the profiler uses a buffer that's not too small, and not too big either.

Comment 21

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

Attachment: Bug 1571171 - Clamp profiler capacity to allowed values - r?canaltinova!,gregtatum

The profiler can be given any power of two, but there were no safety checks to ensure that the buffer had a minimum workable capacity (to hold at least 4 chunks, each capable of holding at least one stack sample), and also to prevent large buffers that could break the currently-supported 2GiB limit.

This fixes the issue with test_merged_stacks.js, which was requesting a too-small buffer. (This started when we switched to the chunk-based buffer, because the profiler was blindly using the provided number as maximum, and dividing that size by 4 for each chunk, which was not enough to hold a full sample in some builds.)

Comment 22

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 13

Platform breakdown:

• linux1804-64-ccov: 13

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1571171&startday=2020-04-27&endday=2020-05-03&tree=all

Comment 23

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/557f9a484473
Clamp profiler capacity to allowed values - r=canaltinova

Comment 24

[Cristina Coroiu [:ccoroiu]]

https://hg.mozilla.org/mozilla-central/rev/557f9a484473