[gambit-list] Experiencing freeze error in |##thread-effective-priority-downgrade!| , a btq became self-referencing so all stops, any thoughts on how fix?

Mikael mikael.rcv at gmail.com
Thu May 2 20:05:13 EDT 2013


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)
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.iro.umontreal.ca/pipermail/gambit-list/attachments/20130503/b81928b3/attachment.htm>


More information about the Gambit-list mailing list