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)
