Bug 766752: Add trace logging, r=jandem

js/src/Makefile.in

@@ -228,6 +228,16 @@ MFBT_ROOT = $(srcdir)/../../mfbt
 VPATH += $(MFBT_ROOT)
 include $(MFBT_ROOT)/exported_headers.mk
 
+
+ifdef ENABLE_TRACE_LOGGING
+
+###############################################
+# BEGIN include sources for trace logging
+#
+CPPSRCS += 	TraceLogging.cpp
+
+endif
+
 ifdef ENABLE_METHODJIT
 
 ###############################################

js/src/TraceLogging.cpp

@@ -0,0 +1,260 @@
+/* -*- Mode: C++; tab-width: 8; indent-tabs-mode: nil; c-basic-offset: 4 -*- */
+/* vim: set ts=4 sw=4 et tw=79: */
+/* This Source Code Form is subject to the terms of the Mozilla Public
+ * License, v. 2.0. If a copy of the MPL was not distributed with this file,
+ * You can obtain one at http://mozilla.org/MPL/2.0/. */
+
+#include "TraceLogging.h"
+#include <cstdarg>
+#include <cstdio>
+#include <cstdlib>
+#include <unistd.h>
+#include <string.h>
+#include <stdint.h>
+
+#ifndef TRACE_LOG_DIR
+# if defined(_WIN32)
+#  define TRACE_LOG_DIR ""
+# else
+#  define TRACE_LOG_DIR "/tmp/"
+# endif
+#endif
+
+namespace js {
+
+#if defined(__i386__)
+static __inline__ uint64_t
+rdtsc(void)
+{
+    uint64_t x;
+    __asm__ volatile (".byte 0x0f, 0x31" : "=A" (x));
+    return x;
+}
+#elif defined(__x86_64__)
+static __inline__ uint64_t
+rdtsc(void)
+{
+    unsigned hi, lo;
+    __asm__ __volatile__ ("rdtsc" : "=a"(lo), "=d"(hi));
+    return ( (uint64_t)lo)|( ((uint64_t)hi)<<32 );
+}
+#elif defined(__powerpc__)
+static __inline__ uint64_t
+rdtsc(void)
+{
+    uint64_t result=0;
+    uint32_t upper, lower,tmp;
+    __asm__ volatile(
+            "0:                  \n"
+            "\tmftbu   %0           \n"
+            "\tmftb    %1           \n"
+            "\tmftbu   %2           \n"
+            "\tcmpw    %2,%0        \n"
+            "\tbne     0b         \n"
+            : "=r"(upper),"=r"(lower),"=r"(tmp)
+            );
+    result = upper;
+    result = result<<32;
+    result = result|lower;
+
+    return(result);
+}
+#endif
+
+const char* TraceLogging::type_name[] = {
+    "start,ion_compile",
+    "stop,ion_compile",
+    "start,ion_cannon",
+    "stop,ion_cannon",
+    "stop,ion_cannon_bailout",
+    "start,ion_side_cannon",
+    "stop,ion_side_cannon",
+    "stop,ion_side_cannon_bailout",
+    "start,yarr_jit_execute",
+    "stop,yarr_jit_execute",
+    "start,jm_safepoint",
+    "stop,jm_safepoint",
+    "start,jm_normal",
+    "stop,jm_normal",
+    "start,jm_compile",
+    "stop,jm_compile",
+    "start,gc",
+    "stop,gc",
+    "start,interpreter",
+    "stop,interpreter"
+};
+TraceLogging* TraceLogging::_defaultLogger = NULL;
+
+TraceLogging::TraceLogging()
+  : loggingTime(0),
+    entries(NULL),
+    curEntry(0),
+    numEntries(1000000),
+    fileno(0),
+    out(NULL)
+{
+}
+
+TraceLogging::~TraceLogging()
+{
+    if (out != NULL) {
+        fclose(out);
+        out = NULL;
+    }
+
+    if (entries != NULL) {
+        flush();
+        free(entries);
+        entries = NULL;
+    }
+}
+
+void
+TraceLogging::grow()
+{
+    Entry* nentries = (Entry*) realloc(entries, numEntries*2*sizeof(Entry));
+
+    // Allocating a bigger array failed.
+    // Keep using the current storage, but remove all entries by flushing them.
+    if (nentries == NULL) {
+        flush();
+        return;
+    }
+
+    entries = nentries;
+    numEntries *= 2;
+}
+
+void
+TraceLogging::log(Type type, const char* file, unsigned int lineno)
+{
+    uint64_t now = rdtsc();
+
+    // Create array containing the entries if not existing.
+    if (entries == NULL) {
+        entries = (Entry*) malloc(numEntries*sizeof(Entry));
+        if (entries == NULL)
+            return;
+    }
+
+    // Copy the logging information,
+    // because original could already be freed before writing the log file.
+    char *copy = NULL;
+    if (file != NULL)
+        copy = strdup(file);
+
+    entries[curEntry++] = Entry(now - loggingTime, copy, lineno, type);
+
+    // Increase length when not enough place in the array
+    if (curEntry >= numEntries)
+        grow();
+
+    // Save the time spend logging the information in order to discard this time from the logged time.
+    // Especially needed when increasing the array or flushing the information.
+    loggingTime += rdtsc()-now;
+}
+
+void
+TraceLogging::log(Type type, JSScript* script)
+{
+    this->log(type, script->filename, script->lineno);
+}
+
+void
+TraceLogging::log(const char* log)
+{
+    this->log(INFO, log, 0);
+}
+
+void
+TraceLogging::log(Type type)
+{
+    this->log(type, NULL, 0);
+}
+
+void
+TraceLogging::flush()
+{
+    // Open the logging file, when not opened yet.
+    if (out == NULL)
+        out = fopen(TRACE_LOG_DIR "tracelogging.log", "w");
+
+    // Print all log entries into the file
+    for (unsigned int i = 0; i < curEntry; i++) {
+        int written;
+        if (entries[i].type() == INFO) {
+            written = fprintf(out, "INFO,%s\n", entries[i].file());
+        } else {
+            if (entries[i].file() == NULL) {
+                written = fprintf(out, "%llu,%s\n",
+                                  (unsigned long long)entries[i].tick(),
+                                  type_name[entries[i].type()]);
+            } else {
+                written = fprintf(out, "%llu,%s,%s:%d\n",
+                                  (unsigned long long)entries[i].tick(),
+                                  type_name[entries[i].type()],
+                                  entries[i].file(),
+                                  entries[i].lineno());
+            }
+        }
+
+        // A logging file can only be 2GB of length (fwrite limit).
+        // When we exceed this limit, the writing will fail.
+        // In that case try creating a extra file to write the log entries.
+        if (written < 0) {
+            fclose(out);
+            if (fileno >= 9999)
+                exit(-1);
+
+            char filename[21 + sizeof(TRACE_LOG_DIR)];
+            sprintf (filename, TRACE_LOG_DIR "tracelogging-%d.log", ++fileno);
+            out = fopen(filename, "w");
+            i--; // Try to print message again
+            continue;
+        }
+
+        if (entries[i].file() != NULL) {
+            free(entries[i].file());
+            entries[i].file_ = NULL;
+        }
+    }
+    curEntry = 0;
+}
+
+TraceLogging*
+TraceLogging::defaultLogger()
+{
+    if (_defaultLogger == NULL) {
+        _defaultLogger = new TraceLogging();
+        atexit (releaseDefaultLogger);
+    }
+    return _defaultLogger;
+}
+
+void
+TraceLogging::releaseDefaultLogger()
+{
+    if (_defaultLogger != NULL) {
+        delete _defaultLogger;
+        _defaultLogger = NULL;
+    }
+}
+
+/* Helper functions for asm calls */
+void
+TraceLog(TraceLogging* logger, TraceLogging::Type type, JSScript* script)
+{
+    logger->log(type, script);
+}
+void
+TraceLog(TraceLogging* logger, const char* log)
+{
+    logger->log(log);
+}
+void
+TraceLog(TraceLogging* logger, TraceLogging::Type type)
+{
+    logger->log(type);
+}
+
+}  /* namespace js */

js/src/TraceLogging.h

@@ -0,0 +1,117 @@
+/* -*- Mode: C++; tab-width: 8; indent-tabs-mode: nil; c-basic-offset: 4 -*- */
+/* vim: set ts=4 sw=4 et tw=79: */
+/* This Source Code Form is subject to the terms of the Mozilla Public
+ * License, v. 2.0. If a copy of the MPL was not distributed with this file,
+ * You can obtain one at http://mozilla.org/MPL/2.0/. */
+
+#if !defined(TraceLogging_h__)
+#define TraceLogging_h__
+
+#include "jsscript.h"
+
+namespace js {
+
+class TraceLogging
+{
+  public:
+    enum Type {
+        ION_COMPILE_START,
+        ION_COMPILE_STOP,
+        ION_CANNON_START,
+        ION_CANNON_STOP,
+        ION_CANNON_BAIL,
+        ION_SIDE_CANNON_START,
+        ION_SIDE_CANNON_STOP,
+        ION_SIDE_CANNON_BAIL,
+        YARR_YIT_START,
+        YARR_YIT_STOP,
+        JM_SAFEPOINT_START,
+        JM_SAFEPOINT_STOP,
+        JM_START,
+        JM_STOP,
+        JM_COMPILE_START,
+        JM_COMPILE_STOP,
+        GC_START,
+        GC_STOP,
+        INTERPRETER_START,
+        INTERPRETER_STOP,
+        INFO
+    };
+
+  private:
+    struct Entry {
+        uint64_t tick_;
+        char* file_;
+        uint32_t lineno_;
+        uint8_t type_;
+
+        Entry(uint64_t tick, char* file, uint32_t lineno, Type type)
+            : tick_(tick), file_(file), lineno_(lineno), type_((uint8_t)type) {}
+
+        uint64_t tick() const { return tick_; }
+        char *file() const { return file_; }
+        uint32_t lineno() const { return lineno_; }
+        Type type() const { return (Type) type_; }
+    };
+
+    uint64_t loggingTime;
+    Entry *entries;
+    unsigned int curEntry;
+    unsigned int numEntries;
+    int fileno;
+    FILE *out;
+
+    const static char *type_name[];
+    static TraceLogging* _defaultLogger;
+  public:
+    TraceLogging();
+    ~TraceLogging();
+
+    void log(Type type, const char* filename, unsigned int line);
+    void log(Type type, JSScript* script);
+    void log(const char* log);
+    void log(Type type);
+    void flush();
+
+    static TraceLogging* defaultLogger();
+    static void releaseDefaultLogger();
+
+  private:
+    void grow();
+};
+
+/* Helpers functions for asm calls */
+void TraceLog(TraceLogging* logger, TraceLogging::Type type, JSScript* script);
+void TraceLog(TraceLogging* logger, const char* log);
+void TraceLog(TraceLogging* logger, TraceLogging::Type type);
+
+/* Automatic logging at the start and end of function call */
+class AutoTraceLog {
+    TraceLogging* logger;
+    TraceLogging::Type stop;
+
+  public:
+    AutoTraceLog(TraceLogging* logger, TraceLogging::Type start, TraceLogging::Type stop, JSScript* script)
+      : logger(logger),
+        stop(stop)
+    {
+        logger->log(start, script);
+    }
+
+    AutoTraceLog(TraceLogging* logger, TraceLogging::Type start, TraceLogging::Type stop)
+      : logger(logger),
+        stop(stop)
+    {
+        logger->log(start);
+    }
+
+    ~AutoTraceLog()
+    {
+        logger->log(stop);
+    }
+};
+
+}  /* namespace js */
+
+#endif // TraceLogging_h__
+

js/src/configure.in

@@ -3482,6 +3482,20 @@ if test -n "$MOZ_DEBUG" -o -n "$MOZ_DEBUG_SYMBOLS"; then
     export MOZ_DEBUG_SYMBOLS
 fi
 
+dnl ========================================================
+dnl = Enable trace logging
+dnl ========================================================
+MOZ_ARG_ENABLE_BOOL(trace-logging,
+[  --enable-trace-logging   Enable trace logging],
+    ENABLE_TRACE_LOGGING=1,
+    ENABLE_TRACE_LOGGING= )
+
+AC_SUBST(ENABLE_TRACE_LOGGING)
+
+if test "$ENABLE_TRACE_LOGGING"; then
+    AC_DEFINE(JS_TRACE_LOGGING)
+fi
+
 dnl ========================================================
 dnl = Enable any treating of compile warnings as errors
 dnl ========================================================

js/src/ion/Ion.cpp

@@ -37,6 +37,10 @@
 #include "ion/CompilerRoot.h"
 #include "methodjit/Retcon.h"
 
+#if JS_TRACE_LOGGING
+#include "TraceLogging.h"
+#endif
+
 using namespace js;
 using namespace js::ion;
 
@@ -845,6 +849,13 @@ template <bool Compiler(IonBuilder &, MIRGraph &)>
 static bool
 IonCompile(JSContext *cx, JSScript *script, JSFunction *fun, jsbytecode *osrPc, bool constructing)
 {
+#if JS_TRACE_LOGGING
+    AutoTraceLog logger(TraceLogging::defaultLogger(),
+                        TraceLogging::ION_COMPILE_START,
+                        TraceLogging::ION_COMPILE_STOP,
+                        script);
+#endif
+
     TempAllocator temp(&cx->tempLifoAlloc());
     IonContext ictx(cx, cx->compartment, &temp);
 
@@ -1177,7 +1188,27 @@ ion::Cannon(JSContext *cx, StackFrame *fp)
     IonCode *code = ion->method();
     void *jitcode = code->raw();
 
-    return EnterIon(cx, fp, jitcode);
+#if JS_TRACE_LOGGING
+    TraceLog(TraceLogging::defaultLogger(),
+             TraceLogging::ION_CANNON_START,
+             script);
+#endif
+
+    IonExecStatus status = EnterIon(cx, fp, jitcode);
+
+#if JS_TRACE_LOGGING
+    if (status == IonExec_Bailout) {
+        TraceLog(TraceLogging::defaultLogger(),
+                 TraceLogging::ION_CANNON_BAIL,
+                 script);
+    } else {
+        TraceLog(TraceLogging::defaultLogger(),
+                 TraceLogging::ION_CANNON_STOP,
+                 script);
+    }
+#endif
+
+    return status;
 }
 
 IonExecStatus
@@ -1190,7 +1221,27 @@ ion::SideCannon(JSContext *cx, StackFrame *fp, jsbytecode *pc)
 
     JS_ASSERT(ion->osrPc() == pc);
 
-    return EnterIon(cx, fp, osrcode);
+#if JS_TRACE_LOGGING
+    TraceLog(TraceLogging::defaultLogger(),
+             TraceLogging::ION_SIDE_CANNON_START,
+             script);
+#endif
+
+    IonExecStatus status = EnterIon(cx, fp, osrcode);
+
+#if JS_TRACE_LOGGING
+    if (status == IonExec_Bailout) {
+        TraceLog(TraceLogging::defaultLogger(),
+                 TraceLogging::ION_SIDE_CANNON_BAIL,
+                 script);
+    } else {
+        TraceLog(TraceLogging::defaultLogger(),
+                 TraceLogging::ION_SIDE_CANNON_STOP,
+                 script);
+    }
+#endif
+
+    return status;
 }
 
 static void

js/src/jsgc.cpp

@@ -105,6 +105,10 @@
 # include <unistd.h>
 #endif
 
+#if JS_TRACE_LOGGING
+#include "TraceLogging.h"
+#endif
+
 using namespace mozilla;
 using namespace js;
 using namespace js::gc;
@@ -4219,6 +4223,12 @@ Collect(JSRuntime *rt, bool incremental, int64_t budget,
 {
     JS_AbortIfWrongThread(rt);
 
+#if JS_TRACE_LOGGING
+    AutoTraceLog logger(TraceLogging::defaultLogger(),
+                        TraceLogging::GC_START,
+                        TraceLogging::GC_STOP);
+#endif
+
     ContextIter cx(rt);
     if (!cx.done())
         MaybeCheckStackRoots(cx);

js/src/jsinterp.cpp

@@ -74,6 +74,10 @@
 #include "methodjit/MonoIC.h"
 #endif
 
+#if JS_TRACE_LOGGING
+#include "TraceLogging.h"
+#endif
+
 using namespace js;
 using namespace js::gc;
 using namespace js::types;
@@ -1237,6 +1241,13 @@ js::Interpret(JSContext *cx, StackFrame *entryFrame, InterpMode interpMode)
     Rooted<JSScript*> script(cx);
     SET_SCRIPT(regs.fp()->script());
 
+#if JS_TRACE_LOGGING
+    AutoTraceLog logger(TraceLogging::defaultLogger(),
+                        TraceLogging::INTERPRETER_START,
+                        TraceLogging::INTERPRETER_STOP,
+                        script);
+#endif
+
     /*
      * Pool of rooters for use in this interpreter frame. References to these
      * are used for local variables within interpreter cases. This avoids

js/src/methodjit/Compiler.cpp

@@ -34,6 +34,10 @@
 
 #include "ion/Ion.h"
 
+#if JS_TRACE_LOGGING
+#include "TraceLogging.h"
+#endif
+
 using namespace js;
 using namespace js::mjit;
 #if defined(JS_POLYIC) || defined(JS_MONOIC)
@@ -111,6 +115,13 @@ mjit::Compiler::compile()
 {
     JS_ASSERT(!outerChunkRef().chunk);
 
+#if JS_TRACE_LOGGING
+    AutoTraceLog logger(TraceLogging::defaultLogger(),
+                        TraceLogging::JM_COMPILE_START,
+                        TraceLogging::JM_COMPILE_STOP,
+                        outerScript);
+#endif
+
     CompileStatus status = performCompilation();
     if (status != Compile_Okay && status != Compile_Retry) {
         if (!outerScript->ensureHasMJITInfo(cx))

js/src/methodjit/MethodJIT.cpp

@@ -25,6 +25,10 @@
 #include "jsgcinlines.h"
 #include "jsinterpinlines.h"
 
+#if JS_TRACE_LOGGING
+#include "TraceLogging.h"
+#endif
+
 using namespace js;
 using namespace js::mjit;
 
@@ -1103,12 +1107,25 @@ mjit::JaegerShot(JSContext *cx, bool partial)
 
     JS_ASSERT(cx->regs().pc == script->code);
 
+#if JS_TRACE_LOGGING
+    AutoTraceLog logger(TraceLogging::defaultLogger(),
+                        TraceLogging::JM_START,
+                        TraceLogging::JM_STOP,
+                        script);
+#endif
+
     return CheckStackAndEnterMethodJIT(cx, cx->fp(), jit->invokeEntry, partial);
 }
 
 JaegerStatus
 js::mjit::JaegerShotAtSafePoint(JSContext *cx, void *safePoint, bool partial)
 {
+#if JS_TRACE_LOGGING
+    AutoTraceLog logger(TraceLogging::defaultLogger(),
+                        TraceLogging::JM_SAFEPOINT_START,
+                        TraceLogging::JM_SAFEPOINT_STOP,
+                        cx->fp()->script());
+#endif
     return CheckStackAndEnterMethodJIT(cx, cx->fp(), safePoint, partial);
 }
 

js/src/shell/js.cpp

@@ -73,6 +73,10 @@
 #include "jswin.h"
 #endif
 
+#if JS_TRACE_LOGGING
+#include "TraceLogging.h"
+#endif
+
 using namespace mozilla;
 using namespace js;
 using namespace js::cli;
@@ -1171,6 +1175,9 @@ PrintInternal(JSContext *cx, unsigned argc, jsval *vp, FILE *file)
         if (!bytes)
             return false;
         fprintf(file, "%s%s", i ? " " : "", bytes);
+#if JS_TRACE_LOGGING
+        TraceLog(TraceLogging::defaultLogger(), bytes);
+#endif
         JS_free(cx, bytes);
     }
 

js/src/yarr/YarrJIT.h

@@ -43,6 +43,10 @@
 #define YARR_CALL
 #endif
 
+#if JS_TRACE_LOGGING
+#include "TraceLogging.h"
+#endif
+
 namespace JSC {
 
 class JSGlobalData;
@@ -69,6 +73,12 @@ public:
 
     int execute(const UChar* input, unsigned start, unsigned length, int* output)
     {
+#if JS_TRACE_LOGGING
+        js::AutoTraceLog logger(js::TraceLogging::defaultLogger(),
+                                js::TraceLogging::YARR_YIT_START,
+                                js::TraceLogging::YARR_YIT_STOP);
+#endif
+
         return JS_EXTENSION((reinterpret_cast<YarrJITCode>(m_ref.m_code.executableAddress()))(input, start, length, output));
     }