568615 - Collect(); Collect(); does not collect everything in Release builds

Status: VERIFIED WONTFIX

(Tamarin Graveyard :: Garbage Collection (mmGC), defect, P4)

Description

[Felix S. Klock II [:pnkfelix, :fklock]]

Attachment: exploratory code that uses finalizers to observe when collections occur

If we want to test things like weak references, we need a reliable way to perform full collections.

I am in the process of investigating a case where the Release build decides not to reclaim certain objects until much later than expected.

The problem is probably related to stale values being left in registers or on the stack, because switching gcc between -O0 and -O1 toggles the behavior.  I want to have a more complete answer than that, though.

To narrow the problem down, I first turned off all of the optimizations that I could _without_ going to -O0.  I also added a flag to stop gcc from reordering the generated units of code.  This all went into the Makefile generated via configure.py:

OPT_CXXFLAGS=-g -O -fno-defer-pop \
           -fno-guess-branch-probability -fno-cprop-registers \
           -fno-if-conversion -fno-if-conversion2 -fno-tree-ccp -fno-tree-dce \
           -fno-tree-dominator-opts -fno-tree-dse -fno-tree-ter -fno-tree-lrs \
           -fno-tree-sra -fno-tree-copyrename -fno-tree-fre -fno-tree-ch      \
           -fno-unit-at-a-time -fno-merge-constants \
           -fno-omit-frame-pointer \
           -fno-toplevel-reorder


I happen to have replicated the problem via a 64-bit build on Mac OS X, so that's why I selected that target above.  The attached self test produces the following output on my machine.

Note in particular that the object s05 is destructed while we are doing unrelated work in the first self test; ideally the destructor for s05 would occur during either the first collection (labelled 11 below; this is what happens in all the Debug builds I tried) or the second collection (labelled 12); but in fact the object is not reclaimed until after a third collection completes as well as a significant amount of allocation busywork is performed.

['start', 'mmgc', 'weakrefs']
['test', 'mmgc', 'weakrefs', 'hello_ff']
Named ctor for s05
 F ctor for f06
 F ctor for f07
s05 name: s05
collect: 11 a prime
~F dtor for f06
~F dtor for f07
collect: 12 b prefab
collect: 13 c prefab twice
fab start
fab finis
fab start
Named dtor for s05
fab finis
collect: 14 d postfab
collect: 15 e drain
['pass', 'mmgc', 'weakrefs', 'hello_ff']
['test', 'mmgc', 'weakrefs', 'hello_world']
Hello World
['pass', 'mmgc', 'weakrefs', 'hello_world']
['end', 'mmgc', 'weakrefs']

Comment 1

[Felix S. Klock II [:pnkfelix, :fklock]]

Attachment: exploratory code that uses finalizers to observe when collections occur

(i accidentally uploaded a version with a #define commented out; the behavior you get is "bad" with or without that particular #define, but to get the output I wrote in the bug description, I need to keep the #define in there.)

Comment 2

[Lars T Hansen]

Try calling Collect with 'false' as the argument.  (Use with care, but it might give you some data.)

Comment 3

[Felix S. Klock II [:pnkfelix, :fklock]]

Yes, turning off stack scanning causes the float to be collected.

I would still like to have a better understanding of what is happening here.

I have been wondering about why the inclusion of extra work (the "fab" stuff) would sometimes also force collection of the float.  I had thought that the changes induced by "fab" would not affect the presence of stale roots on the stack, but maybe that is incorrect.

Comment 4

[Felix S. Klock II [:pnkfelix, :fklock]]

(Note that also forcing the setup_test invocation to be emitted as out-of-line call also makes the problem go away completely, as noted in bug 569361.  I still don't quite understand how the inclusion of the "fab" extra work could be affecting when the float is collected.  For the meantime it seems sensible to write gc tests as long as we have ways to encapsulate the subroutine calls that generate float.)

Comment 5

[Felix S. Klock II [:pnkfelix, :fklock]]

(Widening doubt about my understanding of the problem  -- I am now seeing the behavior on a 32-bit Debug build *with* the no-inline directives applied to the setup_test method.)

Comment 6

[Felix S. Klock II [:pnkfelix, :fklock]]

Ah, I did not realize that one must explicitly call GC's CleanStack method to schedule a clearing out of values in old frames below the current stack pointer.

Comment 7

[Felix S. Klock II [:pnkfelix, :fklock]]

I just discovered how we implement VMPI_cleanStack.  What a marvelous hack!

(Unfortunately I'm starting to suspect its not doing what we want on Snow Leopard... stay tuned...)

Comment 8

[Felix S. Klock II [:pnkfelix, :fklock]]

(In reply to comment #7)
 
> (Unfortunately I'm starting to suspect its not doing what we want on Snow
> Leopard... stay tuned...)

Never mind; I think the bigger problem is that my simplistic test is not giving the GC an appropriate estimate of how much stack it should attempt to clear.  And/Or my simplistic test is not allowing a sufficient number of stack frames between the context of the float-generation and the context of the GC invocation(s).

Comment 9

[Felix S. Klock II [:pnkfelix, :fklock]]

tidbit: changeset:3184 (which makes REALLY_INLINE mean "well, I didn't *really* mean always..." on Mac Debug builds) could be making invocations of gc->CleanStack() less effective, since extra frames may be getting introduced between the client's invocation of the method and the final entry into VMPI_cleanStack.

Thinking about the problem of such intermediate stack frames: The interface to GC::CleanStack itself might need to be changed if you really want to get as much stack cleaning as possible.  For example, instead of returning void, it could return (via out parameters) a fcn ptr and a parameter for that fcn ptr, and then the client would be responsible for invoking the returned routine, thus eliminating one intermediate frame.

Then again, its not making any guarantees anyway, so that might be overkill.

Comment 10

[Felix S. Klock II [:pnkfelix, :fklock]]

Attachment: instrumentation of gc's stack-marking and cleaning

In order to better understand how the GC's stack cleaning and its conservative tracing of the stack roots work, I changed VMPI_cleanStack(amt) to tell me (via optional out param) what address it decided to clean, and added instrumentation all over the GC to tell me what its up to.

I will next upload a new version of my exploratory self-test and discussion of what the instrumentation tells us there.

Comment 11

[Felix S. Klock II [:pnkfelix, :fklock]]

Attachment: exploratory selftest that uses finalizers to observe when collections occur

Revised (but still misnamed) "weakrefs" selftest that still does nothing with weak-refs, since I am still exploring our stack cleaning/scanning behavior.

On a 64-bit Debug build on Mac OS X, the instrumentation I added in attachment 449675 [details] [diff] [review] illustrates that, for this code, the stack cleaning is useless.  (I've included the logging output at the end of the comment for reference; note that the particular addresses that you get can of course change from run-to-run, but the relative relationships between the addresses tends to be stable.)

In particular, DoMarkStack is marking the values in the range [0x5fbfe938, 0x5fbfeac0] (392 bytes), but the actual stack cleaning is zeroing out the (disjoint!) range [0x5fbfe880,0x5fbfe8c0] (64 bytes).

There are various reasons that this is happening:

1. The invocation gc->CleanStack has to get down to VMPI_cleanStack before any cleaning commences, and the stack frames pushed during those invocations are not eligible for cleaning.  (Note that this only addresses the issue that VMPI_cleanStack is starting from an address that is far far away from the stack top that the marker is using for its work.)  There's not much to do about this; the problem can be mitigated by forcing some of the intermediate procedures to be inlined (which might require expressing them as macros).  Or, since I am really only concerned about this for testing the GC, one can adopt the same hack that is used in GCTests.cpp : allocate some extra space on the stack before generating any intended garbage (_and_ pop that extra space before cleaning the stack; otherwise its pointless).

2a. I believe the rememberedStackTop used by CleanStack (and AFAICT, nothing else) is being incorrectly calculated, and that this is causing a gross underestimate of the stack area to be cleaned.  (This belief is based on investigations I did on Friday; I need to double-check this, but it should be easy enough to do.)

2b. Even if the calculation for rememberedStackTop were fixed, its value is only updated by invocations of the incremental marker, which is another source of potential underestimation.  (That assertion depends in practice on how often and in what contexts the incremental marker is invoked.)  I worked-around this on Friday by extending the gc interface with a function that the mutator can invoke to tell it to update the rememberedStackTop; my memory is that this, combined with fixing 2a, made the cleaning area a more reasonable size considering the stack roots that the marker traverses.

Log output follows:

['start', 'mmgc', 'weakrefs']
['test', 'mmgc', 'weakrefs', 'hello_ff']
where:                        setup_test_entry sp:0x5fbfea84
where:           setup_test_before_float_alloc sp:0x5fbfea84
Named ctor for s05
 F ctor for f06
 F ctor for f07
s05 addr: 0x01157060 loc: 0x5fbfea70
f06 addr: 0x01158060 loc: 0x5fbfea68
f07 addr: 0x01158070 loc: 0x5fbfea60
where:                     CollectLoudly entry sp:0x5fbfea9c
collect: 11 a prime &msg:0x5fbfea80
DoMarkFromStack(stackPointer=0x5fbfe938, gc) stackBase:0x5fbfeac0 rememberedStackTop:0x5fbfe938
[gc] set kQueued item:0x01157060 (0x01157060) p-1:0x5fbfea70
~F dtor for f06
~F dtor for f07
DoCleanStack(stackPointer=0x5fbfe978, gc) stackTop:0x5fbfe938 cleaned:[0x5fbfe880,0x5fbfe8c0]
where:                     CollectLoudly entry sp:0x5fbfea9c
collect: 12 b prefab &msg:0x5fbfea80
DoMarkFromStack(stackPointer=0x5fbfe938, gc) stackBase:0x5fbfeac0 rememberedStackTop:0x5fbfe938
[gc] set kQueued item:0x01157060 (0x01157060) p-1:0x5fbfea70
DoCleanStack(stackPointer=0x5fbfe978, gc) stackTop:0x5fbfe938 cleaned:[0x5fbfe880,0x5fbfe8c0]
where:                     CollectLoudly entry sp:0x5fbfea9c
collect: 13 c prefab twice &msg:0x5fbfea80
DoMarkFromStack(stackPointer=0x5fbfe938, gc) stackBase:0x5fbfeac0 rememberedStackTop:0x5fbfe938
[gc] set kQueued item:0x01157060 (0x01157060) p-1:0x5fbfea70
DoCleanStack(stackPointer=0x5fbfe978, gc) stackTop:0x5fbfe938 cleaned:[0x5fbfe880,0x5fbfe8c0]
fab start
fab finis
fab start
DoMarkFromStack(stackPointer=0x5fbfe318, gc) stackBase:0x5fbfeac0 rememberedStackTop:0x5fbfe938
[gc] set kQueued item:0x01268d00 (0x01268d00) p-1:0x5fbfe410
[gc] set kQueued item:0x01265f38 (0x01265f38) p-1:0x5fbfe470
[gc] set kQueued item:0x01268ca0 (0x01268ca0) p-1:0x5fbfe540
[gc] set kQueued item:0x01268cb8 (0x01268cb8) p-1:0x5fbfe548
[gc] set kQueued item:0x01268ce8 (0x01268ce8) p-1:0x5fbfe560
[gc] set kQueued item:0x01268790 (0x01268790) p-1:0x5fbfe6d0
[gc] set kQueued item:0x012687a8 (0x012687a8) p-1:0x5fbfe6d8
[gc] set kQueued item:0x01268ac0 (0x01268ac0) p-1:0x5fbfe6e0
[gc] set kQueued item:0x012679d0 (0x012679d0) p-1:0x5fbfe788
[gc] set kQueued item:0x012679e8 (0x012679e8) p-1:0x5fbfe7e8
[gc] set kQueued item:0x01004958 (0x01004958) p-1:0x5fbfe970
[gc] set kQueued item:0x01004970 (0x01004970) p-1:0x5fbfe978
[gc] set kQueued item:0x0125a118 (0x0125a118) p-1:0x5fbfe980
[gc] set kQueued item:0x011eb0e8 (0x011eb0e8) p-1:0x5fbfea28
[gc] set kQueued item:0x011eb100 (0x011eb100) p-1:0x5fbfea50
Named dtor for s05
fab finis
where:                     CollectLoudly entry sp:0x5fbfea9c
collect: 14 d postfab &msg:0x5fbfea80
DoMarkFromStack(stackPointer=0x5fbfe938, gc) stackBase:0x5fbfeac0 rememberedStackTop:0x5fbfe938
[gc] set kQueued item:0x0127b1c0 (0x0127b1c0) p-1:0x5fbfea98
DoCleanStack(stackPointer=0x5fbfe978, gc) stackTop:0x5fbfe938 cleaned:[0x5fbfe880,0x5fbfe8c0]
where:                     CollectLoudly entry sp:0x5fbfea9c
collect: 15 e drain &msg:0x5fbfea80
DoMarkFromStack(stackPointer=0x5fbfe938, gc) stackBase:0x5fbfeac0 rememberedStackTop:0x5fbfe938
[gc] set kQueued item:0x0127b1c0 (0x0127b1c0) p-1:0x5fbfea98
DoCleanStack(stackPointer=0x5fbfe978, gc) stackTop:0x5fbfe938 cleaned:[0x5fbfe880,0x5fbfe8c0]
['failure', 'mmgc', 'weakrefs', 'hello_ff', 'Named::dead_on_time', 'ST_mmgc_weakrefs.st', 366]
['test', 'mmgc', 'weakrefs', 'hello_world']
Hello World
['pass', 'mmgc', 'weakrefs', 'hello_world']
['end', 'mmgc', 'weakrefs']

Comment 12

[Felix S. Klock II [:pnkfelix, :fklock]]

Attachment: exploratory selftest that uses finalizers to observe when collections occur

(Sorry, the previous upload took the form of a patch, but it was a patch against a version of the repository containing a file that is not actually in tamarin-redux, so it was not helpful.)  Uploading the whole file now.

Comment 13

[Felix S. Klock II [:pnkfelix, :fklock]]

Lars says that we really cannot guarantee that any one object (or small set of them) is reclaimed/reaped, so it is a mistake to try to test that condition.  He recommends instead using a statistical testing strategy: check that N% of the garbage is reclaimed, for some large N.

Comment 14

[Felix S. Klock II [:pnkfelix, :fklock]]

Also, on the correctness of rememberedStackTop: the logic used to match what I think it should be, but Tommy inverted it in changeset:1975.  It might have been an accident, or it might have been deliberate:

                // this is where we will clear to when CleanStack is called
-               if(rememberedStackTop == 0 || rememberedStackTop > item.ptr) {
+               if(rememberedStackTop < item.ptr) {
                        rememberedStackTop = item.ptr;
                }


 (Perhaps he misread it and thought he was simplifying the code?)

Comment 15

[Felix S. Klock II [:pnkfelix, :fklock]]

Attachment: instrumentation of gc's stack-marking and cleaning

Revised, cleaned up, reduced and clarified log output.

Comment 16

[Felix S. Klock II [:pnkfelix, :fklock]]

Attachment: exploratory selftest that uses finalizers to observe when collections occur

FIxed up to take form of patch against tree.  Will be attaching newish log soon.

Comment 17

[Felix S. Klock II [:pnkfelix, :fklock]]

Attachment: Macro-based variant of CleanStack

After discussion in asteam channel, decided to try a macro-based stack cleaner.  This is a hack, but as far as I can tell, all of our stack cleaning is a hack.  (A nifty hack, but nonetheless...)

I've pasted the current log below.  Hopefully with the cleanup I applied to an earlier patch, its easier to see what I have been talking about in this ticket: 

1. The macro variant (MMGC_CLEANSTACK) manages to scrub much closer to the stack base at the point of invocation (272 bytes rather than 96), and most importantly, manages to overlap some of the area that the marker actually scans, which is much more difficult for gc->CleanStack().  Note that the whole exercise of trying to CleanStack is pointless if the cleaned and scanned areas don't overlap at all.  In fact I'd go so far as to suggest that VMPI_cleanStack be extended to accept the addresses that we are targeting, so that it can alter its memset invocation to only clear the subrange that it managed to cover in its alloca() invocation.

2. The log clearly indicates that the rememberedStackTop (which I have taken to calling the peak) remains at 0xbfffebd8 throughout the run (corresponding to the tip of the stack at the first invocation of the marker, when it covers [0xbfffebd8,0xbfffed3c]), _despite_ the fact that the marker at one point covers the range [0xbfffe628,0xbfffed3c]: the tip of the stack has clearly gone beyond the remembered top, and the marker even has observed it, but subsequent cleanings continue to restrain themselves to a smaller area.

(There are different fixes for the latter, but they were not terribly effective/interesting until I made the macro-variant of the stack cleaner.)

Here's the log:

['start', 'mmgc', 'weakrefs']
['test', 'mmgc', 'weakrefs', 'hello_ff']
where:                        setup_test_entry sp:0xbfffecf4
where:           setup_test_before_float_alloc sp:0xbfffecf4
Named ctor for s05
 F ctor for f06
 F ctor for f07
s05 addr: 0x0050b048 loc: 0xbfffecf0
f06 addr: 0x0050c048 loc: 0xbfffecec
f07 addr: 0x0050c060 loc: 0xbfffece8
where:                     CollectLoudly entry sp:0xbfffecfc
collect: 11 a prime &msg:0xbfffed14
DoMarkFromStack                                 marked:[0xbfffebd8,0xbfffed3c] = 356
DoCleanStack sp:0xbfffec38 stackTop:0xbfffebd8 cleaned:[0xbfffeb40,0xbfffeba0] = 96
MMGC_CLEANSTACK tip:0xbfffece8 peak:0xbfffebd8 cleaned:[0xbfffeb60,0xbfffec70] = 272
where:                     CollectLoudly entry sp:0xbfffecfc
collect: 12 b prefab &msg:0xbfffed14
DoMarkFromStack                                 marked:[0xbfffebd8,0xbfffed3c] = 356
~F dtor for f06
~F dtor for f07
Named dtor for s05
DoCleanStack sp:0xbfffec38 stackTop:0xbfffebd8 cleaned:[0xbfffeb40,0xbfffeba0] = 96
MMGC_CLEANSTACK tip:0xbfffece8 peak:0xbfffebd8 cleaned:[0xbfffeb60,0xbfffec70] = 272
where:                     CollectLoudly entry sp:0xbfffecfc
collect: 13 c prefab twice &msg:0xbfffed14
DoMarkFromStack                                 marked:[0xbfffebd8,0xbfffed3c] = 356
DoCleanStack sp:0xbfffec38 stackTop:0xbfffebd8 cleaned:[0xbfffeb40,0xbfffeba0] = 96
MMGC_CLEANSTACK tip:0xbfffece8 peak:0xbfffebd8 cleaned:[0xbfffeb60,0xbfffec70] = 272
fab start
fab finis
fab start
DoMarkFromStack                                 marked:[0xbfffe628,0xbfffed3c] = 1812
fab finis
where:                     CollectLoudly entry sp:0xbfffecfc
collect: 14 d postfab &msg:0xbfffed14
DoMarkFromStack                                 marked:[0xbfffebd8,0xbfffed3c] = 356
DoCleanStack sp:0xbfffec38 stackTop:0xbfffebd8 cleaned:[0xbfffeb40,0xbfffeba0] = 96
MMGC_CLEANSTACK tip:0xbfffece8 peak:0xbfffebd8 cleaned:[0xbfffeb60,0xbfffec70] = 272
where:                     CollectLoudly entry sp:0xbfffecfc
collect: 15 e drain &msg:0xbfffed14
DoMarkFromStack                                 marked:[0xbfffebd8,0xbfffed3c] = 356
DoCleanStack sp:0xbfffec38 stackTop:0xbfffebd8 cleaned:[0xbfffeb40,0xbfffeba0] = 96
MMGC_CLEANSTACK tip:0xbfffece8 peak:0xbfffebd8 cleaned:[0xbfffeb60,0xbfffec70] = 272
['pass', 'mmgc', 'weakrefs', 'hello_ff']
['test', 'mmgc', 'weakrefs', 'hello_world']
Hello World
['pass', 'mmgc', 'weakrefs', 'hello_world']
['end', 'mmgc', 'weakrefs']

Comment 18

[Felix S. Klock II [:pnkfelix, :fklock]]

Attachment: reverts to prior rememberedStackTop update logic

This reverts a change introduced as part of changeset:1975 (see comment 14).

With this in place, the log output is as follows (note that the stack clean area increases when the marker observes that we've seen a deeper stack; that's good.  However, subsequent stack cleanings keep scrubbing the larger area, even if we have not gotten that deep since the last cleaning -- that might be bad.  The mmgc developers may need to discuss.):

['start', 'mmgc', 'weakrefs']
['test', 'mmgc', 'weakrefs', 'hello_ff']
where:                        setup_test_entry sp:0xbfffecf4
where:           setup_test_before_float_alloc sp:0xbfffecf4
Named ctor for s05
 F ctor for f06
 F ctor for f07
s05 addr: 0x0050b048 loc: 0xbfffecf0
f06 addr: 0x0050c048 loc: 0xbfffecec
f07 addr: 0x0050c060 loc: 0xbfffece8
where:                     CollectLoudly entry sp:0xbfffecfc
collect: 11 a prime &msg:0xbfffed14
DoMarkFromStack                                 marked:[0xbfffebd8,0xbfffed3c] = 356
DoCleanStack sp:0xbfffec38 stackTop:0xbfffebd8 cleaned:[0xbfffeb40,0xbfffeba0] = 96
MMGC_CLEANSTACK tip:0xbfffece8 peak:0xbfffebd8 cleaned:[0xbfffeb60,0xbfffec70] = 272
where:                     CollectLoudly entry sp:0xbfffecfc
collect: 12 b prefab &msg:0xbfffed14
DoMarkFromStack                                 marked:[0xbfffebd8,0xbfffed3c] = 356
~F dtor for f06
~F dtor for f07
Named dtor for s05
DoCleanStack sp:0xbfffec38 stackTop:0xbfffebd8 cleaned:[0xbfffeb40,0xbfffeba0] = 96
MMGC_CLEANSTACK tip:0xbfffece8 peak:0xbfffebd8 cleaned:[0xbfffeb60,0xbfffec70] = 272
where:                     CollectLoudly entry sp:0xbfffecfc
collect: 13 c prefab twice &msg:0xbfffed14
DoMarkFromStack                                 marked:[0xbfffebd8,0xbfffed3c] = 356
DoCleanStack sp:0xbfffec38 stackTop:0xbfffebd8 cleaned:[0xbfffeb40,0xbfffeba0] = 96
MMGC_CLEANSTACK tip:0xbfffece8 peak:0xbfffebd8 cleaned:[0xbfffeb60,0xbfffec70] = 272
fab start
fab finis
fab start
DoMarkFromStack                                 marked:[0xbfffe628,0xbfffed3c] = 1812
fab finis
where:                     CollectLoudly entry sp:0xbfffecfc
collect: 14 d postfab &msg:0xbfffed14
DoMarkFromStack                                 marked:[0xbfffebd8,0xbfffed3c] = 356
DoCleanStack sp:0xbfffec38 stackTop:0xbfffe628 cleaned:[0xbfffe590,0xbfffeba0] = 1552
MMGC_CLEANSTACK tip:0xbfffece8 peak:0xbfffe628 cleaned:[0xbfffe5b0,0xbfffec70] = 1728
where:                     CollectLoudly entry sp:0xbfffecfc
collect: 15 e drain &msg:0xbfffed14
DoMarkFromStack                                 marked:[0xbfffebd8,0xbfffed3c] = 356
DoCleanStack sp:0xbfffec38 stackTop:0xbfffe628 cleaned:[0xbfffe590,0xbfffeba0] = 1552
MMGC_CLEANSTACK tip:0xbfffece8 peak:0xbfffe628 cleaned:[0xbfffe5b0,0xbfffec70] = 1728
['pass', 'mmgc', 'weakrefs', 'hello_ff']
['test', 'mmgc', 'weakrefs', 'hello_world']
Hello World
['pass', 'mmgc', 'weakrefs', 'hello_world']
['end', 'mmgc', 'weakrefs']

Comment 19

[Felix S. Klock II [:pnkfelix, :fklock]]

(as indicated in comment 13, we cannot guarantee/test the reclamation of small group of garbage objects, so I am not suggesting that the selftest of attachment 449926 [details] [diff] [review] actually be used as the basis for a real self-test.  But hopefully the logs in comment 17 and comment 18, despite coming from a transient example, serve as reasonable justification for doing something about CleanStack.)

Comment 20

[Felix S. Klock II [:pnkfelix, :fklock]]

FYI, after applying attachment 449934 [details] [diff] [review] (the revert to prior update logic), If I disable the MMGC_CLEANSTACK invocations in the selftest, the selftest fails for both 32-bit and 64-bit debug builds.  So without a version of clean stack that does not add so many extra frames before cleaning, the choice update logic is moot for this self-test.

Here are the relevant logs:

32-bit
------

['start', 'mmgc', 'weakrefs']
['test', 'mmgc', 'weakrefs', 'hello_ff']
where:                        setup_test_entry sp:0xbfffecd4
where:           setup_test_before_float_alloc sp:0xbfffecd4
Named ctor for s05
 F ctor for f06
 F ctor for f07
s05 addr: 0x0050b048 loc: 0xbfffecd0
f06 addr: 0x0050c048 loc: 0xbfffeccc
f07 addr: 0x0050c060 loc: 0xbfffecc8
where:                     CollectLoudly entry sp:0xbfffecdc
collect: 11 a prime &msg:0xbfffecf4
DoMarkFromStack                                 marked:[0xbfffebd8,0xbfffed1c] = 324
~F dtor for f06
DoCleanStack sp:0xbfffec38 stackTop:0xbfffebd8 cleaned:[0xbfffeb40,0xbfffeba0] = 96
where:                     CollectLoudly entry sp:0xbfffecdc
collect: 12 b prefab &msg:0xbfffecf4
DoMarkFromStack                                 marked:[0xbfffebd8,0xbfffed1c] = 324
DoCleanStack sp:0xbfffec38 stackTop:0xbfffebd8 cleaned:[0xbfffeb40,0xbfffeba0] = 96
where:                     CollectLoudly entry sp:0xbfffecdc
collect: 13 c prefab twice &msg:0xbfffecf4
DoMarkFromStack                                 marked:[0xbfffebd8,0xbfffed1c] = 324
DoCleanStack sp:0xbfffec38 stackTop:0xbfffebd8 cleaned:[0xbfffeb40,0xbfffeba0] = 96
fab start
fab finis
fab start
DoMarkFromStack                                 marked:[0xbfffe6a8,0xbfffed1c] = 1652
~F dtor for f07
fab finis
where:                     CollectLoudly entry sp:0xbfffecdc
collect: 14 d postfab &msg:0xbfffecf4
DoMarkFromStack                                 marked:[0xbfffebd8,0xbfffed1c] = 324
DoCleanStack sp:0xbfffec38 stackTop:0xbfffe6a8 cleaned:[0xbfffe610,0xbfffeba0] = 1424
where:                     CollectLoudly entry sp:0xbfffecdc
collect: 15 e drain &msg:0xbfffecf4
DoMarkFromStack                                 marked:[0xbfffebd8,0xbfffed1c] = 324
DoCleanStack sp:0xbfffec38 stackTop:0xbfffe6a8 cleaned:[0xbfffe610,0xbfffeba0] = 1424
['failure', 'mmgc', 'weakrefs', 'hello_ff', 'Named::dead_on_time', 'ST_mmgc_weakrefs.st', 387]
['test', 'mmgc', 'weakrefs', 'hello_world']
Hello World
['pass', 'mmgc', 'weakrefs', 'hello_world']
Named dtor for s05
['end', 'mmgc', 'weakrefs']


64-bit
------

['start', 'mmgc', 'weakrefs']
['test', 'mmgc', 'weakrefs', 'hello_ff']
where:                        setup_test_entry sp:0x5fbfea64
where:           setup_test_before_float_alloc sp:0x5fbfea64
Named ctor for s05
 F ctor for f06
 F ctor for f07
s05 addr: 0x01157060 loc: 0x5fbfea50
f06 addr: 0x01158060 loc: 0x5fbfea48
f07 addr: 0x01158070 loc: 0x5fbfea40
where:                     CollectLoudly entry sp:0x5fbfea7c
collect: 11 a prime &msg:0x5fbfea60
DoMarkFromStack                                 marked:[0x5fbfe918,0x5fbfeaa0] = 392
~F dtor for f06
~F dtor for f07
DoCleanStack sp:0x5fbfe958 stackTop:0x5fbfe918 cleaned:[0x5fbfe860,0x5fbfe8a0] = 64
where:                     CollectLoudly entry sp:0x5fbfea7c
collect: 12 b prefab &msg:0x5fbfea60
DoMarkFromStack                                 marked:[0x5fbfe918,0x5fbfeaa0] = 392
DoCleanStack sp:0x5fbfe958 stackTop:0x5fbfe918 cleaned:[0x5fbfe860,0x5fbfe8a0] = 64
where:                     CollectLoudly entry sp:0x5fbfea7c
collect: 13 c prefab twice &msg:0x5fbfea60
DoMarkFromStack                                 marked:[0x5fbfe918,0x5fbfeaa0] = 392
DoCleanStack sp:0x5fbfe958 stackTop:0x5fbfe918 cleaned:[0x5fbfe860,0x5fbfe8a0] = 64
fab start
fab finis
fab start
DoMarkFromStack                                 marked:[0x5fbfe2f8,0x5fbfeaa0] = 1960
Named dtor for s05
fab finis
where:                     CollectLoudly entry sp:0x5fbfea7c
collect: 14 d postfab &msg:0x5fbfea60
DoMarkFromStack                                 marked:[0x5fbfe918,0x5fbfeaa0] = 392
DoCleanStack sp:0x5fbfe958 stackTop:0x5fbfe2f8 cleaned:[0x5fbfe240,0x5fbfe8a0] = 1632
where:                     CollectLoudly entry sp:0x5fbfea7c
collect: 15 e drain &msg:0x5fbfea60
DoMarkFromStack                                 marked:[0x5fbfe918,0x5fbfeaa0] = 392
DoCleanStack sp:0x5fbfe958 stackTop:0x5fbfe2f8 cleaned:[0x5fbfe240,0x5fbfe8a0] = 1632
['failure', 'mmgc', 'weakrefs', 'hello_ff', 'Named::dead_on_time', 'ST_mmgc_weakrefs.st', 387]
['test', 'mmgc', 'weakrefs', 'hello_world']
Hello World
['pass', 'mmgc', 'weakrefs', 'hello_world']
['end', 'mmgc', 'weakrefs']

Comment 21

[Felix S. Klock II [:pnkfelix, :fklock]]

Filed bug 570965 for future effort to make statistical selftest of gc effectiveness at reclaiming dead objects (and thus form basis of testing e.g. weak references).

Comment 22

[Felix S. Klock II [:pnkfelix, :fklock]]

(In reply to comment #17)
> [...] Note that the whole
> exercise of trying to CleanStack is pointless if the cleaned and scanned areas
> don't overlap at all.  In fact I'd go so far as to suggest that VMPI_cleanStack
> be extended to accept the addresses that we are targeting, so that it can alter
> its memset invocation to only clear the subrange that it managed to cover in
> its alloca() invocation.

The (questionable) value of implementing this suggestion is tied to what the point of CleanStack is supposed to be.

Note that since we precisely track stack extent for the marker's scanning, cleaning the stack is only useful for dealing with false retention due to _future_ stack frames that are allocated but not overwritten.  The invocations of CleanStack are only making predictions about the programs future behavior; they are not going to do anything about the context already in place at the time that CleanStack is allocated.

So, passing precise addresses holding a known past stack extent to VMPI_cleanStack (and then using that to narrow the scope of the cleaning) is only useful if the past stack extent is a reasonable predictor of the stack extent that will be in place at some future invocation of the marker's stack scanning.

(In short, making the interface to VMPI_cleanStack more complicated while not providing any more guarantees about its behavior does not seem like much of a win.  The only motivation I have left for passing the known stack extent would be if we find out that we are spending significant time in the memset invocations in VMPI_cleanStack, but that seems really unlikely.  So I am going to withdraw that particular suggestion for now.)

Comment 23

[Felix S. Klock II [:pnkfelix, :fklock]]

(I am not working on this bug anymore, but I do not want to close it until I get a chance to talk to Tommy about comment 14 above when he's back.)

Comment 24

[Tommy Reilly]

(In reply to comment #14)
> Also, on the correctness of rememberedStackTop: the logic used to match what I
> think it should be, but Tommy inverted it in changeset:1975.  It might have
> been an accident, or it might have been deliberate:
> 
>                 // this is where we will clear to when CleanStack is called
> -               if(rememberedStackTop == 0 || rememberedStackTop > item.ptr) {
> +               if(rememberedStackTop < item.ptr) {
>                         rememberedStackTop = item.ptr;
>                 }
> 
> 
>  (Perhaps he misread it and thought he was simplifying the code?)

Stacks grow down right so < is correct I think

Comment 25

[Felix S. Klock II [:pnkfelix, :fklock]]

(In reply to comment #24)
> (In reply to comment #14)
> > Also, on the correctness of rememberedStackTop: the logic used to match what I
> > think it should be, but Tommy inverted it in changeset:1975.  It might have
> > been an accident, or it might have been deliberate:
> > 
> >                 // this is where we will clear to when CleanStack is called
> > -               if(rememberedStackTop == 0 || rememberedStackTop > item.ptr) {
> > +               if(rememberedStackTop < item.ptr) {
> >                         rememberedStackTop = item.ptr;
> >                 }
> > 
> > 
> >  (Perhaps he misread it and thought he was simplifying the code?)
> 
> Stacks grow down right so < is correct I think

Isn't the code trying to remember the *deepest* point that the stack ever reaches [1]?  And therefore, if the ptr is *less* than the remembered value, then you should update the remembered value?  (That is, I'm not disputing the direction that the stack grows, but rather what rememberedStackTop is for... this may also be a case of the name of rememberedStackTop being poorly chosen)

See also the notes in comment 18 above.  (I apologize for the obtuseness of the output there; come by if you want me to decode it...)

[1] Look at GC::DoCleanStack: there, I believe the intention is that the actual sp reg at the time of call is high (ie somewhere around the base of the stack), and the code is trying to clear out all of the stack frames below on the stack.  But the code as written only works if rememberedStackTop is tracking the deepest point.

Comment 26

[Tommy Reilly]

Right I think I was switching the two sides in my head.   We want to record item.ptr when it is smaller than rememberedStackTop so my change was indeed bogus.

Comment 27

[Felix S. Klock II [:pnkfelix, :fklock]]

(In reply to comment #26)
> Right I think I was switching the two sides in my head.   We want to record
> item.ptr when it is smaller than rememberedStackTop so my change was indeed
> bogus.

Created follow up Bug 591999.

Closing this as "WONTFIX", since we do not guarantee collection completeness and I do not see adding that anytime soon.

Comment 28

[Trevor Baker]

bulk verifying resolved !fixed issues