Bug 944701 - Tracelogging: Add shell functions to enable/disable tracelogging, r=till

js/src/builtin/TestingFunctions.cpp

@@ -23,6 +23,7 @@
 #include "vm/GlobalObject.h"
 #include "vm/Interpreter.h"
 #include "vm/ProxyObject.h"
+#include "vm/TraceLogging.h"
 
 #include "jscntxtinlines.h"
 #include "jsobjinlines.h"
@@ -1488,6 +1489,26 @@ TimesAccessed(JSContext *cx, unsigned argc, jsval *vp)
     return true;
 }
 
+static bool
+EnableTraceLogger(JSContext *cx, unsigned argc, jsval *vp)
+{
+    CallArgs args = CallArgsFromVp(argc, vp);
+    TraceLogger *logger = TraceLoggerForMainThread(cx->runtime());
+    args.rval().setBoolean(TraceLoggerEnable(logger));
+
+    return true;
+}
+
+static bool
+DisableTraceLogger(JSContext *cx, unsigned argc, jsval *vp)
+{
+    CallArgs args = CallArgsFromVp(argc, vp);
+    TraceLogger *logger = TraceLoggerForMainThread(cx->runtime());
+    args.rval().setBoolean(TraceLoggerDisable(logger));
+
+    return true;
+}
+
 static const JSFunctionSpecWithHelp TestingFunctions[] = {
     JS_FN_HELP("gc", ::GC, 0, 0,
 "gc([obj] | 'compartment')",
@@ -1723,6 +1744,15 @@ static const JSFunctionSpecWithHelp TestingFunctions[] = {
 "workerThreadCount()",
 "  Returns the number of worker threads available for off-main-thread tasks."),
 
+    JS_FN_HELP("startTraceLogger", EnableTraceLogger, 0, 0,
+"startTraceLogger()",
+"  Start logging the mainThread.\n"
+"  Note: tracelogging starts automatically. Disable it by setting environment variable\n"
+"  TLOPTIONS=disableMainThread"),
+
+    JS_FN_HELP("stopTraceLogger", DisableTraceLogger, 0, 0,
+"startTraceLogger()",
+"  Stop logging the mainThread."),
     JS_FS_HELP_END
 };
 

js/src/vm/TraceLogging.cpp

@@ -110,6 +110,7 @@ const char* const text[] = {
 
 TraceLogger::TraceLogger()
  : enabled(false),
+   enabledTimes(0),
    failed(false),
    nextTextId(0),
    treeOffset(0),
@@ -128,7 +129,7 @@ TraceLogger::init(uint32_t loggerId)
     if (!events.init())
         return false;
 
-    JS_ASSERT(loggerId <= 999);
+    MOZ_ASSERT(loggerId <= 999);
 
     char dictFilename[sizeof TRACE_LOG_DIR "tl-dict.100.json"];
     sprintf(dictFilename, TRACE_LOG_DIR "tl-dict.%d.json", loggerId);
@@ -159,16 +160,16 @@ TraceLogger::init(uint32_t loggerId)
     uint64_t start = rdtsc() - traceLoggers.startupTime;
 
     TreeEntry &treeEntry = tree.pushUninitialized();
-    treeEntry.start = start;
-    treeEntry.stop = 0;
-    treeEntry.u.s.textId = 0;
-    treeEntry.u.s.hasChildren = false;
-    treeEntry.nextId = 0;
+    treeEntry.setStart(start);
+    treeEntry.setStop(0);
+    treeEntry.setTextId(0);
+    treeEntry.setHasChildren(false);
+    treeEntry.setNextId(0);
 
     StackEntry &stackEntry = stack.pushUninitialized();
-    stackEntry.treeId = 0;
-    stackEntry.lastChildId = 0;
-    stackEntry.active = true;
+    stackEntry.setTreeId(0);
+    stackEntry.setLastChildId(0);
+    stackEntry.setActive(true);
 
     int written = fprintf(dictFile, "[");
     if (written < 0)
@@ -177,17 +178,127 @@ TraceLogger::init(uint32_t loggerId)
     // Eagerly create the default textIds, to match their Tracelogger::TextId.
     for (uint32_t i = 0; i < LAST; i++) {
         mozilla::DebugOnly<uint32_t> textId = createTextId(text[i]);
-        JS_ASSERT(textId == i);
+        MOZ_ASSERT(textId == i);
     }
 
     enabled = true;
+    enabledTimes = 1;
+    return true;
+}
+
+bool
+TraceLogger::enable()
+{
+    if (enabled) {
+        enabledTimes++;
+        return true;
+    }
+
+    if (failed)
+        return false;
+
+    if (!tree.ensureSpaceBeforeAdd(stack.size())) {
+        if (!flush()) {
+            fprintf(stderr, "TraceLogging: Couldn't write the data to disk.\n");
+            failed = true;
+            return false;
+        }
+        if (!tree.ensureSpaceBeforeAdd(stack.size())) {
+            fprintf(stderr, "TraceLogging: Couldn't reserve enough space.\n");
+            failed = true;
+            return false;
+        }
+    }
+
+    uint64_t start = rdtsc() - traceLoggers.startupTime;
+    StackEntry *parent = &stack[0];
+    for (uint32_t i = 1; i < stack.size(); i++) {
+        if (!traceLoggers.isTextIdEnabled(stack[i].textId()))
+            continue;
+#ifdef DEBUG
+        TreeEntry entry;
+        if (!getTreeEntry(parent->treeId(), &entry))
+            return false;
+#endif
+
+        if (parent->lastChildId() == 0) {
+            MOZ_ASSERT(!entry.hasChildren());
+            MOZ_ASSERT(parent->treeId() == tree.currentId() + treeOffset);
+            if (!updateHasChildren(parent->treeId())) {
+                fprintf(stderr, "TraceLogging: Couldn't update an entry.\n");
+                failed = true;
+                return false;
+            }
+        } else {
+            MOZ_ASSERT(entry.hasChildren() == 1);
+            if (!updateNextId(parent->lastChildId(), tree.nextId() + treeOffset)) {
+                fprintf(stderr, "TraceLogging: Couldn't update an entry.\n");
+                failed = true;
+                return false;
+            }
+        }
+
+        TreeEntry &treeEntry = tree.pushUninitialized();
+        treeEntry.setStart(start);
+        treeEntry.setStop(0);
+        treeEntry.setTextId(stack[i].textId());
+        treeEntry.setHasChildren(false);
+        treeEntry.setNextId(0);
+
+        stack[i].setActive(true);
+        stack[i].setTreeId(tree.currentId() + treeOffset);
+
+        parent->setLastChildId(tree.currentId() + treeOffset);
+
+        parent = &stack[i];
+    }
+
+    enabled = true;
+    enabledTimes = 1;
+
+    return true;
+}
+
+bool
+TraceLogger::disable()
+{
+    if (failed)
+        return false;
+
+    if (!enabled)
+        return true;
+
+    if (enabledTimes > 1) {
+        enabledTimes--;
+        return true;
+    }
+
+    uint64_t stop = rdtsc() - traceLoggers.startupTime;
+    for (uint32_t i = 1; i < stack.size(); i++) {
+        if (!stack[i].active())
+            continue;
+
+        if (!updateStop(stack[i].treeId(), stop)) {
+            fprintf(stderr, "TraceLogging: Failed to stop an event.\n");
+            failed = true;
+            enabled = false;
+            return false;
+        }
+
+        stack[i].setActive(false);
+    }
+
+
+    enabled = false;
+    enabledTimes = 0;
+
     return true;
 }
 
 bool
 TraceLogger::flush()
 {
-    JS_ASSERT(!failed);
+    MOZ_ASSERT(!failed);
 
     if (treeFile) {
         // Format data in big endian.
@@ -364,23 +475,23 @@ TraceLogger::logTimestamp(uint32_t id)
 void
 TraceLogger::entryToBigEndian(TreeEntry *entry)
 {
-    entry->start = htobe64(entry->start);
-    entry->stop = htobe64(entry->stop);
-    entry->u.value = htobe32((entry->u.s.textId << 1) + entry->u.s.hasChildren);
-    entry->nextId = htobe32(entry->nextId);
+    entry->start_ = htobe64(entry->start_);
+    entry->stop_ = htobe64(entry->stop_);
+    entry->u.value_ = htobe32((entry->u.s.textId_ << 1) + entry->u.s.hasChildren_);
+    entry->nextId_ = htobe32(entry->nextId_);
 }
 
 void
 TraceLogger::entryToSystemEndian(TreeEntry *entry)
 {
-    entry->start = be64toh(entry->start);
-    entry->stop = be64toh(entry->stop);
+    entry->start_ = be64toh(entry->start_);
+    entry->stop_ = be64toh(entry->stop_);
 
-    uint32_t data = be32toh(entry->u.value);
-    entry->u.s.textId = data >> 1;
-    entry->u.s.hasChildren = data & 0x1;
+    uint32_t data = be32toh(entry->u.value_);
+    entry->u.s.textId_ = data >> 1;
+    entry->u.s.hasChildren_ = data & 0x1;
 
-    entry->nextId = be32toh(entry->nextId);
+    entry->nextId_ = be32toh(entry->nextId_);
 }
 
 bool
@@ -427,13 +538,13 @@ TraceLogger::updateHasChildren(uint32_t treeId, bool hasChildren)
         TreeEntry entry;
         if (!getTreeEntry(treeId, &entry))
             return false;
-        entry.u.s.hasChildren = hasChildren;
+        entry.setHasChildren(hasChildren);
         if (!saveTreeEntry(treeId, &entry))
             return false;
         return true;
     }
 
-    tree[treeId - treeOffset].u.s.hasChildren = hasChildren;
+    tree[treeId - treeOffset].setHasChildren(hasChildren);
     return true;
 }
 
@@ -444,13 +555,13 @@ TraceLogger::updateNextId(uint32_t treeId, uint32_t nextId)
         TreeEntry entry;
         if (!getTreeEntry(treeId, &entry))
             return false;
-        entry.nextId = nextId;
+        entry.setNextId(nextId);
         if (!saveTreeEntry(treeId, &entry))
             return false;
         return true;
     }
 
-    tree[treeId - treeOffset].nextId = nextId;
+    tree[treeId - treeOffset].setNextId(nextId);
     return true;
 }
 
@@ -461,20 +572,20 @@ TraceLogger::updateStop(uint32_t treeId, uint64_t timestamp)
         TreeEntry entry;
         if (!getTreeEntry(treeId, &entry))
             return false;
-        entry.stop = timestamp;
+        entry.setStop(timestamp);
         if (!saveTreeEntry(treeId, &entry))
             return false;
         return true;
     }
 
-    tree[treeId - treeOffset].stop = timestamp;
+    tree[treeId - treeOffset].setStop(timestamp);
     return true;
 }
 
 void
 TraceLogger::startEvent(uint32_t id)
 {
-    if (!enabled)
+    if (failed)
         return;
 
     if (!stack.ensureSpaceBeforeAdd()) {
@@ -484,6 +595,15 @@ TraceLogger::startEvent(uint32_t id)
         return;
     }
 
+    if (!enabled) {
+        StackEntry &stackEntry = stack.pushUninitialized();
+        stackEntry.setTreeId(tree.currentId() + treeOffset);
+        stackEntry.setLastChildId(0);
+        stackEntry.setTextId(id);
+        stackEntry.setActive(false);
+        return;
+    }
+
     if (!tree.ensureSpaceBeforeAdd()) {
         uint64_t start = rdtsc() - traceLoggers.startupTime;
         if (!flush()) {
@@ -517,7 +637,7 @@ TraceLogger::StackEntry &
 TraceLogger::getActiveAncestor()
 {
     uint32_t parentId = stack.currentId();
-    while (!stack[parentId].active)
+    while (!stack[parentId].active())
         parentId--;
     return stack[parentId];
 }
@@ -530,7 +650,7 @@ TraceLogger::startEvent(uint32_t id, uint64_t timestamp)
     // the stop event.
     if (!traceLoggers.isTextIdEnabled(id)) {
         StackEntry &stackEntry = stack.pushUninitialized();
-        stackEntry.active = false;
+        stackEntry.setActive(false);
         return true;
     }
 
@@ -541,39 +661,39 @@ TraceLogger::startEvent(uint32_t id, uint64_t timestamp)
     StackEntry &parent = getActiveAncestor();
 #ifdef DEBUG
     TreeEntry entry;
-    if (!getTreeEntry(parent.treeId, &entry))
+    if (!getTreeEntry(parent.treeId(), &entry))
         return false;
 #endif
 
-    if (parent.lastChildId == 0) {
-        JS_ASSERT(entry.u.s.hasChildren == 0);
-        JS_ASSERT(parent.treeId == tree.currentId() + treeOffset);
+    if (parent.lastChildId() == 0) {
+        MOZ_ASSERT(!entry.hasChildren());
+        MOZ_ASSERT(parent.treeId() == tree.currentId() + treeOffset);
 
-        if (!updateHasChildren(parent.treeId))
+        if (!updateHasChildren(parent.treeId()))
             return false;
     } else {
-        JS_ASSERT(entry.u.s.hasChildren == 1);
+        MOZ_ASSERT(entry.hasChildren());
 
-        if (!updateNextId(parent.lastChildId, tree.nextId() + treeOffset))
+        if (!updateNextId(parent.lastChildId(), tree.nextId() + treeOffset))
             return false;
     }
 
     // Add a new tree entry.
     TreeEntry &treeEntry = tree.pushUninitialized();
-    treeEntry.start = timestamp;
-    treeEntry.stop = 0;
-    treeEntry.u.s.textId = id;
-    treeEntry.u.s.hasChildren = false;
-    treeEntry.nextId = 0;
+    treeEntry.setStart(timestamp);
+    treeEntry.setStop(0);
+    treeEntry.setTextId(id);
+    treeEntry.setHasChildren(false);
+    treeEntry.setNextId(0);
 
     // Add a new stack entry.
     StackEntry &stackEntry = stack.pushUninitialized();
-    stackEntry.treeId = tree.currentId() + treeOffset;
-    stackEntry.lastChildId = 0;
-    stackEntry.active = true;
+    stackEntry.setTreeId(tree.currentId() + treeOffset);
+    stackEntry.setLastChildId(0);
+    stackEntry.setActive(true);
 
     // Set the last child of the parent to this newly added entry.
-    parent.lastChildId = tree.currentId() + treeOffset;
+    parent.setLastChildId(tree.currentId() + treeOffset);
 
     return true;
 }
@@ -583,8 +703,8 @@ TraceLogger::stopEvent(uint32_t id)
 {
 #ifdef DEBUG
     TreeEntry entry;
-    JS_ASSERT(getTreeEntry(stack.current().treeId, &entry));
-    JS_ASSERT(entry.u.s.textId == id);
+    MOZ_ASSERT(getTreeEntry(stack.current().treeId(), &entry));
+    MOZ_ASSERT(entry.textId() == id);
 #endif
     stopEvent();
 }
@@ -592,12 +712,9 @@ TraceLogger::stopEvent(uint32_t id)
 void
 TraceLogger::stopEvent()
 {
-    if (!enabled)
-        return;
-
-    if (stack.current().active) {
+    if (enabled && stack.current().active()) {
         uint64_t stop = rdtsc() - traceLoggers.startupTime;
-        if (!updateStop(stack.current().treeId, stop)) {
+        if (!updateStop(stack.current().treeId(), stop)) {
             fprintf(stderr, "TraceLogging: Failed to stop an event.\n");
             enabled = false;
             failed = true;
@@ -611,6 +728,8 @@ TraceLogging::TraceLogging()
 {
     initialized = false;
     enabled = false;
+    mainThreadEnabled = true;
+    offThreadEnabled = true;
     loggerId = 0;
 
 #ifdef JS_THREADSAFE
@@ -683,7 +802,7 @@ TraceLogging::lazyInit()
 
     const char *env = getenv("TLLOG");
     if (!env)
-        return false;
+        env = "";
 
     if (strstr(env, "help")) {
         fflush(nullptr);
@@ -750,6 +869,28 @@ TraceLogging::lazyInit()
         enabledTextIds[TraceLogger::EliminateRedundantChecks] = true;
     }
 
+    const char *options = getenv("TLOPTIONS");
+    if (options) {
+        if (strstr(options, "help")) {
+            fflush(nullptr);
+            printf(
+                "\n"
+                "usage: TLOPTIONS=option,option,option,... where options can be:\n"
+                "\n"
+                "  DisableMainThread        Don't start logging the mainThread automatically.\n"
+                "  DisableOffThread         Don't start logging the off mainThread automatically.\n"
+            );
+            printf("\n");
+            exit(0);
+            /*NOTREACHED*/
+        }
+
+        if (strstr(options, "DisableMainThread"))
+           mainThreadEnabled = false;
+        if (strstr(options, "DisableOffThread"))
+           offThreadEnabled = false;
+    }
+
     startupTime = rdtsc();
     enabled = true;
     return true;
@@ -793,6 +934,9 @@ TraceLogging::forMainThread(PerThreadData *mainThread)
 
         if (!mainThreadLoggers.append(logger))
             return nullptr;
+
+        if (!mainThreadEnabled)
+            logger->disable();
     }
 
     return mainThread->traceLogger;
@@ -831,6 +975,9 @@ TraceLogging::forThread(PRThread *thread)
         return nullptr;
     }
 
+    if (!offThreadEnabled)
+        logger->disable();
+
     return logger;
 }
 #endif // JS_THREADSAFE

js/src/vm/TraceLogging.h

@@ -152,7 +152,7 @@ class ContinuousSpace {
     }
 
     uint32_t currentId() {
-        JS_ASSERT(next_ > 0);
+        MOZ_ASSERT(next_ > 0);
         return next_ - 1;
     }
 
@@ -160,11 +160,13 @@ class ContinuousSpace {
         return data()[currentId()];
     }
 
-    bool ensureSpaceBeforeAdd() {
-        if (next_ < capacity_)
+    bool ensureSpaceBeforeAdd(uint32_t count = 1) {
+        if (next_ + count <= capacity_)
             return true;
 
         uint32_t nCapacity = capacity_ * 2;
+        if (next_ + count > nCapacity)
+            nCapacity = next_ + count;
         T *entries = (T *) js_realloc(data_, nCapacity * sizeof(T));
 
         if (!entries)
@@ -187,11 +189,12 @@ class ContinuousSpace {
     }
 
     T &pushUninitialized() {
+        MOZ_ASSERT(next_ < capacity_);
         return data()[next_++];
     }
 
     void pop() {
-        JS_ASSERT(next_ > 0);
+        MOZ_ASSERT(next_ > 0);
         next_--;
     }
 
@@ -259,40 +262,102 @@ class TraceLogger
     // The layout of the tree in memory and in the log file. Readable by JS
     // using TypedArrays.
     struct TreeEntry {
-        uint64_t start;
-        uint64_t stop;
+        uint64_t start_;
+        uint64_t stop_;
         union {
             struct {
-                uint32_t textId: 31;
-                uint32_t hasChildren: 1;
+                uint32_t textId_: 31;
+                uint32_t hasChildren_: 1;
             } s;
-            uint32_t value;
+            uint32_t value_;
         } u;
-        uint32_t nextId;
+        uint32_t nextId_;
 
         TreeEntry(uint64_t start, uint64_t stop, uint32_t textId, bool hasChildren,
                   uint32_t nextId)
         {
-            this->start = start;
-            this->stop = stop;
-            this->u.s.textId = textId;
-            this->u.s.hasChildren = hasChildren;
-            this->nextId = nextId;
+            start_ = start;
+            stop_ = stop;
+            u.s.textId_ = textId;
+            u.s.hasChildren_ = hasChildren;
+            nextId_ = nextId;
         }
         TreeEntry()
         { }
+        uint64_t start() {
+            return start_;
+        }
+        uint64_t stop() {
+            return stop_;
+        }
+        uint32_t textId() {
+            return u.s.textId_;
+        }
+        bool hasChildren() {
+            return u.s.hasChildren_;
+        }
+        uint32_t nextId() {
+            return nextId_;
+        }
+        void setStart(uint64_t start) {
+            start_ = start;
+        }
+        void setStop(uint64_t stop) {
+            stop_ = stop;
+        }
+        void setTextId(uint32_t textId) {
+            MOZ_ASSERT(textId < (1<<31) );
+            u.s.textId_ = textId;
+        }
+        void setHasChildren(bool hasChildren) {
+            u.s.hasChildren_ = hasChildren;
+        }
+        void setNextId(uint32_t nextId) {
+            nextId_ = nextId;
+        }
     };
 
     // Helper structure for keeping track of the current entries in
     // the tree. Pushed by `start(id)`, popped by `stop(id)`. The active flag
     // is used to know if a subtree doesn't need to get logged.
     struct StackEntry {
-        uint32_t treeId;
-        uint32_t lastChildId;
-        bool active;
+        uint32_t treeId_;
+        uint32_t lastChildId_;
+        struct {
+            uint32_t textId_: 31;
+            uint32_t active_: 1;
+        } s;
         StackEntry(uint32_t treeId, uint32_t lastChildId, bool active = true)
-          : treeId(treeId), lastChildId(lastChildId), active(active)
-        { }
+          : treeId_(treeId), lastChildId_(lastChildId)
+        {
+            s.textId_ = 0;
+            s.active_ = active;
+        }
+        uint32_t treeId() {
+            return treeId_;
+        }
+        uint32_t lastChildId() {
+            return lastChildId_;
+        }
+        uint32_t textId() {
+            return s.textId_;
+        }
+        bool active() {
+            return s.active_;
+        }
+        void setTreeId(uint32_t treeId) {
+            treeId_ = treeId;
+        }
+        void setLastChildId(uint32_t lastChildId) {
+            lastChildId_ = lastChildId;
+        }
+        void setTextId(uint32_t textId) {
+            MOZ_ASSERT(textId < (1<<31) );
+            s.textId_ = textId;
+        }
+        void setActive(bool active) {
+            s.active_ = active;
+        }
     };
 
     // The layout of the event log in memory and in the log file.
@@ -310,6 +375,7 @@ class TraceLogger
     FILE *eventFile;
 
     bool enabled;
+    uint32_t enabledTimes;
     bool failed;
     uint32_t nextTextId;
 
@@ -356,6 +422,9 @@ class TraceLogger
 
     bool init(uint32_t loggerId);
 
+    bool enable();
+    bool disable();
+
     // The createTextId functions map a unique input to a logger ID.
     // This ID can be used to log something. Calls to these functions should be
     // limited if possible, because of the overhead.
@@ -397,6 +466,8 @@ class TraceLogging
     bool initialized;
     bool enabled;
     bool enabledTextIds[TraceLogger::LAST];
+    bool mainThreadEnabled;
+    bool offThreadEnabled;
 #ifdef JS_THREADSAFE
     ThreadLoggerHashMap threadLoggers;
 #endif // JS_THREADSAFE
@@ -448,6 +519,21 @@ inline TraceLogger *TraceLoggerForCurrentThread() {
 };
 #endif
 
+inline bool TraceLoggerEnable(TraceLogger *logger) {
+#ifdef JS_TRACE_LOGGING
+    if (logger)
+        return logger->enable();
+#endif
+    return false;
+}
+inline bool TraceLoggerDisable(TraceLogger *logger) {
+#ifdef JS_TRACE_LOGGING
+    if (logger)
+        return logger->disable();
+#endif
+    return false;
+}
+
 inline uint32_t TraceLogCreateTextId(TraceLogger *logger, JSScript *script) {
 #ifdef JS_TRACE_LOGGING
     if (logger)