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)
Afficher les réponses par date
On 2013-05-02, at 8:05 PM, Mikael mikael.rcv@gmail.com wrote:
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?
Could you describe the threads that are running? Are they of different priorities, and if so, what are they?
Marc
P.S. For bugs like this, could you use the github issue tracker? It will simplify tracking the issue.
There's no priorities about any of the running threads, or any configuration beyond thunk, thread-name object and that it was started. The only thread operation beyond those two is thread-send and -receive.
Pasted and followed up on https://github.com/feeley/gambit/issues/17 , can continue there.
Thanks, Mikael
2013/5/3 Marc Feeley feeley@iro.umontreal.ca
Could you describe the threads that are running? Are they of different priorities, and if so, what are they?
Marc
P.S. For bugs like this, could you use the github issue tracker? It will simplify tracking the issue.