Bug 1066313 - add timestamps to drainAllocationsLog (carrying forward r=jimb). r=jimb
authorTom Tromey <tom@tromey.com>
Thu, 09 Oct 2014 11:10:00 +0200
changeset 232962 b8098ac8ea6eaa31d16ee6e8a2b583a6cebc12d2
parent 232961 6275dc4c7cdfc4c0b1b3f22b7c07c16dee61a79b
child 232963 19917edca5d7b99219d5ad13add0305f3cea684b
push id1
push usersledru@mozilla.com
push dateThu, 04 Dec 2014 17:57:20 +0000
reviewersjimb, jimb
bugs1066313
milestone35.0a1
Bug 1066313 - add timestamps to drainAllocationsLog (carrying forward r=jimb). r=jimb
js/src/doc/Debugger/Debugger.Memory.md
js/src/doc/Debugger/Tutorial-Alloc-Log-Tree.md
js/src/jit-test/tests/debug/Memory-drainAllocationsLog-01.js
js/src/jit-test/tests/debug/Memory-drainAllocationsLog-03.js
js/src/jit-test/tests/debug/Memory-drainAllocationsLog-08.js
js/src/jit-test/tests/debug/Memory-drainAllocationsLog-14.js
js/src/vm/CommonPropertyNames.h
js/src/vm/Debugger.cpp
js/src/vm/Debugger.h
js/src/vm/DebuggerMemory.cpp
js/src/vm/SavedStacks.cpp
toolkit/devtools/server/actors/memory.js
--- a/js/src/doc/Debugger/Debugger.Memory.md
+++ b/js/src/doc/Debugger/Debugger.Memory.md
@@ -86,22 +86,35 @@ following accessor properties from its p
     value is `5000`.
 
 
 Function Properties of the `Debugger.Memory.prototype` Object
 -------------------------------------------------------------
 
 <code id='drain-alloc-log'>drainAllocationsLog()</code>
 :   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. Entries for objects allocated with
-    no JavaScript frames on the stack are `null`. *Recent* is defined as the
-    `maxAllocationsLogLength` most recent `Object` allocations since the last
-    call to `drainAllocationsLog`. Therefore, calling this method effectively
-    clears the log.
+    recent `Object` allocations within the set of debuggees. *Recent* is
+    defined as the `maxAllocationsLogLength` most recent `Object` allocations
+    since the last call to `drainAllocationsLog`. Therefore, calling this
+    method effectively clears the log.
+
+    Objects in the array are of the form:
+
+    <pre class='language-js'><code>
+    {
+      "timestamp": <i>timestamp</i>,
+      "frame": <i>allocationSite</i>
+    }
+    </code></pre>
+
+    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]).
+    <i>allocationSite</i> is `null` for objects allocated with no
+    JavaScript frames on the stack.
 
     When `trackingAllocationSites` is `false`, `drainAllocationsLog()` throws an
     `Error`.
 
 <code id='take-census'>takeCensus()</code>
 :   Carry out a census of the debuggee compartments' contents. A *census* is a
     complete traversal of the graph of all reachable memory items belonging to a
     particular `Debugger`'s debuggees. The census produces a count of those
--- a/js/src/doc/Debugger/Tutorial-Alloc-Log-Tree.md
+++ b/js/src/doc/Debugger/Tutorial-Alloc-Log-Tree.md
@@ -78,17 +78,17 @@ 3)  Enter the following code in the Scra
         // allocation counts. Note that stack entries are '===' if
         // they represent the same site with the same callers.
         var counts = new Map;
         for (let site of log) {
           // 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);
+          site = Components.utils.waiveXrays(site.frame);
 
           if (!counts.has(site))
             counts.set(site, 0);
           counts.set(site, counts.get(site) + 1);
         }
 
         // Walk from each site that allocated something up to the
         // root, computing allocation totals that include
--- a/js/src/jit-test/tests/debug/Memory-drainAllocationsLog-01.js
+++ b/js/src/jit-test/tests/debug/Memory-drainAllocationsLog-01.js
@@ -20,12 +20,12 @@ root.eval("(" + function immediate() {
 const allocs = dbg.memory.drainAllocationsLog();
 print(allocs.join("\n--------------------------------------------------------------------------\n"));
 print("Total number of allocations logged: " + allocs.length);
 
 let idx = -1;
 for (let object of root.tests) {
   let wrappedObject = wrappedRoot.makeDebuggeeValue(object);
   let allocSite = wrappedObject.allocationSite;
-  let newIdx = allocs.indexOf(allocSite);
+  let newIdx = allocs.map(x => x.frame).indexOf(allocSite);
   assertEq(newIdx > idx, true);
   idx = newIdx;
 }
--- a/js/src/jit-test/tests/debug/Memory-drainAllocationsLog-03.js
+++ b/js/src/jit-test/tests/debug/Memory-drainAllocationsLog-03.js
@@ -14,11 +14,11 @@ root.eval([
   "this.alloc4 = {};", // line 4
 ].join("\n"));
 
 const allocs = dbg.memory.drainAllocationsLog();
 
 // Should have stayed at the maximum length.
 assertEq(allocs.length, 3);
 // Should have kept the most recent allocation.
-assertEq(allocs[2].line, 4);
+assertEq(allocs[2].frame.line, 4);
 // Should have thrown away the oldest allocation.
-assertEq(allocs.map(x => x.line).indexOf(1), -1);
+assertEq(allocs.map(x => x.frame.line).indexOf(1), -1);
--- a/js/src/jit-test/tests/debug/Memory-drainAllocationsLog-08.js
+++ b/js/src/jit-test/tests/debug/Memory-drainAllocationsLog-08.js
@@ -16,15 +16,15 @@ root.eval([
 
 dbg.memory.trackingAllocationSites = true;
 
 root.doFirstAlloc();
 let allocs1 = dbg.memory.drainAllocationsLog();
 root.doSecondAlloc();
 let allocs2 = dbg.memory.drainAllocationsLog();
 
-let allocs1Lines = allocs1.map(x => x.line);
+let allocs1Lines = allocs1.map(x => x.frame.line);
 assertEq(allocs1Lines.indexOf(root.firstAllocLine) != -1, true);
 assertEq(allocs1Lines.indexOf(root.secondAllocLine) == -1, true);
 
-let allocs2Lines = allocs2.map(x => x.line);
+let allocs2Lines = allocs2.map(x => x.frame.line);
 assertEq(allocs2Lines.indexOf(root.secondAllocLine) != -1, true);
 assertEq(allocs2Lines.indexOf(root.firstAllocLine) == -1, true);
new file mode 100644
--- /dev/null
+++ b/js/src/jit-test/tests/debug/Memory-drainAllocationsLog-14.js
@@ -0,0 +1,47 @@
+// Test that drainAllocationsLog returns some timestamps.
+
+load(libdir + 'asserts.js');
+
+var allocTimes = [];
+
+allocTimes.push(1000 * dateNow());
+
+const root = newGlobal();
+const dbg = new Debugger(root);
+
+dbg.memory.trackingAllocationSites = true;
+root.eval("this.alloc1 = {}");
+allocTimes.push(1000 * dateNow());
+root.eval("this.alloc2 = {}");
+allocTimes.push(1000 * dateNow());
+root.eval("this.alloc3 = {}");
+allocTimes.push(1000 * dateNow());
+root.eval("this.alloc4 = {}");
+allocTimes.push(1000 * dateNow());
+
+allocs = dbg.memory.drainAllocationsLog();
+assertEq(allocs.length >= 4, true);
+assertEq(allocs[0].timestamp >= allocTimes[0], true);
+var seenAlloc = 0;
+var lastIndexSeenAllocIncremented = 0;
+for (i = 1; i < allocs.length; ++i) {
+    assertEq(allocs[i].timestamp >= allocs[i - 1].timestamp, true);
+    // 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
+    // track the allocTimes entry we've passed, and then after the
+    // loop assert that we've seen them all.  We also assert that a
+    // non-zero number of allocations has happened since the last seen
+    // increment.
+    while (seenAlloc < allocTimes.length
+           && allocs[i].timestamp >= allocTimes[seenAlloc]) {
+        assertEq(i - lastIndexSeenAllocIncremented > 0, true);
+        lastIndexSeenAllocIncremented = i;
+        ++seenAlloc;
+    }
+}
+// There should be one entry left in allocTimes, because we recorded a
+// time after the last possible allocation in the array.
+assertEq(seenAlloc, allocTimes.length -1);
--- a/js/src/vm/CommonPropertyNames.h
+++ b/js/src/vm/CommonPropertyNames.h
@@ -70,16 +70,17 @@
     macro(fieldOffsets, fieldOffsets, "fieldOffsets") \
     macro(fieldTypes, fieldTypes, "fieldTypes") \
     macro(fileName, fileName, "fileName") \
     macro(fix, fix, "fix") \
     macro(float32, float32, "float32") \
     macro(float32x4, float32x4, "float32x4") \
     macro(float64, float64, "float64") \
     macro(format, format, "format") \
+    macro(frame, frame, "frame") \
     macro(from, from, "from") \
     macro(get, get, "get") \
     macro(getInternals, getInternals, "getInternals") \
     macro(getOwnPropertyDescriptor, getOwnPropertyDescriptor, "getOwnPropertyDescriptor") \
     macro(getOwnPropertyNames, getOwnPropertyNames, "getOwnPropertyNames") \
     macro(getPropertyDescriptor, getPropertyDescriptor, "getPropertyDescriptor") \
     macro(global, global, "global") \
     macro(Handle, Handle, "Handle") \
@@ -170,16 +171,17 @@
     macro(source, source, "source") \
     macro(stack, stack, "stack") \
     macro(sticky, sticky, "sticky") \
     macro(strings, strings, "strings") \
     macro(StructType, StructType, "StructType") \
     macro(style, style, "style") \
     macro(test, test, "test") \
     macro(throw, throw_, "throw") \
+    macro(timestamp, timestamp, "timestamp") \
     macro(timeZone, timeZone, "timeZone") \
     macro(toGMTString, toGMTString, "toGMTString") \
     macro(toISOString, toISOString, "toISOString") \
     macro(toJSON, toJSON, "toJSON") \
     macro(toLocaleString, toLocaleString, "toLocaleString") \
     macro(toSource, toSource, "toSource") \
     macro(toString, toString, "toString") \
     macro(toUTCString, toUTCString, "toUTCString") \
--- a/js/src/vm/Debugger.cpp
+++ b/js/src/vm/Debugger.cpp
@@ -1509,47 +1509,47 @@ Debugger::slowPathOnNewGlobalObject(JSCo
             if (status != JSTRAP_CONTINUE && status != JSTRAP_RETURN)
                 break;
         }
     }
     MOZ_ASSERT(!cx->isExceptionPending());
 }
 
 /* static */ bool
-Debugger::slowPathOnLogAllocationSite(JSContext *cx, HandleSavedFrame frame,
+Debugger::slowPathOnLogAllocationSite(JSContext *cx, HandleSavedFrame frame, int64_t when,
                                       GlobalObject::DebuggerVector &dbgs)
 {
     MOZ_ASSERT(!dbgs.empty());
     mozilla::DebugOnly<Debugger **> begin = dbgs.begin();
 
     for (Debugger **dbgp = dbgs.begin(); dbgp < dbgs.end(); dbgp++) {
         // The set of debuggers had better not change while we're iterating,
         // such that the vector gets reallocated.
         MOZ_ASSERT(dbgs.begin() == begin);
 
         if ((*dbgp)->trackingAllocationSites &&
             (*dbgp)->enabled &&
-            !(*dbgp)->appendAllocationSite(cx, frame))
+            !(*dbgp)->appendAllocationSite(cx, frame, when))
         {
             return false;
         }
     }
 
     return true;
 }
 
 bool
-Debugger::appendAllocationSite(JSContext *cx, HandleSavedFrame frame)
+Debugger::appendAllocationSite(JSContext *cx, HandleSavedFrame frame, int64_t when)
 {
     AutoCompartment ac(cx, object);
     RootedObject wrapped(cx, frame);
     if (!cx->compartment()->wrap(cx, &wrapped))
         return false;
 
-    AllocationSite *allocSite = cx->new_<AllocationSite>(wrapped);
+    AllocationSite *allocSite = cx->new_<AllocationSite>(wrapped, when);
     if (!allocSite)
         return false;
 
     allocationsLog.insertBack(allocSite);
 
     if (allocationsLogLength >= maxAllocationsLogLength) {
         js_delete(allocationsLog.getFirst());
     } else {
--- a/js/src/vm/Debugger.h
+++ b/js/src/vm/Debugger.h
@@ -197,30 +197,31 @@ class Debugger : private mozilla::Linked
     HeapPtrNativeObject object;         /* The Debugger object. Strong reference. */
     GlobalObjectSet debuggees;          /* Debuggee globals. Cross-compartment weak references. */
     js::HeapPtrObject uncaughtExceptionHook; /* Strong reference. */
     bool enabled;
     JSCList breakpoints;                /* Circular list of all js::Breakpoints in this debugger */
 
     struct AllocationSite : public mozilla::LinkedListElement<AllocationSite>
     {
-        explicit AllocationSite(HandleObject frame) : frame(frame) {
+        AllocationSite(HandleObject frame, int64_t when) : frame(frame), when(when) {
             MOZ_ASSERT_IF(frame, UncheckedUnwrap(frame)->is<SavedFrame>());
         };
         RelocatablePtrObject frame;
+        int64_t when;
     };
     typedef mozilla::LinkedList<AllocationSite> AllocationSiteList;
 
     bool trackingAllocationSites;
     double allocationSamplingProbability;
     AllocationSiteList allocationsLog;
     size_t allocationsLogLength;
     size_t maxAllocationsLogLength;
     static const size_t DEFAULT_MAX_ALLOCATIONS_LOG_LENGTH = 5000;
-    bool appendAllocationSite(JSContext *cx, HandleSavedFrame frame);
+    bool appendAllocationSite(JSContext *cx, HandleSavedFrame frame, int64_t when);
     void emptyAllocationsLog();
 
     /*
      * If this Debugger is enabled, and has a onNewGlobalObject handler, then
      * this link is inserted into the circular list headed by
      * JSRuntime::onNewGlobalObjectWatchers. Otherwise, this is set to a
      * singleton cycle.
      */
@@ -371,17 +372,17 @@ class Debugger : private mozilla::Linked
 
     static JSTrapStatus slowPathOnEnterFrame(JSContext *cx, AbstractFramePtr frame);
     static bool slowPathOnLeaveFrame(JSContext *cx, AbstractFramePtr frame, bool ok);
     static JSTrapStatus slowPathOnExceptionUnwind(JSContext *cx, AbstractFramePtr frame);
     static void slowPathOnNewScript(JSContext *cx, HandleScript script,
                                     GlobalObject *compileAndGoGlobal);
     static void slowPathOnNewGlobalObject(JSContext *cx, Handle<GlobalObject *> global);
     static bool slowPathOnLogAllocationSite(JSContext *cx, HandleSavedFrame frame,
-                                            GlobalObject::DebuggerVector &dbgs);
+                                            int64_t when, GlobalObject::DebuggerVector &dbgs);
     static JSTrapStatus dispatchHook(JSContext *cx, MutableHandleValue vp, Hook which);
 
     JSTrapStatus fireDebuggerStatement(JSContext *cx, MutableHandleValue vp);
     JSTrapStatus fireExceptionUnwind(JSContext *cx, MutableHandleValue vp);
     JSTrapStatus fireEnterFrame(JSContext *cx, AbstractFramePtr frame, MutableHandleValue vp);
     JSTrapStatus fireNewGlobalObject(JSContext *cx, Handle<GlobalObject *> global, MutableHandleValue vp);
 
     /*
@@ -504,17 +505,17 @@ class Debugger : private mozilla::Linked
      *   pending exception.
      *
      * - JSTRAP_RETURN: Return from |frame|. onExceptionUnwind has cleared
      *   |cx|'s pending exception and set |frame|'s return value.
      */
     static inline JSTrapStatus onExceptionUnwind(JSContext *cx, AbstractFramePtr frame);
     static inline void onNewScript(JSContext *cx, HandleScript script, GlobalObject *compileAndGoGlobal);
     static inline void onNewGlobalObject(JSContext *cx, Handle<GlobalObject *> global);
-    static inline bool onLogAllocationSite(JSContext *cx, HandleSavedFrame frame);
+    static inline bool onLogAllocationSite(JSContext *cx, HandleSavedFrame frame, int64_t when);
     static JSTrapStatus onTrap(JSContext *cx, MutableHandleValue vp);
     static JSTrapStatus onSingleStep(JSContext *cx, MutableHandleValue vp);
     static bool handleBaselineOsr(JSContext *cx, InterpreterFrame *from, jit::BaselineFrame *to);
     static bool handleIonBailout(JSContext *cx, jit::RematerializedFrame *from, jit::BaselineFrame *to);
     static void propagateForcedReturn(JSContext *cx, AbstractFramePtr frame, HandleValue rval);
 
     /************************************* Functions for use by Debugger.cpp. */
 
@@ -827,22 +828,22 @@ Debugger::onNewGlobalObject(JSContext *c
 #ifdef DEBUG
     global->compartment()->firedOnNewGlobalObject = true;
 #endif
     if (!JS_CLIST_IS_EMPTY(&cx->runtime()->onNewGlobalObjectWatchers))
         Debugger::slowPathOnNewGlobalObject(cx, global);
 }
 
 bool
-Debugger::onLogAllocationSite(JSContext *cx, HandleSavedFrame frame)
+Debugger::onLogAllocationSite(JSContext *cx, HandleSavedFrame frame, int64_t when)
 {
     GlobalObject::DebuggerVector *dbgs = cx->global()->getDebuggers();
     if (!dbgs || dbgs->empty())
         return true;
-    return Debugger::slowPathOnLogAllocationSite(cx, frame, *dbgs);
+    return Debugger::slowPathOnLogAllocationSite(cx, frame, when, *dbgs);
 }
 
 extern bool
 EvaluateInEnv(JSContext *cx, Handle<Env*> env, HandleValue thisv, AbstractFramePtr frame,
               mozilla::Range<const char16_t> chars, const char *filename, unsigned lineno,
               MutableHandleValue rval);
 
 bool ReportObjectRequired(JSContext *cx);
--- a/js/src/vm/DebuggerMemory.cpp
+++ b/js/src/vm/DebuggerMemory.cpp
@@ -194,19 +194,31 @@ DebuggerMemory::drainAllocationsLog(JSCo
     size_t length = dbg->allocationsLogLength;
 
     RootedArrayObject result(cx, NewDenseFullyAllocatedArray(cx, length));
     if (!result)
         return false;
     result->ensureDenseInitializedLength(cx, 0, length);
 
     for (size_t i = 0; i < length; i++) {
-        Debugger::AllocationSite *allocSite = dbg->allocationsLog.popFirst();
-        result->setDenseElement(i, ObjectOrNullValue(allocSite->frame));
-        js_delete(allocSite);
+        RootedObject obj(cx, NewBuiltinClassInstance(cx, &JSObject::class_));
+        if (!obj)
+            return false;
+
+        mozilla::UniquePtr<Debugger::AllocationSite, JS::DeletePolicy<Debugger::AllocationSite> >
+            allocSite(dbg->allocationsLog.popFirst());
+        RootedValue frame(cx, ObjectOrNullValue(allocSite->frame));
+        if (!JSObject::defineProperty(cx, obj, cx->names().frame, frame))
+            return false;
+
+        RootedValue timestampValue(cx, NumberValue(allocSite->when));
+        if (!JSObject::defineProperty(cx, obj, cx->names().timestamp, timestampValue))
+            return false;
+
+        result->setDenseElement(i, ObjectValue(*obj));
     }
 
     dbg->allocationsLogLength = 0;
     args.rval().setObject(*result);
     return true;
 }
 
 /* static */ bool
--- a/js/src/vm/SavedStacks.cpp
+++ b/js/src/vm/SavedStacks.cpp
@@ -11,16 +11,17 @@
 #include <math.h>
 
 #include "jsapi.h"
 #include "jscompartment.h"
 #include "jsfriendapi.h"
 #include "jshashutil.h"
 #include "jsmath.h"
 #include "jsnum.h"
+#include "prmjtime.h"
 
 #include "gc/Marking.h"
 #include "js/Vector.h"
 #include "vm/Debugger.h"
 #include "vm/GlobalObject.h"
 #include "vm/StringBuffer.h"
 
 #include "jscntxtinlines.h"
@@ -803,17 +804,17 @@ SavedStacksMetadataCallback(JSContext *c
                                                 std::log(notSamplingProb));
     }
 
     RootedSavedFrame frame(cx);
     if (!stacks.saveCurrentStack(cx, &frame))
         return false;
     *pmetadata = frame;
 
-    return Debugger::onLogAllocationSite(cx, frame);
+    return Debugger::onLogAllocationSite(cx, frame, PRMJ_Now());
 }
 
 #ifdef JS_CRASH_DIAGNOSTICS
 void
 CompartmentChecker::check(SavedStacks *stacks)
 {
     if (&compartment->savedStacks() != stacks) {
         printf("*** Compartment SavedStacks mismatch: %p vs. %p\n",
--- a/toolkit/devtools/server/actors/memory.js
+++ b/toolkit/devtools/server/actors/memory.js
@@ -253,17 +253,17 @@ let MemoryActor = protocol.ActorClass({
    *          profiling and done only when necessary.
    */
   getAllocations: method(expectState("attached", function() {
     const allocations = this.dbg.memory.drainAllocationsLog()
     const packet = {
       allocations: []
     };
 
-    for (let stack of allocations) {
+    for (let { frame: stack } of allocations) {
       if (stack && Cu.isDeadWrapper(stack)) {
         continue;
       }
 
       // Safe because SavedFrames are frozen/immutable.
       let waived = Cu.waiveXrays(stack);
 
       // Ensure that we have a form, count, and index for new allocations