Hi Marc!
Rarely I get an error that Gambit just stops, while eating up all the CPU core.
It's so rare that I don't consider it a problem, though I'd be happy to see it gone of course.
I believe 50% of the time it happens within 5 seconds after Gambit started and thread-start! was invoked 1-5 times.
I ran into this error now, saw it something like four times in 6mo.
This is on Gambit gsc 4.6.6 on AMD64, compiled from source with --enable-single-host and some more.
The Gambit session is running a couple of Gambit threads, absolutely nothing exotic going on.
Had it in a GDB session so could reliably "profile" the error, output from that GDB session below.
Saved the core file for later reference too.
It's in _thread.scm , and from what I can see it's in |##thread-effective-priority-downgrade!|'s definition.
What it looks like to me is that by some reason we've got a self-referencing btq-deq-next chain element, that keeps it reiterating forever.
I base this on that ___r1 and ___r3 and ___r4 remain constant; I'd guess that ___r1 is thread, ___r3 is btq and ___r4 is leftmost.
Do you have any thought on what the issue might be, or any on how I can track this further?
Many thanks, Mikael
_thread.scm, the rows where the freeze appears to be
;; (##thread-effective-priority-downgrade! thread) is called to ;; recompute the effective priority of a thread. It is only called in ;; situations where the new effective priority is no more than the old ;; one.
(define-prim (##thread-effective-priority-downgrade! thread)
(##declare (not interrupts-enabled))
(let ((floats (macro-thread-floats thread)))
;; save old effective priority for later
(macro-temp-set! (macro-thread-floats (macro-run-queue)) (macro-effective-priority floats))
;; compute the maximum of the boosted priority and the ;; effective priority of all the threads in blocked thread ;; queues (i.e. mutexes, condvars, etc) owned by the thread
(macro-effective-priority-set! floats (macro-boosted-priority floats))
(let loop ((btq (macro-btq-deq-next thread))) (if (##not (##eq? btq thread)) <-- Looks sth like _thread.c:10452 (let ((leftmost (macro-btq-leftmost btq))) <-- :10456 (if (##not (##eq? leftmost btq)) <-- :10457 (let ((leftmost-floats (macro-thread-floats leftmost))) (if (##flonum.< (macro-effective-priority floats) (macro-effective-priority leftmost-floats)) (macro-effective-priority-set! floats (macro-effective-priority leftmost-floats))))) (loop (macro-btq-deq-next btq)))))
Gdb log from "profiling" the frozen gsc session, as we see it's stuck in a loop in _thread.c between rows 10451 and 10458 :
Program received signal SIGINT, Interrupt. 0x000000000075a90a in ___H__20___thread (_(short *)=0x11c47e0) at _thread.c:10457 10457 ___IF(___EQP(___R4,___R3)) (gdb) bt #0 0x000000000075a90a in ___H__20___thread (_(short *)=0x11c47e0) at _thread.c:10457 #1 0x00000000005086fb in ___call (nargs=0, proc=13386241, stack_marker=8829493553) at setup.c:1860 #2 0x000000000050a31d in ___setup (setup_params=0x7f7fffff0460) at setup.c:3024 #3 0x000000000052d8ca in ___main (linker=0x505ddc <____20___gsc__(___global_state_struct*)>) at main.c:711 #4 0x000000000051a9fc in ___main_char (argc=5, argv=0x7f7fffff06a8, linker=0x505ddc <____20___gsc__(___global_state_struct*)>, script_line=0x0) at os_base.c:413 #5 0x0000000000505e16 in main (argc=5, argv=0x7f7fffff06a8) at _gsc_.c:13627 (gdb) cont Continuing.
Program received signal SIGINT, Interrupt. 0x000000000075a8f2 in ___H__20___thread (_(short *)=0x11c47e0) at _thread.c:10452 10452 ___IF(___EQP(___R3,___R1)) (gdb) bt #0 0x000000000075a8f2 in ___H__20___thread (_(short *)=0x11c47e0) at _thread.c:10452 #1 0x00000000005086fb in ___call (nargs=0, proc=13386241, stack_marker=8829493553) at setup.c:1860 #2 0x000000000050a31d in ___setup (setup_params=0x7f7fffff0460) at setup.c:3024 #3 0x000000000052d8ca in ___main (linker=0x505ddc <____20___gsc__(___global_state_struct*)>) at main.c:711 #4 0x000000000051a9fc in ___main_char (argc=5, argv=0x7f7fffff06a8, linker=0x505ddc <____20___gsc__(___global_state_struct*)>, script_line=0x0) at os_base.c:413 #5 0x0000000000505e16 in main (argc=5, argv=0x7f7fffff06a8) at _gsc_.c:13627 (gdb) cont Continuing.
Program received signal SIGINT, Interrupt. 0x000000000075a90a in ___H__20___thread (_(short *)=0x11c47e0) at _thread.c:10457 10457 ___IF(___EQP(___R4,___R3)) (gdb) bt #0 0x000000000075a90a in ___H__20___thread (_(short *)=0x11c47e0) at _thread.c:10457 #1 0x00000000005086fb in ___call (nargs=0, proc=13386241, stack_marker=8829493553) at setup.c:1860 #2 0x000000000050a31d in ___setup (setup_params=0x7f7fffff0460) at setup.c:3024 #3 0x000000000052d8ca in ___main (linker=0x505ddc <____20___gsc__(___global_state_struct*)>) at main.c:711 #4 0x000000000051a9fc in ___main_char (argc=5, argv=0x7f7fffff06a8, linker=0x505ddc <____20___gsc__(___global_state_struct*)>, script_line=0x0) at os_base.c:413 #5 0x0000000000505e16 in main (argc=5, argv=0x7f7fffff06a8) at _gsc_.c:13627 (gdb) ^CQuit (gdb) cont Continuing.
Program received signal SIGINT, Interrupt. ___H__20___thread (_(short *)=0x11c47e0) at _thread.c:10451 10451 ___SET_R3(___VECTORREF(___R3,___FIX(1L))) (gdb) bt #0 ___H__20___thread (_(short *)=0x11c47e0) at _thread.c:10451 #1 0x00000000005086fb in ___call (nargs=0, proc=13386241, stack_marker=8829493553) at setup.c:1860 #2 0x000000000050a31d in ___setup (setup_params=0x7f7fffff0460) at setup.c:3024 #3 0x000000000052d8ca in ___main (linker=0x505ddc <____20___gsc__(___global_state_struct*)>) at main.c:711 #4 0x000000000051a9fc in ___main_char (argc=5, argv=0x7f7fffff06a8, linker=0x505ddc <____20___gsc__(___global_state_struct*)>, script_line=0x0) at os_base.c:413 #5 0x0000000000505e16 in main (argc=5, argv=0x7f7fffff06a8) at _gsc_.c:13627
Program received signal SIGINT, Interrupt. ___H__20___thread (_(short *)=0x11c47e0) at _thread.c:10456 10456 ___SET_R4(___VECTORREF(___R3,___FIX(6L))) (gdb) bt #0 ___H__20___thread (_(short *)=0x11c47e0) at _thread.c:10456 #1 0x00000000005086fb in ___call (nargs=0, proc=13386241, stack_marker=8829493553) at setup.c:1860 #2 0x000000000050a31d in ___setup (setup_params=0x7f7fffff0460) at setup.c:3024 #3 0x000000000052d8ca in ___main (linker=0x505ddc <____20___gsc__(___global_state_struct*)>) at main.c:711 #4 0x000000000051a9fc in ___main_char (argc=5, argv=0x7f7fffff06a8, linker=0x505ddc <____20___gsc__(___global_state_struct*)>, script_line=0x0) at os_base.c:413 #5 0x0000000000505e16 in main (argc=5, argv=0x7f7fffff06a8) at _gsc_.c:13627 (gdb) cont Continuing.
Program received signal SIGINT, Interrupt. 0x000000000075a90a in ___H__20___thread (_(short *)=0x11c47e0) at _thread.c:10457 10457 ___IF(___EQP(___R4,___R3)) (gdb) bt #0 0x000000000075a90a in ___H__20___thread (_(short *)=0x11c47e0) at _thread.c:10457 #1 0x00000000005086fb in ___call (nargs=0, proc=13386241, stack_marker=8829493553) at setup.c:1860 #2 0x000000000050a31d in ___setup (setup_params=0x7f7fffff0460) at setup.c:3024 #3 0x000000000052d8ca in ___main (linker=0x505ddc <____20___gsc__(___global_state_struct*)>) at main.c:711 #4 0x000000000051a9fc in ___main_char (argc=5, argv=0x7f7fffff06a8, linker=0x505ddc <____20___gsc__(___global_state_struct*)>, script_line=0x0) at os_base.c:413 #5 0x0000000000505e16 in main (argc=5, argv=0x7f7fffff06a8) at _gsc_.c:13627 (gdb) cont Continuing.
Program received signal SIGINT, Interrupt. 0x000000000075a90a in ___H__20___thread (_(short *)=0x11c47e0) at _thread.c:10457 10457 ___IF(___EQP(___R4,___R3)) (gdb) bt #0 0x000000000075a90a in ___H__20___thread (_(short *)=0x11c47e0) at _thread.c:10457 #1 0x00000000005086fb in ___call (nargs=0, proc=13386241, stack_marker=8829493553) at setup.c:1860 #2 0x000000000050a31d in ___setup (setup_params=0x7f7fffff0460) at setup.c:3024 #3 0x000000000052d8ca in ___main (linker=0x505ddc <____20___gsc__(___global_state_struct*)>) at main.c:711 #4 0x000000000051a9fc in ___main_char (argc=5, argv=0x7f7fffff06a8, linker=0x505ddc <____20___gsc__(___global_state_struct*)>, script_line=0x0) at os_base.c:413 #5 0x0000000000505e16 in main (argc=5, argv=0x7f7fffff06a8) at _gsc_.c:13627
Well, since that was about a traversal over a structure, let's make some profiling of what the ___r1/3/4 variable is, so we get a clue of how the traversal goes!
(gdb) info locals ___r4 = 9052459177 ___F64V1 = 9.9999999999999995e-07 ___r1 = 9051204137 ___F64V2 = 0 _(char *) = 14328769 ___temp = 9052462209 ___hp = 0x21b91bbc8 _(float, *) = 0x208306628 _(long double, ) = 14327969 ___r2 = 9051204361 ___F64V3 = 0.02 ___start = 14314721 ___r3 = 9052459177 ___F64V4 = 0.02
next:
___r4 = 9052459177 ___F64V1 = 9.9999999999999995e-07 ___r1 = 9051204137 ___F64V2 = 0 _(char *) = 14328769 ___temp = 9052462209 ___hp = 0x21b91bbc8 _(float, *) = 0x208306628 _(long double, ) = 14327969 ___r2 = 9051204361 ___F64V3 = 0.02 ___start = 14314721 ___r3 = 9052459177 ___F64V4 = 0.02
next:
___r4 = 9052459177 ___F64V1 = 9.9999999999999995e-07 ___r1 = 9051204137 ___F64V2 = 0 _(char *) = 14328769 ___temp = 9052462209 ___hp = 0x21b91bbc8 _(float, *) = 0x208306628 _(long double, ) = 14327969 ___r2 = 9051204361 ___F64V3 = 0.02 ___start = 14314721 ___r3 = 9052459177 ___F64V4 = 0.02
next:
___r4 = 9052459177 ___F64V1 = 9.9999999999999995e-07 ___r1 = 9051204137 ___F64V2 = 0 _(char *) = 14328769 ___temp = 9052462209 ___hp = 0x21b91bbc8 _(float, *) = 0x208306628 _(long double, ) = 14327969 ___r2 = 9051204361 ___F64V3 = 0.02 ___start = 14314721 ___r3 = 9052459177 ___F64V4 = 0.02
next:
___r4 = 9052459177 ___F64V1 = 9.9999999999999995e-07 ___r1 = 9051204137 ___F64V2 = 0 _(char *) = 14328769 ___temp = 9052462209 ___hp = 0x21b91bbc8 _(float, *) = 0x208306628 _(long double, ) = 14327969 ___r2 = 9051204361 ___F64V3 = 0.02 ___start = 14314721 ___r3 = 9052459177 ___F64V4 = 0.02
The rows it's stuck at, in _thread.c .
(the following was copied from _thread.c of Gambit 4.6.2, it looks like it's equivalent with 4.6.6 at least on these locations, so should be fine)
#undef ___PH_PROC #define ___PH_PROC ___H__23__23_thread_2d_effective_2d_priority_2d_downgrade_21_ #undef ___PH_LBL0 #define ___PH_LBL0 414 #undef ___PD_ALL #define ___PD_ALL ___D_FP ___D_R0 ___D_R1 ___D_R2 ___D_R3 ___D_R4 ___D_F64(___F64V1) ___D_F64(___F64V2) \
#undef ___PR_ALL #define ___PR_ALL ___R_FP ___R_R0 ___R_R1 ___R_R2 ___R_R3 ___R_R4 #undef ___PW_ALL #define ___PW_ALL ___W_FP ___W_R0 ___W_R1 ___W_R2 ___W_R3 ___W_R4 ___BEGIN_P_COD ___BEGIN_P_HLBL ___DEF_P_HLBL_INTRO
___DEF_P_HLBL(___L0__23__23_thread_2d_effective_2d_priority_2d_downgrade_21_)
___DEF_P_HLBL(___L1__23__23_thread_2d_effective_2d_priority_2d_downgrade_21_) ___END_P_HLBL ___BEGIN_P_SW
___DEF_SLBL(0,___L0__23__23_thread_2d_effective_2d_priority_2d_downgrade_21_) ___IF_NARGS_EQ(1,___NOTHING) ___WRONG_NARGS(0,1,0,0)
___DEF_GLBL(___L__23__23_thread_2d_effective_2d_priority_2d_downgrade_21_)
___SET_R2(___UNCHECKEDSTRUCTUREREF(___R1,___FIX(14L),___SUB(22),___FAL)) ___SET_F64(___F64V1,___F64VECTORREF(___R2,___FIX(6L))) ___SET_R4(___RUNQUEUE)
___SET_R4(___UNCHECKEDSTRUCTUREREF(___R4,___FIX(14L),___SUB(22),___FAL)) ___F64VECTORSET(___R4,___FIX(2L),___F64V1) ___SET_F64(___F64V2,___F64VECTORREF(___R2,___FIX(5L))) ___F64VECTORSET(___R2,___FIX(6L),___F64V2) ___SET_STK(1,___R0) ___SET_STK(2,___R1) ___SET_STK(3,___R2) ___SET_R3(___VECTORREF(___R1,___FIX(1L))) ___SET_R0(___LBL(1)) ___ADJFP(8) ___IF(___EQP(___R3,___R1))
___GOTO(___L6__23__23_thread_2d_effective_2d_priority_2d_downgrade_21_) ___END_IF
___GOTO(___L4__23__23_thread_2d_effective_2d_priority_2d_downgrade_21_)
___DEF_GLBL(___L2__23__23_thread_2d_effective_2d_priority_2d_downgrade_21_)
___SET_R4(___UNCHECKEDSTRUCTUREREF(___R4,___FIX(14L),___SUB(22),___FAL)) ___SET_F64(___F64V1,___F64VECTORREF(___R4,___FIX(6L))) ___SET_F64(___F64V2,___F64VECTORREF(___R2,___FIX(6L))) ___ADJFP(2) ___IF(___F64LT(___F64V2,___F64V1))
___GOTO(___L5__23__23_thread_2d_effective_2d_priority_2d_downgrade_21_) ___END_IF ___ADJFP(-2)
___DEF_GLBL(___L3__23__23_thread_2d_effective_2d_priority_2d_downgrade_21_) 10451: ___SET_R3(___VECTORREF(___R3,___FIX(1L))) 10452: ___IF(___EQP(___R3,___R1))
___GOTO(___L6__23__23_thread_2d_effective_2d_priority_2d_downgrade_21_) ___END_IF
___DEF_GLBL(___L4__23__23_thread_2d_effective_2d_priority_2d_downgrade_21_) 10456: ___SET_R4(___VECTORREF(___R3,___FIX(6L))) 10457: ___IF(___EQP(___R4,___R3)) 10458: ___GOTO(___L3__23__23_thread_2d_effective_2d_priority_2d_downgrade_21_) ___END_IF
___GOTO(___L2__23__23_thread_2d_effective_2d_priority_2d_downgrade_21_)
___DEF_GLBL(___L5__23__23_thread_2d_effective_2d_priority_2d_downgrade_21_) ___SET_F64(___F64V1,___F64VECTORREF(___R4,___FIX(6L))) ___F64VECTORSET(___R2,___FIX(6L),___F64V1) ___ADJFP(-2)
___GOTO(___L3__23__23_thread_2d_effective_2d_priority_2d_downgrade_21_)
___DEF_GLBL(___L6__23__23_thread_2d_effective_2d_priority_2d_downgrade_21_) ___SET_R1(___VOID) ___JUMPPRM(___NOTHING,___R0)