1066313 - [jsdbg2] Add timestamps to the entries in the array returned by Debugger.Memory.prototype.drainAllocationsLog

Status: RESOLVED FIXED

(Core :: JavaScript Engine, defect)

Description

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

Would need to add a member to Debugger::AllocationSite[0] and update the docs in js/src/doc/Debugger/Debugger.Memory.md.

[0] https://mxr.mozilla.org/mozilla-central/source/js/src/vm/Debugger.h#202

Comment 1

[Tom Tromey :tromey]

A couple of notes on this:

First, drainAllocationsLog currently returns an array of captured stacks.
To add a timestamp the type of the array elements would have to be changed.

Second, it only seems readily possible to get timestamps with microsecond resolution.

Comment 2

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

(In reply to Tom Tromey :tromey from comment #1)
> A couple of notes on this:
> 
> First, drainAllocationsLog currently returns an array of captured stacks.
> To add a timestamp the type of the array elements would have to be changed.

Yup, luckily nothing is shipping that relies on this API yet, so its pretty easy to change right now to an object of the form { stack, timeStamp } or something.

> 
> Second, it only seems readily possible to get timestamps with microsecond
> resolution.

Microseconds are fine, as far as I'm concerned. We should definitely document the units and what they are relative to.

Comment 3

[Tom Tromey :tromey]

Attachment: add timestamps to drainAllocationsLog

Comment 4

[Tom Tromey :tromey]

There's a couple of things in the patch I would like comment on.

        JSAtom *timestampAtom = Atomize(cx, "timestamp", strlen("timestamp"));

It's tempting to use sizeof here, but I didn't see other code doing this.
Also I wasn't sure if I should have just added these strings to CommonPropertyNames.h instead.

Converting the timestamp to a Value.  I went back and forth on adding a comment about
when this will overflow -- but there's 100 years until then, maybe it's not so important.

Comment 5

[Jim Blandy :jimb]

Comment on attachment 8489443 [details] [diff] [review]
add timestamps to drainAllocationsLog

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

This looks great so far.

It needs test coverage. You can assert that the timestamps increase, or at least don't decrease, and use the shell's "now" function (which calls PRMJ_Now) to check that the timestamps are within reasonable bounds.

::: js/src/doc/Debugger/Debugger.Memory.md
@@ +92,5 @@
>  <code id='drain-alloc-log'>drainAllocationsLog()</code>
>  :   When `trackingAllocationSites` is `true`, this method returns an array of
> +    recent `Object` allocations within the set of debuggees. Entries
> +    for objects allocated with no JavaScript frames on the stack are
> +    `null`. *Recent* is defined as the `maxAllocationsLogLength` most

This description isn't right, is it? Every entry is { frame: ..., timestamp: ... }.

We're making a non-trivial change to the result type of this function; let's rework the docs properly.

::: js/src/vm/Debugger.h
@@ +200,5 @@
>      JSCList breakpoints;                /* Circular list of all js::Breakpoints in this debugger */
>  
>      struct AllocationSite : public mozilla::LinkedListElement<AllocationSite>
>      {
> +        explicit AllocationSite(HandleObject frame, int64_t when) : frame(frame), when(when) {

No longer any need for "explicit" if the constructor takes two arguments.

::: js/src/vm/DebuggerMemory.cpp
@@ +197,5 @@
>          return false;
>      result->ensureDenseInitializedLength(cx, 0, length);
>  
> +    if (length > 0) {
> +        JSAtom *frameAtom = Atomize(cx, "frame", strlen("frame"));

Pre-existing problem, but:

It's a little crazy to be looking up these atoms every loop iteration. Instead of these Atomize calls, let's just add entries to js/src/vm/CommonPropertyNames.h, and refer to cx->names().blah. Granted, those are js::PropertyName * values instead of jsids, but you can use JSObject::defineProperty instead. See the defineProperty calls here:

https://hg.mozilla.org/mozilla-central/file/989c1c75889c/js/src/vm/DebuggerMemory.cpp#l393

Comment 6

[Jim Blandy :jimb]

(In reply to Jim Blandy :jimb from comment #5)
> It's a little crazy to be looking up these atoms every loop iteration.

Sorry --- of course you're not doing that. I misread the code. But I still think it's okay to use CommonPropertyNames for this.

Comment 7

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

Note that bug 1067491, which defines actors using drainAllocationsLog, is now checkin-needed so you will need to modify that actor to throw away the time stamp and grab the stack only or else tests will start failing.

I'll file a follow up to actually send the time stamp across the RDP too.

Comment 8

[Tom Tromey :tromey]

> It needs test coverage. You can assert that the timestamps increase, or at
> least don't decrease, and use the shell's "now" function (which calls
> PRMJ_Now) to check that the timestamps are within reasonable bounds.

Sorry about that - I had written exactly this test case but it didn't make it
into the attachment.

> >  <code id='drain-alloc-log'>drainAllocationsLog()</code>
> >  :   When `trackingAllocationSites` is `true`, this method returns an array of
> > +    recent `Object` allocations within the set of debuggees. Entries
> > +    for objects allocated with no JavaScript frames on the stack are
> > +    `null`. *Recent* is defined as the `maxAllocationsLogLength` most
> 
> This description isn't right, is it? Every entry is { frame: ..., timestamp:
> ... }.
> 
> We're making a non-trivial change to the result type of this function; let's
> rework the docs properly

I thought the description in the next paragraph covered this...
Do you mean the text "array of ... allocations"?  I hadn't read that as being
overly specific about the type.  Any suggestions?  Or how about "an array of
descriptions for recent `Object` allocations"?

Comment 9

[Jim Blandy :jimb]

(In reply to Tom Tromey :tromey from comment #8)
> > >  <code id='drain-alloc-log'>drainAllocationsLog()</code>
> > >  :   When `trackingAllocationSites` is `true`, this method returns an array of
> > > +    recent `Object` allocations within the set of debuggees. Entries
> > > +    for objects allocated with no JavaScript frames on the stack are
> > > +    `null`. *Recent* is defined as the `maxAllocationsLogLength` most
> > 
> > This description isn't right, is it? Every entry is { frame: ..., timestamp:
> > ... }.
> 
> I thought the description in the next paragraph covered this...
> Do you mean the text "array of ... allocations"?  I hadn't read that as being
> overly specific about the type.  Any suggestions?  Or how about "an array of
> descriptions for recent `Object` allocations"?

The word "Entries" at the beginning of the second sentence seems to refer "entries of the array". Those are definitely not null.

Comment 10

[Tom Tromey :tromey]

https://tbpl.mozilla.org/?tree=Try&rev=e91f13ef0c76

Comment 11

[Tom Tromey :tromey]

Attachment: add timestamps to drainAllocationsLog

I think this version addresses the review comments, fixes the tutorial
docs, and is also rebased onto the patch for 1067491.

Comment 12

[Jim Blandy :jimb]

Comment on attachment 8491644 [details] [diff] [review]
add timestamps to drainAllocationsLog

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

This looks much better! The docs are still not correct, and I have a request for the new test.

::: js/src/doc/Debugger/Debugger.Memory.md
@@ +108,5 @@
> +    Here <i>timestamp</i> is the timestamp of the event in units of
> +    microseconds since the epoch and <i>allocationSite</i> is an
> +    allocation site (as a [captured stack][saved-frame]). Entries for
> +    objects allocated with no JavaScript frames on the stack are
> +    `null`.

This doesn't match what I see in the code. From the code, it looks as if no entry in the array is ever null; and that the allocationSite property is null for objects allocated with no frames on the stack.

::: js/src/doc/Debugger/Tutorial-Alloc-Log-Tree.md
@@ +82,5 @@
>            // This is a kludge, necessary for now. The saved stacks
>            // are new, and Firefox doesn't yet understand that they
>            // are safe for chrome code to use, so we must tell it
>            // so explicitly.
> +          site = Components.utils.waiveXrays(site.frame);

Thanks so much for catching this!

::: js/src/jit-test/tests/debug/Memory-drainAllocationsLog-14.js
@@ +17,5 @@
> +assertEq(allocs.length >= 4, true);
> +assertEq(allocs[0].timestamp >= startupTime, true);
> +for (i = 1; i < allocs.length; ++i) {
> +    assertEq(allocs[i].timestamp >= allocs[i - 1].timestamp, true);
> +}

We should call dateNow both before, between, and after the allocations, and assert that they have the appropriate relationships.

::: js/src/vm/DebuggerMemory.cpp
@@ +210,5 @@
> +        RootedValue timestampValue(cx, NumberValue(allocSite->when));
> +        if (!JSObject::defineProperty(cx, obj, cx->names().timestamp, timestampValue))
> +            return false;
> +
> +        result->setDenseElement(i, ObjectOrNullValue(obj));

Since we know that obj isn't null, we can just use ObjectValue here.

Comment 13

[Tom Tromey :tromey]

Attachment: add timestamps to drainAllocationsLog

Thanks for the review.  I'm sorry about that doc thing, I thought I
had fixed it up, but I think I just moved the text and neglected to
actually edit it.

I think this patch addresses your comments.  It's also been rebased.

The change to the tests are a bit tricky.  The number of allocations
actually done can vary, so we can't exactly correlate entries in
"allocs" to entries in "allocTimes".  So instead the patch checks that
some allocations are done between each recorded time and that the last
time is after the last allocation.

Comment 14

[Tom Tromey :tromey]

Attachment: add timestamps to drainAllocationsLog

Jim found one more buglet in the documentation change.
This version of the patch fixes that as well.

Comment 15

[Jim Blandy :jimb]

Comment on attachment 8502615 [details] [diff] [review]
add timestamps to drainAllocationsLog

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

Looks good, thank you for the revisions. Address the comments below and re-upload if you feel like it, and then put 'checkin-needed' in the keywords.

::: js/src/jit-test/tests/debug/Memory-drainAllocationsLog-14.js
@@ +4,5 @@
> +
> +var nextAlloc = 0;
> +var allocTimes = [];
> +
> +allocTimes[nextAlloc++] = 1000 * dateNow();

If you like, you could just use allocTimes.push(1000 * dateNow()), and eliminate nextAlloc. That's a style people will recognize with little effort.

@@ +30,5 @@
> +    // It isn't possible to exactly correlate the entries in the
> +    // allocs array with the entries in allocTimes, because we can't
> +    // control exactly how many allocations are done during the course
> +    // of a given eval.  However, we can assume that there is some
> +    // allocation recorded after each entry in allocTimes.  So, We

"we" (no caps)

Comment 16

[Tom Tromey :tromey]

Attachment: add timestamps to drainAllocationsLog (carrying forward r=jimb)

Comment 17

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/b8098ac8ea6e

Comment 18

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/b8098ac8ea6e