Awesome that you shared your take on this this directly! Brings valuable perspective.<br><br><div class="gmail_quote">2013/6/6 Marc Feeley <span dir="ltr"><<a href="mailto:feeley@iro.umontreal.ca" target="_blank">feeley@iro.umontreal.ca</a>></span><br>

<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div class="im"><br>
On Jun 4, 2013, at 9:15 AM, Marc Feeley <<a href="mailto:feeley@IRO.UMontreal.CA">feeley@IRO.UMontreal.CA</a>> wrote:<br>
<br>
><br>
> On Jun 4, 2013, at 8:03 AM, Bradley Lucier <<a href="mailto:lucier@math.purdue.edu">lucier@math.purdue.edu</a>> wrote:<br>
><br>
>> On 06/04/2013 10:06 AM, Marc Feeley wrote:<br>
>>> I will look into this today.  Could you try to add the -:m1 option to gsi to see if the problem goes away?<br>
>><br>
>> No, fails in a similar place.  Sorry.<br>
>><br>
>> Brad<br>
><br>
> 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.<br>
><br>
> 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.<br>
><br>
> 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)<br>


><br>
> Step #3, run the program:<br>
><br>
> % gsi/gsi -:d2 chud1.scm<br>
> …<br>
> | | | | | | | |[12] > (ch-split 27 30)<br>
> | | | | | | | |[13] > (ch-split 27 28)<br>
> *** ERROR IN ch-split, *** GC: 1 ms, 23.9M alloc, 3.08M heap, 234K live (7% 139520+100344)<br>
> "chud1.scm"@14.17 -- (Argument 1) NUMBER expected<br>
> (* #\U32bfaeaf #\U32bfaeaf 167)<br>
><br>
> Now those values passed to * are wrong, but they look familiar…  hmmm<br>
><br>
> % gsi/gsi -e "(pp (##encoding->object #xCAFEBABE))"<br>
> #\U32bfaeaf<br>
><br>
> So it would seem that the GC is not tracing some values properly.<br>
<br>
</div>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:<br>


<div class="im"><br>
% gsi/gsi -:d2 chud1.scm<br>
…<br>
</div>| | | | | | | |[14] (26317291 4082981841389223936000 1033313720108256587)<br>
| | | | | | | |[14] > (ch-split 72 73)<br>
| | | | | | | |[14] (27437045 4255479860553068544000 -1092236418414420595)<br>
| | | | | | | |[13] (722068697445095 1737504699703572570287350597957346918400...<br>
| | | | | | | |[13] > (ch-split 73 75)<br>
Segmentation fault: 11<br>
<br>
So it appears that the bug is in the tracing of the stack.<br>
<br>
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):<br>
<br>
% gsi/gsi -:d3 chud1.scm<br>
<div class="im">…<br>
| | | | | | | |[12] > (ch-split 27 30)<br>
| | | | | | | |[13] > (ch-split 27 28)<br>
*** ERROR IN ch-split, *** GC: 1 ms, 23.9M alloc, 3.08M heap, 234K live (7% 139520+100344)<br>
"chud1.scm"@14.17 -- (Argument 1) NUMBER expected<br>
(* #\U32bfaeaf #\U32bfaeaf 167)<br>
</div>% tail -18 console<br>
heap_size          = 403697<br>
WORDS_OCCUPIED     = 29983<br>
avail              = 186857<br>
stack_avail        = 93428<br>
heap_avail         = 93429<br>
stack_msection     = 0x0b2f8008<br>
heap_msection      = 0x0b1f7008<br>
___ps->stack_start = 0x0b3f8028<br>
___ps->stack_break = 0x0b3f8008<br>
___ps->fp          = 0x0b3f7e28<br>
alloc_stack_ptr    = 0x0b3f7e28<br>
___ps->stack_limit = 0x0b388038<br>
alloc_stack_limit  = 0x0b378028<br>
alloc_heap_limit   = 0x0b2f7028<br>
___ps->heap_limit  = 0x0b2e7018<br>
___ps->hp          = 0x0b287ea8<br>
alloc_heap_ptr     = 0x0b287ea8<br>
alloc_heap_start   = 0x0b277028<br>
<br>
Those numbers seem to be OK.<br>
<br>
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.<br>


<br>
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.<br>


<br>
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:<br>


<br>
% gsi/gsi -:d3 chud1.scm<br>
…<br>
| | | | | | | |[11] > (ch-split 27 34)<br>
<div class="im">| | | | | | | |[12] > (ch-split 27 30)<br>
| | | | | | | |[13] > (ch-split 27 28)<br>
</div>*** ERROR IN ch-split, Segmentation fault: 11<br>
<br>
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:<br>
<br>
continuation frame, fs=5 link=0 fp=0x068d3388 ra=0x063b7d81 #<return 1 in #<procedure ##dynamic-env-bind>> (first frame)<br>
   1: 0x063b7d01 #<return 12 in #<procedure ##kernel-handlers>><br>
   2: 0x06968201 #<other ???><br>
___sFRAME object, fs=5 link=0 fp=0x067e5150 ra=0x064c0281 #<return 5 in #<procedure ##repl-within>><br>
   1: #f<br>
   4: 0x06968339 #<other ???><br>
___sFRAME object, fs=5 link=3 fp=0x067e5188 ra=0x06443361 #<return 2 in #<procedure ##subproblem-apply3>><br>
   1: 0x06768ed1 #<other ???><br>
   2: 0x06968249 #<other ???><br>
   4: #f<br>
___sFRAME object, fs=9 link=2 fp=0x067e51c0 ra=0x06440f01 #<return 2 in #<procedure ##cprc-let>><br>
   1: 0x06768851 #<other ???><br>
   2: 0x06968249 "\376\377Y^Al^@p^@^H^@\366\377\234^@^H…<br>
<br>
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.<br>
<br>
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).<br>


<br>
So lets look at the frames which were dumped at the previous garbage collection in the file "console".  We see for example:<br>
<br>
continuation frame, fs=9 link=1 fp=0x0c29ad88 ra=0x0bdaf481 #<return 103 in #<procedure ##bignum.*>> (not first frame)<br>
   1: 41536<br>
   2: 0x0bdb04a1 #<return 85 in #<procedure ##bignum.div>><br>
   3: 0x3387c231 #<other ???><br>
   4: 0x3383f831 #<other ???><br>
   5: 0x0c33d031 #<other ???><br>
   7: 0x33862831 #<other ???><br>
   8: 0x0c785031 #<other ???><br>
   9: 0x0c441031 #<other ???><br>
<br>
This isn't ideal for debugging because it would be good to see the type of the objects, instead of #<other ???>.<br>
<br>
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:<br>
<br>
continuation frame, fs=9 link=2 fp=0x0cc36de8 ra=0x0c817f01 #<return 2 in #<procedure ##cprc-let>> (not first frame)<br>
   1: 0x0cbd0e41 #<vector><br>
   2: 0x0cbd29a1 #<u8vector><br>
   3: 0x0c81a261 #<return 2 in #<procedure ##subproblem-apply1>><br>
   4: 1<br>
   5: 1<br>
   6: ()<br>
<br>
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.<br>


<br>
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.<br>


<br>
*** ERROR IN ch-split, *** GC: 13 ms, 23.9M alloc, 1.33M heap, 234K live (17% 139520+100344)<br>
<div class="im">"chud1.scm"@14.17 -- (Argument 1) NUMBER expected<br>
(* #\U32bfaeaf #\U32bfaeaf 167)<br>
<br>
</div>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:<br>


<br>
#undef ___PH_PROC<br>
#define ___PH_PROC ___H__23__23_subproblem_2d_apply3<br>
#undef ___PH_LBL0<br>
#define ___PH_LBL0 1920<br>
#undef ___PD_ALL<br>
#define ___PD_ALL ___D_FP ___D_R0 ___D_R1 ___D_R4<br>
#undef ___PR_ALL<br>
#define ___PR_ALL ___R_FP ___R_R0 ___R_R1 ___R_R4<br>
#undef ___PW_ALL<br>
#define ___PW_ALL ___W_FP ___W_R0 ___W_R1 ___W_R4<br>
___BEGIN_P_COD<br>
___BEGIN_P_HLBL<br>
___DEF_P_HLBL_INTRO<br>
___DEF_P_HLBL(___L0__23__23_subproblem_2d_apply3)<br>
___DEF_P_HLBL(___L1__23__23_subproblem_2d_apply3)<br>
___DEF_P_HLBL(___L2__23__23_subproblem_2d_apply3)<br>
___END_P_HLBL<br>
___BEGIN_P_SW<br>
___DEF_SLBL(0,___L0__23__23_subproblem_2d_apply3)<br>
   ___IF_NARGS_EQ(6,___NOTHING)<br>
   ___WRONG_NARGS(0,6,0,0)<br>
___DEF_GLBL(___L__23__23_subproblem_2d_apply3)<br>
printf("bbb r0=0x%08x r1=0x%08x r2=0x%08x r3=0x%08x\n",___R0,___R1,___R2,___R3);fflush(stdout);<br>
   ___SET_R4(___VECTORREF(___STK(-2),___FIX(4L)))<br>
   ___SET_R4(___VECTORREF(___R4,___FIX(1L)))<br>
   ___IF(___FALSEP(___R4))<br>
   ___GOTO(___L3__23__23_subproblem_2d_apply3)<br>
   ___END_IF<br>
   ___GOTO(___L4__23__23_subproblem_2d_apply3)<br>
___DEF_SLBL(1,___L1__23__23_subproblem_2d_apply3)<br>
   ___IF_NARGS_EQ(6,___NOTHING)<br>
   ___WRONG_NARGS(1,6,0,0)<br>
___DEF_GLBL(___L3__23__23_subproblem_2d_apply3)<br>
   ___SET_STK(1,___R0)<br>
   ___SET_R0(___LBL(2))<br>
   ___ADJFP(5)<br>
printf("ccc r0=0x%08x r1=0x%08x r2=0x%08x r3=0x%08x\n",___R0,___R1,___R2,___R3);fflush(stdout);<br>
   ___JUMPGENNOTSAFE(___SET_NARGS(3),___STK(-5))<br>
___DEF_SLBL(2,___L2__23__23_subproblem_2d_apply3)<br>
   ___SET_R1(___R1)<br>
   ___ADJFP(-8)<br>
   ___JUMPPRM(___NOTHING,___STK(4))<br>
___DEF_GLBL(___L4__23__23_subproblem_2d_apply3)<br>
   ___SET_STK(1,___STK(-2))<br>
   ___SET_STK(-2,___TRU)<br>
   ___SET_STK(2,___STK(-1))<br>
   ___SET_STK(-1,___STK(1))<br>
   ___SET_STK(1,___STK(0))<br>
   ___SET_STK(0,___STK(2))<br>
   ___SET_STK(2,___STK(1))<br>
   ___SET_STK(1,___LBL(1))<br>
   ___ADJFP(2)<br>
   ___JUMPGENNOTSAFE(___SET_NARGS(8),___R4)<br>
___END_P_SW<br>
___END_P_COD<br>
<br>
After a "make" we get:<br>
<br>
% gsi/gsi -:d3 chud1.scm<br>
…<br>
bbb r0=0x018ddf01 r1=0x0000028c r2=0x000000dc r3=0x0000029c<br>
ccc r0=0x018e0361 r1=0x0000028c r2=0x000000dc r3=0x0000029c<br>
*** ERROR IN ch-split, *** GC: 14 ms, 23.9M alloc, 3.08M heap, 234K live (7% 139520+100344)<br>
<div class="im">"chud1.scm"@14.17 -- (Argument 1) NUMBER expected<br>
(* #\U32bfaeaf #\U32bfaeaf 167)<br>
<br>
</div>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 *.<br>
<br>
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:<br>
<br>
#undef ___PH_PROC<br>
#define ___PH_PROC ___H__2a_<br>
#undef ___PH_LBL0<br>
#define ___PH_LBL0 525<br>
#undef ___PD_ALL<br>
#define ___PD_ALL ___D_FP ___D_R0 ___D_R1 ___D_R2 ___D_R3<br>
#undef ___PR_ALL<br>
#define ___PR_ALL ___R_FP ___R_R0 ___R_R1 ___R_R2 ___R_R3<br>
#undef ___PW_ALL<br>
#define ___PW_ALL ___W_FP ___W_R0 ___W_R1 ___W_R2 ___W_R3<br>
___BEGIN_P_COD<br>
___BEGIN_P_HLBL<br>
___DEF_P_HLBL_INTRO<br>
___DEF_P_HLBL(___L0__2a_)<br>
___DEF_P_HLBL(___L1__2a_)<br>
___DEF_P_HLBL(___L2__2a_)<br>
___DEF_P_HLBL(___L3__2a_)<br>
___DEF_P_HLBL(___L4__2a_)<br>
___DEF_P_HLBL(___L5__2a_)<br>
___DEF_P_HLBL(___L6__2a_)<br>
___DEF_P_HLBL(___L7__2a_)<br>
___DEF_P_HLBL(___L8__2a_)<br>
___DEF_P_HLBL(___L9__2a_)<br>
___DEF_P_HLBL(___L10__2a_)<br>
___DEF_P_HLBL(___L11__2a_)<br>
___END_P_HLBL<br>
___BEGIN_P_SW<br>
___DEF_SLBL(0,___L0__2a_)<br>
   ___IF_NARGS_EQ(0,___SET_R1(___ABSENT) ___SET_R2(___ABSENT) ___SET_R3(___NUL))<br>
   ___IF_NARGS_EQ(1,___SET_R2(___ABSENT) ___SET_R3(___NUL))<br>
   ___IF_NARGS_EQ(2,___SET_R3(___NUL))<br>
   ___GET_REST(0,0,2,0)<br>
___DEF_GLBL(___L__2a_)<br>
printf("ddd r0=0x%08x r1=0x%08x r2=0x%08x r3=0x%08x\n",___R0,___R1,___R2,___R3);fflush(stdout);<br>
   ___IF(___NOT(___EQP(___R2,___ABSENT)))<br>
   ___GOTO(___L16__2a_)<br>
   ___END_IF<br>
…<br>
<br>
After a "make" we get:<br>
<br>
% gsi/gsi -:d3 chud1.scm<br>
…<br>
bbb r0=0x0f80cf01 r1=0x0000028c r2=0x000000dc r3=0x0000029c<br>
ccc r0=0x0f80f361 r1=0x0000028c r2=0x000000dc r3=0x0000029c<br>
ddd r0=0x0f80f361 r1=0xcafebabe r2=0xcafebabe r3=0x0fd33273<br>
*** ERROR IN ch-split, *** GC: 15 ms, 23.9M alloc, 3.08M heap, 234K live (7% 139520+100344)<br>
<div class="im">"chud1.scm"@14.17 -- (Argument 1) NUMBER expected<br>
(* #\U32bfaeaf #\U32bfaeaf 167)<br>
<br>
</div>Interesting… the parameters are changing between the jump to * and the body of * .  Note that the multiplication function is roughly equivalent to<br>
<br>
(define (* #!optional arg1 arg2 #!rest others) …)<br>
<br>
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.<br>
<br>
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).<br>
<br>
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.<br>


<br>
So what is the problem?<br>
<br>
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).<br>


<br>
Time to take a break…<br>
<div class="HOEnZb"><div class="h5"><br>
Marc<br>
<br>
_______________________________________________<br>
Gambit-list mailing list<br>
<a href="mailto:Gambit-list@iro.umontreal.ca">Gambit-list@iro.umontreal.ca</a><br>
<a href="https://webmail.iro.umontreal.ca/mailman/listinfo/gambit-list" target="_blank">https://webmail.iro.umontreal.ca/mailman/listinfo/gambit-list</a><br>
</div></div></blockquote></div><br>