[Mono-bugs] [Bug 81888][Wis] New - tests/delegate3 sometimes hangs

bugzilla-daemon at bugzilla.ximian.com bugzilla-daemon at bugzilla.ximian.com
Sat Jun 16 04:40:56 EDT 2007


Please do not reply to this email- if you want to comment on the bug, go to the
URL shown below and enter your comments there.

Changed by mark.probst at gmail.com.

http://bugzilla.ximian.com/show_bug.cgi?id=81888

--- shadow/81888	2007-06-16 04:40:56.000000000 -0400
+++ shadow/81888.tmp.1465	2007-06-16 04:40:56.000000000 -0400
@@ -0,0 +1,326 @@
+Bug#: 81888
+Product: Mono: Runtime
+Version: 1.2
+OS: 
+OS Details: Fedora Core 6
+Status: NEW   
+Resolution: 
+Severity: 
+Priority: Wishlist
+Component: misc
+AssignedTo: mono-bugs at ximian.com                            
+ReportedBy: mark.probst at gmail.com               
+QAContact: mono-bugs at ximian.com
+TargetMilestone: ---
+URL: 
+Cc: 
+Summary: tests/delegate3 sometimes hangs
+
+Please fill in this template when reporting a bug, unless you know what you
+are doing.
+Description of Problem:
+
+On my system (Core 2 Duo with 64 bit Linux) the current SVN Mono sometimes
+hangs on the delegate3 test.  As far as I can tell that happens much more
+often (maybe only) if the system is unloaded, in which case it happens on
+every 10th run or so.  I haven't been able to reproduce the bug when the
+system was only a little bit busy.
+
+What happens is that the program produces the expected output but then
+doesn't exit.  
+
+Steps to reproduce the problem:
+1. Make sure your system's CPU is not busy.
+2. Run the delegate3 test a number of times, perhaps like this:
+
+  while true ; do echo again! ; ~/Work/novell/trunk/monosvn/mono/mini/mono
+delegate3.exe ; done
+
+Actual Results:
+
+Sometimes the program hangs after producing the expected output.
+
+Expected Results:
+
+The program should always exit.
+
+How often does this happen? 
+
+Once every 10 runs or so on an unloaded system.
+
+Additional Information:
+
+GDB backtraces of all the threads of the program in hung-up state:
+
+Starting program: /home/schani/Work/novell/trunk/monosvn/mono/mini/mono
+delegate3.exe
+[Thread debugging using libthread_db enabled]
+[New Thread 46912496293424 (LWP 25234)]
+[New Thread 1073822016 (LWP 25235)]
+[New Thread 1075988800 (LWP 25236)]
+[New Thread 1078090048 (LWP 25237)]
+Test.F from delegate: 0
+Async Callback 0
+[New Thread 1080256832 (LWP 25238)]
+Test.F from delegate: 1
+Async Callback 1
+[New Thread 1082358080 (LWP 25239)]
+Test.F from delegate: 2
+Async Callback 2
+Test.F from delegate: 3
+Async Callback 3
+[New Thread 1084459328 (LWP 25240)]
+Test.F from delegate: 4
+Async Callback 4
+[Thread 1078090048 (LWP 25237) exited]
+
+Program received signal SIGINT, Interrupt.
+[Switching to Thread 46912496293424 (LWP 25234)]
+0x0000003e4460d4a1 in nanosleep () from /lib64/libpthread.so.0
+(gdb) info threads
+  7 Thread 1084459328 (LWP 25240)  0x0000003e4460c7f8 in
+__lll_mutex_lock_wait () from /lib64/libpthread.so.0
+  6 Thread 1082358080 (LWP 25239)  0x0000003e4460c7f8 in
+__lll_mutex_lock_wait () from /lib64/libpthread.so.0
+  5 Thread 1080256832 (LWP 25238)  0x0000003e4460c7f8 in
+__lll_mutex_lock_wait () from /lib64/libpthread.so.0
+  3 Thread 1075988800 (LWP 25236)  0x0000003e4460a416 in
+pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
+  2 Thread 1073822016 (LWP 25235)  0x0000003e4460d4a1 in nanosleep () from
+/lib64/libpthread.so.0
+* 1 Thread 46912496293424 (LWP 25234)  0x0000003e4460d4a1 in nanosleep ()
+from /lib64/libpthread.so.0
+(gdb) backtrace 
+#0  0x0000003e4460d4a1 in nanosleep () from /lib64/libpthread.so.0
+#1  0x000000000053214a in _wapi_handle_spin (ms=100) at
+../../mono/io-layer/handles-private.h:407
+#2  0x00000000005324f4 in timedwait_signal_poll (handle=0xffffffffffffffff,
+timeout=0x0) at handles.c:1458
+#3  0x0000000000532522 in _wapi_handle_wait_signal (shared=1) at handles.c:1465
+#4  0x000000000052c64d in WaitForMultipleObjectsEx (numobjects=4,
+handles=0x8efa00, waitall=1, timeout=4294967295, alertable=0)
+    at wait.c:679
+#5  0x00000000004b07d5 in wait_for_tids (wait=0x8efa00, timeout=4294967295)
+at threads.c:1972
+#6  0x00000000004b0e6e in mono_thread_manage () at threads.c:2185
+#7  0x00000000004160df in mono_main (argc=2, argv=0x7fff2f889de8) at
+driver.c:1020
+#8  0x00000000004134f3 in main (argc=2, argv=0x7fff2f889de8) at main.c:6
+(gdb) thread 2
+[Switching to thread 2 (Thread 1073822016 (LWP 25235))]#0 
+0x0000003e4460d4a1 in nanosleep () from /lib64/libpthread.so.0
+(gdb) backtrace 
+#0  0x0000003e4460d4a1 in nanosleep () from /lib64/libpthread.so.0
+#1  0x000000000052f27e in collection_thread (unused=0x0) at collection.c:34
+#2  0x0000003e44606305 in start_thread () from /lib64/libpthread.so.0
+#3  0x0000003e42acd50d in clone () from /lib64/libc.so.6
+#4  0x0000000000000000 in ?? ()
+(gdb) thread 3
+[Switching to thread 3 (Thread 1075988800 (LWP 25236))]#0 
+0x0000003e4460a416 in pthread_cond_wait@@GLIBC_2.3.2 ()
+   from /lib64/libpthread.so.0
+(gdb) backtrace 
+#0  0x0000003e4460a416 in pthread_cond_wait@@GLIBC_2.3.2 () from
+/lib64/libpthread.so.0
+#1  0x0000000000532247 in timedwait_signal_wait_cond (cond=0x2aaaae436268,
+mutex=0x2aaaae436240, timeout=0x0, alertable=0, 
+    waiting_on=0x404) at handles.c:1424
+#2  0x0000000000532731 in _wapi_handle_timedwait_signal_handle
+(handle=0x404, timeout=0x0, alertable=0) at handles.c:1504
+#3  0x00000000005325c8 in _wapi_handle_wait_signal_handle (handle=0x404,
+alertable=0) at handles.c:1486
+#4  0x000000000052b9f4 in WaitForSingleObjectEx (handle=0x404,
+timeout=4294967295, alertable=0) at wait.c:200
+#5  0x00000000004fc321 in finalizer_thread (unused=0x0) at gc.c:835
+#6  0x00000000004ae1b1 in start_wrapper (data=0x8abb30) at threads.c:319
+#7  0x0000000000527cd2 in thread_start_routine (args=0x2aaaae4ab6b8) at
+threads.c:253
+#8  0x0000000000543822 in GC_start_routine (arg=<value optimized out>) at
+pthread_support.c:1362
+#9  0x0000003e44606305 in start_thread () from /lib64/libpthread.so.0
+#10 0x0000003e42acd50d in clone () from /lib64/libc.so.6
+#11 0x0000000000000000 in ?? ()
+(gdb) thread 5
+[Switching to thread 5 (Thread 1080256832 (LWP 25238))]#0 
+0x0000003e4460c7f8 in __lll_mutex_lock_wait () from /lib64/libpthread.so.0
+(gdb) backtrace 
+#0  0x0000003e4460c7f8 in __lll_mutex_lock_wait () from /lib64/libpthread.so.0
+#1  0x0000003e44608864 in _L_mutex_lock_107 () from /lib64/libpthread.so.0
+#2  0x0000003e44608303 in pthread_mutex_lock () from /lib64/libpthread.so.0
+#3  0x0000000000528ee8 in _wapi_handle_trip_signal (handle=0x400) at
+../../mono/io-layer/handles-private.h:254
+#4  0x0000000000528c18 in _wapi_thread_queue_apc (thread=0x2aaaae4ab948,
+apc_callback=0x4b21aa <dummy_apc>, param=0x0)
+    at threads.c:1073
+#5  0x0000000000529267 in QueueUserAPC (apc_callback=0x4b21aa <dummy_apc>,
+handle=0x40b, param=0x0) at threads.c:1166
+#6  0x00000000004b24c5 in mono_thread_request_interruption
+(running_managed=0) at threads.c:2881
+#7  0x0000000000578632 in sigusr1_signal_handler (_dummy=35,
+info=0x40635a70, context=0x40635940) at mini.c:11235
+#8  <signal handler called>
+#9  0x0000003e4460a607 in pthread_cond_timedwait@@GLIBC_2.3.2 () from
+/lib64/libpthread.so.0
+#10 0x0000000000532235 in timedwait_signal_wait_cond (cond=0x2aaaae436048,
+mutex=0x2aaaae436020, timeout=0x40635f10, alertable=1, 
+    waiting_on=0x400) at handles.c:1422
+#11 0x0000000000532731 in _wapi_handle_timedwait_signal_handle
+(handle=0x400, timeout=0x40635f10, alertable=1) at handles.c:1504
+#12 0x000000000052ba0f in WaitForSingleObjectEx (handle=0x400,
+timeout=10000, alertable=1) at wait.c:202
+#13 0x000000000050f507 in async_invoke_thread (data=0x0) at threadpool.c:1228
+#14 0x00000000004ae1b1 in start_wrapper (data=0x8af910) at threads.c:319
+#15 0x0000000000527cd2 in thread_start_routine (args=0x2aaaae4ab948) at
+threads.c:253
+#16 0x0000000000543822 in GC_start_routine (arg=<value optimized out>) at
+pthread_support.c:1362
+#17 0x0000003e44606305 in start_thread () from /lib64/libpthread.so.0
+#18 0x0000003e42acd50d in clone () from /lib64/libc.so.6
+#19 0x0000000000000000 in ?? ()
+(gdb) thread 6
+[Switching to thread 6 (Thread 1082358080 (LWP 25239))]#0 
+0x0000003e4460c7f8 in __lll_mutex_lock_wait () from /lib64/libpthread.so.0
+(gdb) backtrace 
+#0  0x0000003e4460c7f8 in __lll_mutex_lock_wait () from /lib64/libpthread.so.0
+#1  0x0000003e44608864 in _L_mutex_lock_107 () from /lib64/libpthread.so.0
+#2  0x0000003e44608303 in pthread_mutex_lock () from /lib64/libpthread.so.0
+#3  0x0000000000528bcb in _wapi_thread_queue_apc (thread=0x2aaaae4aba90,
+apc_callback=0x4b21aa <dummy_apc>, param=0x0)
+    at threads.c:1065
+#4  0x0000000000529267 in QueueUserAPC (apc_callback=0x4b21aa <dummy_apc>,
+handle=0x40c, param=0x0) at threads.c:1166
+#5  0x00000000004b24c5 in mono_thread_request_interruption
+(running_managed=0) at threads.c:2881
+#6  0x0000000000578632 in sigusr1_signal_handler (_dummy=35,
+info=0x40836a70, context=0x40836940) at mini.c:11235
+#7  <signal handler called>
+#8  0x0000003e4460a607 in pthread_cond_timedwait@@GLIBC_2.3.2 () from
+/lib64/libpthread.so.0
+#9  0x0000000000532235 in timedwait_signal_wait_cond (cond=0x2aaaae436048,
+mutex=0x2aaaae436020, timeout=0x40836f10, alertable=1, 
+    waiting_on=0x400) at handles.c:1422
+#10 0x0000000000532731 in _wapi_handle_timedwait_signal_handle
+(handle=0x400, timeout=0x40836f10, alertable=1) at handles.c:1504
+#11 0x000000000052ba0f in WaitForSingleObjectEx (handle=0x400,
+timeout=10000, alertable=1) at wait.c:202
+#12 0x000000000050f507 in async_invoke_thread (data=0x0) at threadpool.c:1228
+#13 0x00000000004ae1b1 in start_wrapper (data=0x2aaab0000900) at threads.c:319
+#14 0x0000000000527cd2 in thread_start_routine (args=0x2aaaae4aba90) at
+threads.c:253
+#15 0x0000000000543822 in GC_start_routine (arg=<value optimized out>) at
+pthread_support.c:1362
+#16 0x0000003e44606305 in start_thread () from /lib64/libpthread.so.0
+#17 0x0000003e42acd50d in clone () from /lib64/libc.so.6
+#18 0x0000000000000000 in ?? ()
+(gdb) thread 7
+[Switching to thread 7 (Thread 1084459328 (LWP 25240))]#0 
+0x0000003e4460c7f8 in __lll_mutex_lock_wait () from /lib64/libpthread.so.0
+(gdb) backtrace 
+#0  0x0000003e4460c7f8 in __lll_mutex_lock_wait () from /lib64/libpthread.so.0
+#1  0x0000003e44608864 in _L_mutex_lock_107 () from /lib64/libpthread.so.0
+#2  0x0000003e44608303 in pthread_mutex_lock () from /lib64/libpthread.so.0
+#3  0x000000000053237f in _wapi_handle_current_thread_set_waiting_on
+(waiting_on=0x0) at ../../mono/io-layer/handles-private.h:200
+#4  0x0000000000532261 in timedwait_signal_wait_cond (cond=0x2aaaae436048,
+mutex=0x2aaaae436020, timeout=0x40a37f10, alertable=1, 
+    waiting_on=0x400) at handles.c:1429
+#5  0x0000000000532731 in _wapi_handle_timedwait_signal_handle
+(handle=0x400, timeout=0x40a37f10, alertable=1) at handles.c:1504
+#6  0x000000000052ba0f in WaitForSingleObjectEx (handle=0x400,
+timeout=10000, alertable=1) at wait.c:202
+#7  0x000000000050f507 in async_invoke_thread (data=0x0) at threadpool.c:1228
+#8  0x00000000004ae1b1 in start_wrapper (data=0x2aaab0000900) at threads.c:319
+#9  0x0000000000527cd2 in thread_start_routine (args=0x2aaaae4abbd8) at
+threads.c:253
+#10 0x0000000000543822 in GC_start_routine (arg=<value optimized out>) at
+pthread_support.c:1362
+#11 0x0000003e44606305 in start_thread () from /lib64/libpthread.so.0
+#12 0x0000003e42acd50d in clone () from /lib64/libc.so.6
+#13 0x0000000000000000 in ?? ()
+
+strace of a run where it hangs, from the point on where it produces output:
+
+[pid 25121] write(1, "Test.F from delegate: 2", 23Test.F from delegate: 2) = 23
+[pid 25121] write(1, "\n", 1
+)           = 1
+[pid 25121] write(1, "Async Callback 2", 16Async Callback 2) = 16
+[pid 25121] write(1, "\n", 1
+)           = 1
+[pid 25121] futex(0x2aaaae43604c, 0x4 /* FUTEX_??? */, 1) = 2
+[pid 25121] write(1, "Test.F from delegate: 3", 23Test.F from delegate: 3) = 23
+[pid 25121] write(1, "\n", 1
+)           = 1
+[pid 25121] write(1, "Async Callback 3", 16Async Callback 3) = 16
+[pid 25121] write(1, "\n", 1
+)           = 1
+[pid 25121] write(1, "Test.F from delegate: 4", 23 <unfinished ...>
+[pid 25119] <... futex resumed> )       = 0
+Test.F from delegate: 4[pid 25121] <... write resumed> )       = 23
+[pid 25121] write(1, "\n", 1
+)           = 1
+[pid 25121] write(1, "Async Callback 4", 16Async Callback 4) = 16
+[pid 25121] write(1, "\n", 1
+)           = 1
+[pid 25121] futex(0x2aaaae436020, FUTEX_WAIT, 2, NULL <unfinished ...>
+[pid 25119] futex(0x2aaaae436020, FUTEX_WAKE, 1 <unfinished ...>
+[pid 25120] <... futex resumed> )       = 0
+[pid 25119] <... futex resumed> )       = 1
+[pid 25120] futex(0x2aaaae436020, FUTEX_WAKE, 1) = 1
+[pid 25120] clock_gettime(CLOCK_REALTIME, {1181981491, 492003000}) = 0
+[pid 25120] futex(0x2aaaae43604c, FUTEX_WAIT, 5, {9, 998997000} <unfinished
+...>
+[pid 25121] <... futex resumed> )       = 0
+[pid 25121] futex(0x2aaaae436020, FUTEX_WAKE, 1) = 0
+[pid 25121] clock_gettime(CLOCK_REALTIME, {1181981491, 492102000}) = 0
+[pid 25121] futex(0x2aaaae43604c, FUTEX_WAIT, 6, {9, 999898000} <unfinished
+...>
+[pid 25119] clock_gettime(CLOCK_REALTIME, {1181981491, 492225000}) = 0
+[pid 25119] futex(0x2aaaae43604c, FUTEX_WAIT, 7, {9, 992775000} <unfinished
+...>
+[pid 25116] <... nanosleep resumed> {46909632806912, 46912496293424}) = 0
+[pid 25116] futex(0x2aaaae43604c, 0x4 /* FUTEX_??? */, 1) = 3
+[pid 25120] <... futex resumed> )       = 0
+[pid 25120] futex(0x2aaaae436020, FUTEX_WAIT, 2, NULL <unfinished ...>
+[pid 25116] futex(0x2aaaae436020, FUTEX_WAKE, 1 <unfinished ...>
+[pid 25121] <... futex resumed> )       = 0
+[pid 25116] <... futex resumed> )       = 1
+[pid 25121] futex(0x2aaaae436020, FUTEX_WAKE, 1) = 1
+[pid 25116] tgkill(25116, 25121, SIGRT_3 <unfinished ...>
+[pid 25121] clock_gettime(CLOCK_REALTIME, {1181981491, 686833000}) = 0
+[pid 25119] <... futex resumed> )       = 0
+[pid 25116] <... tgkill resumed> )      = 0
+[pid 25121] --- SIGRT_3 (Real-time signal 1) @ 0 (0) ---
+[pid 25119] futex(0x2aaaae436048, FUTEX_WAIT, 2, NULL <unfinished ...>
+[pid 25116] tgkill(25116, 25119, SIGRT_3 <unfinished ...>
+[pid 25121] futex(0x2aaaae436048, FUTEX_WAIT, 2, NULL <unfinished ...>
+[pid 25116] <... tgkill resumed> )      = 0
+[pid 25119] <... futex resumed> )       = -1 EINTR (Interrupted system call)
+[pid 25119] --- SIGRT_3 (Real-time signal 1) @ 0 (0) ---
+[pid 25116] tgkill(25116, 25120, SIGRT_3 <unfinished ...>
+[pid 25119] futex(0x852ee0, FUTEX_WAIT, 2, NULL <unfinished ...>
+[pid 25120] <... futex resumed> )       = -1 EINTR (Interrupted system call)
+[pid 25116] <... tgkill resumed> )      = 0
+[pid 25120] --- SIGRT_3 (Real-time signal 1) @ 0 (0) ---
+[pid 25120] futex(0x852ee0, FUTEX_WAIT, 2, NULL <unfinished ...>
+[pid 25116] semop(332464154, 0x7fff14d2d9d0, 1) = 0
+[pid 25116] semop(332464154, 0x7fff14d2d9f0, 1) = 0
+[pid 25116] semop(332464154, 0x7fff14d2d9d0, 1) = 0
+[pid 25116] semop(332464154, 0x7fff14d2d9f0, 1) = 0
+[pid 25116] nanosleep({0, 100000000}, NULL) = 0
+[pid 25116] semop(332464154, 0x7fff14d2d9d0, 1) = 0
+[pid 25116] semop(332464154, 0x7fff14d2d9f0, 1) = 0
+[pid 25116] semop(332464154, 0x7fff14d2d9d0, 1) = 0
+[pid 25116] semop(332464154, 0x7fff14d2d9f0, 1) = 0
+[pid 25116] nanosleep({0, 100000000}, NULL) = 0
+[pid 25116] semop(332464154, 0x7fff14d2d9d0, 1) = 0
+[pid 25116] semop(332464154, 0x7fff14d2d9f0, 1) = 0
+[pid 25116] semop(332464154, 0x7fff14d2d9d0, 1) = 0
+[pid 25116] semop(332464154, 0x7fff14d2d9f0, 1) = 0
+[pid 25116] nanosleep({0, 100000000}, NULL) = 0
+[pid 25116] semop(332464154, 0x7fff14d2d9d0, 1) = 0
+[pid 25116] semop(332464154, 0x7fff14d2d9f0, 1) = 0
+[pid 25116] semop(332464154, 0x7fff14d2d9d0, 1) = 0
+[pid 25116] semop(332464154, 0x7fff14d2d9f0, 1) = 0
+[pid 25116] nanosleep({0, 100000000}, NULL) = 0
+
+This goes on ad infinitum.


More information about the mono-bugs mailing list