Closed Bug 1001678 Opened 10 years ago Closed 10 years ago

[jsdbg2] Implement an allocation log for Debugger.Memory

Categories

(Core :: JavaScript Engine, defect)

x86
macOS
defect
Not set
normal

Tracking

()

RESOLVED FIXED
mozilla34

People

(Reporter: fitzgen, Assigned: fitzgen)

References

Details

Attachments

(2 files, 10 obsolete files)

1.50 KB, patch
jimb
: review+
Details | Diff | Splinter Review
34.24 KB, patch
fitzgen
: review+
Details | Diff | Splinter Review
This should be a bounded log of object allocations. It should be stored on and exposed via |Debugger.Memory.prototype.allocationsLog|.

We can modify the saved stacks metadata callback to insert into this log by finding the appropriate debugger instances for its object's compartment via this vector: https://hg.mozilla.org/mozilla-central/file/09a19b25b9cf/js/src/vm/GlobalObject.h#l661
Assignee: nobody → nfitzgerald
Status: NEW → ASSIGNED
Attached patch WIP (obsolete) — Splinter Review
Compiles, but I'm getting an assertion error when I run the test:

Assertion failure: *stack == reinterpret_cast<Rooted<void*>*>(this), at ../../dist/include/js/RootingAPI.h:792

Which is the assertion here:

> ~Rooted() {
>     MOZ_ASSERT(*stack == reinterpret_cast<Rooted<void*>*>(this));
>     *stack = prev;
> }
Terrence, can you tell me what type of mistake I'm likely making that causes the above assertion to fail?
Flags: needinfo?(terrence)
Never mind, it looks like I need to use Heap<T> rather than Rooted<T> in this case.
Flags: needinfo?(terrence)
Got it working! No try push or review yet, because I need to get a green try push for bug 993085 first.
Attachment #8424370 - Attachment is obsolete: true
Rebased on top of the new patch for bug 993085 and the API changes it introduced.

https://tbpl.mozilla.org/?tree=Try&rev=12f76b72e1b3
Attachment #8424461 - Attachment is obsolete: true
Attachment #8437278 - Flags: review?(jimb)
Fix bad header include order.

https://tbpl.mozilla.org/?tree=Try&rev=2482adf8dfa9
Attachment #8437278 - Attachment is obsolete: true
Attachment #8437278 - Flags: review?(jimb)
Attachment #8437309 - Flags: review?(jimb)
Working on a second patch that provides docs.
Also interested in what a good value for MAX_ALLOCATIONS_LOG_LENGTH might be. I just pulled the existing value out of thin air.
Attachment #8437309 - Attachment description: debugger-memory-allocations-log.patch → Part 1: Implement Debugger.Memory.prototype.flushAllocationsLog
Attachment #8442471 - Attachment description: allocations-log-docs.patch → Part 2: Docs for Debugger.Memory.prototype.flushAllocationsLog
Rebased.

New try push: https://tbpl.mozilla.org/?tree=Try&rev=a8bbf99910c5
Attachment #8437309 - Attachment is obsolete: true
Attachment #8442471 - Attachment is obsolete: true
Attachment #8437309 - Flags: review?(jimb)
Attachment #8442471 - Flags: review?(jimb)
Attachment #8456395 - Flags: review?(jimb)
Docs.
Attachment #8456396 - Flags: review?(jimb)
Would it work to simply allocate an array JSObject to hold the log, and push entries on the end of it? Then the function to retrieve the log could just hand out that array.

We'd need to make sure to allocate the array in the Debugger's compartment, and the elements would need to be wrapped, but that's unavoidable: the debugger compartment can't refer to SavedStack objects directly, so they'll each get wrapped by the time the debugger actually looks at them.
Comment on attachment 8456396 [details] [diff] [review]
debugger-memory-allocations-log-part-2.patch

Review of attachment 8456396 [details] [diff] [review]:
-----------------------------------------------------------------

::: js/src/doc/Debugger/Debugger.Memory.md
@@ +29,5 @@
> +:   When `trackingAllocationSites` is `true`, this method returns an array of
> +    allocation sites (as [captured stacks][saved-frame]) for recent `Object`
> +    allocations within the set of debuggees. *Recent* is defined as the *n* most
> +    recent `Object` allocations since the last call to `flushAllocationsLog`,
> +    where *n* is up to the implementation to define.

This doesn't explain that calling the method clears the log.

If one takes the indeterminate size of the log seriously, it makes the feature hard to use. We should let the caller specify a limit on the log size.

The term "flush" is used for functions that write buffered data, but this function reads data. How about 'readAllocationLog'?

This is a polling-only interface. When we try to use this API, it may be a problem that SpiderMonkey has no way to indicate to the debugger that the log has gone from empty to having some entries; or is about to fill up.
Comment on attachment 8456395 [details] [diff] [review]
debugger-memory-allocations-log-part-1.patch

Review of attachment 8456395 [details] [diff] [review]:
-----------------------------------------------------------------

::: js/src/vm/DebuggerMemory.h
@@ +34,5 @@
> +        RelocatablePtrObject frame;
> +    };
> +    typedef mozilla::LinkedList<AllocationSite> AllocationSiteList;
> +  private:
> +    AllocationSiteList  *getAllocationsLog();

Instead of introducing a new type with custom tracing, I think we should use an ordinary array JSObject to hold the log, and use its 'push' method. If we make this a HeapPtrObject member of js::Debugger, not js::DebuggerMemory, then tracing it is simply a matter of adding a line to js::Debugger::trace.
Attachment #8456395 - Flags: review?(jimb)
Attachment #8456396 - Flags: review?(jimb)
(In reply to Jim Blandy :jimb from comment #14)
> Comment on attachment 8456395 [details] [diff] [review]
> debugger-memory-allocations-log-part-1.patch
> 
> Review of attachment 8456395 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: js/src/vm/DebuggerMemory.h
> @@ +34,5 @@
> > +        RelocatablePtrObject frame;
> > +    };
> > +    typedef mozilla::LinkedList<AllocationSite> AllocationSiteList;
> > +  private:
> > +    AllocationSiteList  *getAllocationsLog();
> 
> Instead of introducing a new type with custom tracing, I think we should use
> an ordinary array JSObject to hold the log, and use its 'push' method. If we
> make this a HeapPtrObject member of js::Debugger, not js::DebuggerMemory,
> then tracing it is simply a matter of adding a line to js::Debugger::trace.

The problem is that when we get to the maximum number of allocations to hold in the log, we start popping off the first allocation before appending the new allocation. This is O(n) with a js Array, vs O(1) with mozilla::LinkedList.

We do this because we prefer to keep the n most recent allocations, rather than the first n allocations after the last time we emptied the log. Maybe we should revisit this decision?
Comment on attachment 8456395 [details] [diff] [review]
debugger-memory-allocations-log-part-1.patch

Yeah, that's a good point. We need a queue, per our spec, and JS arrays make lousy queues. It's disappointing to take two words of overhead per log entry, but O(n) insertion once the queue fills is worse.

Re-taking review.
Attachment #8456395 - Flags: review?(jimb)
Comment on attachment 8456395 [details] [diff] [review]
debugger-memory-allocations-log-part-1.patch

Review of attachment 8456395 [details] [diff] [review]:
-----------------------------------------------------------------

This looks reasonable in general, but there are several areas that need attention. Please address these comments and re-request review.

----

We generally want to have much more thorough test coverage than this for something at this layer. Let's really try to think through the sorts of corner cases that always screw us, and make sure they're covered.

There's always a mix of:

A) Testing under our control, where we use our creative paranoia to hit the code where it's most complex, or at historically troublesome edge cases (empty data sets; cross-compartment references; adding and removing debuggees; weird self-reference; nesting; off-thread compilation; GC), and

B) Testing not under our control, with intermittent oranges, user bug reports, and so on, where there's usually no clear reproduction recipe and they show up at random inconvenient times.

As this patch stands, the A:B ratio is way, way too low. We need more creative paranoia.

Some ideas:

- Empty log? Overflowing log? (It's fine to expose the limit to JS via a function in TestingFunctions.cpp.)

- Switching allocation tracking off, and then retrieving the log?

- Allocating and logging, doing a GC, and then retrieving the log?

- Retrieving the log with allocation tracking never having been enabled?

- Allocation interleaved with several log retrievals puts the right allocations in the right logs?

- With no debuggees? Removing and adding debuggees as we go?

- Disabling the Debugger (Debugger.prototype.enabled)? (Although, see bug 1047655.)

- Logging multi-global debuggees, such that the log includes captured stacks from many compartments?

- Off-main-thread compilation? This causes Debugger so much trouble. Compilation allocates Function and Regexp objects. You can test it in the JS shell with offThreadCompileScript and runOffThreadScript. The compilation takes place in a separate compartment, and then we do a compartment merge --- a maneuver that is only used for exactly this situation, thank god --- on the main thread at join time, so objects just appear in our compartment from nowhere. Perhaps we should just punt measuring this accurately, but we should *definitely* make sure it doesn't crash. (Perhaps this should be an object metadata test, and not a logging test?)

::: js/src/jit-test/tests/debug/Memory-flushAllocationsLog-01.js
@@ +10,5 @@
> +    { name: "regexp literal",  object: /(two|2)\s*problems/,  line: Error().lineNumber },
> +    { name: "new constructor", object: new function Ctor(){}, line: Error().lineNumber },
> +    { name: "new Object",      object: new Object(),          line: Error().lineNumber },
> +    { name: "new Array",       object: new Array(),           line: Error().lineNumber },
> +    { name: "new Date",        object: new Date(),            line: Error().lineNumber }

The name and line aren't used any more, right? Let's try to keep the stuff in a test script relevant to the test. Just produce a plain array, and simplify the iteration.

::: js/src/vm/Debugger.h
@@ +161,5 @@
>      friend class Breakpoint;
>      friend class DebuggerMemory;
>      friend class mozilla::LinkedListElement<Debugger>;
>      friend bool (::JS_DefineDebuggerObject)(JSContext *cx, JS::HandleObject obj);
> +    friend bool (SavedStacksMetadataCallback)(JSContext *cx, JSObject **pmetadata);

What do the parens around SavedStacksMetadataCallback do?

@@ +415,5 @@
> +    // Returns a pointer to the Debugger.Memory instance for this debugger if it
> +    // exists (it is created on demand when the .memory property of a Debugger
> +    // Object is accessed). Returns nullptr when the Debugger.Memory instance
> +    // does not exist.
> +    DebuggerMemory *memory();

In other places we have a 'bool hasMemory() const' method for checking whether things are null, and then a 'DebuggerMemory &memory() const' that asserts that the pointer isn't null before returning it. SpiderMonkey uses C++ references for pointers known not to be null.

::: js/src/vm/DebuggerMemory.cpp
@@ +64,5 @@
> +    AllocationSite *allocSite = cx->new_<AllocationSite>(frame);
> +    AllocationSiteList *allocs = getAllocationsLog();
> +    allocs->insertBack(allocSite);
> +
> +    if (getAllocationsLogLength() + 1 > MAX_ALLOCATIONS_LOG_LENGTH) {

Why not just ">=", instead of "+ 1 >"?

@@ +107,5 @@
> +    if (!allocs)
> +        return;
> +    for (AllocationSite *allocSite = allocs->getFirst(); allocSite; allocSite = allocSite->getNext())
> +        MarkObject(trc, &allocSite->frame, "live SavedFrame held by Debugger.Memory");
> +}

I don't think this is going to be good enough: all those AllocationSite::frame members are cross-compartment references, and a partial GC is not going to know that some DebuggerMemory in another compartment is holding all these references.

I think the origin of the problem is that you didn't carefully consider what compartment the AllocationSites belong to (well, they're C++ objects, but which compartment nominally). I think the logical thing would be to treat them as belonging to the DebuggerMemory's compartment. That would make them cross-compartment references, which would suggest that appendAllocationSite should enter the DebuggerMemory's compartment, wrap the stack frame, and store that in the list. Then 'flushAllocationLog' won't need to wrap any more. The GC knows that wrappers are cross-compartment references, so it looks for them when it does a partial GC.

I'm speaking here of the code as it stands in the patch; if you move the members to js::Debugger as I suggest elsewhere, then s/DebuggerMemory/Debugger/, but the general idea still stands.

::: js/src/vm/DebuggerMemory.h
@@ +33,5 @@
> +        AllocationSite(Handle<SavedFrame *> frame) : frame(frame) { };
> +        RelocatablePtrObject frame;
> +    };
> +    typedef mozilla::LinkedList<AllocationSite> AllocationSiteList;
> +  private:

Blank line before visibility labels.

@@ +44,5 @@
>  
>      enum {
>          JSSLOT_DEBUGGER,
> +        JSSLOT_ALLOCATIONS_LOG,
> +        JSSLOT_ALLOCATIONS_LOG_LENGTH,

Rather than making these slots, if you make them members of the C++ js::Debugger class, I think lots of code will be simplified. Slots should be used for things where the GC's default tracing behavior is helpful, but here we have a count, which doesn't need to be traced; and a log, which needs custom tracing.

::: js/src/vm/SavedStacks.cpp
@@ +684,5 @@
> +    if (!dbgs)
> +        return true;
> +
> +    for (Debugger **dbgp = dbgs->begin(); dbgp != dbgs->end(); dbgp++) {
> +        if ((*dbgp)->trackingAllocationSites()) {

Let's make this look more like onDebuggerStatement, onNewGlobalObject, and the rest: a static inline function declared in DebuggerMemory.h, which does the check for debuggers, and a DebuggerMemory::slowPathOnLogAllocation function that does the multi-debugger dispatch. Or, maybe in Debugger.h, and Debugger::? Whatever's simplest.

Also: Could we assert in this loop that dbgs->begin() is what it was before we started the loop? The set of debuggers had better not change while we're iterating, such that the vector gets reallocated. (Like, say, could appendAllocationSite cause a GC, which causes a Debugger to get collected, which causes the vector to get shrunk and reallocated? I think our Vector template doesn't shrink, but our correctness really shouldn't depend on that...)
Attachment #8456395 - Flags: review?(jimb)
Attachment #8456395 - Attachment is obsolete: true
Attachment #8468088 - Flags: review?(jimb)
Attachment #8456396 - Attachment is obsolete: true
Attachment #8468089 - Flags: review?(jimb)
s/flushAllocationsLog/drainAllocationsLog/ -- I didn't like "read" much, so I asked on IRC, and everyone liked drain (it came up twice independently).

Lots new tests.

Moved a bunch of stuff onto Debugger directly, as you suggested.

Generally updated based on last review.

Try push: https://tbpl.mozilla.org/?tree=Try&rev=08484a90924a
Added

  if (helperThreadCount() === 0) {
    quit(0);
  }

to the top of the off-main-tread compilation test, which should fix those try failures.

New try push: https://tbpl.mozilla.org/?tree=Try&rev=7cabe74fc37a
Attachment #8468088 - Attachment is obsolete: true
Attachment #8468088 - Flags: review?(jimb)
Attachment #8468627 - Flags: review?(jimb)
Comment on attachment 8468089 [details] [diff] [review]
debugger-memory-allocations-log-part-2.patch

Review of attachment 8468089 [details] [diff] [review]:
-----------------------------------------------------------------

::: js/src/doc/Debugger/Debugger.Memory.md
@@ +29,5 @@
> +## Function Properties of the `Debugger.Memory.prototype` Object
> +
> +`drainAllocationsLog()`
> +:   When `trackingAllocationSites` is `true`, this method returns an array of
> +    allocation sites (as [captured stacks][saved-frame]) for recent `Object`

`Object` seems to refer to the Object class. I think we want to just use "object" here, with no `code` markup. The ECMAScript spec says things like "Array objects give special treatment to ..." and "A Date object contains a Number indicating... "
Comment on attachment 8468627 [details] [diff] [review]
debugger-memory-allocations-log-part-1.patch

Review of attachment 8468627 [details] [diff] [review]:
-----------------------------------------------------------------

I haven't looked over the tests, yet, but the code looks great. Some comments as I go:

::: js/src/vm/Debugger.cpp
@@ +1462,5 @@
> +{
> +    JS_ASSERT(!dbgs.empty());
> +    mozilla::DebugOnly<Debugger **> begin = dbgs.begin();
> +
> +    for (Debugger **dbgp = dbgs.begin(); dbgp != dbgs.end(); dbgp++) {

Paranoia: can we use dbgp < dbgs.end() here? Otherwise, if the last element gets removed while dbgp is pointing at it, then dbgp will be > dbgs.end() and we'll run off into tumbolia. I can't imagine how this would happen, but since it's easy enough not to count on it not happening...

@@ +1484,5 @@
> +{
> +    AutoCompartment ac(cx, object);
> +    RootedObject wrapped(cx, frame);
> +    if (!cx->compartment()->wrap(cx, &wrapped))
> +        return false;

This may end up being a perf problem --- switching compartments on every alloc --- but let's cross that bridge when we come to it. Correctness first...

@@ +1493,5 @@
> +
> +    allocationsLog.insertBack(allocSite);
> +
> +    if (allocationsLogLength >= maxAllocationsLogLength) {
> +        allocationsLog.popFirst();

This just unlinks and returns the first element; it doesn't js_delete it.

@@ +1505,5 @@
> +void
> +Debugger::emptyAllocationsLog()
> +{
> +    while (!allocationsLog.isEmpty())
> +        js_delete(allocationsLog.getFirst());

This is the right way to remove the first element --- I think.

@@ +1709,5 @@
> +    /*
> +     * Mark every allocation site in our allocation log.
> +     */
> +    for (AllocationSite *s = allocationsLog.getFirst(); s; s = s->getNext())
> +        MarkObject(trc, &s->frame, "live SavedFrame");

Beautiful. Let's make this "allocation log SavedFrame".

::: js/src/vm/Debugger.h
@@ +788,5 @@
> +{
> +    GlobalObject::DebuggerVector *dbgs = frame->global().getDebuggers();
> +    return (!dbgs || dbgs->empty())
> +        ? true
> +        : Debugger::slowPathOnLogAllocationSite(cx, frame, *dbgs);

Could we do this like this instead?

if (!dbgs || dbgs->empty())
    return true;
return Debugger::slowPathOnLogAllocationSite(cx, frame, *dbgs);

::: js/src/vm/DebuggerMemory.cpp
@@ +212,5 @@
> +          (doubleMax = args[0].toNumber()) > 0 &&
> +          (unsigned int) doubleMax == doubleMax))
> +    {
> +        JS_ReportErrorNumber(cx, js_GetErrorMessage, nullptr, JSMSG_UNEXPECTED_TYPE,
> +                             "(set maxAllocationsLogLength)'s paramater",

I think you actually just want to call JS::ToInt32 here. Then you don't have to do all these checks.

@@ +221,5 @@
> +    Debugger *dbg = memory->getDebugger();
> +    dbg->maxAllocationsLogLength = doubleMax;
> +
> +    while (dbg->allocationsLogLength > dbg->maxAllocationsLogLength) {
> +        dbg->allocationsLog.popFirst();

This removes the list element and returns it; it doesn't js_delete it. The emptyAllocationsLog function does it correctly, I think.

::: js/src/vm/DebuggerMemory.h
@@ +6,5 @@
>  
>  #ifndef vm_DebuggerMemory_h
>  #define vm_DebuggerMemory_h
>  
> +#include "mozilla/LinkedList.h"

I think this, and "gc/Barrier.h" and "vm/SavedStacks.h", probably belong in Debugger.h now, since that's where the types they define are actually used.

@@ +35,5 @@
>      };
>  
>      static bool construct(JSContext *cx, unsigned argc, Value *vp);
> +    static void finalize(FreeOp *fop, JSObject *obj);
> +    static void trace(JSTracer *trc, JSObject *obj);

These can go now, right?
(In reply to Jim Blandy :jimb from comment #23)
> I think you actually just want to call JS::ToInt32 here. Then you don't have
> to do all these checks.

Err, well, you still need to check for < 0...
I did find some leaks (I think??). I'd try running the allocation log tests under valgrind: just pass --valgrind-all.
Updated based on review comments. The drain should be less leaky now.
Attachment #8468627 - Attachment is obsolete: true
Attachment #8468627 - Flags: review?(jimb)
Attachment #8468769 - Flags: review?(jimb)
Comment on attachment 8468769 [details] [diff] [review]
debugger-memory-allocations-log-part-1.patch

Review of attachment 8468769 [details] [diff] [review]:
-----------------------------------------------------------------

::: js/src/jit-test/tests/debug/Memory-drainAllocationsLog-03.js
@@ +18,5 @@
> +
> +// Should have stayed at the maximum length.
> +assertEq(allocs.length, 3);
> +// Should have kept the most recent allocation.
> +assertEq(allocs[2].line, 4);

I wonder if SpiderMonkey will ever decide to allocate random objects for its internal use at random times. I guess we'll find out. :D

@@ +22,5 @@
> +assertEq(allocs[2].line, 4);
> +// Should have thrown away the oldest allocation.
> +assertEq(allocs.map(x => x.line).indexOf(1), -1);
> +
> +dbg.memory.trackingAllocationSites = false;

Each test runs in a fresh shell, so this shouldn't be needed, here or in the other tests. Unless the intent is to exercise the 'clear log' function?

::: js/src/jit-test/tests/debug/Memory-drainAllocationsLog-13.js
@@ +7,5 @@
> +}
> +
> +const root = newGlobal();
> +root.eval("this.dbg = new Debugger()");
> +root.debuggee = this;

You could turn this test inside out; newGlobal globals should support offThreadCompileScript, too. But there's nothing wrong with it this way, either; it's just surprising.

That said: since you've allocated the Debugger in the correct compartment above, you can just do stuff like:

root.dbg.addDebuggee(this);
root.dbg.memory.trackingAllocationSites = true;

directly at the top level of the script. The compartment machinery will turn the functions into wrappers when you reference them; and then do the compartment switch automatically when you call them.

::: js/src/vm/DebuggerMemory.cpp
@@ +211,5 @@
> +        return false;
> +
> +    if (max < 1) {
> +        JS_ReportErrorNumber(cx, js_GetErrorMessage, nullptr, JSMSG_UNEXPECTED_TYPE,
> +                             "(set maxAllocationsLogLength)'s paramater",

"parameter"

::: js/src/vm/SavedStacks.cpp
@@ +13,5 @@
>  #include "jsnum.h"
>  
>  #include "gc/Marking.h"
>  #include "js/Vector.h"
> +#include "vm/DebuggerMemory.h"

We don't need this, right?

@@ +20,5 @@
>  
>  #include "jscntxtinlines.h"
>  #include "jsobjinlines.h"
>  
> +#include "vm/Debugger-inl.h"

Nor this?
Attachment #8468769 - Flags: review?(jimb) → review+
Attachment #8468089 - Flags: review?(jimb) → review+
Updated based on feedback and carrying over r+.

No try push because the tree is closed.
Attachment #8468769 - Attachment is obsolete: true
Attachment #8468883 - Flags: review+
https://hg.mozilla.org/mozilla-central/rev/81b4ed1b7a4c
https://hg.mozilla.org/mozilla-central/rev/32a6720cdd7a
Status: ASSIGNED → RESOLVED
Closed: 10 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla34
What's the use case for this feature?

I ask because I have a patch that dumps to file the top stack trace entry on every GC thing allocation (and slots/elements resize). It's extremely useful -- e.g. I've used it a great deal with pdf.js -- but it generates very large log files that I have to post-process. If the log was bounded it would be *much* less useful...
(In reply to Nicholas Nethercote [:njn] from comment #32)
> What's the use case for this feature?
> 
> I ask because I have a patch that dumps to file the top stack trace entry on
> every GC thing allocation (and slots/elements resize). It's extremely useful
> -- e.g. I've used it a great deal with pdf.js -- but it generates very large
> log files that I have to post-process. If the log was bounded it would be
> *much* less useful...

We want to stream the allocations from the device to the desktop Firefox in "real time" and build graphs of allocations, as well as aggregate allocation counts on the desktop device.

Basically, we just have the bound so that if someone turns on allocation logging and then forgets to ever do anything with it, we won't OOM.
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: