Skip to content

[browser][MT] GC deadlock #96190

Closed
Closed

Description

@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

Activity

  1. added this to the 9.0.0 milestone on Dec 19, 2023
  2. self-assigned this
    on Dec 19, 2023
  3. changed the title [-][browser][MT] deadlock in System.Collections.Concurrent.Tests[/-] [+][browser][MT] GC deadlock[/+] on Jan 15, 2024
  4. pavelsavara commented on Jan 16, 2024

    @pavelsavara
    MemberAuthor
  5. pavelsavara commented on Jan 17, 2024

    @pavelsavara
    MemberAuthor

    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))
    
  6. pavelsavara commented on Feb 14, 2024

    @pavelsavara
    MemberAuthor

    this is Blazor MT deadlock during renderBatch

    image

  7. pavelsavara commented on Mar 25, 2024

    @pavelsavara
    MemberAuthor

    In 3 last cases the cue card shows the problem is with Finalizer thread.

  8. pavelsavara commented on Apr 4, 2024

    @pavelsavara
    MemberAuthor

    Interesting Log

    [15:44:38] fail: [0x040d7ae0-norm 15:44:38.822] [MONO] * Assertion at /__w/1/s/src/mono/mono/metadata/threads.c:478, condition `<disabled>' not met
    ...
    
    [15:44:47] info: --thread 0x42db018 id 0x40d7ae0 [0] state 105
    
    ...
    
    [15:44:47] info: 005 | 0x040d7ae0-norm: isRunning: true isAttached: true isEventLoop:false reuseCount:  1 - Finalizer
    

    Why the Finalizer died in free_synch_cs ?

  9. pavelsavara commented on Apr 4, 2024

    @pavelsavara
    MemberAuthor

    Log

    [10:17:09] info: [PASS] System.Reflection.Tests.AssemblyTests.CustomAttributes
    [10:17:09] fail: [0x05600040-long 10:17:09.644] [MONO] * Assertion: should not be reached at /__w/1/s/src/mono/mono/sgen/sgen-scan-object.h:93
    [10:46:57] fail: Tests timed out. Killing driver service pid 79
    [10:46:57] fail: Application has finished with exit code TIMED_OUT but 0 was expected
    
  10. pavelsavara commented on Apr 4, 2024

    @pavelsavara
    MemberAuthor

    This is great Log

    It shows that NRE in finalizer was unhandled and it killed the finalizer thread, but not the whole process.

    [15:51:44] warn: 
    [15:51:44] warn: Unhandled Exception:
    [15:51:44] warn: System.NullReferenceException: Object reference not set to an instance of an object.
    [15:51:44] warn:    at System.Runtime.InteropServices.HandleCollectorTests.HandleLimitTester.Finalize()
    
    ...
    
    [15:51:44] warn: 
    [15:51:44] warn: Unhandled Exception:
    [15:51:44] warn: System.NullReferenceException: Object reference not set to an instance of an object.
    [15:51:44] warn:    at System.Runtime.InteropServices.HandleCollectorTests.HandleLimitTester.Finalize()
    [15:51:44] warn: [ERROR] FATAL UNHANDLED EXCEPTION: System.NullReferenceException: Object reference not set to an instance of an object.
    [15:51:44] warn:    at System.Runtime.InteropServices.HandleCollectorTests.HandleLimitTester.Finalize()
    
    ...
    
    [15:51:49] fail: [0x063c0040-long 15:51:49.281] [MONO] /__w/1/s/src/mono/mono/utils/mono-threads.c:336 <disabled>
                     
                     Error
                         at cu (http://127.0.0.1:33089/_framework/dotnet.runtime.js:3:201001)
                         at wasm_trace_logger (http://127.0.0.1:33089/_framework/dotnet.native.wasm:wasm-function[199]:0x14a7f)
                         at eglib_log_adapter (http://127.0.0.1:33089/_framework/dotnet.native.wasm:wasm-function[689]:0x4b8a0)
                         at monoeg_g_logv_nofree (http://127.0.0.1:33089/_framework/dotnet.native.wasm:wasm-function[611]:0x49cb1)
                         at monoeg_g_log (http://127.0.0.1:33089/_framework/dotnet.native.wasm:wasm-function[613]:0x49d74)
                         at monoeg_g_log_disabled (http://127.0.0.1:33089/_framework/dotnet.native.wasm:wasm-function[614]:0x49da7)
                         at mono_threads_wait_pending_operations (http://127.0.0.1:33089/_framework/dotnet.native.wasm:wasm-function[786]:0x4f2f1)
                         at unified_suspend_stop_world (http://127.0.0.1:33089/_framework/dotnet.native.wasm:wasm-function[3152]:0xf017c)
                         at sgen_stop_world (http://127.0.0.1:33089/_framework/dotnet.native.wasm:wasm-function[925]:0x542d1)
                         at sgen_perform_collection (http://127.0.0.1:33089/_framework/dotnet.native.wasm:wasm-function[924]:0x53f28)
                         at sgen_ensure_free_space (http://127.0.0.1:33089/_framework/dotnet.native.wasm:wasm-function[923]:0x53eae)
                         at sgen_alloc_obj_nolock (http://127.0.0.1:33089/_framework/dotnet.native.wasm:wasm-function[910]:0x532f5)
                         at mono_gc_alloc_vector (http://127.0.0.1:33089/_framework/dotnet.native.wasm:wasm-function[3172]:0xf0d25)
                         at mono_array_new_specific_internal (http://127.0.0.1:33089/_framework/dotnet.native.wasm:wasm-function[2703]:0xd5044)
                         at mono_array_new_specific_checked (http://127.0.0.1:33089/_framework/dotnet.native.wasm:wasm-function[2704]:0xd507b)
                         at mono_interp_exec_method (http://127.0.0.1:33089/_framework/dotnet.native.wasm:wasm-function[258]:0x20897)
                         at interp_runtime_invoke (http://127.0.0.1:33089/_framework/dotnet.native.wasm:wasm-function[297]:0x270c1)
                         at mono_jit_runtime_invoke (http://127.0.0.1:33089/_framework/dotnet.native.wasm:wasm-function[3342]:0xfd28b)
                         at do_runtime_invoke (http://127.0.0.1:33089/_framework/dotnet.native.wasm:wasm-function[2622]:0xcfb09)
                         at mono_runtime_invoke_checked (http://127.0.0.1:33089/_framework/dotnet.native.wasm:wasm-function[2621]:0xcfa99)
                         at ves_icall_InternalInvoke_raw (http://127.0.0.1:33089/_framework/dotnet.native.wasm:wasm-function[1980]:0xaa57d)
                         at do_icall (http://127.0.0.1:33089/_framework/dotnet.native.wasm:wasm-function[338]:0x28d1e)
                         at do_icall_wrapper (http://127.0.0.1:33089/_framework/dotnet.native.wasm:wasm-function[267]:0x26433)
                         at mono_interp_exec_method (http://127.0.0.1:33089/_framework/dotnet.native.wasm:wasm-function[258]:0x18cf1)
                         at interp_runtime_invoke (http://127.0.0.1:33089/_framework/dotnet.native.wasm:wasm-function[297]:0x270c1)
                         at mono_jit_runtime_invoke (http://127.0.0.1:33089/_framework/dotnet.native.wasm:wasm-function[3342]:0xfd28b)
                         at do_runtime_invoke (http://127.0.0.1:33089/_framework/dotnet.native.wasm:wasm-function[2622]:0xcfb09)
                         at mono_runtime_invoke_checked (http://127.0.0.1:33089/_framework/dotnet.native.wasm:wasm-function[2621]:0xcfa99)
                         at start_wrapper (http://127.0.0.1:33089/_framework/dotnet.native.wasm:wasm-function[2770]:0xd6cb2)
                         at Object.invokeEntryPoint (http://127.0.0.1:33089/_framework/dotnet.native.js:8:69009)
                         at handleMessage (http://127.0.0.1:33089/_framework/dotnet.native.worker.js:1:2306)
    [16:21:34] fail: Tests timed out. Killing driver service pid 79
    [16:21:34] fail: Application has finished with exit code TIMED_OUT but 0 was expected
    
  11. dotnet-policy-service commented on Apr 24, 2024

    @dotnet-policy-service
    Contributor

    Tagging subscribers to this area: @BrzVlad
    See info in area-owners.md if you want to be subscribed.

  12. locked and limited conversation to collaborators on Jun 14, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Type

No type

Projects

No projects

    Milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions