[gambit-list] Consistent, small program segmentation fault between 4.6.7 and 4.5.8

Mikael mikael.rcv at gmail.com
Fri Jun 7 18:12:29 EDT 2013


Awesome that you shared your take on this this directly! Brings valuable
perspective.

2013/6/6 Marc Feeley <feeley at iro.umontreal.ca>

>
> On Jun 4, 2013, at 9:15 AM, Marc Feeley <feeley at IRO.UMontreal.CA> wrote:
>
> >
> > On Jun 4, 2013, at 8:03 AM, Bradley Lucier <lucier at math.purdue.edu>
> wrote:
> >
> >> On 06/04/2013 10:06 AM, Marc Feeley wrote:
> >>> I will look into this today.  Could you try to add the -:m1 option to
> gsi to see if the problem goes away?
> >>
> >> No, fails in a similar place.  Sorry.
> >>
> >> Brad
> >
> > I thought I would document the steps I am taking to debug this issue so
> that others will have a debugging strategy if such an issue happens again.
> >
> > Step #1, I suspect there is a GC bug.  Why?  Because the bug seems to
> declare itself at different moments depending on what was loaded before,
> the previous REPL commands, the size of the heap, etc.
> >
> > Step #2, recompile Gambit with --enable-debug and with
> ENABLE_CONSISTENCY_CHECKS (this enables many different checks during the GC
> that things are as they should be, and it also adds a loop at the end of
> the GC to fill the freed space with the value #xCAFEBABE which is easy to
> notice)
> >
> > Step #3, run the program:
> >
> > % gsi/gsi -:d2 chud1.scm
> > …
> > | | | | | | | |[12] > (ch-split 27 30)
> > | | | | | | | |[13] > (ch-split 27 28)
> > *** ERROR IN ch-split, *** GC: 1 ms, 23.9M alloc, 3.08M heap, 234K live
> (7% 139520+100344)
> > "chud1.scm"@14.17 -- (Argument 1) NUMBER expected
> > (* #\U32bfaeaf #\U32bfaeaf 167)
> >
> > Now those values passed to * are wrong, but they look familiar…  hmmm
> >
> > % gsi/gsi -e "(pp (##encoding->object #xCAFEBABE))"
> > #\U32bfaeaf
> >
> > So it would seem that the GC is not tracing some values properly.
>
> Step #4, comment out "zap_section (start, end - start);" in lib/mem.c .
>  This is the call that stores #xCAFEBABE in the part of the stack that has
> been freed by the GC.  Running the program indicates that the bug is
> declaring itself differently:
>
> % gsi/gsi -:d2 chud1.scm
>> | | | | | | | |[14] (26317291 4082981841389223936000 1033313720108256587)
> | | | | | | | |[14] > (ch-split 72 73)
> | | | | | | | |[14] (27437045 4255479860553068544000 -1092236418414420595)
> | | | | | | | |[13] (722068697445095
> 1737504699703572570287350597957346918400...
> | | | | | | | |[13] > (ch-split 73 75)
> Segmentation fault: 11
>
> So it appears that the bug is in the tracing of the stack.
>
> Step #5, uncomment out the call to zap_section and run the program with
> debug level 3 (which dumps in the file "console" some detailed information
> about the layout of the Scheme stack and heap):
>
> % gsi/gsi -:d3 chud1.scm
>> | | | | | | | |[12] > (ch-split 27 30)
> | | | | | | | |[13] > (ch-split 27 28)
> *** ERROR IN ch-split, *** GC: 1 ms, 23.9M alloc, 3.08M heap, 234K live
> (7% 139520+100344)
> "chud1.scm"@14.17 -- (Argument 1) NUMBER expected
> (* #\U32bfaeaf #\U32bfaeaf 167)
> % tail -18 console
> heap_size          = 403697
> WORDS_OCCUPIED     = 29983
> avail              = 186857
> stack_avail        = 93428
> heap_avail         = 93429
> stack_msection     = 0x0b2f8008
> heap_msection      = 0x0b1f7008
> ___ps->stack_start = 0x0b3f8028
> ___ps->stack_break = 0x0b3f8008
> ___ps->fp          = 0x0b3f7e28
> alloc_stack_ptr    = 0x0b3f7e28
> ___ps->stack_limit = 0x0b388038
> alloc_stack_limit  = 0x0b378028
> alloc_heap_limit   = 0x0b2f7028
> ___ps->heap_limit  = 0x0b2e7018
> ___ps->hp          = 0x0b287ea8
> alloc_heap_ptr     = 0x0b287ea8
> alloc_heap_start   = 0x0b277028
>
> Those numbers seem to be OK.
>
> Step #6, I now suspect that there may be a bug in the Gambit compiler when
> it creates the GC map of live variables for stack frames.  The GC map
> indicates which slots in the stack frame contain a live Scheme object.
>  Each slot has a corresponding bit in the GC map.  A 1 means "live object"
> (GC must trace) and a 0 means "not live object" (GC must ignore).  If the
> GC map is not created properly by the Gambit compiler, the GC will not
> trace the stack properly.
>
> Step #7, I now doubt that it is a GC map problem.  If some slots have a 0
> where it should have been 1, the slot is still copied verbatim by the GC,
> it is just not traced.  In the test program, some bignums were replaced by
> #xCAFEBABE.  If it was a GC map problem, the reference would have been
> copied verbatim, which means there woud be a reference to the old space,
> which would have been zapped by #xCAFEBABE.  So the symptoms would have
> been different.  The references would have appeared as strange subtyped
> objects, not characters as we observed.  But I'm not 100% sure because the
> effect of memory corruption are hard to predict accurately.
>
> Step #8, the problem is clearly related to the GC of stack frames, so lets
> turn on SHOW_FRAMES to get a dump of all the stack frames visited by the
> GC.  This requires changing "#undef SHOW_FRAMES" to "#define SHOW_FRAMES"
> in lib/mem.c and recompiling.  Then:
>
> % gsi/gsi -:d3 chud1.scm
>> | | | | | | | |[11] > (ch-split 27 34)
> | | | | | | | |[12] > (ch-split 27 30)
> | | | | | | | |[13] > (ch-split 27 28)
> *** ERROR IN ch-split, Segmentation fault: 11
>
> The crash is now in the code enabled by SHOW_FRAMES, probably because some
> of the objects in the frames are garbage.  Indeed, at the end of the
> "console" file we see:
>
> continuation frame, fs=5 link=0 fp=0x068d3388 ra=0x063b7d81 #<return 1 in
> #<procedure ##dynamic-env-bind>> (first frame)
>    1: 0x063b7d01 #<return 12 in #<procedure ##kernel-handlers>>
>    2: 0x06968201 #<other ???>
> ___sFRAME object, fs=5 link=0 fp=0x067e5150 ra=0x064c0281 #<return 5 in
> #<procedure ##repl-within>>
>    1: #f
>    4: 0x06968339 #<other ???>
> ___sFRAME object, fs=5 link=3 fp=0x067e5188 ra=0x06443361 #<return 2 in
> #<procedure ##subproblem-apply3>>
>    1: 0x06768ed1 #<other ???>
>    2: 0x06968249 #<other ???>
>    4: #f
> ___sFRAME object, fs=9 link=2 fp=0x067e51c0 ra=0x06440f01 #<return 2 in
> #<procedure ##cprc-let>>
>    1: 0x06768851 #<other ???>
>    2: 0x06968249 "\376\377Y^Al^@p^@^H^@\366\377\234^@^H…
>
> The last frame wasn't printed completely.  Slot #2 is pointing to a bogus
> string, and the segmentation fault is probably occurring during the
> printing of that string.
>
> Note that the garbage collection where we get the segmentation fault is
> not the one we are interested in.  It is some garbage collection before
> that that is faulty (in other words, the "*** ERROR IN ch-split," that was
> output was due to the detection of an inconsistency after the previous
> garbage collection, and in the middle of printing the error message, the
> final garbage collection was performed which caused a segment violation).
>
> So lets look at the frames which were dumped at the previous garbage
> collection in the file "console".  We see for example:
>
> continuation frame, fs=9 link=1 fp=0x0c29ad88 ra=0x0bdaf481 #<return 103
> in #<procedure ##bignum.*>> (not first frame)
>    1: 41536
>    2: 0x0bdb04a1 #<return 85 in #<procedure ##bignum.div>>
>    3: 0x3387c231 #<other ???>
>    4: 0x3383f831 #<other ???>
>    5: 0x0c33d031 #<other ???>
>    7: 0x33862831 #<other ???>
>    8: 0x0c785031 #<other ???>
>    9: 0x0c441031 #<other ???>
>
> This isn't ideal for debugging because it would be good to see the type of
> the objects, instead of #<other ???>.
>
> Step #9, so the function print_subtyped in lib/mem.c must be extended with
> all the subtypes.  Now we observe something strange in the console file:
>
> continuation frame, fs=9 link=2 fp=0x0cc36de8 ra=0x0c817f01 #<return 2 in
> #<procedure ##cprc-let>> (not first frame)
>    1: 0x0cbd0e41 #<vector>
>    2: 0x0cbd29a1 #<u8vector>
>    3: 0x0c81a261 #<return 2 in #<procedure ##subproblem-apply1>>
>    4: 1
>    5: 1
>    6: ()
>
> This frame was created by the function ##cprc-let.  The function
> ##cprc-let is used in the implementation of the "let" form by the
> interpreter.  This frame is strange because there is a u8vector in slot 2.
>  Given that the test program does not use u8vectors and the u8vector has to
> be related to an interpreted let, it seems strange that a u8vector would
> pop up in that continuation frame.  Closer inspection of other frames
> indicates that slot 2 of other ##cprc-let continuation frames sometimes
> contains u8vectors, u32vectors, structures and strings.  I now think that
> slot 2 is probably a dead slot that has wrongly been marked as a live slot.
>  So that's the next thing to check.
>
> Step #10, after closer inspection it seems that this is due to a bug in
> the SHOW_FRAMES debugging code which does not correctly handle forwarded
> objects.  So I had to fix that bug.  Now slot 2 is reasonable (it is a
> #<vector> corresponding to the rte, i.e. run-time environment, used by the
> interpreter).  After fixing this bug, the program terminates as before, i.e.
>
> *** ERROR IN ch-split, *** GC: 13 ms, 23.9M alloc, 1.33M heap, 234K live
> (17% 139520+100344)
> "chud1.scm"@14.17 -- (Argument 1) NUMBER expected
> (* #\U32bfaeaf #\U32bfaeaf 167)
>
> Step #11, let's do some printf-style debugging.  The multiplication at
> line 14 of chud1.scm is receiving three parameters and the first two are
> garbage.  Let's find out when the garbage is introduced.  We can add some
> printfs directly in lib/_eval.c to print the content of the registers ___R0
> to ___R3 in which those parameters are passed.  The function in the
> interpreter that is calling * with 3 parameters is ##subproblem-apply3 .
>  So we add printfs like this:
>
> #undef ___PH_PROC
> #define ___PH_PROC ___H__23__23_subproblem_2d_apply3
> #undef ___PH_LBL0
> #define ___PH_LBL0 1920
> #undef ___PD_ALL
> #define ___PD_ALL ___D_FP ___D_R0 ___D_R1 ___D_R4
> #undef ___PR_ALL
> #define ___PR_ALL ___R_FP ___R_R0 ___R_R1 ___R_R4
> #undef ___PW_ALL
> #define ___PW_ALL ___W_FP ___W_R0 ___W_R1 ___W_R4
> ___BEGIN_P_COD
> ___BEGIN_P_HLBL
> ___DEF_P_HLBL_INTRO
> ___DEF_P_HLBL(___L0__23__23_subproblem_2d_apply3)
> ___DEF_P_HLBL(___L1__23__23_subproblem_2d_apply3)
> ___DEF_P_HLBL(___L2__23__23_subproblem_2d_apply3)
> ___END_P_HLBL
> ___BEGIN_P_SW
> ___DEF_SLBL(0,___L0__23__23_subproblem_2d_apply3)
>    ___IF_NARGS_EQ(6,___NOTHING)
>    ___WRONG_NARGS(0,6,0,0)
> ___DEF_GLBL(___L__23__23_subproblem_2d_apply3)
> printf("bbb r0=0x%08x r1=0x%08x r2=0x%08x
> r3=0x%08x\n",___R0,___R1,___R2,___R3);fflush(stdout);
>    ___SET_R4(___VECTORREF(___STK(-2),___FIX(4L)))
>    ___SET_R4(___VECTORREF(___R4,___FIX(1L)))
>    ___IF(___FALSEP(___R4))
>    ___GOTO(___L3__23__23_subproblem_2d_apply3)
>    ___END_IF
>    ___GOTO(___L4__23__23_subproblem_2d_apply3)
> ___DEF_SLBL(1,___L1__23__23_subproblem_2d_apply3)
>    ___IF_NARGS_EQ(6,___NOTHING)
>    ___WRONG_NARGS(1,6,0,0)
> ___DEF_GLBL(___L3__23__23_subproblem_2d_apply3)
>    ___SET_STK(1,___R0)
>    ___SET_R0(___LBL(2))
>    ___ADJFP(5)
> printf("ccc r0=0x%08x r1=0x%08x r2=0x%08x
> r3=0x%08x\n",___R0,___R1,___R2,___R3);fflush(stdout);
>    ___JUMPGENNOTSAFE(___SET_NARGS(3),___STK(-5))
> ___DEF_SLBL(2,___L2__23__23_subproblem_2d_apply3)
>    ___SET_R1(___R1)
>    ___ADJFP(-8)
>    ___JUMPPRM(___NOTHING,___STK(4))
> ___DEF_GLBL(___L4__23__23_subproblem_2d_apply3)
>    ___SET_STK(1,___STK(-2))
>    ___SET_STK(-2,___TRU)
>    ___SET_STK(2,___STK(-1))
>    ___SET_STK(-1,___STK(1))
>    ___SET_STK(1,___STK(0))
>    ___SET_STK(0,___STK(2))
>    ___SET_STK(2,___STK(1))
>    ___SET_STK(1,___LBL(1))
>    ___ADJFP(2)
>    ___JUMPGENNOTSAFE(___SET_NARGS(8),___R4)
> ___END_P_SW
> ___END_P_COD
>
> After a "make" we get:
>
> % gsi/gsi -:d3 chud1.scm
>> bbb r0=0x018ddf01 r1=0x0000028c r2=0x000000dc r3=0x0000029c
> ccc r0=0x018e0361 r1=0x0000028c r2=0x000000dc r3=0x0000029c
> *** ERROR IN ch-split, *** GC: 14 ms, 23.9M alloc, 3.08M heap, 234K live
> (7% 139520+100344)
> "chud1.scm"@14.17 -- (Argument 1) NUMBER expected
> (* #\U32bfaeaf #\U32bfaeaf 167)
>
> So the content of the registers r1, r2 and r3 appears to be correct (they
> contain fixnums to multiply).  Right up to the statement ___JUMPGENNOTSAFE
> which transfers control to *.
>
> Step #12, let's add a printf at the beginning of the multiplication
> function (in lib/_num.c) to see the content of the parameters:
>
> #undef ___PH_PROC
> #define ___PH_PROC ___H__2a_
> #undef ___PH_LBL0
> #define ___PH_LBL0 525
> #undef ___PD_ALL
> #define ___PD_ALL ___D_FP ___D_R0 ___D_R1 ___D_R2 ___D_R3
> #undef ___PR_ALL
> #define ___PR_ALL ___R_FP ___R_R0 ___R_R1 ___R_R2 ___R_R3
> #undef ___PW_ALL
> #define ___PW_ALL ___W_FP ___W_R0 ___W_R1 ___W_R2 ___W_R3
> ___BEGIN_P_COD
> ___BEGIN_P_HLBL
> ___DEF_P_HLBL_INTRO
> ___DEF_P_HLBL(___L0__2a_)
> ___DEF_P_HLBL(___L1__2a_)
> ___DEF_P_HLBL(___L2__2a_)
> ___DEF_P_HLBL(___L3__2a_)
> ___DEF_P_HLBL(___L4__2a_)
> ___DEF_P_HLBL(___L5__2a_)
> ___DEF_P_HLBL(___L6__2a_)
> ___DEF_P_HLBL(___L7__2a_)
> ___DEF_P_HLBL(___L8__2a_)
> ___DEF_P_HLBL(___L9__2a_)
> ___DEF_P_HLBL(___L10__2a_)
> ___DEF_P_HLBL(___L11__2a_)
> ___END_P_HLBL
> ___BEGIN_P_SW
> ___DEF_SLBL(0,___L0__2a_)
>    ___IF_NARGS_EQ(0,___SET_R1(___ABSENT) ___SET_R2(___ABSENT)
> ___SET_R3(___NUL))
>    ___IF_NARGS_EQ(1,___SET_R2(___ABSENT) ___SET_R3(___NUL))
>    ___IF_NARGS_EQ(2,___SET_R3(___NUL))
>    ___GET_REST(0,0,2,0)
> ___DEF_GLBL(___L__2a_)
> printf("ddd r0=0x%08x r1=0x%08x r2=0x%08x
> r3=0x%08x\n",___R0,___R1,___R2,___R3);fflush(stdout);
>    ___IF(___NOT(___EQP(___R2,___ABSENT)))
>    ___GOTO(___L16__2a_)
>    ___END_IF
>>
> After a "make" we get:
>
> % gsi/gsi -:d3 chud1.scm
>> bbb r0=0x0f80cf01 r1=0x0000028c r2=0x000000dc r3=0x0000029c
> ccc r0=0x0f80f361 r1=0x0000028c r2=0x000000dc r3=0x0000029c
> ddd r0=0x0f80f361 r1=0xcafebabe r2=0xcafebabe r3=0x0fd33273
> *** ERROR IN ch-split, *** GC: 15 ms, 23.9M alloc, 3.08M heap, 234K live
> (7% 139520+100344)
> "chud1.scm"@14.17 -- (Argument 1) NUMBER expected
> (* #\U32bfaeaf #\U32bfaeaf 167)
>
> Interesting… the parameters are changing between the jump to * and the
> body of * .  Note that the multiplication function is roughly equivalent to
>
> (define (* #!optional arg1 arg2 #!rest others) …)
>
> That's because * must support any number of arguments, but we want to
> avoid creating a rest parameter list in the very common case of 2 arguments.
>
> So the corruption is happening in the creation of the rest parameter.  The
> code that handles the creation of the rest parameter is defined in
> lib/_kernel.scm at label ___LBL(7).
>
> The code is non-trivial because it must handle the case where the free
> space in the heap is exhausted while the parameter list is being allocated.
>  When this happens, all the arguments are moved from the stack into a
> Scheme vector, a garbage collection is performed, and then the content of
> the vector is put back on the stack and the creation of the parameter list
> is resumed.  Note that the memory manager guarantees that there is always
> enough free space to allocate a Scheme vector for the maximum number of
> arguments, so it is unlikely that this is not the problem.
>
> So what is the problem?
>
> Step #13, closer inspection reveals that there's another bug in the
> SHOW_FRAMES debugging code which zaps sections of the stack with #xCAFEBABE
> that are still live.  After correcting that problem the program crashes at
> a completely different spot, so most of the line of debugging since step 3
> has been useless (except for fixing bugs in the debugging code).
>
> Time to take a break…
>
> Marc
>
> _______________________________________________
> Gambit-list mailing list
> Gambit-list at iro.umontreal.ca
> https://webmail.iro.umontreal.ca/mailman/listinfo/gambit-list
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.iro.umontreal.ca/pipermail/gambit-list/attachments/20130608/23b9676e/attachment.htm>


More information about the Gambit-list mailing list