[browser][MT] GC deadlock

[pavelsavara]

Related #86903

Build Information

Build: https://dev.azure.com/dnceng-public/public/_build/results?buildId=524168

Error Message

{
  "ErrorMessage": "info: STATE CUE CARD",
  "ErrorPattern": "",
  "BuildRetry": false,
  "ExcludeConsoleLog": false
}

Log
Build

[20:00:27] warn: [2024-01-11T20:00:27.311Z] [ERROR] FATAL UNHANDLED EXCEPTION: System.OperationCanceledException: The operation was canceled.
[20:00:27] warn:    at System.Runtime.InteropServices.JavaScript.JSSynchronizationContext.Post(SendOrPostCallback , Object )
[20:00:27] warn:    at System.Threading.Tasks.SynchronizationContextAwaitTaskContinuation.PostAction(Object state)
[20:00:27] warn:    at System.Threading.Tasks.AwaitTaskContinuation.RunCallback(ContextCallback , Object , Task& )
[20:00:27] warn: --- End of stack trace from previous location ---
[20:00:27] warn:    at System.Threading.Tasks.Task.<>c.<ThrowAsync>b__128_1(Object state)
[20:00:27] warn:    at System.Threading.QueueUserWorkItemCallback.<>c.<.cctor>b__6_0(QueueUserWorkItemCallback quwi)
[20:00:27] warn:    at System.Threading.ExecutionContext.RunForThreadPoolUnsafe[QueueUserWorkItemCallback](ExecutionContext , Action`1 , QueueUserWorkItemCallback& )
[20:00:27] warn:    at System.Threading.QueueUserWorkItemCallback.Execute()
[20:00:27] warn:    at System.Threading.ThreadPoolWorkQueue.Dispatch()
[20:00:27] warn:    at System.Threading.PortableThreadPool.WorkerThread.WorkLoopSemaphoreSuccess(LowLevelLifoAsyncWaitSemaphore semaphore, Object stateObject)
[20:00:27] warn:    at System.Threading.LowLevelLifoAsyncWaitSemaphore.InternalAsyncWaitSuccess(LowLevelLifoAsyncWaitSemaphore , WaitEntry )
[20:00:27] warn:    at System.Threading.LowLevelLifoAsyncWaitSemaphore.SuccessCallback(IntPtr lifoSemaphore, IntPtr userData)
[20:00:27] info: [0x4890000-worker] MONO_WASM [0x4890000-worker]: forceDisposeProxies done: 2 imports, 0 exports, 0 GCHandles, 0 JSHandles.
[20:00:27] info: [2024-01-11T20:00:27.693Z] [FAIL] System.Runtime.InteropServices.JavaScript.Tests.WebWorkerTest.NativeThreadId(executor: JSWebWorker)
[20:00:27] info: System.OperationCanceledException : The operation was canceled.
[20:00:27] info:    at System.Runtime.InteropServices.JavaScript.Tests.WebWorkerTest.NativeThreadId(Executor executor)
[20:00:27] info: --- End of stack trace from previous location ---
[20:00:32] info: STATE CUE CARD: (? means a positive number, usually 1 or 2, * means any number)
[20:00:32] info: 	0x0	- starting (GOOD, unless the thread is running managed code)
[20:00:32] info: 	0x1	- detached (GOOD, unless the thread is running managed code)
[20:00:32] info: 	0x2	- running (BAD, unless it's the gc thread)
[20:00:32] info: 	0x?03	- async suspended (GOOD)
[20:00:32] info: 	0x?04	- self suspended (GOOD)
[20:00:32] info: 	0x?05	- async suspend requested (BAD)
[20:00:32] info: 	0x6	- blocking (BAD, unless there's no suspend initiator)
[20:00:32] info: 	0x?07	- blocking async suspended (GOOD)
[20:00:32] info: 	0x?08	- blocking self suspended (GOOD)
[20:00:32] info: 	0x?09	- blocking suspend requested (GOOD in coop; BAD in hybrid)
[20:00:32] info: --thread 0xa93fc0 id 0xdc5ec [0] state 109
[20:00:32] info: --thread 0x1ed8750 id 0x1edb5c0 [0] state 6
[20:00:32] info: --thread 0x20f3ec8 id 0x2157128 [0] state 109
[20:00:32] info: --thread 0x235d668 id 0x2460040 [0] state 108
[20:00:32] info: --thread 0x2b0fa68 id 0x2b1a038 [0] state 105
[20:00:32] info: --thread 0x325c9d8 id 0x326f0d0 [0] state 109
[20:00:32] info: --thread 0x360bac0 id 0x3617c78 [0] state 108
[20:00:32] info: --thread 0x3958368 id 0x3b3c3e8 [0] state 109
[20:00:32] info: --thread 0x45b9160 id 0x45ef460 [0] state 109
[20:00:32] info: --thread 0x4552258 id 0x4890000 [0] state 2  GC INITIATOR
[20:00:32] info: --thread 0x51c5738 id 0x53c0040 [0] state 104
[20:00:32] info: WAITING for 2 threads, got 1 suspended
[20:00:32] fail: [0x4890000-worker] Error: [MONO] /__w/1/s/src/mono/mono/utils/mono-threads.c:330 <disabled>
                     at Rt (http://127.0.0.1:36983/_framework/dotnet.runtime.js:3:13935)
                     at md (http://127.0.0.1:36983/_framework/dotnet.runtime.js:3:211225)
                     at http://127.0.0.1:36983/_framework/dotnet.native.wasm:wasm-function[9144]:0x235edb
                     at http://127.0.0.1:36983/_framework/dotnet.native.wasm:wasm-function[804]:0x43878
                     at http://127.0.0.1:36983/_framework/dotnet.native.wasm:wasm-function[722]:0x41bf7
                     at http://127.0.0.1:36983/_framework/dotnet.native.wasm:wasm-function[724]:0x41cba
                     at http://127.0.0.1:36983/_framework/dotnet.native.wasm:wasm-function[725]:0x41ced
                     at http://127.0.0.1:36983/_framework/dotnet.native.wasm:wasm-function[897]:0x4709b
                     at http://127.0.0.1:36983/_framework/dotnet.native.wasm:wasm-function[3503]:0x100084
                     at http://127.0.0.1:36983/_framework/dotnet.native.wasm:wasm-function[1033]:0x4c112
[20:30:07] fail: Tests timed out. Killing driver service pid 78
[20:30:07] fail: Application has finished with exit code TIMED_OUT but 0 was expected

Older Log

[15:40:48] fail: [pthread-worker] Error: [MONO] /__w/1/s/src/mono/mono/utils/mono-threads.c:330 <disabled>
                     at Rt (http://127.0.0.1:44637/_framework/dotnet.runtime.js:3:13935)
                     at ud (http://127.0.0.1:44637/_framework/dotnet.runtime.js:3:208105)
                     at http://127.0.0.1:44637/_framework/dotnet.native.wasm:wasm-function[199]:0x148b6
                     at http://127.0.0.1:44637/_framework/dotnet.native.wasm:wasm-function[683]:0x48f8e
                     at http://127.0.0.1:44637/_framework/dotnet.native.wasm:wasm-function[604]:0x4739b
                     at http://127.0.0.1:44637/_framework/dotnet.native.wasm:wasm-function[606]:0x4745e
                     at http://127.0.0.1:44637/_framework/dotnet.native.wasm:wasm-function[607]:0x47491
                     at http://127.0.0.1:44637/_framework/dotnet.native.wasm:wasm-function[777]:0x4c810
                     at http://127.0.0.1:44637/_framework/dotnet.native.wasm:wasm-function[3150]:0xeda68
                     at http://127.0.0.1:44637/_framework/dotnet.native.wasm:wasm-function[910]:0x51708
[15:40:48] info: STATE CUE CARD: (? means a positive number, usually 1 or 2, * means any number)
[15:40:48] info: 	0x0	- starting (GOOD, unless the thread is running managed code)
[15:40:48] info: 	0x1	- detached (GOOD, unless the thread is running managed code)
[15:40:48] info: 	0x2	- running (BAD, unless it's the gc thread)
[15:40:48] info: 	0x?03	- async suspended (GOOD)
[15:40:48] info: 	0x?04	- self suspended (GOOD)
[15:40:48] info: 	0x?05	- async suspend requested (BAD)
[15:40:48] info: 	0x6	- blocking (BAD, unless there's no suspend initiator)
[15:40:48] info: 	0x?07	- blocking async suspended (GOOD)
[15:40:48] info: 	0x?08	- blocking self suspended (GOOD)
[15:40:48] info: 	0x?09	- blocking suspend requested (GOOD in coop; BAD in hybrid)
[15:40:48] info: --thread 0x1ae6e30 id 0xdbddc [0] state 109
[15:40:48] info: --thread 0x2ed37c0 id 0x2fc5fa8 [0] state 6
[15:40:48] info: --thread 0x324e668 id 0x325e048 [0] state 109
[15:40:48] info: --thread 0x3777b58 id 0x3575c18 [0] state 108
[15:40:48] info: --thread 0x3cf12f8 id 0x3cff828 [0] state 109
[15:40:48] info: --thread 0x4d92e00 id 0x4b71c18 [0] state 2  GC INITIATOR
[15:40:48] info: --thread 0x63d8910 id 0x4dbe6a0 [0] state 109
[15:40:48] info: --thread 0x63fe760 id 0x5190040 [0] state 109
[15:40:48] info: --thread 0x4fcca28 id 0x55be060 [0] state 105
[15:40:48] info: --thread 0x78dcdd8 id 0x5bde318 [0] state 109
[15:40:48] info: --thread 0x63d4038 id 0x7b80000 [0] state 109
[15:40:48] info: WAITING for 1 threads, got 0 suspended

Known issue validation

Build: 🔎 https://dev.azure.com/dnceng-public/public/_build/results?buildId=524168
Error message validated: info: STATE CUE CARD
Result validation: ✅ Known issue matched with the provided build.
Validation performed at: 1/15/2024 3:45:34 PM UTC

Report

Build	Definition	Test	Pull Request
655920	dotnet/runtime	WasmTestOnFirefox-MT-System.Collections.Concurrent.Tests.WorkItemExecution	#101252
648322	dotnet/runtime	WasmTestOnChrome-System.Collections.Concurrent.Tests.WorkItemExecution	#101252
647412	dotnet/runtime	WasmTestOnBrowser-System.Runtime.Tests.WorkItemExecution	#101217

Summary

24-Hour Hit Count	7-Day Hit Count	1-Month Count
0	0	3

Tagging subscribers to 'arch-wasm': @lewing
See info in area-owners.md if you want to be subscribed.

Issue Details

---

[15:40:48] fail: [pthread-worker] Error: [MONO] /__w/1/s/src/mono/mono/utils/mono-threads.c:330 <disabled>
                     at Rt (http://127.0.0.1:44637/_framework/dotnet.runtime.js:3:13935)
                     at ud (http://127.0.0.1:44637/_framework/dotnet.runtime.js:3:208105)
                     at http://127.0.0.1:44637/_framework/dotnet.native.wasm:wasm-function[199]:0x148b6
                     at http://127.0.0.1:44637/_framework/dotnet.native.wasm:wasm-function[683]:0x48f8e
                     at http://127.0.0.1:44637/_framework/dotnet.native.wasm:wasm-function[604]:0x4739b
                     at http://127.0.0.1:44637/_framework/dotnet.native.wasm:wasm-function[606]:0x4745e
                     at http://127.0.0.1:44637/_framework/dotnet.native.wasm:wasm-function[607]:0x47491
                     at http://127.0.0.1:44637/_framework/dotnet.native.wasm:wasm-function[777]:0x4c810
                     at http://127.0.0.1:44637/_framework/dotnet.native.wasm:wasm-function[3150]:0xeda68
                     at http://127.0.0.1:44637/_framework/dotnet.native.wasm:wasm-function[910]:0x51708
[15:40:48] info: STATE CUE CARD: (? means a positive number, usually 1 or 2, * means any number)
[15:40:48] info: 	0x0	- starting (GOOD, unless the thread is running managed code)
[15:40:48] info: 	0x1	- detached (GOOD, unless the thread is running managed code)
[15:40:48] info: 	0x2	- running (BAD, unless it's the gc thread)
[15:40:48] info: 	0x?03	- async suspended (GOOD)
[15:40:48] info: 	0x?04	- self suspended (GOOD)
[15:40:48] info: 	0x?05	- async suspend requested (BAD)
[15:40:48] info: 	0x6	- blocking (BAD, unless there's no suspend initiator)
[15:40:48] info: 	0x?07	- blocking async suspended (GOOD)
[15:40:48] info: 	0x?08	- blocking self suspended (GOOD)
[15:40:48] info: 	0x?09	- blocking suspend requested (GOOD in coop; BAD in hybrid)
[15:40:48] info: --thread 0x1ae6e30 id 0xdbddc [0] state 109
[15:40:48] info: --thread 0x2ed37c0 id 0x2fc5fa8 [0] state 6
[15:40:48] info: --thread 0x324e668 id 0x325e048 [0] state 109
[15:40:48] info: --thread 0x3777b58 id 0x3575c18 [0] state 108
[15:40:48] info: --thread 0x3cf12f8 id 0x3cff828 [0] state 109
[15:40:48] info: --thread 0x4d92e00 id 0x4b71c18 [0] state 2  GC INITIATOR
[15:40:48] info: --thread 0x63d8910 id 0x4dbe6a0 [0] state 109
[15:40:48] info: --thread 0x63fe760 id 0x5190040 [0] state 109
[15:40:48] info: --thread 0x4fcca28 id 0x55be060 [0] state 105
[15:40:48] info: --thread 0x78dcdd8 id 0x5bde318 [0] state 109
[15:40:48] info: --thread 0x63d4038 id 0x7b80000 [0] state 109
[15:40:48] info: WAITING for 1 threads, got 0 suspended

Log

Author:	pavelsavara
Assignees:	pavelsavara
Labels:	arch-wasm, area-VM-threading-mono, os-browser
Milestone:	9.0.0

[pavelsavara]

cc @lambdageek

[pavelsavara]

locally on my machine

info: STATE CUE CARD: (? means a positive number, usually 1 or 2, * means any number)
  info:         0x0     - starting (GOOD, unless the thread is running managed code)
  info:         0x1     - detached (GOOD, unless the thread is running managed code)
  info:         0x2     - running (BAD, unless it's the gc thread)
  info:         0x?03   - async suspended (GOOD)
  info:         0x?04   - self suspended (GOOD)
  info:         0x?05   - async suspend requested (BAD)
  info:         0x6     - blocking (BAD, unless there's no suspend initiator)
  info:         0x?07   - blocking async suspended (GOOD)
  info:         0x?08   - blocking self suspended (GOOD)
  info:         0x?09   - blocking suspend requested (GOOD in coop; BAD in hybrid)
  info: --thread 0xe32cd8 id 0xf15a0 [0] state 108
  info: --thread 0x2404b38 id 0x240a5b0 [0] state 6
  info: --thread 0x2697c30 id 0x269f748 [0] state 105
  info: --thread 0x29b0ae0 id 0x29bd0e0 [0] state 108
  info: --thread 0x3637c30 id 0x3435aa8 [0] state 109
  info: --thread 0x3a6f650 id 0x3a78d30 [0] state 108
  info: --thread 0x57265f0 id 0x4580000 [0] state 109
  info: --thread 0x57bc5e8 id 0x4cd0df0 [0] state 2  GC INITIATOR
  info: --thread 0x3f72850 id 0x50d92b0 [0] state 109
  info: --thread 0x573b580 id 0x5b20040 [0] state 109
  info: WAITING for 1 threads, got 0 suspended
  fail: [0x4cd0df0-worker] Error: [MONO] suspend_thread suspend took 5006 ms, which is more than the allowed 5000 ms
      at mono_wasm_stringify_as_error_with_stack (http://127.0.0.1:52752/_framework/dotnet.runtime.js:1186:18)
      at mono_wasm_trace_logger (http://127.0.0.1:52752/_framework/dotnet.runtime.js:1205:27)
      at wasm_trace_logger (http://127.0.0.1:52752/_framework/dotnet.native.wasm:wasm-function[18451]:0x35aa38)
      at eglib_log_adapter (http://127.0.0.1:52752/_framework/dotnet.native.wasm:wasm-function[946]:0x5f57a)
      at monoeg_g_logstr (http://127.0.0.1:52752/_framework/dotnet.native.wasm:wasm-function[822]:0x5b1f2)
      at monoeg_g_logv_nofree (http://127.0.0.1:52752/_framework/dotnet.native.wasm:wasm-function[820]:0x5b147)
      at monoeg_g_logv (http://127.0.0.1:52752/_framework/dotnet.native.wasm:wasm-function[819]:0x5b0ba)
      at monoeg_g_log (http://127.0.0.1:52752/_framework/dotnet.native.wasm:wasm-function[823]:0x5b23a)
      at mono_threads_wait_pending_operations (http://127.0.0.1:52752/_framework/dotnet.native.wasm:wasm-function[1192]:0x6844f)
      at unified_suspend_stop_world (http://127.0.0.1:52752/_framework/dotnet.native.wasm:wasm-function[8596]:0x1e1f48)
  fail: Error: [MONO] Cannot transition thread 0xf15a0 from STATE_BLOCKING_SELF_SUSPENDED with ABORT_BLOCKING
      at mono_wasm_stringify_as_error_with_stack (http://127.0.0.1:52752/_framework/dotnet.runtime.js:1186:18)
      at mono_wasm_trace_logger (http://127.0.0.1:52752/_framework/dotnet.runtime.js:1205:27)
      at wasm_trace_logger (wasm_trace_logger (http://127.0.0.1:52752/_framework/dotnet.native.wasm:wasm-function[18451]:0x35aa38))
      at eglib_log_adapter (eglib_log_adapter (http://127.0.0.1:52752/_framework/dotnet.native.wasm:wasm-function[946]:0x5f57a))
      at monoeg_g_logstr (monoeg_g_logstr (http://127.0.0.1:52752/_framework/dotnet.native.wasm:wasm-function[822]:0x5b1f2))
      at monoeg_g_logv_nofree (monoeg_g_logv_nofree (http://127.0.0.1:52752/_framework/dotnet.native.wasm:wasm-function[820]:0x5b147))
      at monoeg_g_logv (monoeg_g_logv (http://127.0.0.1:52752/_framework/dotnet.native.wasm:wasm-function[819]:0x5b0ba))
      at monoeg_g_log (monoeg_g_log (http://127.0.0.1:52752/_framework/dotnet.native.wasm:wasm-function[823]:0x5b23a))
      at mono_threads_transition_abort_blocking (mono_threads_transition_abort_blocking (http://127.0.0.1:52752/_framework/dotnet.native.wasm:wasm-function[1351]:0x6df82))
      at mono_threads_enter_gc_unsafe_region_unbalanced_with_info (mono_threads_enter_gc_unsafe_region_unbalanced_with_info (http://127.0.0.1:52752/_framework/dotnet.native.wasm:wasm-function[1409]:0x6f0b1))