Closed Bug 1333276 Opened 3 years ago Closed 3 years ago

Intermittent toolkit/components/telemetry/tests/unit/test_ThreadHangStats.js | check_results - [check_results : 89] false == true

Categories

(Toolkit :: Telemetry, defect)

defect
Not set

Tracking

()

RESOLVED FIXED
mozilla55
Tracking Status
firefox52 --- unaffected
firefox-esr52 --- unaffected
firefox53 --- unaffected
firefox54 --- unaffected
firefox55 --- fixed

People

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

References

Details

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

Attachments

(1 file)

Big spike in failure frequency here seems to correspond to recent changes to the test.
Blocks: 1312883
Flags: needinfo?(mconley)
Whiteboard: [stockwell needswork]
this is failing on win8 opt/pgo quite frequently, here is a snippet from a log[0]:
8:19:07     INFO -  TEST-START | toolkit/components/telemetry/tests/unit/test_ThreadHangStats.js
18:19:18  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/components/telemetry/tests/unit/test_ThreadHangStats.js | xpcshell return code: 0
18:19:18     INFO -  TEST-INFO took 11232ms
18:19:18     INFO -  >>>>>>>
18:19:18     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
18:19:18     INFO -  (xpcshell/head.js) | test pending (2)
18:19:18     INFO -  (xpcshell/head.js) | test pending (3)
18:19:18     INFO -  (xpcshell/head.js) | test pending (4)
18:19:18     INFO -  (xpcshell/head.js) | test MAIN run_test finished (4)
18:19:18     INFO -  running event loop
18:19:18     INFO -  (xpcshell/head.js) | test finished (3)
18:19:18     INFO -  (xpcshell/head.js) | test finished (2)
18:19:18     INFO -  (xpcshell/head.js) | test pending (2)
18:19:18     INFO -  TEST-PASS | toolkit/components/telemetry/tests/unit/test_ThreadHangStats.js | check_results - [check_results : 77] "object" == "object"
18:19:18     INFO -  TEST-PASS | toolkit/components/telemetry/tests/unit/test_ThreadHangStats.js | check_histogram - [check_histogram : 66] "object" == "object"
18:19:18     INFO -  TEST-PASS | toolkit/components/telemetry/tests/unit/test_ThreadHangStats.js | check_histogram - [check_histogram : 67] 0 == 0
18:19:18     INFO -  TEST-PASS | toolkit/components/telemetry/tests/unit/test_ThreadHangStats.js | check_histogram - [check_histogram : 68] "number" == "number"
18:19:18     INFO -  TEST-PASS | toolkit/components/telemetry/tests/unit/test_ThreadHangStats.js | check_histogram - [check_histogram : 69] "number" == "number"
18:19:18     INFO -  TEST-PASS | toolkit/components/telemetry/tests/unit/test_ThreadHangStats.js | check_histogram - [check_histogram : 70] "number" == "number"
18:19:18     INFO -  TEST-PASS | toolkit/components/telemetry/tests/unit/test_ThreadHangStats.js | check_histogram - [check_histogram : 71] true == true
18:19:18     INFO -  TEST-PASS | toolkit/components/telemetry/tests/unit/test_ThreadHangStats.js | check_histogram - [check_histogram : 72] true == true
18:19:18     INFO -  TEST-PASS | toolkit/components/telemetry/tests/unit/test_ThreadHangStats.js | check_histogram - [check_histogram : 73] 33 == 33
18:19:18     INFO -  TEST-PASS | toolkit/components/telemetry/tests/unit/test_ThreadHangStats.js | check_results - [check_results : 80] true == true
18:19:18     INFO -  TEST-PASS | toolkit/components/telemetry/tests/unit/test_ThreadHangStats.js | check_results - [check_results : 81] 2 != 0
18:19:18     INFO -  TEST-PASS | toolkit/components/telemetry/tests/unit/test_ThreadHangStats.js | check_results - [check_results : 83] true == true
18:19:18     INFO -  TEST-PASS | toolkit/components/telemetry/tests/unit/test_ThreadHangStats.js | check_results - [check_results : 84] 4 != 0
18:19:18     INFO -  TEST-PASS | toolkit/components/telemetry/tests/unit/test_ThreadHangStats.js | check_results - [check_results : 85] "string" == "string"
18:19:18  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/components/telemetry/tests/unit/test_ThreadHangStats.js | check_results - [check_results : 91] false == true
18:19:18     INFO -  C:/slave/test/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/test_ThreadHangStats.js:check_results:91
18:19:18     INFO -  C:/slave/test/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/test_ThreadHangStats.js:run_test/<:105
18:19:18     INFO -  C:\slave\test\build\tests\xpcshell\head.js:run:703
18:19:18     INFO -  C:\slave\test\build\tests\xpcshell\head.js:_do_main:211
18:19:18     INFO -  C:\slave\test\build\tests\xpcshell\head.js:_execute_test:546
18:19:18     INFO -  -e:null:1
18:19:18     INFO -  exiting test
18:19:18     INFO -  (xpcshell/head.js) | test finished (2)
18:19:18     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "1488507558383	Toolkit.Telemetry	ERROR	TelemetrySend::shutdown - failed to remove observer for idle-daily: [Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIObserverService.removeObserver]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: resource://gre/modules/TelemetrySend.jsm :: TelemetrySendImpl.shutdown< :: line 643"  data: no] Stack trace: TelemetrySendImpl.shutdown<()@resource://gre/modules/TelemetrySend.jsm:643 < TaskImpl_run()@resource://gre/modules/Task.jsm:319 < TaskImpl()@resource://gre/modules/Task.jsm:277 < asyncFunction()@resource://gre/modules/Task.jsm:252 < shutdown()@resource://gre/modules/TelemetrySend.jsm:197 < C:/slave/test/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/head.js:321 < _execute_test/<()@C:\\slave\\test\\build\\tests\\xpcshell\\head.js:602 < TaskImpl_run()@resource://gre/modules/Task.jsm:319 < TaskImpl()@resource://gre/modules/Task.jsm:277 < asyncFunction()@resource://gre/modules/Task.jsm:252 < Task_spawn()@resource://gre/modules/Task.jsm:166 < _execute_test()@C:\\slave\\test\\build\\tests\\xpcshell\\head.js:599 < -e:1" {file: "resource://gre/modules/Log.jsm" line: 748}]
18:19:18     INFO -  App_append@resource://gre/modules/Log.jsm:748:9
18:19:18     INFO -  log@resource://gre/modules/Log.jsm:386:7
18:19:18     INFO -  getLoggerWithMessagePrefix/proxy.log@resource://gre/modules/Log.jsm:501:44
18:19:18     INFO -  error@resource://gre/modules/Log.jsm:394:5
18:19:18     INFO -  TelemetrySendImpl.shutdown<@resource://gre/modules/TelemetrySend.jsm:645:9
18:19:18     INFO -  TaskImpl_run@resource://gre/modules/Task.jsm:319:42
18:19:18     INFO -  TaskImpl@resource://gre/modules/Task.jsm:277:3
18:19:18     INFO -  asyncFunction@resource://gre/modules/Task.jsm:252:14
18:19:18     INFO -  shutdown@resource://gre/modules/TelemetrySend.jsm:197:12
18:19:18     INFO -  @C:/slave/test/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/head.js:321:29
18:19:18     INFO -  _execute_test/<@C:\\slave\\test\\build\\tests\\xpcshell\\head.js:602:15
18:19:18     INFO -  TaskImpl_run@resource://gre/modules/Task.jsm:319:42
18:19:18     INFO -  TaskImpl@resource://gre/modules/Task.jsm:277:3
18:19:18     INFO -  asyncFunction@resource://gre/modules/Task.jsm:252:14
18:19:18     INFO -  Task_spawn@resource://gre/modules/Task.jsm:166:12
18:19:18     INFO -  _execute_test@C:\\slave\\test\\build\\tests\\xpcshell\\head.js:599:3
18:19:18     INFO -  @-e:1:1
18:19:18     INFO -  "
18:19:18     INFO -  "CONSOLE_MESSAGE: (info) 1488507558385	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::shutdown"
18:19:18     INFO -  "CONSOLE_MESSAGE: (info) 1488507558386	Toolkit.Telemetry	TRACE	TelemetrySend::promisePendingPingActivity - Waiting for ping task"
18:19:18     INFO -  <<<<<<<


while this looks to be related to a change from mconley, maybe George can help shed light or bring in help from the Telemetry team :)


[0] https://archive.mozilla.org/pub/firefox/tinderbox-builds/graphics-win64/1488490492/graphics_win8_64_test-xpcshell-bm119-tests1-windows-build1.txt.gz
Flags: needinfo?(gfritzsche)
Yeah, I have a high degree of confidence that this is my fault.

I hope to get a shot at this next week after I get some other high-priority stuff off of my lap.
I threw a quick hack at try to get more info: https://treeherder.mozilla.org/#/jobs?repo=try&revision=7e114293fa3690d2794896684cd6b62239eda472

I see a failure at 

https://dxr.mozilla.org/mozilla-central/rev/77d5a39a4677ed8e32a7ed46561c962d807fa7b1/toolkit/components/telemetry/tests/unit/test_ThreadHangStats.js#91

    ok(endHangs.hangs.some((hang) => (
          hang.nativeStack &&
          Array.isArray(hang.nativeStack.memoryMap) &&
          hang.nativeStack.memoryMap.length !== 0 &&
          Array.isArray(hang.nativeStack.stacks) &&
          hang.nativeStack.stacks.length !== 0

If my logging is to be believed, endHangs.hangs has 2 hangs; the first has nativeStack == undefined; the second has a nativeStack, but memoryMap.length == 0.
Ah, okay. I _suspect_ there are cases where memoryMap, and sometimes even the stack itself will be empty. I don't think we can easily detect or avoid those cases in this test. Probably the best thing to do here is to remove the length checks. I'll put up a patch.
Flags: needinfo?(mconley)
Comment on attachment 8844216 [details]
Bug 1333276 - Remove length checks on non-deterministic nativeStack memoryMap and stack properties.

https://reviewboard.mozilla.org/r/117732/#review119668
Attachment #8844216 - Flags: review?(nchen) → review+
Pushed by mconley@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/fb390c905648
Remove length checks on non-deterministic nativeStack memoryMap and stack properties. r=jchen
Whiteboard: [stockwell needswork] → [stockwell fixed]
https://hg.mozilla.org/mozilla-central/rev/fb390c905648
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla55
Assignee: nobody → mconley
Flags: needinfo?(gfritzsche)
You need to log in before you can comment on or make changes to this bug.