1635619 - Intermittent TEST-UNEXPECTED-TIMEOUT | tools/profiler/tests/xpcshell/test_feature_mainthreadio.js | Test timed out

Status: RESOLVED INCOMPLETE

(Core :: Gecko Profiler, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2020-05-05T23:23:43.314Z] 23:23:43     INFO -  TEST-START | toolkit/components/downloads/test/unit/test_DownloadList.js
[task 2020-05-05T23:23:50.164Z] 23:23:50     INFO -  TEST-PASS | toolkit/components/downloads/test/unit/test_DownloadList.js | took 6849ms
[task 2020-05-05T23:23:50.172Z] 23:23:50     INFO -  TEST-START | toolkit/components/places/tests/unit/test_bookmarks_json_corrupt.js
[task 2020-05-05T23:23:54.816Z] 23:23:54     INFO -  TEST-PASS | toolkit/components/places/tests/unit/test_bookmarks_json_corrupt.js | took 4645ms
[task 2020-05-05T23:23:54.824Z] 23:23:54     INFO -  TEST-START | tools/profiler/tests/xpcshell/test_feature_mainthreadio.js
[task 2020-05-05T23:28:54.821Z] 23:28:54  WARNING -  TEST-UNEXPECTED-TIMEOUT | tools/profiler/tests/xpcshell/test_feature_mainthreadio.js | Test timed out
[task 2020-05-05T23:28:54.822Z] 23:28:54     INFO -  TEST-INFO took 300000ms
[task 2020-05-05T23:28:54.822Z] 23:28:54     INFO -  >>>>>>>
[task 2020-05-05T23:28:54.823Z] 23:28:54     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2020-05-05T23:28:54.823Z] 23:28:54     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2020-05-05T23:28:54.823Z] 23:28:54     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2020-05-05T23:28:54.823Z] 23:28:54     INFO -  running event loop
[task 2020-05-05T23:28:54.824Z] 23:28:54     INFO -  "CONSOLE_MESSAGE: (info) No chrome package registered for chrome://branding/locale/brand.properties"
[task 2020-05-05T23:28:54.824Z] 23:28:54     INFO -  tools/profiler/tests/xpcshell/test_feature_mainthreadio.js | Starting
[task 2020-05-05T23:28:54.824Z] 23:28:54     INFO -  (xpcshell/head.js) | test pending (2)
[task 2020-05-05T23:28:54.825Z] 23:28:54     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2020-05-05T23:28:54.825Z] 23:28:54     INFO -  <<<<<<<
[task 2020-05-05T23:28:54.833Z] 23:28:54     INFO -  xpcshell return code: None
[task 2020-05-05T23:28:54.833Z] 23:28:54     INFO -  tools/profiler/tests/xpcshell/test_feature_mainthreadio.js | Process still running after test!
[task 2020-05-05T23:28:54.889Z] 23:28:54     INFO -  INFO | Result summary:
[task 2020-05-05T23:28:54.891Z] 23:28:54     INFO -  INFO | Passed: 533
[task 2020-05-05T23:28:54.892Z] 23:28:54  WARNING -  INFO | Failed: 1
[task 2020-05-05T23:28:54.892Z] 23:28:54  WARNING -  One or more unittests failed.
[task 2020-05-05T23:28:54.893Z] 23:28:54     INFO -  INFO | Todo: 0
[task 2020-05-05T23:28:54.893Z] 23:28:54     INFO -  INFO | Retried: 3
[task 2020-05-05T23:28:54.894Z] 23:28:54     INFO -  SUITE-END | took 4602s
[task 2020-05-05T23:28:54.895Z] 23:28:54     INFO -  Node moz-http2 server shutting down ...
[task 2020-05-05T23:28:54.945Z] 23:28:54    ERROR - Return code: 1
[task 2020-05-05T23:28:54.946Z] 23:28:54     INFO - TinderboxPrint: xpcshell-xpcshell<br/>533/<em class="testfail">1</em>/0
[task 2020-05-05T23:28:54.946Z] 23:28:54  WARNING - # TBPL FAILURE #
[task 2020-05-05T23:28:54.947Z] 23:28:54  WARNING - setting return code to 2
[task 2020-05-05T23:28:54.947Z] 23:28:54  WARNING - The xpcshell suite: xpcshell ran with return status: FAILURE
[task 2020-05-05T23:28:54.947Z] 23:28:54     INFO - Running post-action listener: _package_coverage_data
[task 2020-05-05T23:28:54.948Z] 23:28:54     INFO - Running post-action listener: _resource_record_post_action
[task 2020-05-05T23:28:54.949Z] 23:28:54     INFO - Running post-action listener: process_java_coverage_data
[task 2020-05-05T23:28:54.949Z] 23:28:54     INFO - [mozharness: 2020-05-05 23:28:54.949129Z] Finished run-tests step (success)
[task 2020-05-05T23:28:54.949Z] 23:28:54     INFO - Running post-run listener: _resource_record_post_run
[task 2020-05-05T23:28:55.226Z] 23:28:55     INFO - Validating Perfherder data against /builds/worker/workspace/mozharness/external_tools/performance-artifact-schema.json
[task 2020-05-05T23:28:55.230Z] 23:28:55     INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"subtests": [{"name": "cpu_percent", "value": 87.17697041675652}, {"name": "io_write_bytes", "value": 12389855232}, {"name": "io.read_bytes", "value": 897470464}, {"name": "io_write_time", "value": 649596}, {"name": "io_read_time", "value": 17184}], "extraOptions": ["e10s", "taskcluster-m5.large"], "name": "xpcshell.xpcshell.overall"}, {"subtests": [{"name": "time", "value": 0.030916213989257812}], "name": "xpcshell.xpcshell.start-pulseaudio"}, {"subtests": [{"name": "time", "value": 30.929887771606445}, {"name": "cpu_percent", "value": 50.38103448275862}], "name": "xpcshell.xpcshell.install"}, {"subtests": [{"name": "time", "value": 0.011712074279785156}], "name": "xpcshell.xpcshell.stage-files"}, {"subtests": [{"name": "time", "value": 4604.784519195557}, {"name": "cpu_percent", "value": 87.42396739130425}], "name": "xpcshell.xpcshell.run-tests"}]}
[task 2020-05-05T23:28:55.231Z] 23:28:55     INFO - Total resource usage - Wall time: 4636s; CPU: 87.0%; Read bytes: 897470464; Write bytes: 12389855232; Read time: 17184; Write time: 649596
[task 2020-05-05T23:28:55.232Z] 23:28:55     INFO - TinderboxPrint: CPU usage<br/>87.4%
[task 2020-05-05T23:28:55.233Z] 23:28:55     INFO - TinderboxPrint: I/O read bytes / time<br/>897,470,464 / 17,184
[task 2020-05-05T23:28:55.233Z] 23:28:55     INFO - TinderboxPrint: I/O write bytes / time<br/>12,389,855,232 / 649,596
[task 2020-05-05T23:28:55.234Z] 23:28:55     INFO - TinderboxPrint: CPU idle<br/>1,190.3 (12.8%)
[task 2020-05-05T23:28:55.235Z] 23:28:55     INFO - TinderboxPrint: CPU system<br/>1,088.3 (11.7%)
[task 2020-05-05T23:28:55.235Z] 23:28:55     INFO - TinderboxPrint: CPU user<br/>6,983.7 (75.3%)
[task 2020-05-05T23:28:55.236Z] 23:28:55     INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2020-05-05T23:28:55.237Z] 23:28:55     INFO - start-pulseaudio - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2020-05-05T23:28:55.239Z] 23:28:55     INFO - install - Wall time: 31s; CPU: 50.0%; Read bytes: 552960; Write bytes: 954773504; Read time: 4; Write time: 91052

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 3

Platform breakdown:

• linux1804-64-tsan: 3

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

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 3

Platform breakdown:

• linux1804-64-tsan: 3

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

Comment 3

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 3

Platform breakdown:

• linux1804-64-tsan: 3

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

Comment 4

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform breakdown:

• linux1804-64-tsan: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1635619&startday=2020-06-01&endday=2020-06-07&tree=all

Comment 5

[Cristina Coroiu [:ccoroiu]]

Done the retriggers:
https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=Linux%2C18.04%2Cx64%2Ctsan%2Copt%2CXpcshell%2Ctests%2Ctest-linux1804-64-tsan%2Fopt-xpcshell-e10s-4%2CX%28X4%29&tochange=bd39e75bf891c3a5484fe3fd390b2dc6e854d90b&fromchange=ab8da9fe39fe8e086a642bc967695be0bed3c6d3&selectedTaskRun=Hf3yZxQrScK7qvMMLPLkWg.0

Comment 6

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 13
• mozilla-central: 1

Platform breakdown:

• linux1804-64-tsan: 14

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1635619&startday=2020-06-08&endday=2020-06-14&tree=all

Comment 7

[Intermittent Failures Robot]

15 failures in 942 pushes (0.016 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 14
• mozilla-central: 1

Platform breakdown:

• linux1804-64-tsan: 15

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1635619&startday=2020-06-17&endday=2020-06-17&tree=all

Comment 8

[Intermittent Failures Robot]

49 failures in 4035 pushes (0.012 failures/push) were associated with this bug in the last 7 days.

This is the #26 most frequent failure this week.

** 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: 44
• mozilla-central: 5

Platform breakdown:

• linux1804-64-tsan: 49

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1635619&startday=2020-06-15&endday=2020-06-21&tree=all

Comment 9

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

I'll have a look...

Comment 10

[Paul Adenot (:padenot)]

This fails locally in opt+debug TSAN:

pid:12945 ==================
 0:02.80 pid:12945 WARNING: ThreadSanitizer: data race (pid=12945)
 0:02.80 pid:12945   Write of size 4 at 0x7f6ecc0a67a4 by thread T3:
 0:02.80 pid:12945     #0 PR_Unlock /home/padenot/src/trees/mozilla-unified/nsprpub/pr/src/pthreads/ptsynch.c:217:29 (libnspr4.so+0x3bff2)
 0:02.80 pid:12945     #1 _pt_root /home/padenot/src/trees/mozilla-unified/nsprpub/pr/src/pthreads/ptthread.c:199:5 (libnspr4.so+0x577a0)
 0:02.80 pid:12945   Previous write of size 4 at 0x7f6ecc0a67a4 by main thread:
 0:02.80 pid:12945     #0 PR_Unlock /home/padenot/src/trees/mozilla-unified/nsprpub/pr/src/pthreads/ptsynch.c:217:29 (libnspr4.so+0x3bff2)
 0:02.80 pid:12945     #1 _PR_CreateThread /home/padenot/src/trees/mozilla-unified/nsprpub/pr/src/pthreads/ptthread.c:518:9 (libnspr4.so+0x4e085)
 0:02.80 pid:12945     #2 PR_CreateThread /home/padenot/src/trees/mozilla-unified/nsprpub/pr/src/pthreads/ptthread.c:533:12 (libnspr4.so+0x42ed7)
 0:02.80 pid:12945     #3 nsThread::Init(nsTSubstring<char> const&) /home/padenot/src/trees/mozilla-unified/xpcom/threads/nsThread.cpp:659:8 (libxul.so+0x67fcfa0)
 0:02.80 pid:12945     #4 nsThreadManager::NewNamedThread(nsTSubstring<char> const&, unsigned int, nsIThread**) /home/padenot/src/trees/mozilla-unified/xpcom/threads/nsThreadManager.cpp:619:12 (libxul.so+0x680737c)
 0:02.80 pid:12945     #5 NS_NewNamedThread(nsTSubstring<char> const&, nsIThread**, already_AddRefed<nsIRunnable>, unsigned int) /home/padenot/src/trees/mozilla-unified/xpcom/threads/nsThreadUtils.cpp:157:57 (libxul.so+0x681027f)
 0:02.80 pid:12945     #6 nsresult NS_NewNamedThread<16ul>(char const (&) [16ul], nsIThread**, nsIRunnable*, unsigned int) /home/padenot/src/trees/mozilla-unified/objdir-ff-tsan/dist/include/nsThreadUtils.h:82:10 (libxul.so+0x6a8700e)
 0:02.80 pid:12945     #7 mozilla::net::NetlinkService::Init(mozilla::net::NetlinkServiceListener*) /home/padenot/src/trees/mozilla-unified/netwerk/system/netlink/NetlinkService.cpp:1244:8 (libxul.so+0x72c6eb0)
 0:02.80 pid:12945     #8 nsNetworkLinkService::Init() /home/padenot/src/trees/mozilla-unified/netwerk/system/linux/nsNetworkLinkService.cpp:98:21 (libxul.so+0x72bea2a)
 0:02.80 pid:12945     #9 mozilla::xpcom::CreateInstanceImpl(mozilla::xpcom::ModuleID, nsISupports*, nsID const&, void**) /home/padenot/src/trees/mozilla-unified/objdir-ff-tsan/xpcom/components/StaticComponents.cpp:9482:7 (libxul.so+0x679729f)
 0:02.80 pid:12945     #10 mozilla::xpcom::StaticModule::CreateInstance(nsISupports*, nsID const&, void**) const /home/padenot/src/trees/mozilla-unified/objdir-ff-tsan/xpcom/components/StaticComponents.cpp:11562:10 (libxul.so+0x6793cf2)
 0:02.80 pid:12945     #11 CreateInstance /home/padenot/src/trees/mozilla-unified/xpcom/components/nsComponentManager.cpp:219:46 (libxul.so+0x67be978)
 0:02.80 pid:12945     #12 nsComponentManagerImpl::GetServiceLocked((anonymous namespace)::MutexLock&, (anonymous namespace)::EntryWrapper&, nsID const&, void**) /home/padenot/src/trees/mozilla-unified/xpcom/components/nsComponentManager.cpp:1372:17 (libxul.so+0x67be978)
 0:02.80 pid:12945     #13 nsComponentManagerImpl::GetServiceByContractID(char const*, nsID const&, void**) /home/padenot/src/trees/mozilla-unified/xpcom/components/nsComponentManager.cpp:1559:10 (libxul.so+0x67b8044)
 0:02.80 pid:12945     #14 CallGetService /home/padenot/src/trees/mozilla-unified/xpcom/components/nsComponentManagerUtils.cpp:61:43 (libxul.so+0x67c3b7e)
 0:02.80 pid:12945     #15 nsGetServiceByContractIDWithError::operator()(nsID const&, void**) const /home/padenot/src/trees/mozilla-unified/xpcom/components/nsComponentManagerUtils.cpp:253:21 (libxul.so+0x67c3b7e)
 0:02.81 pid:12945     #16 assign_from_gs_contractid_with_error /home/padenot/src/trees/mozilla-unified/objdir-ff-tsan/dist/include/nsCOMPtr.h:1232:7 (libxul.so+0x69e3e74)
 0:02.81 pid:12945     #17 operator= /home/padenot/src/trees/mozilla-unified/objdir-ff-tsan/dist/include/nsCOMPtr.h:762:5 (libxul.so+0x69e3e74)
 0:02.81 pid:12945     #18 mozilla::net::nsIOService::InitializeNetworkLinkService() /home/padenot/src/trees/mozilla-unified/netwerk/base/nsIOService.cpp:385:23 (libxul.so+0x69e3e74)
 0:02.81 pid:12945     #19 mozilla::net::nsIOService::Init() /home/padenot/src/trees/mozilla-unified/netwerk/base/nsIOService.cpp:293:3 (libxul.so+0x69e33e8)
 0:02.81 pid:12945     #20 mozilla::net::nsIOService::GetInstance() /home/padenot/src/trees/mozilla-unified/netwerk/base/nsIOService.cpp:411:9 (libxul.so+0x69e51f0)
 0:02.81 pid:12945     #21 mozilla::xpcom::CreateInstanceImpl(mozilla::xpcom::ModuleID, nsISupports*, nsID const&, void**) /home/padenot/src/trees/mozilla-unified/objdir-ff-tsan/xpcom/components/StaticComponents.cpp:9532:48 (libxul.so+0x679a2f9)
 0:02.81 pid:12945     #22 mozilla::xpcom::StaticModule::CreateInstance(nsISupports*, nsID const&, void**) const /home/padenot/src/trees/mozilla-unified/objdir-ff-tsan/xpcom/components/StaticComponents.cpp:11562:10 (libxul.so+0x6793cf2)
 0:02.81 pid:12945     #23 CreateInstance /home/padenot/src/trees/mozilla-unified/xpcom/components/nsComponentManager.cpp:219:46 (libxul.so+0x67be978)
 0:02.81 pid:12945     #24 nsComponentManagerImpl::GetServiceLocked((anonymous namespace)::MutexLock&, (anonymous namespace)::EntryWrapper&, nsID const&, void**) /home/padenot/src/trees/mozilla-unified/xpcom/components/nsComponentManager.cpp:1372:17 (libxul.so+0x67be978)
 0:02.81 pid:12945     #25 nsComponentManagerImpl::GetServiceByContractID(char const*, nsID const&, void**) /home/padenot/src/trees/mozilla-unified/xpcom/components/nsComponentManager.cpp:1559:10 (libxul.so+0x67b8044)
 0:02.81 pid:12945     #26 CallGetService(char const*, nsID const&, void**) /home/padenot/src/trees/mozilla-unified/xpcom/components/nsComponentManagerUtils.cpp:61:43 (libxul.so+0x67c33e1)
 0:02.81 pid:12945     #27 CallGetService<nsIIOService> /home/padenot/src/trees/mozilla-unified/objdir-ff-tsan/dist/include/nsServiceManagerUtils.h:72:10 (libxul.so+0x8319481)
 0:02.81 pid:12945     #28 nsScriptSecurityManager::Init() /home/padenot/src/trees/mozilla-unified/caps/nsScriptSecurityManager.cpp:1369:17 (libxul.so+0x8319481)
 0:02.81 pid:12945     #29 nsScriptSecurityManager::InitStatics() /home/padenot/src/trees/mozilla-unified/caps/nsScriptSecurityManager.cpp:1430:28 (libxul.so+0x8319d5a)
 0:02.81 pid:12945     #30 nsXPConnect::InitStatics() /home/padenot/src/trees/mozilla-unified/js/xpconnect/src/nsXPConnect.cpp:153:3 (libxul.so+0x7f38140)
 0:02.81 pid:12945     #31 xpcModuleCtor() /home/padenot/src/trees/mozilla-unified/js/xpconnect/src/XPCModule.cpp:11:3 (libxul.so+0x7ee5ba1)
 0:02.81 pid:12945     #32 nsLayoutModuleInitialize() /home/padenot/src/trees/mozilla-unified/layout/build/nsLayoutModule.cpp:108:7 (libxul.so+0xd26aa9b)
 0:02.81 pid:12945     #33 nsComponentManagerImpl::Init() /home/padenot/src/trees/mozilla-unified/xpcom/components/nsComponentManager.cpp:482:5 (libxul.so+0x67b8cca)
 0:02.81 pid:12945     #34 NS_InitXPCOM /home/padenot/src/trees/mozilla-unified/xpcom/build/XPCOMInit.cpp:447:51 (libxul.so+0x6864a36)
 0:02.81 pid:12945     #35 XRE_XPCShellMain(int, char**, char**, XREShellData const*) /home/padenot/src/trees/mozilla-unified/js/xpconnect/src/XPCShellImpl.cpp:1204:10 (libxul.so+0x7f0c1b4)
 0:02.81 pid:12945     #36 mozilla::BootstrapImpl::XRE_XPCShellMain(int, char**, char**, XREShellData const*) /home/padenot/src/trees/mozilla-unified/toolkit/xre/Bootstrap.cpp:54:12 (libxul.so+0xf072d1e)
 0:02.81 pid:12945     #37 main /home/padenot/src/trees/mozilla-unified/js/xpconnect/shell/xpcshell.cpp:66:27 (xpcshell+0x11d265)
 0:02.81 pid:12945   Location is global 'pt_debug' of size 40 at 0x7f6ecc0a6790 (libnspr4.so+0x00000005d7a4)
 0:02.81 pid:12945   Thread T3 (tid=12949, running) created by main thread at:
 0:02.81 pid:12945     #0 pthread_create /builds/worker/fetches/llvm-project/llvm/projects/compiler-rt/lib/tsan/rtl/tsan_interceptors.cc:967:3 (xpcshell+0xabb1b)
 0:02.81 pid:12945     #1 _PR_CreateThread /home/padenot/src/trees/mozilla-unified/nsprpub/pr/src/pthreads/ptthread.c:458:14 (libnspr4.so+0x4ddec)
 0:02.81 pid:12945     #2 PR_CreateThread /home/padenot/src/trees/mozilla-unified/nsprpub/pr/src/pthreads/ptthread.c:533:12 (libnspr4.so+0x42ed7)
 0:02.81 pid:12945     #3 nsThread::Init(nsTSubstring<char> const&) /home/padenot/src/trees/mozilla-unified/xpcom/threads/nsThread.cpp:659:8 (libxul.so+0x67fcfa0)
 0:02.81 pid:12945     #4 nsThreadManager::NewNamedThread(nsTSubstring<char> const&, unsigned int, nsIThread**) /home/padenot/src/trees/mozilla-unified/xpcom/threads/nsThreadManager.cpp:619:12 (libxul.so+0x680737c)
 0:02.81 pid:12945     #5 NS_NewNamedThread(nsTSubstring<char> const&, nsIThread**, already_AddRefed<nsIRunnable>, unsigned int) /home/padenot/src/trees/mozilla-unified/xpcom/threads/nsThreadUtils.cpp:157:57 (libxul.so+0x681027f)
 0:02.81 pid:12945     #6 nsresult NS_NewNamedThread<16ul>(char const (&) [16ul], nsIThread**, nsIRunnable*, unsigned int) /home/padenot/src/trees/mozilla-unified/objdir-ff-tsan/dist/include/nsThreadUtils.h:82:10 (libxul.so+0x6a8700e)
 0:02.81 pid:12945     #7 mozilla::net::NetlinkService::Init(mozilla::net::NetlinkServiceListener*) /home/padenot/src/trees/mozilla-unified/netwerk/system/netlink/NetlinkService.cpp:1244:8 (libxul.so+0x72c6eb0)
 0:02.81 pid:12945     #8 nsNetworkLinkService::Init() /home/padenot/src/trees/mozilla-unified/netwerk/system/linux/nsNetworkLinkService.cpp:98:21 (libxul.so+0x72bea2a)
 0:02.81 pid:12945     #9 mozilla::xpcom::CreateInstanceImpl(mozilla::xpcom::ModuleID, nsISupports*, nsID const&, void**) /home/padenot/src/trees/mozilla-unified/objdir-ff-tsan/xpcom/components/StaticComponents.cpp:9482:7 (libxul.so+0x679729f)
 0:02.81 pid:12945     #10 mozilla::xpcom::StaticModule::CreateInstance(nsISupports*, nsID const&, void**) const /home/padenot/src/trees/mozilla-unified/objdir-ff-tsan/xpcom/components/StaticComponents.cpp:11562:10 (libxul.so+0x6793cf2)
 0:02.81 pid:12945     #11 CreateInstance /home/padenot/src/trees/mozilla-unified/xpcom/components/nsComponentManager.cpp:219:46 (libxul.so+0x67be978)
 0:02.82 pid:12945     #12 nsComponentManagerImpl::GetServiceLocked((anonymous namespace)::MutexLock&, (anonymous namespace)::EntryWrapper&, nsID const&, void**) /home/padenot/src/trees/mozilla-unified/xpcom/components/nsComponentManager.cpp:1372:17 (libxul.so+0x67be978)
 0:02.82 pid:12945     #13 nsComponentManagerImpl::GetServiceByContractID(char const*, nsID const&, void**) /home/padenot/src/trees/mozilla-unified/xpcom/components/nsComponentManager.cpp:1559:10 (libxul.so+0x67b8044)
 0:02.82 pid:12945     #14 CallGetService /home/padenot/src/trees/mozilla-unified/xpcom/components/nsComponentManagerUtils.cpp:61:43 (libxul.so+0x67c3b7e)
 0:02.82 pid:12945     #15 nsGetServiceByContractIDWithError::operator()(nsID const&, void**) const /home/padenot/src/trees/mozilla-unified/xpcom/components/nsComponentManagerUtils.cpp:253:21 (libxul.so+0x67c3b7e)
 0:02.82 pid:12945     #16 assign_from_gs_contractid_with_error /home/padenot/src/trees/mozilla-unified/objdir-ff-tsan/dist/include/nsCOMPtr.h:1232:7 (libxul.so+0x69e3e74)
 0:02.82 pid:12945     #17 operator= /home/padenot/src/trees/mozilla-unified/objdir-ff-tsan/dist/include/nsCOMPtr.h:762:5 (libxul.so+0x69e3e74)
 0:02.82 pid:12945     #18 mozilla::net::nsIOService::InitializeNetworkLinkService() /home/padenot/src/trees/mozilla-unified/netwerk/base/nsIOService.cpp:385:23 (libxul.so+0x69e3e74)
 0:02.82 pid:12945     #19 mozilla::net::nsIOService::Init() /home/padenot/src/trees/mozilla-unified/netwerk/base/nsIOService.cpp:293:3 (libxul.so+0x69e33e8)
 0:02.82 pid:12945     #20 mozilla::net::nsIOService::GetInstance() /home/padenot/src/trees/mozilla-unified/netwerk/base/nsIOService.cpp:411:9 (libxul.so+0x69e51f0)
 0:02.82 pid:12945     #21 mozilla::xpcom::CreateInstanceImpl(mozilla::xpcom::ModuleID, nsISupports*, nsID const&, void**) /home/padenot/src/trees/mozilla-unified/objdir-ff-tsan/xpcom/components/StaticComponents.cpp:9532:48 (libxul.so+0x679a2f9)
 0:02.82 pid:12945     #22 mozilla::xpcom::StaticModule::CreateInstance(nsISupports*, nsID const&, void**) const /home/padenot/src/trees/mozilla-unified/objdir-ff-tsan/xpcom/components/StaticComponents.cpp:11562:10 (libxul.so+0x6793cf2)
 0:02.82 pid:12945     #23 CreateInstance /home/padenot/src/trees/mozilla-unified/xpcom/components/nsComponentManager.cpp:219:46 (libxul.so+0x67be978)
 0:02.82 pid:12945     #24 nsComponentManagerImpl::GetServiceLocked((anonymous namespace)::MutexLock&, (anonymous namespace)::EntryWrapper&, nsID const&, void**) /home/padenot/src/trees/mozilla-unified/xpcom/components/nsComponentManager.cpp:1372:17 (libxul.so+0x67be978)
 0:02.82 pid:12945     #25 nsComponentManagerImpl::GetServiceByContractID(char const*, nsID const&, void**) /home/padenot/src/trees/mozilla-unified/xpcom/components/nsComponentManager.cpp:1559:10 (libxul.so+0x67b8044)
 0:02.82 pid:12945     #26 CallGetService(char const*, nsID const&, void**) /home/padenot/src/trees/mozilla-unified/xpcom/components/nsComponentManagerUtils.cpp:61:43 (libxul.so+0x67c33e1)
 0:02.82 pid:12945     #27 CallGetService<nsIIOService> /home/padenot/src/trees/mozilla-unified/objdir-ff-tsan/dist/include/nsServiceManagerUtils.h:72:10 (libxul.so+0x8319481)
 0:02.82 pid:12945     #28 nsScriptSecurityManager::Init() /home/padenot/src/trees/mozilla-unified/caps/nsScriptSecurityManager.cpp:1369:17 (libxul.so+0x8319481)
 0:02.82 pid:12945     #29 nsScriptSecurityManager::InitStatics() /home/padenot/src/trees/mozilla-unified/caps/nsScriptSecurityManager.cpp:1430:28 (libxul.so+0x8319d5a)
 0:02.82 pid:12945     #30 nsXPConnect::InitStatics() /home/padenot/src/trees/mozilla-unified/js/xpconnect/src/nsXPConnect.cpp:153:3 (libxul.so+0x7f38140)
 0:02.82 pid:12945     #31 xpcModuleCtor() /home/padenot/src/trees/mozilla-unified/js/xpconnect/src/XPCModule.cpp:11:3 (libxul.so+0x7ee5ba1)
 0:02.82 pid:12945     #32 nsLayoutModuleInitialize() /home/padenot/src/trees/mozilla-unified/layout/build/nsLayoutModule.cpp:108:7 (libxul.so+0xd26aa9b)
 0:02.82 pid:12945     #33 nsComponentManagerImpl::Init() /home/padenot/src/trees/mozilla-unified/xpcom/components/nsComponentManager.cpp:482:5 (libxul.so+0x67b8cca)
 0:02.82 pid:12945     #34 NS_InitXPCOM /home/padenot/src/trees/mozilla-unified/xpcom/build/XPCOMInit.cpp:447:51 (libxul.so+0x6864a36)
 0:02.82 pid:12945     #35 XRE_XPCShellMain(int, char**, char**, XREShellData const*) /home/padenot/src/trees/mozilla-unified/js/xpconnect/src/XPCShellImpl.cpp:1204:10 (libxul.so+0x7f0c1b4)
 0:02.82 pid:12945     #36 mozilla::BootstrapImpl::XRE_XPCShellMain(int, char**, char**, XREShellData const*) /home/padenot/src/trees/mozilla-unified/toolkit/xre/Bootstrap.cpp:54:12 (libxul.so+0xf072d1e)
 0:02.83 pid:12945     #37 main /home/padenot/src/trees/mozilla-unified/js/xpconnect/shell/xpcshell.cpp:66:27 (xpcshell+0x11d265)
 0:02.83 pid:12945 SUMMARY: ThreadSanitizer: data race /home/padenot/src/trees/mozilla-unified/nsprpub/pr/src/pthreads/ptsynch.c:217:29 in PR_Unlock

Comment 11

[Intermittent Failures Robot]

50 failures in 5252 pushes (0.01 failures/push) were associated with this bug in the last 7 days.

This is the #30 most frequent failure this week.

** 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: 45
• try: 3
• mozilla-central: 2

Platform breakdown:

• linux1804-64-tsan: 50

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1635619&startday=2020-06-22&endday=2020-06-28&tree=all

Comment 12

[Julien Wajsberg [:julienw]]

hey gerald, may this be linked to bug 1622477 ?

From a quick look at the failures, it seems to fail mostly when starting the profiler again in the second part of the test, but it fails also sometimes for the first start. We don't have logs as fine as for the test_active_configuration test (from bug 1622477) so we don't know for sure this is timing out on starting the profiler, or capturing, or stopping.

Comment 13

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

Yes, thanks for the tip. Investigating...

Comment 14

[Intermittent Failures Robot]

30 failures in 4516 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: 28
• mozilla-central: 1
• try: 1

Platform breakdown:

• linux1804-64-tsan: 30

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1635619&startday=2020-06-29&endday=2020-07-05&tree=all

Comment 15

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

(In reply to Paul Adenot (:padenot) from comment #10)

This fails locally in opt+debug TSAN:

...
 0:02.81 pid:12945     #18 mozilla::net::nsIOService::InitializeNetworkLinkService() /home/padenot/src/trees/mozilla-unified/netwerk/base/nsIOService.cpp:385:23 (libxul.so+0x69e3e74)
...

Could this be somehow related to bug 1647759, and not be relevant to our issue here?

Anyway, today I ran some Try tests to verify whether bug 1626918 is the cause (as Cristina found in comment 5), and to attempt to hone in on the actual cause:

1. Central -> Intermittents in "Linux 18.04 x64 tsan" opt X4 tests (same as recorded in this bug and bug 1622477)
   https://treeherder.mozilla.org/#/jobs?repo=try&group_state=expanded&selectedTaskRun=D4x0TgMYQXqtyAyznriV3A.0&revision=a325e6dc947f3b1aa3df48792ee3441df0abdd51
2. Forcefully disable MOZ_GECKO_PROFILER in AsyncLogger.h -> Intermittents are still present.
   https://treeherder.mozilla.org/#/jobs?repo=try&group_state=expanded&selectedTaskRun=D4x0TgMYQXqtyAyznriV3A.0&revision=2bf178055b736b3cbd6b27393f86821973e8d990
3. Same as 2, and also don't start&stop audio callback tracing -> No intermittents! (So far, I've just restarted more X4 test runs)
   https://treeherder.mozilla.org/#/jobs?repo=try&group_state=expanded&selectedTaskRun=dmMnUigpR4GQrE6mSOqWxQ.0&revision=f972b0b58291a97e117b5f57f476a7fdd41261a0

If the results in 3 hold, this is pointing towards the AsyncLogger, even when there is no profiler code.

Paul, could you please have a look, see if there's anything obvious to you?
(End of my day here, I can investigate further tomorrow, depending on what you find...)

Comment 16

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

(In reply to Gerald Squelart [:gerald] (he/him) from comment #15)

3. Same as 2, and also don't start&stop audio callback tracing -> No intermittents! (So far, I've just restarted more X4 test runs)
   https://treeherder.mozilla.org/#/jobs?repo=try&group_state=expanded&selectedTaskRun=dmMnUigpR4GQrE6mSOqWxQ.0&revision=f972b0b58291a97e117b5f57f476a7fdd41261a0

If the results in 3 hold, this is pointing towards the AsyncLogger, even when there is no profiler code.

Woops, one intermittent happened in that last try, in test_active_configuration.js (bug 1626918), out of 30 runs.
It's interesting though that overall there are much fewer intermittents. Or it could just be a coincidence (only 15-30 runs, maybe on different machines, etc.).
Anyway, more work needed...

Comment 17

[Paul Adenot (:padenot)]

Tried adding an explicit linearization point in my code, in the form of a global lock, no luck.

Having stacks for all threads when the xpcshell time out should help.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=52b5e7d3c818e7f60b4847f36c56f44111f2a14a

Comment 18

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 17
• mozilla-central: 1

Platform breakdown:

• linux1804-64-tsan: 18

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1635619&startday=2020-07-06&endday=2020-07-12&tree=all

Comment 19

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 7
• mozilla-central: 2

Platform breakdown:

• linux1804-64-tsan: 9

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1635619&startday=2020-07-13&endday=2020-07-19&tree=all

Comment 20

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 3

Platform breakdown:

• linux1804-64-tsan: 3

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

Comment 21

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

Bug 1653181 removed the spikes introduced by bug 1626918, but there are still a few hits like before, so I'm keeping this bug open at a lower priority.

Comment 22

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform breakdown:

• linux1804-64-tsan: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1635619&startday=2020-07-27&endday=2020-08-02&tree=all

Comment 23

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 5

Platform breakdown:

• linux1804-64-tsan: 5

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1635619&startday=2020-08-10&endday=2020-08-16&tree=all

Comment 24

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 2
• autoland: 3

Platform breakdown:

• linux1804-64-tsan: 5

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1635619&startday=2020-08-17&endday=2020-08-23&tree=all

Comment 25

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform breakdown:

• linux1804-64-tsan: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1635619&startday=2020-08-24&endday=2020-08-30&tree=all

Comment 26

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1
• autoland: 2

Platform breakdown:

• linux1804-64-tsan: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1635619&startday=2020-08-31&endday=2020-09-06&tree=all

Comment 27

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Comment 28

[Natalia Csoregi [:nataliaCs]]

https://treeherder.mozilla.org/logviewer?job_id=325534000&repo=mozilla-central&lineNumber=2923

Comment 29

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• linux1804-64-tsan: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1635619&startday=2020-12-28&endday=2021-01-03&tree=all

Comment 30

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• linux1804-64-tsan: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1635619&startday=2021-01-18&endday=2021-01-24&tree=all

Comment 31

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• linux1804-64-tsan: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1635619&startday=2021-02-01&endday=2021-02-07&tree=all

Comment 32

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Comment 33

[Iulian Moraru]

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=353395924&repo=autoland&lineNumber=3141

[task 2021-10-01T20:40:35.633Z] 20:40:35     INFO -  TEST-START | tools/profiler/tests/xpcshell/test_feature_mainthreadio.js
[task 2021-10-01T20:45:35.637Z] 20:45:35  WARNING -  TEST-UNEXPECTED-TIMEOUT | tools/profiler/tests/xpcshell/test_feature_mainthreadio.js | Test timed out
[task 2021-10-01T20:45:35.638Z] 20:45:35     INFO -  TEST-INFO took 300001ms
[task 2021-10-01T20:45:35.638Z] 20:45:35     INFO -  >>>>>>>
[task 2021-10-01T20:45:35.639Z] 20:45:35     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2021-10-01T20:45:35.640Z] 20:45:35     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2021-10-01T20:45:35.641Z] 20:45:35     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2021-10-01T20:45:35.641Z] 20:45:35     INFO -  running event loop
[task 2021-10-01T20:45:35.641Z] 20:45:35     INFO -  tools/profiler/tests/xpcshell/test_feature_mainthreadio.js | Starting
[task 2021-10-01T20:45:35.641Z] 20:45:35     INFO -  (xpcshell/head.js) | test pending (2)
[task 2021-10-01T20:45:35.642Z] 20:45:35     INFO -  "Get the file"
[task 2021-10-01T20:45:35.643Z] 20:45:35     INFO -  "Generate file IO on the main thread using FileUtils.openSafeFileOutputStream."
[task 2021-10-01T20:45:35.645Z] 20:45:35     INFO -  "Write to the file"
[task 2021-10-01T20:45:35.645Z] 20:45:35     INFO -  "Close the file"
[task 2021-10-01T20:45:35.645Z] 20:45:35     INFO -  "Remove the file"
[task 2021-10-01T20:45:35.645Z] 20:45:35     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2021-10-01T20:45:35.645Z] 20:45:35     INFO -  "Check the FileIO markers when using the mainthreadio feature"
[task 2021-10-01T20:45:35.646Z] 20:45:35     INFO -  TEST-PASS | tools/profiler/tests/xpcshell/test_feature_mainthreadio.js |  - Found some markers - 3 > 0

Comment 34

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• linux1804-64-tsan-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1635619&startday=2021-09-27&endday=2021-10-03&tree=all

Comment 35

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Comment 36

[Cosmin Sabou [:CosminS]]

https://treeherder.mozilla.org/logviewer?job_id=358896303&repo=autoland

Comment 37

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• linux1804-64-tsan-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1635619&startday=2021-11-22&endday=2021-11-28&tree=all

Comment 38

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.