1756146 - Intermittent 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 DUPLICATE of bug 1760142

(Core :: Gecko Profiler, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2022-02-18T11:44:49.837Z] 11:44:49  WARNING -  TEST-UNEXPECTED-FAIL | tools/profiler/tests/xpcshell/test_merged_stacks.js | xpcshell return code: 0
[task 2022-02-18T11:44:49.837Z] 11:44:49     INFO -  TEST-INFO took 2722ms
[task 2022-02-18T11:44:49.838Z] 11:44:49     INFO -  >>>>>>>
[task 2022-02-18T11:44:49.838Z] 11:44:49     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2022-02-18T11:44:49.838Z] 11:44:49     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2022-02-18T11:44:49.838Z] 11:44:49     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2022-02-18T11:44:49.838Z] 11:44:49     INFO -  running event loop
[task 2022-02-18T11:44:49.838Z] 11:44:49     INFO -  tools/profiler/tests/xpcshell/test_merged_stacks.js | Starting
[task 2022-02-18T11:44:49.838Z] 11:44:49     INFO -  (xpcshell/head.js) | test pending (2)
[task 2022-02-18T11:44:49.838Z] 11:44:49     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2022-02-18T11:44:49.839Z] 11:44:49     INFO -  "Could not find a match for: "js::RunScript""
[task 2022-02-18T11:44:49.839Z] 11:44:49  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 2022-02-18T11:44:49.840Z] 11:44:49     INFO -  test_merged_stacks.js:null:31
[task 2022-02-18T11:44:49.840Z] 11:44:49     INFO -  /data/local/tmp/test_root/xpc/head.js:_do_main:240
[task 2022-02-18T11:44:49.840Z] 11:44:49     INFO -  /data/local/tmp/test_root/xpc/head.js:_execute_test:604
[task 2022-02-18T11:44:49.840Z] 11:44:49     INFO -  -e:null:1
[task 2022-02-18T11:44:49.840Z] 11:44:49     INFO -  exiting test
[task 2022-02-18T11:44:49.840Z] 11:44:49     INFO -  Unexpected exception NS_ERROR_ABORT:
[task 2022-02-18T11:44:49.840Z] 11:44:49     INFO -  _abort_failed_test@/data/local/tmp/test_root/xpc/head.js:875:20
[task 2022-02-18T11:44:49.840Z] 11:44:49     INFO -  do_report_result@/data/local/tmp/test_root/xpc/head.js:976:5
[task 2022-02-18T11:44:49.840Z] 11:44:49     INFO -  Assert<@/data/local/tmp/test_root/xpc/head.js:75:21
[task 2022-02-18T11:44:49.840Z] 11:44:49     INFO -  proto.report@resource://testing-common/Assert.jsm:228:10
[task 2022-02-18T11:44:49.840Z] 11:44:49     INFO -  proto.ok@resource://testing-common/Assert.jsm:254:10
[task 2022-02-18T11:44:49.840Z] 11:44:49     INFO -  expectStackToContain@/data/local/tmp/test_root/xpc/tools/profiler/tests/xpcshell/head.js:100:16
[task 2022-02-18T11:44:49.840Z] 11:44:49     INFO -  @test_merged_stacks.js:31:23
[task 2022-02-18T11:44:49.840Z] 11:44:49     INFO -  _do_main@/data/local/tmp/test_root/xpc/head.js:240:6
[task 2022-02-18T11:44:49.840Z] 11:44:49     INFO -  _execute_test@/data/local/tmp/test_root/xpc/head.js:604:5
[task 2022-02-18T11:44:49.840Z] 11:44:49     INFO -  @-e:1:1
[task 2022-02-18T11:44:49.840Z] 11:44:49     INFO -  exiting test
[task 2022-02-18T11:44:49.841Z] 11:44:49     INFO -  "CONSOLE_MESSAGE: (info) Actual stack:  (root),xpcshell argument processing,js::RunScript,js::RunScript,XPCWrappedJS method call,js::RunScript,functionA (test_merged_stacks.js:64:18),functionB (test_merged_stacks.js:68:18),functionC (test_merged_stacks.js:72:24),captureAtLeastOneJsSample (file:///data/local/tmp/test_root/xpc/tools/profiler/tests/xpcshell/shared-head.js:204:34),getProfileSampleCount (file:///data/local/tmp/test_root/xpc/tools/profiler/tests/xpcshell/shared-head.js:205:32),nsIProfiler.getProfileData,0x36,0x79c10e558cb5"
[task 2022-02-18T11:44:49.841Z] 11:44:49     INFO -  "CONSOLE_MESSAGE: (info) 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 2022-02-18T11:44:49.841Z] 11:44:49     INFO -  <<<<<<<
[task 2022-02-18T11:44:49.932Z] 11:44:49     INFO -  Cleaning up profile for /builds/worker/workspace/build/tests/xpcshell/tests/tools/profiler/tests/xpcshell/test_merged_stacks.js folder: /data/local/tmp/test_root/xpc/p/c4090c8e-9ea9-4d13-9a48-735132b30fd6
[task 2022-02-18T11:44:50.203Z] 11:44:50     INFO -  INFO | Result summary:
[task 2022-02-18T11:44:50.203Z] 11:44:50     INFO -  INFO | Passed: 850
[task 2022-02-18T11:44:50.203Z] 11:44:50  WARNING -  INFO | Failed: 1
[task 2022-02-18T11:44:50.203Z] 11:44:50  WARNING -  One or more unittests failed.
[task 2022-02-18T11:44:50.204Z] 11:44:50     INFO -  INFO | Todo: 7
[task 2022-02-18T11:44:50.204Z] 11:44:50     INFO -  INFO | Retried: 1
[task 2022-02-18T11:44:50.204Z] 11:44:50     INFO -  SUITE-END | took 599s
[task 2022-02-18T11:44:50.204Z] 11:44:50     INFO -  Node moz-http2 server shutting down ...
[task 2022-02-18T11:44:50.204Z] 11:44:50     INFO -  Process stdout
[task 2022-02-18T11:44:50.204Z] 11:44:50     INFO -  forked process without handler sent: {"error":"","errorStack":""}
[task 2022-02-18T11:44:50.210Z] 11:44:50     INFO -  Process stderr
[task 2022-02-18T11:44:50.210Z] 11:44:50     INFO -  (node:2854) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 window_update listeners added to [Flow]. Use emitter.setMaxListeners() to increase limit
[task 2022-02-18T11:44:50.210Z] 11:44:50     INFO -  (node:2854) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 window_update listeners added to [Flow]. Use emitter.setMaxListeners() to increase limit
[task 2022-02-18T11:44:50.264Z] 11:44:50    ERROR - Return code: 1
[task 2022-02-18T11:44:50.265Z] 11:44:50     INFO - TinderboxPrint: xpcshell<br/>850/<em class="testfail">1</em>/7
[task 2022-02-18T11:44:50.265Z] 11:44:50     INFO - ##### xpcshell log ends
[task 2022-02-18T11:44:50.265Z] 11:44:50  WARNING - # TBPL WARNING #
[task 2022-02-18T11:44:50.265Z] 11:44:50  WARNING - setting return code to 1
[task 2022-02-18T11:44:50.265Z] 11:44:50  WARNING - The xpcshell suite: xpcshell ran with return status: WARNING
[task 2022-02-18T11:44:50.265Z] 11:44:50     INFO - Running post-action listener: _package_coverage_data
[task 2022-02-18T11:44:50.266Z] 11:44:50     INFO - Running post-action listener: _resource_record_post_action
[task 2022-02-18T11:44:50.266Z] 11:44:50     INFO - Running post-action listener: process_java_coverage_data
[task 2022-02-18T11:44:50.266Z] 11:44:50     INFO - Running post-action listener: stop_device
[task 2022-02-18T11:44:50.679Z] 11:44:50     INFO - Killing logcat pid 1910.
[task 2022-02-18T11:44:50.679Z] 11:44:50     INFO - Killing every process called qemu-system-x86_64
[task 2022-02-18T11:44:50.688Z] 11:44:50     INFO - [mozharness: 2022-02-18 11:44:50.688123Z] Finished run-tests step (success)
[task 2022-02-18T11:44:50.688Z] 11:44:50     INFO - Running post-run listener: _resource_record_post_run
[task 2022-02-18T11:44:51.025Z] 11:44:51     INFO - Total resource usage - Wall time: 645s; CPU: 67%; Read bytes: 40960; Write bytes: 197242880; Read time: 2; Write time: 15513
[task 2022-02-18T11:44:51.025Z] 11:44:51     INFO - TinderboxPrint: CPU usage<br/>67.4%
[task 2022-02-18T11:44:51.025Z] 11:44:51     INFO - TinderboxPrint: I/O read bytes / time<br/>40,960 / 2
[task 2022-02-18T11:44:51.025Z] 11:44:51     INFO - TinderboxPrint: I/O write bytes / time<br/>197,242,880 / 15,513
[task 2022-02-18T11:44:51.025Z] 11:44:51     INFO - TinderboxPrint: CPU guest<br/>12,328.1 (16.9%)
[task 2022-02-18T11:44:51.025Z] 11:44:51     INFO - TinderboxPrint: CPU idle<br/>19,777.4 (27.1%)
[task 2022-02-18T11:44:51.025Z] 11:44:51     INFO - TinderboxPrint: CPU system<br/>5,764.6 (7.9%)
[task 2022-02-18T11:44:51.025Z] 11:44:51     INFO - TinderboxPrint: CPU user<br/>34,379.9 (47.1%)
[task 2022-02-18T11:44:51.025Z] 11:44:51     INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2022-02-18T11:44:51.026Z] 11:44:51     INFO - start-emulator - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2022-02-18T11:44:51.031Z] 11:44:51     INFO - verify-device - Wall time: 29s; CPU: 48%; Read bytes: 0; Write bytes: 3850240; Read time: 0; Write time: 721
[task 2022-02-18T11:44:51.032Z] 11:44:51     INFO - install - Wall time: 3s; CPU: 37%; Read bytes: 0; Write bytes: 73728; Read time: 0; Write time: 2
[task 2022-02-18T11:44:51.120Z] 11:44:51     INFO - run-tests - Wall time: 612s; CPU: 68%; Read bytes: 40960; Write bytes: 193110016; Read time: 2; Write time: 14785
[task 2022-02-18T11:44:52.877Z] 11:44:52  WARNING - returning nonzero exit status 1
[task 2022-02-18T11:44:53.043Z] cleanup
[task 2022-02-18T11:44:53.043Z] + cleanup
[task 2022-02-18T11:44:53.043Z] + local rv=1
[task 2022-02-18T11:44:53.043Z] + [[ -s /builds/worker/.xsession-errors ]]
[task 2022-02-18T11:44:53.043Z] + cp /builds/worker/.xsession-errors /builds/worker/artifacts/public/xsession-errors.log
[task 2022-02-18T11:44:53.045Z] + '[' ']'
[task 2022-02-18T11:44:53.045Z] + true
[task 2022-02-18T11:44:53.045Z] + cleanup_xvfb
[task 2022-02-18T11:44:53.045Z] ++ pidof Xvfb
[task 2022-02-18T11:44:53.050Z] + local xvfb_pid=54
[task 2022-02-18T11:44:53.050Z] + local vnc=false
[task 2022-02-18T11:44:53.050Z] + local interactive=false
[task 2022-02-18T11:44:53.050Z] + '[' -n 54 ']'
[task 2022-02-18T11:44:53.050Z] + [[ false == false ]]
[task 2022-02-18T11:44:53.050Z] + [[ false == false ]]
[task 2022-02-18T11:44:53.050Z] + kill 54
[task 2022-02-18T11:44:53.050Z] + screen -XS xvfb quit
[task 2022-02-18T11:44:53.063Z] + exit 1
[taskcluster 2022-02-18 11:44:53.834Z] === Task Finished ===
[taskcluster 2022-02-18 11:45:01.423Z] Unsuccessful task run with exit code: 1 completed in 843.834 seconds

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 1

Platform and build breakdown:

• android-em-7-0-x86_64-shippable-lite-qr: 1
  • opt: 1

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

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 3

Platform and build breakdown:

• android-em-7-0-x86_64-shippable-lite-qr: 1
  • opt: 1
• android-em-7-0-x86_64-shippable-qr: 2
  • opt: 2

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

Comment 3

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 1

Platform and build breakdown:

• android-em-7-0-x86_64-shippable-lite-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1756146&startday=2022-02-28&endday=2022-03-06&tree=all

Comment 4

[Intermittent Failures Robot]

8 failures in 2837 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-beta: 5
• try: 3

Platform and build breakdown:

• android-em-7-0-x86_64-shippable-lite-qr: 4
  • opt: 4
• android-em-7-0-x86_64-shippable-qr: 4
  • opt: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1756146&startday=2022-03-07&endday=2022-03-13&tree=all

Comment 5

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 2
• mozilla-beta: 1

Platform and build breakdown:

• android-em-7-0-x86_64-shippable-qr: 3
  • opt: 3

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

Comment 6

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 1

Platform and build breakdown:

• android-em-7-0-x86_64-shippable-qr: 1
  • opt: 1

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