Closed Bug 1596761 Opened 24 days ago Closed 19 days ago

Perma tools/profiler/tests/xpcshell/test_feature_nativeallocations.js | - Native allocation payloads were recorded for the parent process' main thread when the Native Allocation feature was turned on. - 0 > 0 - when Gecko 72 merges to Beta on 2019-12-02

Categories

(Core :: Gecko Profiler, defect, P1)

defect

Tracking

()

VERIFIED FIXED
mozilla72
Tracking Status
firefox-esr68 --- unaffected
firefox70 --- unaffected
firefox71 --- unaffected
firefox72 + verified

People

(Reporter: opoprus, Assigned: gregtatum)

References

(Regression)

Details

Attachments

(2 files)

[Tracking Requested - why for this release]:

Central-as-beta simulation: https://treeherder.mozilla.org/#/jobs?repo=try&selectedJob=276423000&resultStatus=testfailed%2Cbusted%2Cexception%2Cretry%2Cusercancel%2Crunnable&revision=ef926f5d8bbb62a2749de42a3018b37b93326f41&searchStr=xpc

Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=276423000&repo=try&lineNumber=2702

[task 2019-11-15T13:09:22.284Z] 13:09:22 INFO - TEST-START | tools/profiler/tests/xpcshell/test_feature_nativeallocations.js
[task 2019-11-15T13:09:23.702Z] 13:09:23 WARNING - TEST-UNEXPECTED-FAIL | tools/profiler/tests/xpcshell/test_feature_nativeallocations.js | xpcshell return code: 0
[task 2019-11-15T13:09:23.702Z] 13:09:23 INFO - TEST-INFO took 1414ms
[task 2019-11-15T13:09:23.702Z] 13:09:23 INFO - >>>>>>>
[task 2019-11-15T13:09:23.702Z] 13:09:23 INFO - PID 17860 | [17860, Main Thread] WARNING: 'result.isErr()', file /builds/worker/workspace/build/src/startupcache/StartupCache.cpp, line 173
[task 2019-11-15T13:09:23.702Z] 13:09:23 INFO - PID 17860 | [17860, Main Thread] WARNING: 'result.isErr()', file /builds/worker/workspace/build/src/startupcache/StartupCache.cpp, line 173
[task 2019-11-15T13:09:23.703Z] 13:09:23 INFO - PID 17860 | [17860, Main Thread] WARNING: 'result.isErr()', file /builds/worker/workspace/build/src/startupcache/StartupCache.cpp, line 173
[task 2019-11-15T13:09:23.703Z] 13:09:23 INFO - PID 17860 | [17860, Main Thread] WARNING: 'result.isErr()', file /builds/worker/workspace/build/src/startupcache/StartupCache.cpp, line 173
[task 2019-11-15T13:09:23.704Z] 13:09:23 INFO - PID 17860 | [17860, Main Thread] WARNING: 'result.isErr()', file /builds/worker/workspace/build/src/startupcache/StartupCache.cpp, line 173
[task 2019-11-15T13:09:23.705Z] 13:09:23 INFO - PID 17860 | [17860, Main Thread] WARNING: 'result.isErr()', file /builds/worker/workspace/build/src/startupcache/StartupCache.cpp, line 173
[task 2019-11-15T13:09:23.706Z] 13:09:23 INFO - PID 17860 | [17860, Main Thread] WARNING: 'result.isErr()', file /builds/worker/workspace/build/src/startupcache/StartupCache.cpp, line 173
[task 2019-11-15T13:09:23.707Z] 13:09:23 INFO - PID 17860 | [17860, Main Thread] WARNING: 'result.isErr()', file /builds/worker/workspace/build/src/startupcache/StartupCache.cpp, line 173
[task 2019-11-15T13:09:23.708Z] 13:09:23 INFO - PID 17860 | [17860, Main Thread] WARNING: 'result.isErr()', file /builds/worker/workspace/build/src/startupcache/StartupCache.cpp, line 173
[task 2019-11-15T13:09:23.708Z] 13:09:23 INFO - PID 17860 | [17860, Main Thread] WARNING: 'result.isErr()', file /builds/worker/workspace/build/src/startupcache/StartupCache.cpp, line 173
[task 2019-11-15T13:09:23.709Z] 13:09:23 INFO - PID 17860 | [17860, Main Thread] WARNING: 'result.isErr()', file /builds/worker/workspace/build/src/startupcache/StartupCache.cpp, line 173
[task 2019-11-15T13:09:23.710Z] 13:09:23 INFO - PID 17860 | [17860, Main Thread] WARNING: 'result.isErr()', file /builds/worker/workspace/build/src/startupcache/StartupCache.cpp, line 173
[task 2019-11-15T13:09:23.711Z] 13:09:23 INFO - PID 17860 | [17860, Main Thread] WARNING: Couldn't get the user appdata directory. Crash events may not be produced.: file /builds/worker/workspace/build/src/toolkit/crashreporter/nsExceptionHandler.cpp, line 2632
[task 2019-11-15T13:09:23.712Z] 13:09:23 INFO - PID 17860 | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2019-11-15T13:09:23.713Z] 13:09:23 INFO - PID 17860 | [17860, Main Thread] WARNING: 'result.isErr()', file /builds/worker/workspace/build/src/startupcache/StartupCache.cpp, line 173
[task 2019-11-15T13:09:23.714Z] 13:09:23 INFO - PID 17860 | [17860, Main Thread] WARNING: 'result.isErr()', file /builds/worker/workspace/build/src/startupcache/StartupCache.cpp, line 173
[task 2019-11-15T13:09:23.714Z] 13:09:23 INFO - PID 17860 | [17860, Main Thread] WARNING: 'result.isErr()', file /builds/worker/workspace/build/src/startupcache/StartupCache.cpp, line 173
[task 2019-11-15T13:09:23.715Z] 13:09:23 INFO - (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2019-11-15T13:09:23.716Z] 13:09:23 INFO - (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2019-11-15T13:09:23.717Z] 13:09:23 INFO - (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2019-11-15T13:09:23.718Z] 13:09:23 INFO - running event loop
[task 2019-11-15T13:09:23.719Z] 13:09:23 INFO - PID 17860 | [17860, Main Thread] WARNING: Could not get the program name for a cubeb stream.: 'NS_SUCCEEDED(rv)', file /builds/worker/workspace/build/src/dom/media/CubebUtils.cpp, line 381
[task 2019-11-15T13:09:23.719Z] 13:09:23 INFO - "CONSOLE_MESSAGE: (info) No chrome package registered for chrome://branding/locale/brand.properties"
[task 2019-11-15T13:09:23.720Z] 13:09:23 INFO - tools/profiler/tests/xpcshell/test_feature_nativeallocations.js | Starting
[task 2019-11-15T13:09:23.721Z] 13:09:23 INFO - (xpcshell/head.js) | test pending (2)
[task 2019-11-15T13:09:23.722Z] 13:09:23 INFO - TEST-PASS | tools/profiler/tests/xpcshell/test_feature_nativeallocations.js | - The profiler is not currently active - true == true
[task 2019-11-15T13:09:23.723Z] 13:09:23 INFO - "Test that the profiler can install memory hooks and collect native allocation information in the marker payloads."
[task 2019-11-15T13:09:23.723Z] 13:09:23 INFO - "Start the profiler."
[task 2019-11-15T13:09:23.724Z] 13:09:23 INFO - PID 17860 | JavaScript strict warning: file:///builds/worker/workspace/build/tests/xpcshell/tests/tools/profiler/tests/xpcshell/shared-head.js, line 27: ReferenceError: reference to undefined property "duration"
[task 2019-11-15T13:09:23.725Z] 13:09:23 INFO - "Do some JS work for a little bit. This will increase the amount of allocations that take place."
[task 2019-11-15T13:09:23.726Z] 13:09:23 INFO - "Get the profile data and analyze it."
[task 2019-11-15T13:09:23.727Z] 13:09:23 INFO - PID 17860 | [17860, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, kKnownEsrVersion) failed with result 0x80004002: file /builds/worker/workspace/build/src/toolkit/components/resistfingerprinting/nsRFPService.cpp, line 661
[task 2019-11-15T13:09:23.727Z] 13:09:23 INFO - (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2019-11-15T13:09:23.728Z] 13:09:23 INFO - "CONSOLE_MESSAGE: (warn) [JavaScript Warning: "ReferenceError: reference to undefined property "duration"" {file: "file:///builds/worker/workspace/build/tests/xpcshell/tests/tools/profiler/tests/xpcshell/shared-head.js" line: 27}]"
[task 2019-11-15T13:09:23.729Z] 13:09:23 WARNING - TEST-UNEXPECTED-FAIL | tools/profiler/tests/xpcshell/test_feature_nativeallocations.js | - Native allocation payloads were recorded for the parent process' main thread when the Native Allocation feature was turned on. - 0 > 0
[task 2019-11-15T13:09:23.730Z] 13:09:23 INFO - /builds/worker/workspace/build/tests/xpcshell/tests/tools/profiler/tests/xpcshell/test_feature_nativeallocations.js:null:42
[task 2019-11-15T13:09:23.731Z] 13:09:23 INFO - /builds/worker/workspace/build/tests/xpcshell/head.js:_do_main:246
[task 2019-11-15T13:09:23.731Z] 13:09:23 INFO - /builds/worker/workspace/build/tests/xpcshell/head.js:_execute_test:573
[task 2019-11-15T13:09:23.732Z] 13:09:23 INFO - -e:null:1
[task 2019-11-15T13:09:23.733Z] 13:09:23 INFO - exiting test
[task 2019-11-15T13:09:23.734Z] 13:09:23 INFO - Unexpected exception NS_ERROR_ABORT:
[task 2019-11-15T13:09:23.735Z] 13:09:23 INFO - _abort_failed_test@/builds/worker/workspace/build/tests/xpcshell/head.js:791:20
[task 2019-11-15T13:09:23.735Z] 13:09:23 INFO - do_report_result@/builds/worker/workspace/build/tests/xpcshell/head.js:892:5
[task 2019-11-15T13:09:23.735Z] 13:09:23 INFO - Assert<@/builds/worker/workspace/build/tests/xpcshell/head.js:67:21
[task 2019-11-15T13:09:23.736Z] 13:09:23 INFO - proto.report@resource://testing-common/Assert.jsm:233:10
[task 2019-11-15T13:09:23.736Z] 13:09:23 INFO - compareNumbers@resource://testing-common/Assert.jsm:501:10
[task 2019-11-15T13:09:23.737Z] 13:09:23 INFO - greater@resource://testing-common/Assert.jsm:526:18
[task 2019-11-15T13:09:23.737Z] 13:09:23 INFO - @/builds/worker/workspace/build/tests/xpcshell/tests/tools/profiler/tests/xpcshell/test_feature_nativeallocations.js:42:12
[task 2019-11-15T13:09:23.738Z] 13:09:23 INFO - _do_main@/builds/worker/workspace/build/tests/xpcshell/head.js:246:6
[task 2019-11-15T13:09:23.738Z] 13:09:23 INFO - _execute_test@/builds/worker/workspace/build/tests/xpcshell/head.js:573:5
[task 2019-11-15T13:09:23.739Z] 13:09:23 INFO - @-e:1:1
[task 2019-11-15T13:09:23.739Z] 13:09:23 INFO - exiting test
[task 2019-11-15T13:09:23.739Z] 13:09:23 INFO - PID 17860 | [17860, Main Thread] WARNING: OOPDeinit() without successful OOPInit(): file /builds/worker/workspace/build/src/toolkit/crashreporter/nsExceptionHandler.cpp, line 3114
[task 2019-11-15T13:09:23.740Z] 13:09:23 INFO - PID 17860 | nsStringStats
[task 2019-11-15T13:09:23.740Z] 13:09:23 INFO - PID 17860 | => mAllocCount: 11646
[task 2019-11-15T13:09:23.741Z] 13:09:23 INFO - PID 17860 | => mReallocCount: 0
[task 2019-11-15T13:09:23.741Z] 13:09:23 INFO - PID 17860 | => mFreeCount: 11646
[task 2019-11-15T13:09:23.742Z] 13:09:23 INFO - PID 17860 | => mShareCount: 11682
[task 2019-11-15T13:09:23.742Z] 13:09:23 INFO - PID 17860 | => mAdoptCount: 132
[task 2019-11-15T13:09:23.743Z] 13:09:23 INFO - PID 17860 | => mAdoptFreeCount: 132
[task 2019-11-15T13:09:23.743Z] 13:09:23 INFO - PID 17860 | => Process ID: 17860, Thread ID: 140536462729216
[task 2019-11-15T13:09:23.744Z] 13:09:23 INFO - <<<<<<<
[task 2019-11-15T13:09:23.744Z] 13:09:23 INFO - INFO | Result summary:
[task 2019-11-15T13:09:23.745Z] 13:09:23 INFO - INFO | Passed: 559
[task 2019-11-15T13:09:23.746Z] 13:09:23 WARNING - INFO | Failed: 1
[task 2019-11-15T13:09:23.746Z] 13:09:23 WARNING - One or more unittests failed.
[task 2019-11-15T13:09:23.746Z] 13:09:23 INFO - INFO | Todo: 0
[task 2019-11-15T13:09:23.747Z] 13:09:23 INFO - INFO | Retried: 6
[task 2019-11-15T13:09:23.748Z] 13:09:23 INFO - SUITE-END | took 721s
[task 2019-11-15T13:09:23.748Z] 13:09:23 INFO - Node moz-http2 server shutting down ...
[task 2019-11-15T13:09:23.749Z] 13:09:23 INFO - Process stderr
[task 2019-11-15T13:09:23.749Z] 13:09:23 INFO - (node:1084) ExperimentalWarning: The http2 module is an experimental API.
[task 2019-11-15T13:09:23.776Z] 13:09:23 ERROR - Return code: 1
[task 2019-11-15T13:09:23.777Z] 13:09:23 INFO - TinderboxPrint: xpcshell-xpcshell<br/>559/<em class="testfail">1</em>/0
[task 2019-11-15T13:09:23.777Z] 13:09:23 WARNING - # TBPL FAILURE #
[task 2019-11-15T13:09:23.778Z] 13:09:23 WARNING - setting return code to 2
[task 2019-11-15T13:09:23.778Z] 13:09:23 WARNING - The xpcshell suite: xpcshell ran with return status: FAILURE
[task 2019-11-15T13:09:23.778Z] 13:09:23 INFO - Running post-action listener: _package_coverage_data
[task 2019-11-15T13:09:23.779Z] 13:09:23 INFO - Running post-action listener: _resource_record_post_action
[task 2019-11-15T13:09:23.779Z] 13:09:23 INFO - Running post-action listener: process_java_coverage_data
[task 2019-11-15T13:09:23.779Z] 13:09:23 INFO - [mozharness: 2019-11-15 13:09:23.778566Z] Finished run-tests step (success)
[task 2019-11-15T13:09:23.780Z] 13:09:23 INFO - Running post-run listener: _resource_record_post_run
[task 2019-11-15T13:09:23.898Z] 13:09:23 INFO - Validating Perfherder data against /builds/worker/workspace/mozharness/external_tools/performance-artifact-schema.json
[task 2019-11-15T13:09:23.902Z] 13:09:23 INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"subtests": [{"name": "cpu_percent", "value": 94.87209302325583}, {"name": "io_write_bytes", "value": 2963406848}, {"name": "io.read_bytes", "value": 983040}, {"name": "io_write_time", "value": 546332}, {"name": "io_read_time", "value": 532}], "extraOptions": ["e10s", "taskcluster-m5.large"], "name": "xpcshell.xpcshell.6.overall"}, {"subtests": [{"name": "time", "value": 0.025300025939941406}], "name": "xpcshell.xpcshell.6.start-pulseaudio"}, {"subtests": [{"name": "time", "value": 10.131531000137329}, {"name": "cpu_percent", "value": 51.12777777777777}], "name": "xpcshell.xpcshell.6.install"}, {"subtests": [{"name": "time", "value": 0.01677989959716797}], "name": "xpcshell.xpcshell.6.stage-files"}, {"subtests": [{"name": "time", "value": 722.249470949173}, {"name": "cpu_percent", "value": 95.53006944444448}], "name": "xpcshell.xpcshell.6.run-tests"}]}
[task 2019-11-15T13:09:23.903Z] 13:09:23 INFO - Total resource usage - Wall time: 732s; CPU: 96.0%; Read bytes: 983040; Write bytes: 2963406848; Read time: 532; Write time: 546332
[task 2019-11-15T13:09:23.904Z] 13:09:23 INFO - TinderboxPrint: CPU usage<br/>95.5%
[task 2019-11-15T13:09:23.904Z] 13:09:23 INFO - TinderboxPrint: I/O read bytes / time<br/>983,040 / 532
[task 2019-11-15T13:09:23.904Z] 13:09:23 INFO - TinderboxPrint: I/O write bytes / time<br/>2,963,406,848 / 546,332
[task 2019-11-15T13:09:23.905Z] 13:09:23 INFO - TinderboxPrint: CPU idle<br/>73.1 (5.0%)
[task 2019-11-15T13:09:23.905Z] 13:09:23 INFO - TinderboxPrint: CPU system<br/>109.8 (7.5%)
[task 2019-11-15T13:09:23.906Z] 13:09:23 INFO - TinderboxPrint: CPU user<br/>1,278.5 (87.4%)
[task 2019-11-15T13:09:23.906Z] 13:09:23 INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2019-11-15T13:09:23.907Z] 13:09:23 INFO - start-pulseaudio - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2019-11-15T13:09:23.908Z] 13:09:23 INFO - install - Wall time: 10s; CPU: 51.0%; Read bytes: 0; Write bytes: 27500544; Read time: 0; Write time: 23596
[task 2019-11-15T13:09:23.908Z] 13:09:23 INFO - stage-files - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2019-11-15T13:09:23.911Z] 13:09:23 INFO - run-tests - Wall time: 722s; CPU: 96.0%; Read bytes: 966656; Write bytes: 2931146752; Read time: 532; Write time: 521372
[task 2019-11-15T13:09:24.015Z] 13:09:24 WARNING - returning nonzero exit status 2
[task 2019-11-15T13:09:24.042Z] cleanup
[task 2019-11-15T13:09:24.042Z] + cleanup
[task 2019-11-15T13:09:24.042Z] + local rv=2
[task 2019-11-15T13:09:24.042Z] + [[ -s /builds/worker/.xsession-errors ]]
[task 2019-11-15T13:09:24.042Z] + cp /builds/worker/.xsession-errors /builds/worker/artifacts/public/xsession-errors.log
[task 2019-11-15T13:09:24.044Z] + true
[task 2019-11-15T13:09:24.044Z] + cleanup_xvfb
[task 2019-11-15T13:09:24.044Z] pidof Xvfb
[task 2019-11-15T13:09:24.045Z] ++ pidof Xvfb
[task 2019-11-15T13:09:24.048Z] + local xvfb_pid=27
[task 2019-11-15T13:09:24.048Z] + local vnc=false
[task 2019-11-15T13:09:24.048Z] + local interactive=false
[task 2019-11-15T13:09:24.049Z] + '[' -n 27 ']'
[task 2019-11-15T13:09:24.049Z] + [[ false == false ]]
[task 2019-11-15T13:09:24.049Z] + [[ false == false ]]
[task 2019-11-15T13:09:24.049Z] + kill 27
[task 2019-11-15T13:09:24.049Z] + screen -XS xvfb quit
[task 2019-11-15T13:09:24.211Z] No screen session found.
[task 2019-11-15T13:09:24.211Z] + true
[task 2019-11-15T13:09:24.211Z] + exit 2
[fetches 2019-11-15T13:09:24.212Z] removing /builds/worker/fetches
[fetches 2019-11-15T13:09:24.382Z] finished
[taskcluster 2019-11-15 13:09:24.707Z] === Task Finished ===
[taskcluster 2019-11-15 13:09:25.915Z] Unsuccessful task run with exit code: 2 completed in 799.383 seconds

Memory hooks aren't on beta, I forgot to check for the feature first in the test.

Flags: needinfo?(gtatum)
Pushed by gtatum@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/9b475c5496bd
Only run the allocations test when it is supported; r=canaltinova
Status: NEW → RESOLVED
Closed: 23 days ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla72
Status: RESOLVED → REOPENED
Flags: needinfo?(gtatum)
Resolution: FIXED → ---
Target Milestone: mozilla72 → ---
Priority: -- → P1

hm, I thought Services.profiler.GetFeatures() was returning the correct features but it looks like it always includes "nativeallocations" regardless of the platform/update channel: https://searchfox.org/mozilla-central/rev/524bed6dfbc5ae21c62632d83b7573448b29e0ac/tools/profiler/core/platform.cpp#197-223
We should solve this function call to include only available platforms. But to solve this issue as soon as possible, we can put skip-if = release_or_beta to ini file for now.

Thanks Nazim. I went with fixing the root issue, which was the correctness one. I added the ifdef to the features to clear the native allocations correctly.

Flags: needinfo?(gtatum)
Pushed by gtatum@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/b7aecce8a7c0
Clear native allocations feature when not supported; r=canaltinova
Pushed by rmaries@mozilla.com:
https://hg.mozilla.org/mozilla-central/rev/5a002b32092f
Clear native allocations feature when not supported; r=canaltinova
Status: REOPENED → RESOLVED
Closed: 23 days ago19 days ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla72
You need to log in before you can comment on or make changes to this bug.