Hang in threads.test

[Neil Jerram]

My nightly build of master, on a relatively slow old machine, is
hanging, on most nights, in `make check'.  The tail of check-guile.log
says

PASS: threads.test: mutex-ownership: mutex ownership for unlocked mutex
PASS: threads.test: mutex-ownership: locking mutex on behalf of other thread
PASS: threads.test: mutex-ownership: locking mutex with no owner

so it looks like the problematic test is "mutex with owner not retained
(bug #27450)" in threads.test.  Here are the backtraces from GDB, from
today's build.

(gdb) info threads
  3 Thread 0x40bd8b70 (LWP 22491)  0x4001d424 in __kernel_vsyscall ()
  2 Thread 0x409d7b70 (LWP 22605)  0x4001d424 in __kernel_vsyscall ()
* 1 Thread 0x404ff8f0 (LWP 22194)  0x4001d424 in __kernel_vsyscall ()
(gdb) bt
#0  0x4001d424 in __kernel_vsyscall ()
#1  0x40469385 in sem_wait@@GLIBC_2.1 () from /lib/i686/cmov/libpthread.so.0
#2  0x40182018 in GC_stop_world () from /usr/lib/libgc.so.1
#3  0x40171b1e in GC_stopped_mark () from /usr/lib/libgc.so.1
#4  0x40171df9 in GC_try_to_collect_inner () from /usr/lib/libgc.so.1
#5  0x40172194 in GC_try_to_collect () from /usr/lib/libgc.so.1
#6  0x40172270 in GC_gcollect () from /usr/lib/libgc.so.1
#7  0x4007abca in scm_i_gc () at ../../libguile/gc.c:398
#8  scm_gc () at ../../libguile/gc.c:381
#9  0x400fb4fb in vm_debug_engine (vm=0x92031b8, program=0x9250b30, 
argv=0xbf98d880, nargs=1) at ../../libguile/vm-i-system.c:847
#10 0x400ea8aa in scm_c_vm_run (vm=0x92031b8, program=0x9250b30, 
argv=0xbf98d880, nargs=1) at ../../libguile/vm.c:560
#11 0x4006f8b7 in scm_primitive_eval (exp=0x993b6b8) at 
../../libguile/eval.c:844
#12 0x40092473 in scm_primitive_load (filename=0xcb4a020) at 
../../libguile/load.c:126
#13 0x400fb4f2 in vm_debug_engine (vm=0x92031b8, program=0x936bf18, 
argv=0xbf98d9d4, nargs=1) at ../../libguile/vm-i-system.c:850
#14 0x400ea8aa in scm_c_vm_run (vm=0x92031b8, program=0x936bf18, 
argv=0xbf98d9d4, nargs=1) at ../../libguile/vm.c:560
#15 0x4006e175 in scm_call_1 (proc=0x936bf18, arg1=0x94846b0) at 
../../libguile/eval.c:561
#16 0x4006fcfe in scm_for_each (proc=0x936bf18, arg1=0x93f2930, args=0x304) at 
../../libguile/eval.c:789
#17 0x400fb4c9 in vm_debug_engine (vm=0x92031b8, program=0x9250b30, 
argv=0xbf98db40, nargs=1) at ../../libguile/vm-i-system.c:856
#18 0x400ea8aa in scm_c_vm_run (vm=0x92031b8, program=0x9250b30, 
argv=0xbf98db40, nargs=1) at ../../libguile/vm.c:560
#19 0x4006f8b7 in scm_primitive_eval (exp=0x935c6a8) at 
../../libguile/eval.c:844
#20 0x4006f931 in scm_eval (exp=0x935c6a8, module_or_state=0x9205828) at 
../../libguile/eval.c:878
#21 0x400bc5d5 in scm_shell (argc=10, argv=0xbf98dfe4) at 
../../libguile/script.c:760
#22 0x4008b316 in invoke_main_func (body_data=0xbf98df00) at 
../../libguile/init.c:383
#23 0x400658d2 in c_body (d=0xbf98de54) at ../../libguile/continuations.c:473
#24 0x400e7242 in apply_catch_closure (clo=0x0, args=0x304) at 
../../libguile/throw.c:146
#25 0x400fa942 in vm_debug_engine (vm=0x92031b8, program=0x9198840, 
argv=0xbf98dd30, nargs=4) at ../../libguile/vm-i-system.c:918
#26 0x400ea8aa in scm_c_vm_run (vm=0x92031b8, program=0x9198840, 
argv=0xbf98dd30, nargs=4) at ../../libguile/vm.c:560
#27 0x4006e08d in scm_call_4 (proc=0x9198840, arg1=0x404, arg2=0x9315f70, 
arg3=0x9315f60, arg4=0x9315f50) at ../../libguile/eval.c:582
#28 0x400e7ba2 in scm_catch_with_pre_unwind_handler (key=0x404, 
thunk=0x9315f70, handler=0x9315f60, pre_unwind_handler=0x9315f50) at 
../../libguile/throw.c:86
#29 0x400e7c72 in scm_c_catch (tag=0x404, body=0x400658c0 <c_body>, 
body_data=0xbf98de54, handler=0x400658e0 <c_handler>, handler_data=0xbf98de54, 
pre_unwind_handler=0x400e75e0 <scm_handle_by_message_noexit>, 
pre_unwind_handler_data=0x0) at ../../libguile/throw.c:213
#30 0x40065b9b in scm_i_with_continuation_barrier (body=0x400658c0 <c_body>, 
body_data=0xbf98de54, handler=0x400658e0 <c_handler>, handler_data=0xbf98de54, 
pre_unwind_handler=0x400e75e0 <scm_handle_by_message_noexit>, 
pre_unwind_handler_data=0x0) at ../../libguile/continuations.c:450
#31 0x40065c73 in scm_c_with_continuation_barrier (func=0x4008b2d0 
<invoke_main_func>, data=0xbf98df00) at ../../libguile/continuations.c:491
#32 0x400e6e1c in scm_i_with_guile_and_parent (func=0x4008b2d0 
<invoke_main_func>, data=0xbf98df00, parent=0x0) at ../../libguile/threads.c:741
#33 0x400e6f3e in scm_with_guile (func=0x4008b2d0 <invoke_main_func>, 
data=0xbf98df00) at ../../libguile/threads.c:720
#34 0x4008b2af in scm_boot_guile (argc=10, argv=0xbf98dfe4, main_func=0x80488a0 
<inner_main>, closure=0x0) at ../../libguile/init.c:366
#35 0x0804889b in main (argc=10, argv=0xbf98dfe4) at ../../libguile/guile.c:70
(gdb) thread 2
[Switching to thread 2 (Thread 0x409d7b70 (LWP 22605))]#0  0x4001d424 in 
__kernel_vsyscall ()
(gdb) bt
#0  0x4001d424 in __kernel_vsyscall ()
#1  0x4033ab5e in sigsuspend () from /lib/i686/cmov/libc.so.6
#2  0x4018222b in GC_suspend_handler_inner () from /usr/lib/libgc.so.1
#3  0x401822b5 in GC_suspend_handler () from /usr/lib/libgc.so.1
#4  <signal handler called>
#5  0x4001d422 in __kernel_vsyscall ()
#6  0x40469c39 in __lll_lock_wait () from /lib/i686/cmov/libpthread.so.0
#7  0x4046503b in _L_lock_748 () from /lib/i686/cmov/libpthread.so.0
#8  0x40464e61 in pthread_mutex_lock () from /lib/i686/cmov/libpthread.so.0
#9  0x403e9286 in pthread_mutex_lock () from /lib/i686/cmov/libc.so.6
#10 0x40180ae7 in GC_lock () from /usr/lib/libgc.so.1
#11 0x4017760f in GC_core_malloc_atomic () from /usr/lib/libgc.so.1
#12 0x401807e8 in GC_malloc_atomic () from /usr/lib/libgc.so.1
#13 0x40079c7d in scm_gc_malloc_pointerless (size=15, what=0x4011f551 "string") 
at ../../libguile/gc-malloc.c:177
#14 0x400dac4e in make_stringbuf (len=6) at ../../libguile/strings.c:128
#15 0x400dca54 in scm_i_make_string (len=6, charsp=0x409d6d78) at 
../../libguile/strings.c:268
#16 0x400dd2f7 in scm_from_stringn (str=0x409d6dfb "125576n\235@", len=6, 
encoding=0x9dfc7c0 "ANSI_X3.4-1968", 
handler=SCM_FAILED_CONVERSION_QUESTION_MARK) at ../../libguile/strings.c:1487
#17 0x400dd48a in scm_from_locale_stringn (str=0x409d6dfb "125576n\235@", 
len=6) at ../../libguile/strings.c:1536
#18 0x400e3853 in scm_gensym (prefix=0x9254e10) at ../../libguile/symbols.c:357
#19 0x400fb4f2 in vm_debug_engine (vm=0xc827bd0, program=0x9198840, 
argv=0x409d6f74, nargs=3) at ../../libguile/vm-i-system.c:850
#20 0x400ea8aa in scm_c_vm_run (vm=0xc827bd0, program=0x9198840, 
argv=0x409d6f74, nargs=3) at ../../libguile/vm.c:560
#21 0x4006e0e7 in scm_call_3 (proc=0x9198840, arg1=0x404, arg2=0xc98b1e0, 
arg3=0xcb62f30) at ../../libguile/eval.c:575
#22 0x400e7af8 in scm_catch (key=0x404, thunk=0xc98b1e0, handler=0xcb62f30) at 
../../libguile/throw.c:73
#23 0x400e6713 in really_launch (d=0xbf98d6e4) at ../../libguile/threads.c:839
#24 0x400658d2 in c_body (d=0x409d7284) at ../../libguile/continuations.c:473
#25 0x400e7242 in apply_catch_closure (clo=0x4018a0a0, args=0x304) at 
../../libguile/throw.c:146
#26 0x400fa942 in vm_debug_engine (vm=0xc827bd0, program=0x9198840, 
argv=0x409d7160, nargs=4) at ../../libguile/vm-i-system.c:918
#27 0x400ea8aa in scm_c_vm_run (vm=0xc827bd0, program=0x9198840, 
argv=0x409d7160, nargs=4) at ../../libguile/vm.c:560
#28 0x4006e08d in scm_call_4 (proc=0x9198840, arg1=0x404, arg2=0xc981ba0, 
arg3=0xc981b90, arg4=0xc981b80) at ../../libguile/eval.c:582
#29 0x400e7ba2 in scm_catch_with_pre_unwind_handler (key=0x404, 
thunk=0xc981ba0, handler=0xc981b90, pre_unwind_handler=0xc981b80) at 
../../libguile/throw.c:86
#30 0x400e7c72 in scm_c_catch (tag=0x404, body=0x400658c0 <c_body>, 
body_data=0x409d7284, handler=0x400658e0 <c_handler>, handler_data=0x409d7284, 
pre_unwind_handler=0x400e75e0 <scm_handle_by_message_noexit>, 
pre_unwind_handler_data=0x0) at ../../libguile/throw.c:213
#31 0x40065b9b in scm_i_with_continuation_barrier (body=0x400658c0 <c_body>, 
body_data=0x409d7284, handler=0x400658e0 <c_handler>, handler_data=0x409d7284, 
pre_unwind_handler=0x400e75e0 <scm_handle_by_message_noexit>, 
pre_unwind_handler_data=0x0) at ../../libguile/continuations.c:450
#32 0x40065c73 in scm_c_with_continuation_barrier (func=0x400e6690 
<really_launch>, data=0xbf98d6e4) at ../../libguile/continuations.c:491
#33 0x400e6e1c in scm_i_with_guile_and_parent (func=0x400e6690 <really_launch>, 
data=0xbf98d6e4, parent=0x91bf538) at ../../libguile/threads.c:741
#34 0x400e6eff in launch_thread (d=0xbf98d6e4) at ../../libguile/threads.c:852
#35 0x40180e48 in GC_inner_start_routine () from /usr/lib/libgc.so.1
#36 0x4017b21c in GC_call_with_stack_base () from /usr/lib/libgc.so.1
#37 0x40180cd7 in GC_start_routine () from /usr/lib/libgc.so.1
#38 0x40462955 in start_thread () from /lib/i686/cmov/libpthread.so.0
#39 0x403dc10e in clone () from /lib/i686/cmov/libc.so.6
(gdb) thread 3
[Switching to thread 3 (Thread 0x40bd8b70 (LWP 22491))]#0  0x4001d424 in 
__kernel_vsyscall ()
(gdb) bt
#0  0x4001d424 in __kernel_vsyscall ()
#1  0x4033ab5e in sigsuspend () from /lib/i686/cmov/libc.so.6
#2  0x4018222b in GC_suspend_handler_inner () from /usr/lib/libgc.so.1
#3  0x401822b5 in GC_suspend_handler () from /usr/lib/libgc.so.1
#4  <signal handler called>
#5  0x4001d422 in __kernel_vsyscall ()
#6  0x403cd1db in read () from /lib/i686/cmov/libc.so.6
#7  0x400bb0f2 in signal_delivery_thread (data=0x0) at 
../../libguile/scmsigs.c:164
#8  0x400e7242 in apply_catch_closure (clo=0x1, args=0x304) at 
../../libguile/throw.c:146
#9  0x400fa942 in vm_debug_engine (vm=0x97f3f20, program=0x9198840, 
argv=0x40bd7ea4, nargs=3) at ../../libguile/vm-i-system.c:918
#10 0x400ea8aa in scm_c_vm_run (vm=0x97f3f20, program=0x9198840, 
argv=0x40bd7ea4, nargs=3) at ../../libguile/vm.c:560
#11 0x4006e0e7 in scm_call_3 (proc=0x9198840, arg1=0x404, arg2=0x993a500, 
arg3=0x993a4f0) at ../../libguile/eval.c:575
#12 0x400e7af8 in scm_catch (key=0x404, thunk=0x993a500, handler=0x993a4f0) at 
../../libguile/throw.c:73
#13 0x400e7c06 in scm_catch_with_pre_unwind_handler (key=0x404, 
thunk=0x993a500, handler=0x993a4f0, pre_unwind_handler=0x904) at 
../../libguile/throw.c:81
#14 0x400e7c72 in scm_c_catch (tag=0x404, body=0x400bb090 
<signal_delivery_thread>, body_data=0x0, handler=0x400e7660 
<scm_handle_by_message>, handler_data=0x40125564, pre_unwind_handler=0, 
pre_unwind_handler_data=0x0) at ../../libguile/throw.c:213
#15 0x400e7cc9 in scm_internal_catch (tag=0x404, body=0x400bb090 
<signal_delivery_thread>, body_data=0x0, handler=0x400e7660 
<scm_handle_by_message>, handler_data=0x40125564) at ../../libguile/throw.c:222
#16 0x400e651b in really_spawn (d=0x409d714c) at ../../libguile/threads.c:929
#17 0x400658d2 in c_body (d=0x40bd8284) at ../../libguile/continuations.c:473
#18 0x400e7242 in apply_catch_closure (clo=0x1, args=0x304) at 
../../libguile/throw.c:146
#19 0x400fa942 in vm_debug_engine (vm=0x97f3f20, program=0x9198840, 
argv=0x40bd8160, nargs=4) at ../../libguile/vm-i-system.c:918
#20 0x400ea8aa in scm_c_vm_run (vm=0x97f3f20, program=0x9198840, 
argv=0x40bd8160, nargs=4) at ../../libguile/vm.c:560
#21 0x4006e08d in scm_call_4 (proc=0x9198840, arg1=0x404, arg2=0x993a680, 
arg3=0x993a670, arg4=0x993a660) at ../../libguile/eval.c:582
#22 0x400e7ba2 in scm_catch_with_pre_unwind_handler (key=0x404, 
thunk=0x993a680, handler=0x993a670, pre_unwind_handler=0x993a660) at 
../../libguile/throw.c:86
#23 0x400e7c72 in scm_c_catch (tag=0x404, body=0x400658c0 <c_body>, 
body_data=0x40bd8284, handler=0x400658e0 <c_handler>, handler_data=0x40bd8284, 
pre_unwind_handler=0x400e75e0 <scm_handle_by_message_noexit>, 
pre_unwind_handler_data=0x0) at ../../libguile/throw.c:213
#24 0x40065b9b in scm_i_with_continuation_barrier (body=0x400658c0 <c_body>, 
body_data=0x40bd8284, handler=0x400658e0 <c_handler>, handler_data=0x40bd8284, 
pre_unwind_handler=0x400e75e0 <scm_handle_by_message_noexit>, 
pre_unwind_handler_data=0x0) at ../../libguile/continuations.c:450
#25 0x40065c73 in scm_c_with_continuation_barrier (func=0x400e6480 
<really_spawn>, data=0x409d714c) at ../../libguile/continuations.c:491
#26 0x400e6e1c in scm_i_with_guile_and_parent (func=0x400e6480 <really_spawn>, 
data=0x409d714c, parent=0x97f3fe0) at ../../libguile/threads.c:741
#27 0x400e6eaf in spawn_thread (d=0x409d714c) at ../../libguile/threads.c:941
#28 0x40180e48 in GC_inner_start_routine () from /usr/lib/libgc.so.1
#29 0x4017b21c in GC_call_with_stack_base () from /usr/lib/libgc.so.1
#30 0x40180cd7 in GC_start_routine () from /usr/lib/libgc.so.1
#31 0x40462955 in start_thread () from /lib/i686/cmov/libpthread.so.0
#32 0x403dc10e in clone () from /lib/i686/cmov/libc.so.6
(gdb) 

Going by the tail of check-guile.log, which I have saved off for every
day in September, this happened every day except the 1st, 3rd, 6th, 9th
and 11th.  So it's not completely deterministic, but happens more often
than not.

When the build hangs in `make check', it doesn't get as far as running
benchmarks, and so there is no data for the relevant date at
http://ossau.homelinux.net:8000/~neil/benchmark-results/master/.  So the
pattern of missing dates on that page suggests that this problem might
have been introduced by a commit on 16th August.

Any ideas?

    Neil