1749621 - Intermittent tools/profiler/tests/xpcshell/test_feature_fileioall.js | - Has a marker.name that starts with FileIO - false == true | after xpcshell return code: 0

Status: RESOLVED DUPLICATE of bug 1749528

(Core :: Gecko Profiler, defect, P5)

Description

[Treeherder Bug Filer]

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

---

 INFO -  TEST-PASS | tools/profiler/tests/xpcshell/test_feature_fileioall.js |  - Found some markers - 17 > 0
[task 2022-01-11T22:02:28.528Z] 22:02:28  WARNING -  TEST-UNEXPECTED-FAIL | tools/profiler/tests/xpcshell/test_feature_fileioall.js |  - Has a marker.name that starts with FileIO - false == true
[task 2022-01-11T22:02:28.529Z] 22:02:28     INFO -  Z:/task_164193451435771/build/tests/xpcshell/tests/tools/profiler/tests/xpcshell/test_feature_fileioall.js:null:86
[task 2022-01-11T22:02:28.529Z] 22:02:28     INFO -  Z:\task_164193451435771\build\tests\xpcshell\head.js:_do_main:240
[task 2022-01-11T22:02:28.529Z] 22:02:28     INFO -  Z:\task_164193451435771\build\tests\xpcshell\head.js:_execute_test:604
[task 2022-01-11T22:02:28.529Z] 22:02:28     INFO -  -e:null:1
[task 2022-01-11T22:02:28.530Z] 22:02:28     INFO -  exiting test
[task 2022-01-11T22:02:28.530Z] 22:02:28     INFO -  PID 6908 | console.error: "Failing inflated FileIO marker:" ({name:"PipeIO (non-profiled thread)", startTime:288.9908, endTime:288.9997, phase:1, category:1, data:{stack:{processType:"default", name:"", processName:"Parent Process", registerTime:null, unregisterTime:null, samples:{schema:{stack:0, time:1, eventDelay:2, threadCPUDelta:3}, data:[]}, markers:{schema:{name:0, startTime:1, endTime:2, phase:3, category:4, data:5}, data:[]}, pid:6908, tid:4468}, type:"FileIO", operation:"write", source:"PoisonIOInterposer", filename:"C:\\Users\\task_164193451435771\\AppData\\Local\\Temp\\test_marker_fileio", threadId:4468}})
[task 2022-01-11T22:02:28.531Z] 22:02:28     INFO -  Unexpected exception NS_ERROR_ABORT:
[task 2022-01-11T22:02:28.531Z] 22:02:28     INFO -  _abort_failed_test@Z:\task_164193451435771\build\tests\xpcshell\head.js:875:20
[task 2022-01-11T22:02:28.531Z] 22:02:28     INFO -  do_report_result@Z:\task_164193451435771\build\tests\xpcshell\head.js:976:5
[task 2022-01-11T22:02:28.531Z] 22:02:28     INFO -  Assert<@Z:\task_164193451435771\build\tests\xpcshell\head.js:75:21
[task 2022-01-11T22:02:28.532Z] 22:02:28     INFO -  proto.report@resource://testing-common/Assert.jsm:228:10
[task 2022-01-11T22:02:28.532Z] 22:02:28     INFO -  proto.ok@resource://testing-common/Assert.jsm:254:10
[task 2022-01-11T22:02:28.532Z] 22:02:28     INFO -  checkInflatedFileIOMarkers@Z:/task_164193451435771/build/tests/xpcshell/tests/tools/profiler/tests/xpcshell/head.js:158:9
[task 2022-01-11T22:02:28.532Z] 22:02:28     INFO -  @Z:/task_164193451435771/build/tests/xpcshell/tests/tools/profiler/tests/xpcshell/test_feature_fileioall.js:86:29
[task 2022-01-11T22:02:28.533Z] 22:02:28     INFO -  _do_main@Z:\task_164193451435771\build\tests\xpcshell\head.js:240:6
[task 2022-01-11T22:02:28.533Z] 22:02:28     INFO -  _execute_test@Z:\task_164193451435771\build\tests\xpcshell\head.js:604:5
[task 2022-01-11T22:02:28.533Z] 22:02:28     INFO -  @-e:1:1
[task 2022-01-11T22:02:28.533Z] 22:02:28     INFO -  exiting test
[task 2022-01-11T22:02:28.534Z] 22:02:28     INFO -  PID 6908 | [Socket 6124, Main Thread] WARNING: IPC message 'PSocketProcess::Msg_FOGData' discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:523
[task 2022-01-11T22:02:28.534Z] 22:02:28     INFO -  PID 6908 | [Socket 6124, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4438
[task 2022-01-11T22:02:28.535Z] 22:02:28     INFO -  PID 6908 | [Parent 6908, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3351
[task 2022-01-11T22:02:28.535Z] 22:02:28     INFO -  PID 6908 | [Parent 6908, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4438
[task 2022-01-11T22:02:28.535Z] 22:02:28     INFO -  PID 6908 | [Parent 6908, Main Thread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp:204
[task 2022-01-11T22:02:28.536Z] 22:02:28     INFO -  PID 6908 | [Parent 6908, Main Thread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp:204
[task 2022-01-11T22:02:28.536Z] 22:02:28     INFO -  PID 6908 | [Parent 6908, Main Thread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp:204
[task 2022-01-11T22:02:28.536Z] 22:02:28     INFO -  PID 6908 | [Parent 6908, Main Thread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp:204
[task 2022-01-11T22:02:28.537Z] 22:02:28     INFO -  <<<<<<<
[task 2022-01-11T22:02:28.537Z] 22:02:28     INFO -  INFO | Result summary:
[task 2022-01-11T22:02:28.537Z] 22:02:28     INFO -  INFO | Passed: 1134
[task 2022-01-11T22:02:28.537Z] 22:02:28  WARNING -  INFO | Failed: 1
[task 2022-01-11T22:02:28.537Z] 22:02:28  WARNING -  One or more unittests failed.
 INFO -  INFO | Todo: 0
[task 2022-01-11T22:02:28.538Z] 22:02:28     INFO -  INFO | Retried: 2
[task 2022-01-11T22:02:28.538Z] 22:02:28     INFO -  SUITE-END | took 1657s
[task 2022-01-11T22:02:28.538Z] 22:02:28     INFO -  Node moz-http2 server shutting down ...
[task 2022-01-11T22:02:28.538Z] 22:02:28     INFO -  Process stdout
[task 2022-01-11T22:02:28.538Z] 22:02:28     INFO -  forked process without handler sent: {"error":"","errorStack":""}
[task 2022-01-11T22:02:28.539Z] 22:02:28     INFO -  Process stderr
[task 2022-01-11T22:02:28.539Z] 22:02:28     INFO -  (node:8164) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 window_update listeners added to [Flow]. Use emitter.setMaxListeners() to increase limit
[task 2022-01-11T22:02:28.539Z] 22:02:28     INFO -  (node:8164) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 window_update listeners added to [Flow]. Use emitter.setMaxListeners() to increase limit
[task 2022-01-11T22:02:28.540Z] 22:02:28     INFO -  (node:8164) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 window_update listeners added to [Flow]. Use emitter.setMaxListeners() to increase limit
[task 2022-01-11T22:02:28.540Z] 22:02:28     INFO -  (node:8164) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 window_update listeners added to [Flow]. Use emitter.setMaxListeners() to increase limit
[task 2022-01-11T22:02:28.540Z] 22:02:28     INFO -  http3Server server shutting down ...
[task 2022-01-11T22:02:28.648Z] 22:02:28     INFO -  Process stderr
[task 2022-01-11T22:02:28.649Z] 22:02:28     INFO -  zero length datagram received?
[task 2022-01-11T22:02:28.649Z] 22:02:28     INFO -  zero length datagram received?
[task 2022-01-11T22:02:28.649Z] 22:02:28     INFO -  zero length datagram received?
[task 2022-01-11T22:02:28.650Z] 22:02:28     INFO -  zero length datagram received?
[task 2022-01-11T22:02:28.650Z] 22:02:28     INFO -  zero length datagram received?
[task 2022-01-11T22:02:28.651Z] 22:02:28     INFO -  zero length datagram received?
[task 2022-01-11T22:02:28.651Z] 22:02:28     INFO -  zero length datagram received?
[task 2022-01-11T22:02:28.651Z] 22:02:28     INFO -  zero length datagram received?
[task 2022-01-11T22:02:28.651Z] 22:02:28     INFO -  zero length datagram received?
[task 2022-01-11T22:02:28.743Z] 22:02:28    ERROR - Return code: 1