Bug 20073 - Deadlock in gc finalizer_thread
Summary: Deadlock in gc finalizer_thread
Status: NEW
Alias: None
Product: Runtime
Classification: Mono
Component: io-layer (show other bugs)
Version: 3.4.0
Hardware: PC Linux
: --- normal
Target Milestone: ---
Assignee: Bugzilla
URL:
Depends on:
Blocks:
 
Reported: 2014-05-27 16:35 UTC by Sergey Zhukov
Modified: 2016-12-15 00:50 UTC (History)
7 users (show)

See Also:
Tags:
Is this bug a regression?: ---
Last known good build:


Attachments

Description Sergey Zhukov 2014-05-27 16:35:10 UTC
While running ASP.NET VNext application, 
I've got deadlock between System.Threading.Thread.StartInternal and GC. 

To reproduce the issue, do the following things:
1. Install KRuntime as described in bug #20031
2. git clone https://github.com/davidfowl/HelloWorldVNext.git
3. navigate to src/helloworldweb directory
4. run "k web" from command line
5. run "ab -c 30 -n 10000 http://localhost:8080/" from command line

after several hundreds of requests application hangs with the following backtrace (look at threads#5 and #8).

Also there is other issue with dubugging info. It shows wrong line numbers for *.cs files (Thread.cs, WaitHandle.cs). I did not notice such things before in previous versions of mono.

mono --version

Mono JIT compiler version 3.4.1 (master/09126b1 Mon May 26 03:54:44 NOVT 2014)
Copyright (C) 2002-2014 Novell, Inc, Xamarin Inc and Contributors. www.mono-project.com
	TLS:           __thread
	SIGSEGV:       altstack
	Notifications: epoll
	Architecture:  x86
	Disabled:      none
	Misc:          softdebug 
	LLVM:          supported, not enabled.
	GC:            sgen

t a a bt
Thread 8 (Thread 0xb5c55b40 (LWP 737)):
#0  0xb77a3424 in __kernel_vsyscall ()
#1  0xb7738cc5 in sem_wait@@GLIBC_2.1 ()
    at ../nptl/sysdeps/unix/sysv/linux/i386/i686/../i486/sem_wait.S:80
#2  0x08281268 in mono_sem_wait (sem=0x83c2768, alertable=1)
    at mono-semaphore.c:119
#3  0x081f20a3 in finalizer_thread (unused=0x0) at gc.c:1073
#4  0x081d4bdd in start_wrapper_internal (data=0x970b728) at threads.c:660
#5  start_wrapper (data=0x970b728) at threads.c:707
#6  0x08285e75 in inner_start_thread (arg=0xbfc81b3c)
    at mono-threads-posix.c:94
#7  0xb7732d4c in start_thread (arg=0xb5c55b40) at pthread_create.c:308
#8  0xb7671bae in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:130

Thread 7 (Thread 0xb46efb40 (LWP 752)):
#0  0xb7750eea in clock_nanosleep (clock_id=138133492, flags=1, req=
    0xb46ef208, rem=0x0) at ../sysdeps/unix/sysv/linux/clock_nanosleep.c:49
#1  0x08273b58 in SleepEx (ms=500, alertable=1) at wthreads.c:277
#2  0x081d72d7 in monitor_thread (unused=0x0) at threadpool.c:779
#3  0x081d4bdd in start_wrapper_internal (data=0xa6934b8) at threads.c:660
#4  start_wrapper (data=0xa6934b8) at threads.c:707
#5  0x08285e75 in inner_start_thread (arg=0xbfc801ec)
---Type <return> to continue, or q <return> to quit---
    at mono-threads-posix.c:94
#6  0xb7732d4c in start_thread (arg=0xb46efb40) at pthread_create.c:308
#7  0xb7671bae in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:130

Thread 6 (Thread 0xb3dffb40 (LWP 753)):
#0  0xb77a3424 in __kernel_vsyscall ()
#1  0xb7738e78 in sem_timedwait ()
    at ../nptl/sysdeps/unix/sysv/linux/i386/i686/../i486/sem_timedwait.S:111
#2  0x0828134c in mono_sem_timedwait (sem=0x83c2574, timeout_ms=2000, 
    alertable=1) at mono-semaphore.c:82
#3  0x081da0b0 in async_invoke_thread (data=0x0) at threadpool.c:1566
#4  0x081d4bdd in start_wrapper_internal (data=0xa6934b8) at threads.c:660
#5  start_wrapper (data=0xa6934b8) at threads.c:707
#6  0x08285e75 in inner_start_thread (arg=0xbfc801bc)
    at mono-threads-posix.c:94
#7  0xb7732d4c in start_thread (arg=0xb3dffb40) at pthread_create.c:308
#8  0xb7671bae in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:130

Thread 5 (Thread 0xb3affb40 (LWP 762)):
#0  0xb77a3424 in __kernel_vsyscall ()
#1  0xb7736d13 in pthread_cond_timedwait@@GLIBC_2.3.2 ()
    at ../nptl/sysdeps/unix/sysv/linux/i386/i686/../i486/pthread_cond_timedwait.S:236
---Type <return> to continue, or q <return> to quit---
#2  0x0825d916 in _wapi_handle_timedwait_signal_handle (handle=0x4c4, timeout=
    0xb3afef38, alertable=1, poll=0) at handles.c:1594
#3  0x08272554 in WaitForSingleObjectEx (handle=0x4c4, timeout=999, alertable=
    1) at wait.c:196
#4  0x081d2381 in mono_wait_uninterrupted (thread=0xb3c8d820, multiple=0, 
    numhandles=1, handles=0xb3afefd4, waitall=0, ms=999, alertable=1)
    at threads.c:1329
#5  0x081d441b in ves_icall_System_Threading_WaitHandle_WaitOne_internal (this=
    0xb6e37318, handle=0x4c4, ms=999, exitContext=0) at threads.c:1461
#6  0xb4a1b090 in ?? ()
#7  0xb5ff9c64 in System.Threading.WaitHandle:WaitOne (this=..., 
    millisecondsTimeout=999, exitContext=false)
    at /home/sergey/Projects/mono/mono/mcs/class/corlib/System.Threading/WaitHandle.cs:744
#8  0xb5ff9d06 in System.Threading.WaitHandle:WaitOne (this=..., 
    millisecondsTimeout=999)
    at /home/sergey/Projects/mono/mono/mcs/class/corlib/System.Threading/WaitHandle.cs:783
#9  0xb5ff8dbc in System.Threading.Timer/Scheduler:SchedulerThread (this=...)
    at /home/sergey/Projects/mono/mono/mcs/class/corlib/System.Threading/Timer.cs:706
#10 0xb5ff4cca in System.Threading.Thread:StartInternal (this=...)
    at /home/sergey/Projects/mono/mono/mcs/class/corlib/System.Threading/Thread.---Type <return> to continue, or q <return> to quit---
cs:1378
#11 0xb5d18d88 in ?? ()
#12 0x0806ab5d in mono_jit_runtime_invoke (method="%s:%s ()", obj=0xb6e37500, 
    params=0xb3aff2bc, exc=0x0) at mini.c:6723
#13 0x081fa39f in mono_runtime_invoke (method="%s:%s ()", obj=0xb6e37500, 
    params=0xb3aff2bc, exc=0x0) at object.c:2828
#14 0x081fb215 in mono_runtime_delegate_invoke (delegate=0xb6e37500, params=
    0xb3aff2bc, exc=0x0) at object.c:3539
#15 0x081d4cc0 in start_wrapper_internal (data=0xa978000) at threads.c:666
#16 start_wrapper (data=0xa978000) at threads.c:707
#17 0x08285e75 in inner_start_thread (arg=0xbfc804dc)
    at mono-threads-posix.c:94
#18 0xb7732d4c in start_thread (arg=0xb3affb40) at pthread_create.c:308
#19 0xb7671bae in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:130

Thread 4 (Thread 0xb3f66b40 (LWP 763)):
#0  0xb77a3424 in __kernel_vsyscall ()
#1  0xb7672766 in epoll_wait () at ../sysdeps/unix/syscall-template.S:82
#2  0x081d7c71 in tp_epoll_wait (p=0x83c24a0)
    at ../../mono/metadata/tpool-epoll.c:118
#3  0x081d4bdd in start_wrapper_internal (data=0xa997af0) at threads.c:660
#4  start_wrapper (data=0xa997af0) at threads.c:707
#5  0x08285e75 in inner_start_thread (arg=0xbfc80cdc)
---Type <return> to continue, or q <return> to quit---
    at mono-threads-posix.c:94
#6  0xb7732d4c in start_thread (arg=0xb3f66b40) at pthread_create.c:308
#7  0xb7671bae in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:130

Thread 3 (Thread 0xb3f45b40 (LWP 764)):
#0  0xb77a3424 in __kernel_vsyscall ()
#1  0xb7738e78 in sem_timedwait ()
    at ../nptl/sysdeps/unix/sysv/linux/i386/i686/../i486/sem_timedwait.S:111
#2  0x0828134c in mono_sem_timedwait (sem=0x83c24f4, timeout_ms=2000, 
    alertable=1) at mono-semaphore.c:82
#3  0x081da0b0 in async_invoke_thread (data=0x0) at threadpool.c:1566
#4  0x081d4bdd in start_wrapper_internal (data=0xa98ad08) at threads.c:660
#5  start_wrapper (data=0xa98ad08) at threads.c:707
#6  0x08285e75 in inner_start_thread (arg=0xbfc80cac)
    at mono-threads-posix.c:94
#7  0xb7732d4c in start_thread (arg=0xb3f45b40) at pthread_create.c:308
#8  0xb7671bae in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:130

Thread 2 (Thread 0xb4067b40 (LWP 765)):
#0  0xb77a3424 in __kernel_vsyscall ()
#1  0xb7738e78 in sem_timedwait ()
    at ../nptl/sysdeps/unix/sysv/linux/i386/i686/../i486/sem_timedwait.S:111
#2  0x0828134c in mono_sem_timedwait (sem=0x83c2574, timeout_ms=2000, 
---Type <return> to continue, or q <return> to quit---
    alertable=1) at mono-semaphore.c:82
#3  0x081da0b0 in async_invoke_thread (data=0x0) at threadpool.c:1566
#4  0x081d4bdd in start_wrapper_internal (data=0xb3e02330) at threads.c:660
#5  start_wrapper (data=0xb3e02330) at threads.c:707
#6  0x08285e75 in inner_start_thread (arg=0xb46ef14c)
    at mono-threads-posix.c:94
#7  0xb7732d4c in start_thread (arg=0xb4067b40) at pthread_create.c:308
#8  0xb7671bae in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:130

Thread 1 (Thread 0xb7580700 (LWP 736)):
#0  0xb77a3424 in __kernel_vsyscall ()
#1  0xb77399db in read () at ../sysdeps/unix/syscall-template.S:82
#2  0x0825f228 in read (__nbytes=1024, __buf=0xb5c92aa0, __fd=0)
    at /usr/include/i386-linux-gnu/bits/unistd.h:45
#3  console_read (handle=0x0, buffer=0xb5c92aa0, numbytes=1024, bytesread=
    0xbfc80d8c, overlapped=0x0) at io.c:1079
#4  0x082612eb in ReadFile (handle=0x0, buffer=0xb5c92aa0, numbytes=1024, 
    bytesread=0xbfc80d8c, overlapped=0x0) at io.c:2246
#5  0x08256f78 in ves_icall_System_IO_MonoIO_Read (handle=0x0, dest=
    0xb5c92a90, dest_offset=0, count=1024, error=0xbfc80e2c) at file-io.c:833
#6  0xb5b38c10 in ?? ()
#7  0xb5e66b23 in System.IO.FileStream:ReadData (this=..., handle=0, buf=
    %s [%d], offset=0, count=1024)
---Type <return> to continue, or q <return> to quit---
    at /home/sergey/Projects/mono/mono/mcs/class/corlib/System.IO/FileStream.cs:2149
#8  0xb5e649d2 in System.IO.FileStream:ReadInternal (this=..., dest=%s [%d], 
    offset=0, count=1024)
    at /home/sergey/Projects/mono/mono/mcs/class/corlib/System.IO/FileStream.cs:1061
#9  0xb5e647ec in System.IO.FileStream:Read (this=..., array=%s [%d], offset=
    0, count=1024)
    at /home/sergey/Projects/mono/mono/mcs/class/corlib/System.IO/FileStream.cs:1017
#10 0xb5e6fe2b in System.IO.StreamReader:ReadBuffer (this=...)
    at /home/sergey/Projects/mono/mono/mcs/class/corlib/System.IO/StreamReader.cs:784
#11 0xb5e70057 in System.IO.StreamReader:Read (this=...)
    at /home/sergey/Projects/mono/mono/mcs/class/corlib/System.IO/StreamReader.cs:909
#12 0xb5def278 in System.TermInfoDriver:ReadKeyInternal (this=..., fresh=
    -1077407789)
    at /home/sergey/Projects/mono/mono/mcs/class/corlib/System/TermInfoDriver.cs:1956
#13 0xb5def969 in System.TermInfoDriver:ReadLine (this=...)
    at /home/sergey/Projects/mono/mono/mcs/class/corlib/System/TermInfoDriver.cs:2311
---Type <return> to continue, or q <return> to quit---
#14 0xb5d9985f in System.ConsoleDriver:ReadLine ()
    at /home/sergey/Projects/mono/mono/mcs/class/corlib/System/ConsoleDriver.cs:469
#15 0xb5d97b01 in System.Console:ReadLine ()
    at /home/sergey/Projects/mono/mono/mcs/class/corlib/System/Console.cs:1052
#16 0xb51abce8 in ?? ()
#17 0xb51aba14 in ?? ()
#18 0x0806ab5d in mono_jit_runtime_invoke (method="%s:%s ()", obj=0xb6e9f1c0, 
    params=0xbfc81160, exc=0x0) at mini.c:6723
#19 0x081fa39f in mono_runtime_invoke (method="%s:%s ()", obj=0xb6e9f1c0, 
    params=0xbfc81160, exc=0x0) at object.c:2828
#20 0x081fdceb in mono_runtime_invoke_array (method="%s:%s ()", obj=
    0xb6e9f1c0, params=0xb6e9f240, exc=0x0) at object.c:4297
#21 0x08178658 in ves_icall_InternalInvoke (method=0xb6e9efb8, this=
    0xb6e9f1c0, params=0xb6e9f240, exc=0xbfc812ac) at icall.c:2845
#22 0xb5d18fb8 in ?? ()
#23 0xb5e959ef in System.Reflection.MonoMethod:Invoke (this=..., obj=%s.%s, 
    invokeAttr=Default, binder=..., parameters=%s [%d], culture=...)
    at /home/sergey/Projects/mono/mono/mcs/class/corlib/System.Reflection/MonoMethod.cs:433
#24 0xb5e90550 in System.Reflection.MethodBase:Invoke (this=..., obj=%s.%s, 
    parameters=%s [%d])
    at /home/sergey/Projects/mono/mono/mcs/class/corlib/System.Reflection/Method---Type <return> to continue, or q <return> to quit---
Base.cs:227
#25 0xb51ab1e4 in ?? ()
#26 0xb51eb0c8 in ?? ()
#27 0xb5b35ac8 in ?? ()
#28 0xb5b35cd7 in ?? ()
#29 0x0806ab5d in mono_jit_runtime_invoke (method="%s:%s ()", obj=0xb6c148c8, 
    params=0xbfc81550, exc=0x0) at mini.c:6723
#30 0x081fa39f in mono_runtime_invoke (method="%s:%s ()", obj=0xb6c148c8, 
    params=0xbfc81550, exc=0x0) at object.c:2828
#31 0x081fdceb in mono_runtime_invoke_array (method="%s:%s ()", obj=
    0xb6c148c8, params=0xb6c14b08, exc=0x0) at object.c:4297
#32 0x08178658 in ves_icall_InternalInvoke (method=0xb6c14570, this=
    0xb6c148c8, params=0xb6c14b08, exc=0xbfc8169c) at icall.c:2845
#33 0xb5d18fb8 in ?? ()
#34 0xb5e959ef in System.Reflection.MonoMethod:Invoke (this=..., obj=%s.%s, 
    invokeAttr=Default, binder=..., parameters=%s [%d], culture=...)
    at /home/sergey/Projects/mono/mono/mcs/class/corlib/System.Reflection/MonoMethod.cs:433
#35 0xb5e90550 in System.Reflection.MethodBase:Invoke (this=..., obj=%s.%s, 
    parameters=%s [%d])
    at /home/sergey/Projects/mono/mono/mcs/class/corlib/System.Reflection/MethodBase.cs:227
#36 0xb5b33da4 in ?? ()
---Type <return> to continue, or q <return> to quit---
#37 0xb5d19a20 in ?? ()
#38 0xb5d19237 in ?? ()
#39 0x0806ab5d in mono_jit_runtime_invoke (method="%s:%s ()", obj=0xb6c11468, 
    params=0xbfc81870, exc=0x0) at mini.c:6723
#40 0x081fa39f in mono_runtime_invoke (method="%s:%s ()", obj=0xb6c11468, 
    params=0xbfc81870, exc=0x0) at object.c:2828
#41 0x081fdceb in mono_runtime_invoke_array (method="%s:%s ()", obj=
    0xb6c11468, params=0xb6c11478, exc=0x0) at object.c:4297
#42 0x08178658 in ves_icall_InternalInvoke (method=0xb6c11340, this=
    0xb6c11468, params=0xb6c11478, exc=0xbfc819bc) at icall.c:2845
#43 0xb5d18fb8 in ?? ()
#44 0xb5e959ef in System.Reflection.MonoMethod:Invoke (this=..., obj=%s.%s, 
    invokeAttr=Default, binder=..., parameters=%s [%d], culture=...)
    at /home/sergey/Projects/mono/mono/mcs/class/corlib/System.Reflection/MonoMethod.cs:433
#45 0xb5e90550 in System.Reflection.MethodBase:Invoke (this=..., obj=%s.%s, 
    parameters=%s [%d])
    at /home/sergey/Projects/mono/mono/mcs/class/corlib/System.Reflection/MethodBase.cs:227
#46 0xb5d13e68 in ?? ()
#47 0xb5d128dc in ?? ()
#48 0xb5d11e54 in ?? ()
#49 0xb5d11f35 in ?? ()
---Type <return> to continue, or q <return> to quit---
#50 0x0806ab5d in mono_jit_runtime_invoke (method="%s:%s ()", obj=0x0, params=
    0xbfc81c8c, exc=0x0) at mini.c:6723
#51 0x081fa39f in mono_runtime_invoke (method="%s:%s ()", obj=0x0, params=
    0xbfc81c8c, exc=0x0) at object.c:2828
#52 0x081fc545 in mono_runtime_exec_main (method="%s:%s ()", args=0xb6c007e8, 
    exc=0x0) at object.c:4085
#53 0x080d14c3 in main_thread_handler (user_data=<synthetic pointer>)
    at driver.c:1065
#54 mono_main (argc=4, argv=0xbfc81e54) at driver.c:2024
#55 0x0805db6c in mono_main_with_options (argv=0xbfc81e54, argc=4) at main.c:91
#56 main (argc=4, argv=0xbfc81e54) at main.c:122
(gdb) t 5
[Switching to thread 5 (Thread 0xb3affb40 (LWP 762))]
#0  0xb77a3424 in __kernel_vsyscall ()
(gdb) up 9
#9  0xb5ff8dbc in System.Threading.Timer/Scheduler:SchedulerThread (this=...)
    at /home/sergey/Projects/mono/mono/mcs/class/corlib/System.Threading/Timer.cs:706
Comment 1 Zoltan Varga 2014-05-29 08:56:48 UTC
There is no deadlock there, both threads are just waiting.
Comment 2 Sergey Zhukov 2014-05-30 02:59:11 UTC
Additional info: it's not GC issue, it's related to the sockets.

The application `k web` does not close sockets properly, and when all file descriptors run out it hangs. What is strange that I don't see the exception from mono about 'could not open file descriptor`. Will try to create simple app and see does mono throw an exception or not.
Comment 3 shiggs 2014-05-30 08:57:45 UTC
Just fyi, 

You can see exactly the same behaviour when running an app self hosted on nowin under mono on osx and linux. Mono on windows did not appear to show the issue.
Comment 4 Boris Letocha 2014-05-30 16:00:17 UTC
Hi, author of Nowin here.
I properly Disconnect socket, but I set http://iosapi.xamarin.com/index.aspx?link=P%3ASystem.Net.Sockets.SocketAsyncEventArgs.DisconnectReuseSocket to true, so  .Net FW could reuse Socket. And next Accept could return me same one.
If this is not properly implemented I expect it could have such behavior of leaking of sockets.
Comment 5 Boris Letocha 2014-05-30 16:15:32 UTC
To add more details, you can see whole critical code here:
https://github.com/Bobris/Nowin/blob/master/Nowin/SaeaLayerCallback.cs#L42

Also you can see I never null http://iosapi.xamarin.com/?link=P%3aSystem.Net.Sockets.SocketAsyncEventArgs.AcceptSocket and reusing whole SocketAsyncEventArgs for next AcceptAsync.
Comment 6 Sergey Zhukov 2014-05-30 22:34:28 UTC
As far as I know Sockets in mono always set REUSE_SOCKET on disconnect, no matter reuseSocket parameter was set or not. 

https://github.com/mono/mono/blob/master/mono/metadata/socket-io.c#L1386

Note You need to log in before you can comment on or make changes to this bug.