Phalanger/Mono hangs

[kripper]

By repeating a request/post sequence about 8 times, mono server randomly hangs.
The browser seems to be loading and there is no error message in the logs nor a crash or reloading of the mono-server.

Attaching the process gdb I see these threads:

Code: Select all

#0  0x007b0402 in __kernel_vsyscall ()
#1  0x00beabc5 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/libpthread.so.0
#2  0x081f306d in _wapi_handle_timedwait_signal_handle (handle=0x400, timeout=
    0x0, alertable=1, poll=0) at handles.c:1655
#3  0x081f3177 in _wapi_handle_wait_signal (poll=0) at handles.c:1584
#4  0x08205164 in WaitForMultipleObjectsEx (numobjects=2, handles=0xbfcfe0b4,
    waitall=0, timeout=4294967295, alertable=1) at wait.c:722
#5  0x081daccf in wait_for_tids_or_state_change () at threads.c:2802
#6  mono_thread_manage () at threads.c:3017
#7  0x080baa1c in mono_main (argc=9, argv=0xbfcfe4f4) at driver.c:1856
#8  0x0805732a in mono_main_with_options (argc=-1076894436, argv=0xa50ca0)
    at main.c:66
#9  main (argc=-1076894436, argv=0xa50ca0) at main.c:97

---

[Switching to thread 2 (Thread 0xb6dc0b90 (LWP 26613))]#0  0x007b0402 in __kernel_vsyscall ()
(gdb) bt
#0  0x007b0402 in __kernel_vsyscall ()
#1  0x00becff8 in sem_timedwait () from /lib/libpthread.so.0
#2  0x0820cda2 in mono_sem_timedwait (sem=0x82f6174, timeout_ms=2000,
    alertable=1) at mono-semaphore.c:76
#3  0x081d3725 in async_invoke_thread (data=0x0) at threadpool.c:1485
#4  0x081d90bb in start_wrapper_internal (data=0xb3a00488) at threads.c:784
#5  start_wrapper (data=0xb3a00488) at threads.c:832
#6  0x08207465 in thread_start_routine (args=0x96e9f1c) at wthreads.c:287
#7  0x0822c199 in GC_start_routine (arg=0xb6b35c80) at pthread_support.c:1468
#8  0x00be6832 in start_thread () from /lib/libpthread.so.0
#9  0x00b264de in clone () from /lib/libc.so.6

---

[Switching to thread 3 (Thread 0xb40a8b90 (LWP 26602))]#0  0x007b0402 in __kernel_vsyscall ()
(gdb) bt
#0  0x007b0402 in __kernel_vsyscall ()
#1  0x00beaef2 in pthread_cond_timedwait@@GLIBC_2.3.2 ()
   from /lib/libpthread.so.0
#2  0x081f2eb9 in _wapi_handle_timedwait_signal_handle (handle=0x475, timeout=
    0xb40a7608, alertable=1, poll=0) at handles.c:1653
#3  0x082049be in WaitForSingleObjectEx (handle=0x475, timeout=259200000,
    alertable=1) at wait.c:205
#4  0x081d5c1e in ves_icall_System_Threading_WaitHandle_WaitOne_internal (this=
    0xb6b71e40, handle=0x475, ms=259200000, exitContext=0) at threads.c:1665
#5  0x003452dc in ?? ()
#6  0xb6b71e40 in ?? ()
#7  0x00000475 in ?? ()
#8  0x0f731400 in ?? ()
#9  0x00000000 in ?? ()

---

(gdb) thread 4
[Switching to thread 4 (Thread 0xb3fa3b90 (LWP 26583))]#0  0x007b0402 in __kernel_vsyscall ()
(gdb) bt
#0  0x007b0402 in __kernel_vsyscall ()
#1  0x00beaef2 in pthread_cond_timedwait@@GLIBC_2.3.2 ()
   from /lib/libpthread.so.0
#2  0x081f2eb9 in _wapi_handle_timedwait_signal_handle (handle=0x46b, timeout=
    0xb3fa2608, alertable=1, poll=0) at handles.c:1653
#3  0x082049be in WaitForSingleObjectEx (handle=0x46b, timeout=259200000,
    alertable=1) at wait.c:205
#4  0x081d5c1e in ves_icall_System_Threading_WaitHandle_WaitOne_internal (this=
    0xb4851420, handle=0x46b, ms=259200000, exitContext=0) at threads.c:1665
#5  0x003452dc in ?? ()
#6  0xb4851420 in ?? ()
#7  0x0000046b in ?? ()
#8  0x0f731400 in ?? ()
#9  0x00000000 in ?? ()

---

(gdb) thread 5
[Switching to thread 5 (Thread 0xb5a7fb90 (LWP 26574))]#0  0x007b0402 in __kernel_vsyscall ()
(gdb) bt
#0  0x007b0402 in __kernel_vsyscall ()
#1  0x00beaef2 in pthread_cond_timedwait@@GLIBC_2.3.2 ()
   from /lib/libpthread.so.0
#2  0x081f2eb9 in _wapi_handle_timedwait_signal_handle (handle=0x462, timeout=
    0xb5a7e608, alertable=1, poll=0) at handles.c:1653
#3  0x082049be in WaitForSingleObjectEx (handle=0x462, timeout=259200000,
    alertable=1) at wait.c:205
#4  0x081d5c1e in ves_icall_System_Threading_WaitHandle_WaitOne_internal (this=
    0xb520f6f0, handle=0x462, ms=259200000, exitContext=0) at threads.c:1665
#5  0x003452dc in ?? ()
#6  0xb520f6f0 in ?? ()
#7  0x00000462 in ?? ()
#8  0x0f731400 in ?? ()
#9  0x00000000 in ?? ()

---

(gdb) thread 6
[Switching to thread 6 (Thread 0xb3e9eb90 (LWP 26572))]#0  0x007b0402 in __kernel_vsyscall ()
(gdb) bt
#0  0x007b0402 in __kernel_vsyscall ()
#1  0x00beaef2 in pthread_cond_timedwait@@GLIBC_2.3.2 ()
   from /lib/libpthread.so.0
#2  0x081f2eb9 in _wapi_handle_timedwait_signal_handle (handle=0x45f, timeout=
    0xb3e9d608, alertable=1, poll=0) at handles.c:1653
#3  0x082049be in WaitForSingleObjectEx (handle=0x45f, timeout=259200000,
    alertable=1) at wait.c:205
#4  0x081d5c1e in ves_icall_System_Threading_WaitHandle_WaitOne_internal (this=
    0xb51b0828, handle=0x45f, ms=259200000, exitContext=0) at threads.c:1665
#5  0x003452dc in ?? ()
#6  0xb51b0828 in ?? ()
#7  0x0000045f in ?? ()
#8  0x0f731400 in ?? ()
#9  0x00000000 in ?? ()

---

(gdb) thread 7
[Switching to thread 7 (Thread 0xb3d85b90 (LWP 26551))]#0  0x007b0402 in __kernel_vsyscall ()
(gdb) bt
#0  0x007b0402 in __kernel_vsyscall ()
#1  0x00beaef2 in pthread_cond_timedwait@@GLIBC_2.3.2 ()
   from /lib/libpthread.so.0
#2  0x081f2eb9 in _wapi_handle_timedwait_signal_handle (handle=0x464, timeout=
    0xb3d84608, alertable=1, poll=0) at handles.c:1653
#3  0x082049be in WaitForSingleObjectEx (handle=0x464, timeout=259200000,
    alertable=1) at wait.c:205
#4  0x081d5c1e in ves_icall_System_Threading_WaitHandle_WaitOne_internal (this=
    0xb4eb15e8, handle=0x464, ms=259200000, exitContext=0) at threads.c:1665
#5  0x003452dc in ?? ()
#6  0xb4eb15e8 in ?? ()
#7  0x00000464 in ?? ()
#8  0x0f731400 in ?? ()
#9  0x00000000 in ?? ()

---

(gdb) thread 8
[Switching to thread 8 (Thread 0xb5b84b90 (LWP 26418))]#0  0x007b0402 in __kernel_vsyscall ()
(gdb) bt
#0  0x007b0402 in __kernel_vsyscall ()
#1  0x00beaef2 in pthread_cond_timedwait@@GLIBC_2.3.2 ()
   from /lib/libpthread.so.0
#2  0x081f2eb9 in _wapi_handle_timedwait_signal_handle (handle=0x427, timeout=
    0xb5b83fe8, alertable=1, poll=0) at handles.c:1653
#3  0x082049be in WaitForSingleObjectEx (handle=0x427, timeout=489, alertable=
    1) at wait.c:205
#4  0x081d5c1e in ves_icall_System_Threading_WaitHandle_WaitOne_internal (this=
    0xb6fd5828, handle=0x427, ms=489, exitContext=0) at threads.c:1665
#5  0x003452dc in ?? ()
#6  0xb6fd5828 in ?? ()
#7  0x00000427 in ?? ()
#8  0x000001e9 in ?? ()
#9  0x00000000 in ?? ()

---

(gdb) thread 9
[Switching to thread 9 (Thread 0xb6cb7b90 (LWP 26415))]#0  0x007b0402 in __kernel_vsyscall ()
(gdb) bt
#0  0x007b0402 in __kernel_vsyscall ()
#1  0x00b1707b in read () from /lib/libc.so.6
#2  0x002a03c8 in ?? ()
#3  0x00000008 in ?? ()
#4  0xb6fa2010 in ?? ()
#5  0x00001000 in ?? ()
#6  0xb6cb71d8 in ?? ()
#7  0x002a02d8 in ?? ()
#8  0x09b469f8 in ?? ()
#9  0x00000000 in ?? ()

---

(gdb) thread 10
[Switching to thread 10 (Thread 0xb6de1b90 (LWP 26413))]#0  0x007b0402 in __kernel_vsyscall ()
(gdb) bt
#0  0x007b0402 in __kernel_vsyscall ()
#1  0x00bee346 in nanosleep () from /lib/libpthread.so.0
#2  0x08205c78 in SleepEx (ms=500, alertable=1) at wthreads.c:1027
#3  0x081d107d in monitor_thread (unused=0x0) at threadpool.c:777
#4  0x081d90bb in start_wrapper_internal (data=0x9b08de0) at threads.c:784
#5  start_wrapper (data=0x9b08de0) at threads.c:832
#6  0x08207465 in thread_start_routine (args=0x96e66cc) at wthreads.c:287
#7  0x0822c199 in GC_start_routine (arg=0xb6fb6f60) at pthread_support.c:1468
#8  0x00be6832 in start_thread () from /lib/libpthread.so.0
#9  0x00b264de in clone () from /lib/libc.so.6

---

(gdb) thread 11
[Switching to thread 11 (Thread 0xb6e0ab90 (LWP 26412))]#0  0x007b0402 in __kernel_vsyscall ()
(gdb) bt
#0  0x007b0402 in __kernel_vsyscall ()
#1  0x00becff8 in sem_timedwait () from /lib/libpthread.so.0
#2  0x0820cda2 in mono_sem_timedwait (sem=0x82f61f4, timeout_ms=2000,
    alertable=1) at mono-semaphore.c:76
#3  0x081d3725 in async_invoke_thread (data=0x0) at threadpool.c:1485
#4  0x081d90bb in start_wrapper_internal (data=0x9b6faf0) at threads.c:784
#5  start_wrapper (data=0x9b6faf0) at threads.c:832
#6  0x08207465 in thread_start_routine (args=0x96e6644) at wthreads.c:287
#7  0x0822c199 in GC_start_routine (arg=0xb6fb6fe0) at pthread_support.c:1468
#8  0x00be6832 in start_thread () from /lib/libpthread.so.0
#9  0x00b264de in clone () from /lib/libc.so.6

---

(gdb) thread 12
[Switching to thread 12 (Thread 0xb6e2bb90 (LWP 26411))]#0  0x007b0402 in __kernel_vsyscall ()
(gdb) bt
#0  0x007b0402 in __kernel_vsyscall ()
#1  0x00b26b56 in epoll_wait () from /lib/libc.so.6
#2  0x081d1b08 in tp_epoll_wait (p=0x82f6120)
    at ../../mono/metadata/tpool-epoll.c:101
#3  0x081d90bb in start_wrapper_internal (data=0x9b0b0d0) at threads.c:784
#4  start_wrapper (data=0x9b0b0d0) at threads.c:832
#5  0x08207465 in thread_start_routine (args=0x96e65bc) at wthreads.c:287
#6  0x0822c199 in GC_start_routine (arg=0xb6fb6fe0) at pthread_support.c:1468
#7  0x00be6832 in start_thread () from /lib/libpthread.so.0
#8  0x00b264de in clone () from /lib/libc.so.6

---

(gdb) thread 13
[Switching to thread 13 (Thread 0xb6f30b90 (LWP 26410))]#0  0x007b0402 in __kernel_vsyscall ()
(gdb) bt
#0  0x007b0402 in __kernel_vsyscall ()
#1  0x00bee346 in nanosleep () from /lib/libpthread.so.0
#2  0x08205c78 in SleepEx (ms=1000000, alertable=1) at wthreads.c:1027
#3  0x081db188 in ves_icall_System_Threading_Thread_Sleep_internal (ms=1000000)
    at threads.c:1320
#4  0x00c4108c in ?? ()
#5  0x000f4240 in ?? ()
#6  0xb6fcc930 in ?? ()
#7  0xb70069d8 in ?? ()
#8  0xb6f301a8 in ?? ()
#9  0x00c41008 in ?? ()
#10 0x09a85598 in ?? ()
#11 0x00c40ff0 in ?? ()
#12 0x09a85598 in ?? ()
#13 0x00000000 in ?? ()

---

(gdb) thread 14
[Switching to thread 14 (Thread 0xb7b0eb90 (LWP 26409))]#0  0x007b0402 in __kernel_vsyscall ()
(gdb) bt
#0  0x007b0402 in __kernel_vsyscall ()
#1  0x00bece55 in sem_wait@@GLIBC_2.1 () from /lib/libpthread.so.0
#2  0x0820ccb2 in mono_sem_wait (sem=0x82f5bb4, alertable=1)
    at mono-semaphore.c:113
#3  0x0815530e in finalizer_thread (unused=0x0) at gc.c:1066
#4  0x081d90bb in start_wrapper_internal (data=0x96f72c0) at threads.c:784
#5  start_wrapper (data=0x96f72c0) at threads.c:832
#6  0x08207465 in thread_start_routine (args=0x96e5f5c) at wthreads.c:287
#7  0x0822c199 in GC_start_routine (arg=0x52fe0) at pthread_support.c:1468
#8  0x00be6832 in start_thread () from /lib/libpthread.so.0
#9  0x00b264de in clone () from /lib/libc.so.6


I tried to use pdm2mdb to export the webpages.pdb file to a .mdb symbols file, but it seems like the VS2010 PDB format is not supported by pdm2mdb.

Any hint for debugging this problem?

The problem is present in Phalanger 2.1 and Phalanger 3, with mono versions 2.10.2 (?), 2.10.8 and 2.10.9.

I will try to isolate the problem and create a simple test case.

[Jakub Misek]

This does not happen on IIS/ASP.NET, and Mono uses the same RequestHandler as it is configured on ASP.NET. So it seems as a bug in Mono? Maybe some misbehaviour.

Attaching to the process may cause requests to be processes sequentially, so it makes debugging behave differently.

I would let it hang, and attach to the processes, pause, and look at Processes which are waiting (are in sleep state), and look at their call stack, where it sleeps. I have no idea how to achieve this on Linux. When you compile Phalanger in MonoDevelop, there must some proper linuxish debug symbols; and Monodevelop should be able to attach to process, right? (guessing)