[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