Tracelogger: Create version 0.2

RESOLVED FIXED in mozilla31

Status

()

RESOLVED FIXED
5 years ago
4 years ago

People

(Reporter: h4writer, Assigned: h4writer)

Tracking

(Blocks: 1 bug)

unspecified
mozilla31
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(2 attachments, 5 obsolete attachments)

(Assignee)

Description

5 years ago
It is time to improve the capabilities of tracelogger a bit. I think I almost completely rewrote it, with keeping in mind the comments I got and future needs.

1) Use dummy empty functions instead of #if JS_TRACE_LOGGING everywhere
2) Created js_TraceLoggers that keeps track of the multiple loggers and will host future options (like filtering)
3) Should work in browser
4) Output already in right format. No need for conversion python scripts!
5) Split logger into tree logging and event logging (Used to be INFO, but will get more support now. So it will be easy to log events happening. I.e. bailouts/invalidation/...).
(Assignee)

Comment 1

5 years ago
Created attachment 8339940 [details] [diff] [review]
tracelogger_improvements
Assignee: nobody → hv1989
(Assignee)

Updated

5 years ago
Blocks: 944698
(Assignee)

Updated

5 years ago
Blocks: 944701
(Assignee)

Updated

5 years ago
Blocks: 944702
(Assignee)

Updated

5 years ago
Blocks: 944706
(Assignee)

Comment 2

5 years ago
Created attachment 8340496 [details] [diff] [review]
WIP

TODO before ready for review:
- handle OOM (disable tracelogging)
- update tracelogger UI
- test extensively
Attachment #8339940 - Attachment is obsolete: true
(Assignee)

Comment 3

5 years ago
Created attachment 8341698 [details] [diff] [review]
Patch

This should be good to go. Probably some minor details, but I want already some feedback before I polish too much.

TODO:
- debug assert for no " when reporting
- make js_TraceLoggers threadsafe
- decide between js_TraceLoggers.forMainThread() or function TraceLoggerForMainThread()

Note: probably I'll have to also fix bug 944706, before pushing. Small testcases aren't a problem, but a few of octane tests don't run to completion, before having to stop the tracelogger. (This would be a regression from v0.1)
Attachment #8340496 - Attachment is obsolete: true
Attachment #8341698 - Flags: feedback?(till)
Comment on attachment 8341698 [details] [diff] [review]
Patch

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

This all looks very nice! I do have quite a bit of feedback, ranging from real issues to whitespace nits. Here's some high-level comments, but most is in-line:

"TraceLogging" should really be named "TraceLogger". "TraceLoggers" could maybe be renamed to "TraceLogging" instead? Still not ideal, but makes more sense to me than the current naming.

Can you explain what the js_TraceLoggers is required for?

I think you could be a lot more aggressive with how much entry space you pre-allocate. It's almost entirely out of the question that you'll only log 4 events in any one thread, ever.

I can't really comment on the baseline and Ion code generation parts, so for a review, you should ask someone else about those parts.

Urgh, I just saw that you're doing a null check in the AutoTraceLog ctor, so disregard all the "Needs a null check" comments in those cases where the logger is only used for AutoTraceLog. I stopped doing those comments in jsworkers.cpp.

::: js/src/TraceLogging.cpp
@@ +66,5 @@
>      return(result);
>  }
>  #endif
>  
> +TraceLoggers js::js_TraceLoggers;

urgh, js::js_ really isn't nice. I also don't understand why it's needed, but I'm sure there's a good reason. That reason shouldn't force you to prefix the name this weirdly, though.

@@ +139,5 @@
> +
> +    fprintf(dictFile, "[");
> +
> +    for (uint32_t i = 0; i < LAST; i++)
> +        prepare(text[i]);

This could use a comment.

@@ +141,5 @@
> +
> +    for (uint32_t i = 0; i < LAST; i++)
> +        prepare(text[i]);
> +
> +    disabled = false;

I'm not a fan of this inversion. I understand that being enabled is the default case (for now, at least), but initializing `disabled` to `true`, and setting it to `false` in init() just seems very weird. Maybe invert and add a comment to the field explaining when it is toggled?

@@ +153,5 @@
> +
> +    dictFile = nullptr;
> +
> +    // Make sure the tree is closed, for reporting purposes.
> +    // Temporary enable logging for this.

"Temporarily"

@@ +157,5 @@
> +    // Temporary enable logging for this.
> +    disabled = false;
> +    while (curStackId > 0)
> +        stop();
> +    disabled = true;

How would this ever be relevant after the dtor has run?

Also, I think this should happen when the logger is disabled, not when it is destroyed. Maybe disabling a logger should be encapsulated and this logic moved to a ::disable() method.

@@ +181,3 @@
>      }
> +
> +    fwrite(events, sizeof(EventEntry), curEventId, eventFile);

I think we should at least print a warning in stderr if the fwrite result is smaller than expected.

@@ +181,5 @@
>      }
> +
> +    fwrite(events, sizeof(EventEntry), curEventId, eventFile);
> +    curEventId = 0;
> +    fclose(eventFile);

same here

@@ +189,5 @@
> +
> +uint32_t
> +TraceLogging::prepare(const char *text)
> +{
> +    //TODO: in debug mode assert no " are in the text.

Don't forget about this.

@@ +199,5 @@
> +    if (!textMap.add(p, text, textId))
> +        return -1;
> +
> +    if (textId > 0)
> +        fprintf(dictFile, ",\n");

I'm not sure this is important, but it'd be cleaner to check for success here, too.
Alternatively, how about appending \n to all entries and fwriting size-1 bytes at the end?

@@ +223,5 @@
> +
> +    if (textId > 0)
> +        fprintf(dictFile, ",\n");
> +
> +    int written = fprintf(dictFile, "\"script %s:%d\"", script->filename(), script->lineno);

This should also include the column. Especially in minified scripts, we'll have the same line number for lots of scripts.

@@ +234,5 @@
> +uint32_t
> +TraceLogging::prepare(const char *filename, uint32_t lineno)
> +{
> +    // This doesn\"t have a cache yet, since it is only used by CompileInfo when
> +    // there is no Script to use instead. As a result this isn\"t optmized with

s/Script/script/

@@ +235,5 @@
> +TraceLogging::prepare(const char *filename, uint32_t lineno)
> +{
> +    // This doesn\"t have a cache yet, since it is only used by CompileInfo when
> +    // there is no Script to use instead. As a result this isn\"t optmized with
> +    // a cache yet. Try to avoid this call or implement the cache!

Something went awry with this comment's formatting. ('doesn\"t' and 'isn\"t')

@@ +258,2 @@
>  
> +    checkEventSpace();

This doesn't check if an OOM occurred during checkEventSpace. How about
if (disabled || !checkEventSpace())
    return;

@@ +271,3 @@
>  
> +    checkTreeSpace();
> +    checkStackSpace();

Same here: have to return on OOM.

@@ +280,5 @@
> +    if (stack[curStackId - 1].lastChildId != 0)
> +        tree[stack[curStackId - 1].lastChildId].nextId = curTreeId;
> +    else
> +        tree[stack[curStackId - 1].treeId].u.s.hasChilds = 1;
> +    stack[curStackId - 1].lastChildId = curTreeId;

Can you create a local var for stack[curStackId - 1] and use it here?

@@ +296,5 @@
> +    JS_ASSERT(tree[stack[curStackId - 1].treeId].u.s.textId == id);
> +
> +    uint64_t stop = rdtsc() - js_TraceLoggers.startupTime;
> +    tree[stack[curStackId - 1].treeId].stop = stop;
> +    curStackId--;

Just call stop() here instead.

@@ +312,4 @@
>  }
>  
> +bool
> +TraceLogging::checkEventSpace()

Can you templatize these? It's really three repetitions of the same code with just different field names.

@@ +375,3 @@
>  {
> +    loggerId = 0;
> +    out = fopen(TRACE_LOG_DIR "tl-data.json", "w");

Check for success here and at the very least print an error. Really, a failure should just disable all tracelogging, though.

@@ +380,5 @@
>  
> +TraceLoggers::~TraceLoggers()
> +{
> +    fprintf(out, "]");
> +    fclose(out);

Here, a failure should just result in an error being printed to stderr.

@@ +400,5 @@
> +bool
> +TraceLoggers::lazyInit()
> +{
> +    if (mainLoggers.initialized() && threadLoggers.initialized())
> +        return true;

I think this should just be removed. It's a strict duplication of the two conditionals below.

@@ +461,5 @@
> +
> +TraceLogging *
> +TraceLoggers::create()
> +{
> +    if (loggerId >= 100)

This seems very arbitrary. At the very least, print a warning about it to stderr.

@@ +466,5 @@
> +        return nullptr;
> +
> +    char dictFilename[sizeof TRACE_LOG_DIR "tl-dict.100.json"];
> +    sprintf(dictFilename, TRACE_LOG_DIR "tl-dict.%d.json", loggerId);
> +    FILE *dictFile = fopen(dictFilename, "w");

Return nullptr on failure here.

@@ +470,5 @@
> +    FILE *dictFile = fopen(dictFilename, "w");
> +
> +    char treeFilename[sizeof TRACE_LOG_DIR "tl-tree.100.tl"];
> +    sprintf(treeFilename, TRACE_LOG_DIR "tl-tree.%d.tl", loggerId);
> +    FILE *treeFile = fopen(treeFilename, "wb");

And here.

@@ +474,5 @@
> +    FILE *treeFile = fopen(treeFilename, "wb");
> +
> +    char eventFilename[sizeof TRACE_LOG_DIR "tl-event.100.tl"];
> +    sprintf(eventFilename, TRACE_LOG_DIR "tl-event.%d.tl", loggerId);
> +    FILE *eventFile = fopen(eventFilename, "wb");

And here. And close all potentially-opened files, of course.

@@ +489,5 @@
> +    if (!logger)
> +        return nullptr;
> +
> +    if (!logger->init())
> +        return nullptr;

Here and above, the opened files should be closed on failure.

::: js/src/TraceLogging.h
@@ +24,4 @@
>  class TraceLogging
>  {
>    public:
> +    // Predefined id's for common operation. These id's can be used,

s/id's/IDs/ (or "ids", but that looks weird)

@@ +45,5 @@
> +      Baseline,
> +      IonMonkey,
> +      Bailout,
> +      Invalidation,
> +      

Nit: whitespace

@@ +64,3 @@
>  
> +    // The layout of the tree in memory and also exact copy of what will get
> +    // in the tree log file. Readable by JS using TypedArrays.

This sounds weird. How about just "The layout of the tree in memory and the log file. Readable by JS using TypedArrays."

@@ +69,5 @@
> +        uint64_t stop;
> +        union {
> +            struct {
> +                uint32_t textId : 31;
> +                uint32_t hasChilds: 1;

hasChildren

@@ +85,3 @@
>      };
>  
> +    // Helper structure for keeping track which tree entry to adjust.

"track of which"

@@ +94,5 @@
> +        { }
> +    };
> +
> +    // The layout of the event log in memory and also exact copy of event log
> +    // file. Readable by JS using TypedArrays.

Same proposed rephrasing as above

@@ +115,1 @@
>      uint32_t nextTextId;

This isn't really a textId, anymore. It's also not an etryId, though, so I don't really have a better name, either.

@@ +116,3 @@
>  
> +    TreeEntry *tree;
> +    uint32_t curTreeId;

This should be nextTreeId, as it's not actually the currently used one, but the next free one.

@@ +118,5 @@
> +    uint32_t curTreeId;
> +    uint32_t numTreeIds;
> +
> +    StackEntry *stack;
> +    uint32_t curStackId;

Same here: nextStackId. You're even using "curStackId - 1" to get the current stack entry in a number of places.

@@ +122,5 @@
> +    uint32_t curStackId;
> +    uint32_t numStackIds;
> +
> +    EventEntry *events;
> +    uint32_t curEventId;

And here, too: nextEventId

@@ +137,2 @@
>  
> +    // The prepare functions transform an uniq output to an loger id.

"map a unique input to a logger id"?

ISTM that 'map' makes more sense than 'transform', and 'input' more than 'output', but you might disagree on both counts. At the very least, the spelling should be fixed.

@@ +139,5 @@
> +    // This id can be used to log something. Calls to these functions should be
> +    // limited if possible, because of the overhead.
> +    uint32_t prepare(const char *text);
> +    uint32_t prepare(JSScript *script);
> +    uint32_t prepare(const char *filename, uint32_t lineno);

"prepare" doesn't seem like the right word for this. Maybe just "getId"?

@@ +141,5 @@
> +    uint32_t prepare(const char *text);
> +    uint32_t prepare(JSScript *script);
> +    uint32_t prepare(const char *filename, uint32_t lineno);
> +
> +    // Log an event (no start/stop, only time of happening is recorded).

"only the timestamp is recorded"?

@@ +144,5 @@
> +
> +    // Log an event (no start/stop, only time of happening is recorded).
> +    void log(uint32_t id);
> +
> +    // Log a begin and end of an event.

"Record timestamps for start and stop of an event"?

@@ +147,5 @@
> +
> +    // Log a begin and end of an event.
> +    void start(uint32_t id);
> +    void stop(uint32_t id);
> +    void stop();

Can you add a comment explaining when the id-less stop is used?

@@ +183,5 @@
> +    MainLoggerHashMap mainLoggers;
> +    ThreadLoggerHashMap threadLoggers;
> +    uint32_t loggerId;
> +    FILE *out;
> +    

Nit: whitespace

@@ +269,3 @@
>      {
> +        if (logger) {
> +            js_TraceLoggers.start(logger, textId);

Why are you using js_TraceLoggers here and below?

::: js/src/frontend/BytecodeCompiler.cpp
@@ +172,5 @@
>  {
>      RootedString source(cx, source_);
>      SkipRoot skip(cx, &chars);
>  
> +    js::TraceLogging *logger = NULL;

nullptr

@@ +176,5 @@
> +    js::TraceLogging *logger = NULL;
> +    if (cx->isJSContext())
> +        logger = js::js_TraceLoggers.forMainThread(cx->asJSContext()->runtime());
> +    else
> +        logger = js::js_TraceLoggers.forThread(PR_GetCurrentThread()); 

Nit: whitespace
Needs a null check

@@ +179,5 @@
> +    else
> +        logger = js::js_TraceLoggers.forThread(PR_GetCurrentThread()); 
> +    uint32_t logId = js::js_TraceLoggers.prepare(logger, options.filename(), options.lineno);
> +    js::AutoTraceLog logger1(logger, logId);
> +    js::AutoTraceLog logger2(logger, TraceLogging::ParserCompileScript);

I'm not too crazy about the duplication that goes with pretty much always having to log two events like this. How about adding an optional second parameter to the AutoTraceLog ctor giving one of the builtin IDs?

@@ +417,5 @@
>             .setCompileAndGo(true)
>             .setNoScriptRval(false)
>             .setSelfHostingMode(false);
>  
> +    js::TraceLogging *logger = js::js_TraceLoggers.forMainThread(cx->runtime());

Needs a null check

@@ +475,5 @@
>  CompileFunctionBody(JSContext *cx, MutableHandleFunction fun, const ReadOnlyCompileOptions &options,
>                      const AutoNameVector &formals, const jschar *chars, size_t length,
>                      GeneratorKind generatorKind)
>  {
> +    js::TraceLogging *logger = js::js_TraceLoggers.forMainThread(cx->runtime());

Needs a null check

::: js/src/jit/Bailouts.cpp
@@ +72,5 @@
>      JitActivationIterator jitActivations(cx->runtime());
>      IonBailoutIterator iter(jitActivations, sp);
>      JitActivation *activation = jitActivations.activation()->asJit();
>  
> +    TraceLogging *logger = js_TraceLoggers.forMainThread(cx->runtime());

Needs a null check

@@ +106,5 @@
>      JitActivationIterator jitActivations(cx->runtime());
>      IonBailoutIterator iter(jitActivations, sp);
>      JitActivation *activation = jitActivations.activation()->asJit();
>  
> +    TraceLogging *logger = js_TraceLoggers.forMainThread(cx->runtime());

Needs a null check

::: js/src/jit/BaselineBailouts.cpp
@@ +1195,5 @@
>  {
>      JS_ASSERT(bailoutInfo != nullptr);
>      JS_ASSERT(*bailoutInfo == nullptr);
>  
> +    TraceLogging *logger = js_TraceLoggers.forMainThread(cx->runtime());

Needs a null check

@@ +1197,5 @@
>      JS_ASSERT(*bailoutInfo == nullptr);
>  
> +    TraceLogging *logger = js_TraceLoggers.forMainThread(cx->runtime());
> +    js_TraceLoggers.stop(logger, TraceLogging::IonMonkey); 
> +    js_TraceLoggers.start(logger, TraceLogging::Baseline); 

Nit: whitespace twice

::: js/src/jit/BaselineCompiler.cpp
@@ +346,5 @@
>      if (needsEarlyStackCheck())
>          masm.bind(&earlyStackCheckFailed);
>  
>  #if JS_TRACE_LOGGING
> +    TraceLogging *logger = js_TraceLoggers.forMainThread(cx->runtime());

Needs a null check

@@ +388,5 @@
>  {
>      masm.bind(&return_);
>  
>  #if JS_TRACE_LOGGING
> +    Register logger = RegisterSet::Volatile().takeGeneral();

Needs a null check

::: js/src/jit/BaselineJIT.cpp
@@ +200,5 @@
>              data.calleeToken = CalleeToToken(fp->script());
>      }
>  
>  #if JS_TRACE_LOGGING
> +    TraceLogging *logger = js_TraceLoggers.forMainThread(cx->runtime());

Needs a null check

::: js/src/jit/CodeGenerator.cpp
@@ +5945,5 @@
>      if (patchableBackedges_.length() > 0)
>          ionScript->copyPatchableBackedges(cx, code, patchableBackedges_.begin());
>  
> +#if JS_TRACE_LOGGING
> +    TraceLogging *logger = js_TraceLoggers.forMainThread(cx->runtime());

Needs a null check

::: js/src/jit/Ion.cpp
@@ +1504,5 @@
>      AutoLockWorkerThreadState lock(*cx->runtime()->workerThreadState);
>  
>      OffThreadCompilationVector &compilations = ion->finishedOffThreadCompilations();
>  
> +    TraceLogging *logger = js_TraceLoggers.forMainThread(cx->runtime());

Needs a null check

@@ +1604,5 @@
>             BaselineFrame *baselineFrame, jsbytecode *osrPc, bool constructing,
>             ExecutionMode executionMode)
>  {
>  #if JS_TRACE_LOGGING
> +    TraceLogging *logger = js_TraceLoggers.forMainThread(cx->runtime());

Needs a null check

::: js/src/jit/arm/CodeGenerator-arm.cpp
@@ +54,5 @@
>  
>  bool
>  CodeGeneratorARM::generateEpilogue()
>  {
>      masm.bind(&returnLabel_); 

Nit: whitespace (I know: preexisting)

@@ +60,2 @@
>  #if JS_TRACE_LOGGING
> +    if (!gen->compilingAsmJS() && gen->info().executionMode() == SequentialExecution) 

Needs braces

::: js/src/jit/shared/CodeGenerator-shared.cpp
@@ +1019,5 @@
> +    if (!patchableTLScripts_.append(patchScript))
> +        return false;
> +
> +    masm.tracelogStart(logger, script);
> +    

Nit: whitespace

@@ +1044,5 @@
> +    if (!patchableTLScripts_.append(patchScript))
> +        return false;
> +
> +    masm.tracelogStop(logger, script);
> +    

Nit: whitespace

@@ +1064,5 @@
> +    if (!patchableTraceLoggers_.append(patchLocation))
> +        return false;
> +
> +    masm.tracelogStart(logger, start);
> +    

Nit: whitespace

@@ +1082,5 @@
> +    if (!patchableTraceLoggers_.append(patchLocation))
> +        return false;
> +
> +    masm.tracelogStop(logger);
> +    

Nit: whitespace

@@ +1100,5 @@
> +    if (!patchableTraceLoggers_.append(patchLocation))
> +        return false;
> +
> +    masm.tracelogStop(logger);
> +    

Nit: whitespace

::: js/src/jit/shared/CodeGenerator-shared.h
@@ +447,5 @@
> +    bool emitTracelogScript();
> +    bool emitTracelogScriptStop();
> +    bool emitTracelogStart(uint32_t start);
> +    bool emitTracelogStop(uint32_t stop);
> +    bool emitTracelogStop();

ISTM like you should be able to combine the logScriptStart/Stop and the logStart/Stop functions.

::: js/src/jsgc.cpp
@@ +2497,5 @@
>  GCHelperThread::threadLoop()
>  {
>      AutoLockGC lock(rt);
>  
> +    TraceLogging *logger = js_TraceLoggers.forThread(PR_GetCurrentThread());

Needs a null check

@@ +4841,5 @@
>  
>      if (rt->mainThread.suppressGC)
>          return;
>  
> +    TraceLogging *logger = js_TraceLoggers.forMainThread(rt);

Needs a null check

@@ +5000,5 @@
>  void
>  js::MinorGC(JSRuntime *rt, JS::gcreason::Reason reason)
>  {
>  #ifdef JSGC_GENERATIONAL
> +    TraceLogging *logger = js_TraceLoggers.forMainThread(rt);

Needs a null check

@@ +5013,5 @@
>  {
>      // Alternate to the runtime-taking form above which allows marking type
>      // objects as needing pretenuring.
>  #ifdef JSGC_GENERATIONAL
> +    TraceLogging *logger = js_TraceLoggers.forMainThread(rt);

Needs a null check

::: js/src/vm/RegExpObject.cpp
@@ +574,2 @@
>      result = JSC::Yarr::interpret(cx, bytecode, chars, length, start, outputBuf);
> +    js_TraceLoggers.stop(logger, TraceLogging::YarrInterpret);

Why not just wrap the interpret in a block and use an AutoTraceLog?
Attachment #8341698 - Flags: feedback?(till) → feedback+
(Assignee)

Updated

5 years ago
Duplicate of this bug: 969717
(Assignee)

Comment 6

5 years ago
Created attachment 8379736 [details] [diff] [review]
tracelogger_improvements

Updated version according to review. Contains also extra improvements, next to the requested changes. Note: the only thing I didn't do was create a version of AutoTraceLogger with two parameters, since I don't find it that elegant...

(I'll ask Jan or so to review the assembly/ion/baseline parts after you reviewed)
Attachment #8341698 - Attachment is obsolete: true
Attachment #8379736 - Flags: review?(till)
Comment on attachment 8379736 [details] [diff] [review]
tracelogger_improvements

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

Sorry for the long delay - and the large amount of feedback.

From a technical point of view, I largely have nits. However, this is all really pretty complicated, and it lacks documentation. One big part of that is solid documentation of the logged data's format. I.e., what data is stored in which file, in which format, and how multiple sets of data can get generated. Please add that to the top of TraceLogging.h. Additionally, I asked for lots of inline documentation of various parts that weren't at all obvious to me.

Based on that, r=me on the functional side of things, but the documentation should get looked at before this lands. Since I'll be on vacation for 3 weeks starting this weekend, I'd also be ok with things landing now and a follow-up patch with documentation happening within those weeks. Alternatively, you could ask someone else for review of those parts. That'd nicely demonstrate the effectiveness of the documentation, too.

Other general remarks:

I wonder if TraceLogging shouldn't move into the vm/ directory. It seems to fit in there quite well.

I think `make check` runs the style checker script that tells you about issues like include ordering. I have noted wrong orderings when I saw them, but might well have missed some. A try run should turn red or orange or something, too.

::: js/src/TraceLogging.cpp
@@ +62,5 @@
>  #endif
>  
> +TraceLogging traceLoggers;
> +
> +const char* const text[] = {

Please add a comment about keeping this synched with the TextId enum here, too.

@@ +101,5 @@
> +        return false;
> +    if (!stack.init())
> +        return false;
> +    if (!events.init())
> +        return false;

how about combining these to
if (!(textMap.init() && scriptMap.init() && ...)
   return false;

?

@@ +104,5 @@
> +    if (!events.init())
> +        return false;
> +
> +    char dictFilename[sizeof TRACE_LOG_DIR "tl-dict.100.json"];
> +    sprintf(dictFilename, TRACE_LOG_DIR "tl-dict.%d.json", loggerId);

This needs an assert that loggerId is < 1000. Yes, very unlikely to be violated, but still. In fact, you could make the id a byte and make this fully safe. Obviously that would require asserting against creating more than 255 loggers somewhere else ...

Same comment applies at the two equivalent places below.

@@ +110,5 @@
> +    if (!dictFile)
> +        return false;
> +
> +    char treeFilename[sizeof TRACE_LOG_DIR "tl-tree.100.tl"];
> +    sprintf(treeFilename, TRACE_LOG_DIR "tl-tree.%d.tl", loggerId);

here

@@ +119,5 @@
> +        return false;
> +    }
> +
> +    char eventFilename[sizeof TRACE_LOG_DIR "tl-event.100.tl"];
> +    sprintf(eventFilename, TRACE_LOG_DIR "tl-event.%d.tl", loggerId);

and here

@@ +138,5 @@
> +    StackEntry stackEntry(0, 0);
> +    stack.push(stackEntry);
> +
> +    // Already prepare the default textIds, so they don't need to get prepared,
> +    // before logging.

Style nits: s/Already/Eagerly/ and get rid of both commas.

@@ +149,5 @@
> +}
> +
> +TraceLogger::~TraceLogger()
> +{
> +    // Output dictionary.

"Write dictionary to disk."?

@@ +151,5 @@
> +TraceLogger::~TraceLogger()
> +{
> +    // Output dictionary.
> +    if (dictFile) {
> +        fprintf(dictFile, "]");

Needs error checking.

Also, does it make sense to continue with the rest of the output after this happens? Same applies to the fwrite operations below. I guess just trying to write out the rest makes handling cleanup easiest, but it doesn't seem right to me.

@@ +157,5 @@
> +
> +        dictFile = nullptr;
> +    }
> +
> +    // Output the tree into the file.

Maybe "Write tree of logged events to disk."?

@@ +167,5 @@
> +        while (stack.size() > 0)
> +            stop();
> +        enabled = false;
> +
> +        // But we need to adjust the data to be Big Endian.

"Convert data to Big Endian."?

@@ +172,5 @@
> +        for (uint32_t i = 0; i < tree.size(); i++) {
> +            tree[i].start = htobe64(tree[i].start);
> +            tree[i].stop = htobe64(tree[i].stop);
> +            tree[i].u.value = htobe32(tree[i].u.s.textId*2 + tree[i].u.s.hasChildren);
> +            tree[i].nextId = htobe32(tree[i].nextId);

Can you store tree[i] in a local var, treeEntry perhaps, and replace all usages of tree[i] in the loop with that?

@@ +175,5 @@
> +            tree[i].u.value = htobe32(tree[i].u.s.textId*2 + tree[i].u.s.hasChildren);
> +            tree[i].nextId = htobe32(tree[i].nextId);
> +        }
> +
> +        // Write data

I don't think this comment is needed. In combination with the writing of *more* data happening below, it's actively irritating.

@@ +176,5 @@
> +            tree[i].nextId = htobe32(tree[i].nextId);
> +        }
> +
> +        // Write data
> +        size_t witems = fwrite(tree.space(), sizeof(TreeEntry), tree.size(), treeFile);

s/witems/bytesWritten/

@@ +178,5 @@
> +
> +        // Write data
> +        size_t witems = fwrite(tree.space(), sizeof(TreeEntry), tree.size(), treeFile);
> +        if (witems < tree.size())
> +            fprintf(stderr, "TraceLogging: Couldn't write the full tree to the file.\n");

s/to the file/to disk/

@@ +185,5 @@
> +
> +        treeFile = nullptr;
> +    }
> +
> +    // Output the events into the file.

"Write details for all log entries to disk."?

@@ +193,5 @@
> +            events[i].time = htobe64(events[i].time);
> +            events[i].textId = htobe64(events[i].textId);
> +        }
> +
> +        size_t witems = fwrite(events.space(), sizeof(EventEntry), events.size(), eventFile);

s/witems/bytesWritten/

@@ +195,5 @@
> +        }
> +
> +        size_t witems = fwrite(events.space(), sizeof(EventEntry), events.size(), eventFile);
> +        if (witems < events.size())
> +            fprintf(stderr, "TraceLogging: Couldn't write all event entries to the file.\n");

s/to the file/to disk/

@@ +207,5 @@
> +uint32_t
> +TraceLogger::prepare(const char *text)
> +{
> +#ifdef DEBUG
> +    const char *quote = strchr(text, (int)'"');

Please add a short comment explaining what this is about.

@@ +266,5 @@
> +uint32_t
> +TraceLogger::prepare(const char *filename, uint32_t lineno)
> +{
> +    // This doesn't have a cache yet, since it is only used by CompileInfo when
> +    // there is no script to use instead. As a result this isn't optmized with

Nits: duplicate mention of the cache-lessness, and missing explanation of when and why this is used.

@@ +302,5 @@
> +    }
> +
> +    uint64_t start = rdtsc() - traceLoggers.startupTime;
> +    EventEntry entry(start, id);
> +    events.push(entry);

To reduce the overhead tracelogging causes, it'd be very nice to not create the entry on the stack and then immediatly copy it to the heap. Maybe add something like `EvenEntry pushUninitializedEntry()` and then fill in the entry's fields in-place?

@@ +323,5 @@
> +    if (stack.peek(-1).lastChildId != 0)
> +        tree[stack.peek(-1).lastChildId].nextId = tree.current();
> +    else
> +        tree[stack.peek(-1).treeId].u.s.hasChildren = 1;
> +    stack.peek(-1).lastChildId = tree.current();

Please add a short explanation of what's going on here.

@@ +329,5 @@
> +    TreeEntry treeEntry(start, 0, id, false, 0);
> +    StackEntry stackEntry(tree.current(), 0);
> +
> +    tree.push(treeEntry);
> +    stack.push(stackEntry);

Obviously, the above comment about in-place initialization of entries applies here, too.

@@ +369,2 @@
>      if (out) {
> +        fprintf(out, "]");

Needs error checking.

@@ +396,5 @@
> +
> +    out = fopen(TRACE_LOG_DIR "tl-data.json", "w");
> +    if (!out)
> +        return false;
> +    fprintf(out, "[");

Needs error checking.

@@ +457,5 @@
> +TraceLogger *
> +TraceLogging::create()
> +{
> +    if (loggerId >= 100) {
> +        fprintf(stderr, "TraceLogging: Can't create more 100 different loggers.");

Oh, this is already checked (I commented on missing checks above). In that case, how about turning the id into a byte/ uint_8?

@@ +463,4 @@
>      }
>  
> +    if (loggerId > 0)
> +        fprintf(out, ",\n");

Needs error checking.

@@ +467,3 @@
>  
> +    fprintf(out, "{\"tree\":\"tl-tree.%d.tl\", \"events\":\"tl-event.%d.tl\", \"dict\":\"tl-dict.%d.json\", \"treeFormat\":\"64,64,31,1,32\"}",
> +            loggerId, loggerId, loggerId);

Needs error checking.

::: js/src/TraceLogging.h
@@ +14,4 @@
>  
>  #include "js/HashTable.h"
>  #include "js/TypeDecls.h"
> +#include "mozilla/GuardObjects.h"

This include needs to go above all others, followed by an empty line.

@@ +23,5 @@
>  
> +class AutoTraceLog;
> +
> +template <class T>
> +class ContinuousSpace {

This seems like it's something that might well live in MFBT. Maybe propose an uplift to there?

@@ +43,5 @@
> +
> +        return true;
> +    }
> +
> +    T *space() {

How about calling this, and space_, "data" instead? "Space" sounds like it returns a size (i.e., "available space") to me.

@@ +59,5 @@
> +    uint32_t current() {
> +        return current_;
> +    }
> +
> +    bool checkSpaceBeforeAdd() {

Maybe "ensureSpaceBeforeAdd"?

@@ +63,5 @@
> +    bool checkSpaceBeforeAdd() {
> +        if (current_ < capacity_)
> +            return true;
> +
> +        T *entries = (T *) js_realloc(space_, capacity_ * 2 * sizeof(T));

Please store `capacity_ * 2` in a local `newCapacity` and use that here and below.
Also, maybe it makes sense to cap the doubling at some point?

@@ +103,5 @@
> +
> +class TraceLogger
> +{
> +  public:
> +    // Predefined ID's for common operation. These ID's can be used,

Nits: no ' in IDs, and no , at the EOL

@@ +105,5 @@
> +{
> +  public:
> +    // Predefined ID's for common operation. These ID's can be used,
> +    // without using prepare, because there are already prepared.
> +    // When changing the enum here, you should update the array containing the

s/should/must/
And please add the exact name of the array to update.

@@ +122,5 @@
> +      MinorGC,
> +      ParserCompileFunction,
> +      ParserCompileLazy,
> +      ParserCompileScript,
> +      TL,

Any reason to give this such a short and non-descriptive name?

@@ +141,5 @@
> +    typedef HashMap<JSScript *,
> +                    uint32_t,
> +                    PointerHasher<JSScript *, 3>,
> +                    SystemAllocPolicy> ScriptHashMap;
> +

Why do we need two different maps for JSScripts and char pointers? Isn't having just one for generic pointers entirely sufficient?

@@ +169,5 @@
> +        }
> +    };
> +
> +    // Helper structure for keeping track of which tree entry to adjust.
> +    // Represents the stack to find back the TreeEntry to 'stop'.

Maybe
"Helper structure for keeping track of the currently active entries.
Pushed by `start(id)`, popped by `stop(id)`."
?

@@ +212,5 @@
> +
> +    bool init(uint32_t loggerId);
> +
> +    // The prepare functions map a unique input to a logger id.
> +    // This id can be used to log something. Calls to these functions should be

Nit: for consistency, ID should be uppercase in these two lines

@@ +216,5 @@
> +    // This id can be used to log something. Calls to these functions should be
> +    // limited if possible, because of the overhead.
> +    uint32_t prepare(const char *text);
> +    uint32_t prepare(JSScript *script);
> +    uint32_t prepare(const char *filename, uint32_t lineno);

I'm not a fan of the name "prepare" for this. What it really does is map something to an ID. How about just getId()? ("get" because it's fallible.) The fact that, the first time it's called for something, it creates a mapping (which is preparation work, I guess), really is an implementation detail.

@@ +222,5 @@
> +    // Log an event (no start/stop, only the timestamp is recorded).
> +    void log(uint32_t id);
> +
> +    // Record timestamps for start and stop of an event.
> +    // The ID of the stop func is only used in debug builds to test correctness.

"In the stop method, the ID is only used in debug [...]"

@@ +237,5 @@
> +                    TraceLogger *,
> +                    PointerHasher<PRThread *, 3>,
> +                    SystemAllocPolicy> ThreadLoggerHashMap;
> +
> +    bool inited;

"initialized", please!

@@ +273,5 @@
> +    return nullptr;
> +};
> +#endif
> +
> +inline uint32_t TraceLogPrepare(TraceLogger* logger, JSScript *script) {

Together with the prepare(foo) methods, I think these should be renamed to something like GetTraceLogId.

@@ +276,5 @@
> +
> +inline uint32_t TraceLogPrepare(TraceLogger* logger, JSScript *script) {
> +#if JS_TRACE_LOGGING
> +    if (logger)
> +        logger->prepare(script);

Doesn't return the return value of prepare

@@ +290,5 @@
> +}
> +inline uint32_t TraceLogPrepare(TraceLogger* logger, const char *filename) {
> +#if JS_TRACE_LOGGING
> +    if (logger)
> +        logger->prepare(filename);

Doesn't return the return value of prepare

@@ +317,5 @@
> +#if JS_TRACE_LOGGING
> +    if (logger)
> +        logger->stop();
> +#endif
> +}

Please add a comment above this entire block of functions explaining why using them doesn't require null checks. I forgot about that again and started adding "needs error checking" comments everywhere. ;)

@@ +322,2 @@
>  
>  /* Automatic logging at the start and end of function call */

Because I just saw it: //-style comment and "." at the end, please

@@ +323,5 @@
>  /* Automatic logging at the start and end of function call */
>  class AutoTraceLog {
> +#if JS_TRACE_LOGGING
> +    TraceLogger* logger;
> +    uint32_t textId;

This is really a generic pointer ID, isn't it? It also applies to JSScript pointers, after all. Maybe just call it id or logId?

::: js/src/frontend/BytecodeCompiler.cpp
@@ +197,5 @@
>  {
>      RootedString source(cx, source_);
>      SkipRoot skip(cx, &chars);
>  
> +    js::TraceLogger *logger = NULL;

nullptr

@@ +204,5 @@
> +    else
> +        logger = TraceLoggerForThread(PR_GetCurrentThread());
> +    uint32_t logId = js::TraceLogPrepare(logger, options.filename(), options.lineno);
> +    js::AutoTraceLog logger1(logger, logId);
> +    js::AutoTraceLog logger2(logger, TraceLogger::ParserCompileScript);

Please give these speaking names

@@ +444,5 @@
>  
> +    js::TraceLogger *logger = js::TraceLoggerForMainThread(cx->runtime());
> +    uint32_t logId = js::TraceLogPrepare(logger, options.filename(), options.lineno);
> +    js::AutoTraceLog logger1(logger, logId);
> +    js::AutoTraceLog logger2(logger, TraceLogger::ParserCompileLazy);

Speaking names

@@ +502,5 @@
>  {
> +    js::TraceLogger *logger = js::TraceLoggerForMainThread(cx->runtime());
> +    uint32_t logId = js::TraceLogPrepare(logger, options.filename(), options.lineno);
> +    js::AutoTraceLog logger1(logger, logId);
> +    js::AutoTraceLog logger2(logger, TraceLogger::ParserCompileFunction);

Speaking names

::: js/src/jit/BaselineJIT.cpp
@@ +200,5 @@
>          else
>              data.calleeToken = CalleeToToken(fp->script());
>      }
>  
>  #if JS_TRACE_LOGGING

No need for the #if, anymore

::: js/src/jit/arm/CodeGenerator-arm.cpp
@@ +54,5 @@
>  
>  bool
>  CodeGeneratorARM::generateEpilogue()
>  {
>      masm.bind(&returnLabel_); 

drive-by nit: whitespace at line end

::: js/src/vm/Interpreter.cpp
@@ +1790,5 @@
>      if (activation.entryFrame() != REGS.fp())
>    inline_return:
>      {
> +        // No information about which engine exactely stopped,
> +        // could be interpreter/baseline or ionmonkey

"the interpreter, Baseline or IonMonkey."

@@ +3484,5 @@
>                             REGS.fp()->hasPushedSPSFrame());
>  
>      gc::MaybeVerifyBarriers(cx, true);
>  
>  #if JS_TRACE_LOGGING

No need for the #if, anymore

::: js/src/vm/RegExpObject.cpp
@@ +7,5 @@
>  #include "vm/RegExpObject.h"
>  
>  #include "mozilla/MemoryReporting.h"
>  
> +#include "TraceLogging.h" //TODO: check convention about top level

https://wiki.mozilla.org/JavaScript:SpiderMonkey:Coding_Style#.23include_ordering
In short: the ordering is correct, but you have to add an empty line after this include.

This makes me wonder, however: shouldn't TraceLogging.cpp/h be in vm/?

::: js/src/vm/Runtime.cpp
@@ +72,5 @@
>      ionTop(nullptr),
>      ionJSContext(nullptr),
>      ionStackLimit(0),
> +#if JS_TRACE_LOGGING
> +    traceLogger(NULL),

nullptr
Attachment #8379736 - Flags: review?(till) → review+
(Assignee)

Comment 8

5 years ago
Created attachment 8393480 [details] [diff] [review]
tracelogger_improvements

So this already got r+ from till. But since there were so many comments, I think it is best to do an extra review. Since bbouvier showed interest, I'm gonna give him the patch updated with comments. (To kill two birds with one stone, so he can start to know the system a bit more and to see if the comments are sufficient).
Attachment #8379736 - Attachment is obsolete: true
Attachment #8393480 - Flags: review?(benj)
(Assignee)

Comment 9

5 years ago
Note: I didn't move it to vm/Tracelogging.cpp/h, but the final patch will do that. (I think the diff is better without that move atm).
Comment on attachment 8393480 [details] [diff] [review]
tracelogger_improvements

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

Very nice! I like the RAII classes and the levels of granularity with which you can trace. I have a lot of nits about naming and a few non nits that Till already mentioned, so resetting the flag for now but it looks very good overall, good work!

Also, it might be nice to check that we push stack entries in a consistent fashion (script first, then engine, or the other way around, but consistently across the patch). I kinda remember I've seen some places where it wasn't the case.

::: js/src/TraceLogging.cpp
@@ +105,5 @@
> +        return false;
> +    if (!events.init())
> +        return false;
> +
> +    JS_ASSERT(loggerId < 999);

nit: off by one. 999 is still valid :)

@@ +108,5 @@
> +
> +    JS_ASSERT(loggerId < 999);
> +
> +    char dictFilename[sizeof TRACE_LOG_DIR "tl-dict.100.json"];
> +    sprintf(dictFilename, TRACE_LOG_DIR "tl-dict.%d.json", loggerId);

For this call and all other sprintf calls, could you check that the return value is >0?

@@ +110,5 @@
> +
> +    char dictFilename[sizeof TRACE_LOG_DIR "tl-dict.100.json"];
> +    sprintf(dictFilename, TRACE_LOG_DIR "tl-dict.%d.json", loggerId);
> +    dictFile = fopen(dictFilename, "w");
> +    if (!dictFile)

How about factoring out the closing procedure already present in ~TraceLogger(), making it return false in all cases and call from all places where it can fail here and from ~TraceLogger?

@@ +181,5 @@
> +        while (stack.size() > 0)
> +            stop();
> +        enabled = false;
> +
> +        // Convert data to Big Endian.

Format data to big endian?

@@ +185,5 @@
> +        // Convert data to Big Endian.
> +        for (uint32_t i = 0; i < tree.size(); i++) {
> +            tree[i].start = htobe64(tree[i].start);
> +            tree[i].stop = htobe64(tree[i].stop);
> +            tree[i].u.value = htobe32(tree[i].u.s.textId*2 + tree[i].u.s.hasChildren);

To make it clearer that we're making a 32 bits out of 31 bits and 1 bit values, could you use << 1 instead of * 2?

@@ +200,5 @@
> +    }
> +
> +    // Write details for all log entries to disk.
> +    if (eventFile) {
> +        // Get data in big endian

Format data to big endian?

@@ +290,5 @@
> +#ifdef DEBUG
> +    // Make sure no double quotes are logged. They don't get escaped,
> +    // so would break the json output.
> +    const char *quote = strchr(filename, (int)'"');
> +    MOZ_ASSERT(!quote);

Might be worth creating a function for that check, as it's repeated a few times.

@@ +344,5 @@
> +    // Patch up the tree to be correct. There are two scenarios:
> +    // 1) Parent has no children yet. So update parent to include children.
> +    // 2) Parent has already children. Update last child to link to the new
> +    //    child.
> +    StackEntry &parent = stack.peek(-1);

peek seems to be called with -1 as an argument. Could we call it peekLast() instead, so that we don't have the check in peek() nor the argument?

@@ +356,5 @@
> +
> +        tree[parent.lastChildId].nextId = tree.current();
> +    }
> +
> +    // Set the last child of te parent to this newly added entry.

s/te/the

@@ +359,5 @@
> +
> +    // Set the last child of te parent to this newly added entry.
> +    parent.lastChildId = tree.current();
> +
> +    // Add the a new stack entry.

nit: s/the//

@@ +421,5 @@
> +        threadLoggers.finish();
> +    }
> +
> +    if (lock)
> +        PR_DestroyLock(lock);

also reset lock to nullptr?

@@ +504,3 @@
>      }
>  
> +    if (loggerId > 0) {

it seems that forMainThread could call within this function without lazyInit being called, causing out to be nullptr or a garbage pointer. Could you call and check lazyInit here?

::: js/src/TraceLogging.h
@@ +24,5 @@
>  
> +/*
> + * Tracelogging overview.
> + *
> + * Tracelogging makes it possible to trace the time of a single event and/or

Do you mean 'timestamp' in place of 'time', here?

@@ +29,5 @@
> + * the duration of an event. This is implemented to give an as low overhead as
> + * possible so it doesn't interfere with running.
> + *
> + * The output of a tracelogging session is saved in /tmp/tl-data.json.
> + * The format of that file is an JS array per tracelogger (=thread), with a assoc

nit: an JS array => a JS array, a assoc array => an associative array (doesn't map sound even better? without an uppercase M, there is no ambiguity with es6 Maps, imho)

@@ +37,5 @@
> + *  - events: Name of the file containing a flat list of log events saved
> + *            in binary format.
> + *            (64bit: Time Stamp Counter, 32bit index to dict)
> + *  - tree:   Name of the file containing the events with duration. The content
> + *            is already saved in a tree. This is also saved in a binary file.

Do you mean "as a tree"? Or might be worth precising "in a tree data structure". Had to read it a few times before getting it.

@@ +38,5 @@
> + *            in binary format.
> + *            (64bit: Time Stamp Counter, 32bit index to dict)
> + *  - tree:   Name of the file containing the events with duration. The content
> + *            is already saved in a tree. This is also saved in a binary file.
> + *  - treeFormat: The format how the tree is saved. By default "64,64,31,1,32".

What about "the format used to encode a tree node"?

@@ +39,5 @@
> + *            (64bit: Time Stamp Counter, 32bit index to dict)
> + *  - tree:   Name of the file containing the events with duration. The content
> + *            is already saved in a tree. This is also saved in a binary file.
> + *  - treeFormat: The format how the tree is saved. By default "64,64,31,1,32".
> + *                There are currently no other formats to save the tree.

To save a tree node?

@@ +79,5 @@
> + * 1) Get the tracelogger of the current thread.
> + *     - TraceLoggerForMainThread(JSRuntime *)
> + *     - TraceLoggerForThread(PR_GetCurrentThread());
> + * 2) Optionally prepare the log event, to get an text:
> + *     - TraceLogPrepare(logger, ...);

Could you precise that this function returns an ID? For the TraceLoggerFor*Thread, we understand that a TraceLogger will get returned, but in that case the return value is less obvious, unless jumping at TraceLogPrepare definition.

@@ +81,5 @@
> + *     - TraceLoggerForThread(PR_GetCurrentThread());
> + * 2) Optionally prepare the log event, to get an text:
> + *     - TraceLogPrepare(logger, ...);
> + *    There are also some text IDs that get used by default
> + *    (Tracelogger::TextId). In that case no need to prepare the text.

", in which case there is no need to prepare the text." (otherwise this sentence has no verb :P)

@@ +85,5 @@
> + *    (Tracelogger::TextId). In that case no need to prepare the text.
> + *    This step takes some time, so try to have the textId prepared
> + *    and don't do this over and over, since it will criple performance.
> + * 3) Log the event:
> + *    - TraceLogLog(logger, textId);

How about TraceLogEvent or TraceLogTimestamp?

@@ +89,5 @@
> + *    - TraceLogLog(logger, textId);
> + *    or
> + *    - TraceLogStart(logger, textId);
> + *    - TraceLogStop(logger, textId);
> + *    - AutoTraceLog logger(logger, textId);

Might be worth it to word it differently for that last one, as it's a RAII class instance and not a function as the previous ones.

@@ +90,5 @@
> + *    or
> + *    - TraceLogStart(logger, textId);
> + *    - TraceLogStop(logger, textId);
> + *    - AutoTraceLog logger(logger, textId);
> + */

Very nice comment overall!

@@ +106,5 @@
> +     : data_(nullptr)
> +    { }
> +
> +    bool init() {
> +        capacity_ = 4;

Maybe you'd like to initialize capacity to an higher value, as it seems unexpected to have only four events. Measures on benchmarking should give you an idea of what could be a good initial value.

@@ +147,5 @@
> +
> +        return true;
> +    }
> +
> +    T& operator[](size_t i) {

nit: T &operator

@@ +152,5 @@
> +        MOZ_ASSERT(i < current_);
> +        return data()[i];
> +    }
> +
> +    T& peek(int32_t i) {

same here

@@ +155,5 @@
> +
> +    T& peek(int32_t i) {
> +        MOZ_ASSERT(i < 0);
> +        MOZ_ASSERT(current_ >= uint32_t(-i));
> +        return data()[current_ + i];

so you're adding an unsigned integer with a signed integer. How about making the implicit conversion explicit?

@@ +158,5 @@
> +        MOZ_ASSERT(current_ >= uint32_t(-i));
> +        return data()[current_ + i];
> +    }
> +
> +    void push(T& data) {

nit: T &data

Actually it seems unused.

@@ +163,5 @@
> +        MOZ_ASSERT(current_ < capacity_);
> +        data()[current_++] = data;
> +    }
> +
> +    T& pushUninitialized() {

nit: T &pushUninitialized

@@ +172,5 @@
> +        JS_ASSERT(current_ > 0);
> +        current_--;
> +    }
> +
> +    void empty() {

empty() makes me think it'll return a bool (might be a C++ std lib bias, though :-)). How about calling it clear()?

@@ +180,5 @@
> +
> +class TraceLogger
> +{
> +  public:
> +    // Predefined IDs for common operation. These IDs can be used

nit: common operations

@@ +181,5 @@
> +class TraceLogger
> +{
> +  public:
> +    // Predefined IDs for common operation. These IDs can be used
> +    // without using prepare, because there are already prepared.

nit: please refer to the new name of prepare.

@@ +223,5 @@
> +        uint64_t stop;
> +        union {
> +            struct {
> +                uint32_t textId : 31;
> +                uint32_t hasChildren: 1;

nit: you might want to have uniform whitespaces around the colon here

@@ +229,5 @@
> +            uint32_t value;
> +        } u;
> +        uint32_t nextId;
> +        uint32_t t1;
> +        uint32_t t2;

nit: t1 and t2 are unused.

@@ +286,5 @@
> +
> +    // The prepare 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.
> +    uint32_t prepare(const char *text);

I agree with Till that the name is (still) not very explicit. How about "createId" or "getId", or anything that makes it clear that it will return an ID?

@@ +291,5 @@
> +    uint32_t prepare(JSScript *script);
> +    uint32_t prepare(const char *filename, uint32_t lineno);
> +
> +    // Log an event (no start/stop, only the timestamp is recorded).
> +    void log(uint32_t id);

How about "timestamp", or "singleEvent", or anything clearer you'd have in mind?

@@ +353,5 @@
> +        return logger->prepare(script);
> +#endif
> +    return TraceLogger::TL_Error;
> +}
> +inline uint32_t TraceLogPrepare(TraceLogger* logger, const char *filename, uint32_t lineno) {

How about also getting the column number? For minified scripts which could hold in one line, that seems important. With that done, the next TraceLogPrepare variant could be deleted.

@@ +367,5 @@
> +        return logger->prepare(filename);
> +#endif
> +    return TraceLogger::TL_Error;
> +}
> +inline void TraceLogLog(TraceLogger* logger, uint32_t textId) {

Referring to my previous comment, TraceLogEvent?

@@ +397,3 @@
>  class AutoTraceLog {
> +#if JS_TRACE_LOGGING
> +    TraceLogger* logger;

nit: TraceLogger *logger

@@ +403,3 @@
>  
>    public:
> +    AutoTraceLog(TraceLogger* logger, uint32_t textId MOZ_GUARD_OBJECT_NOTIFIER_PARAM)

nit: TraceLogger *logger

::: js/src/jit/BaselineCompiler.cpp
@@ +390,5 @@
>  
>  #if JS_TRACE_LOGGING
> +    Register logger = RegisterSet::Volatile().takeGeneral();
> +    masm.Push(logger);
> +    masm.movePtr(ImmPtr(TraceLoggerForMainThread(cx->runtime())), logger);

Could you put TraceLoggerForMainThread(cx->runtime()) into a local please, as in emitPrologue?

@@ +392,5 @@
> +    Register logger = RegisterSet::Volatile().takeGeneral();
> +    masm.Push(logger);
> +    masm.movePtr(ImmPtr(TraceLoggerForMainThread(cx->runtime())), logger);
> +    masm.tracelogStop(logger);
> +    masm.tracelogStop(logger);

And a comment please, explaining why we have two calls without arguments (one for the engine id, one for the script). Actually, at this point you could precise that the engine is Baseline, right?

::: js/src/jit/CodeGenerator.cpp
@@ +1249,5 @@
>      masm.flushBuffer();
>      setOsrEntryOffset(masm.size());
>  
>  #if JS_TRACE_LOGGING
> +    if (!gen->compilingAsmJS() && gen->info().executionMode() == SequentialExecution) {

AsmJS doesn't have OSR, so the first part of this check looks weird to me.

::: js/src/jit/IonMacroAssembler.cpp
@@ +1499,5 @@
>  }
>  
>  #if JS_TRACE_LOGGING
>  void
> +MacroAssembler::tracelogStart(Register logger, uint32_t start)

start is actually and id, right?

@@ +1520,5 @@
>      PopRegsInMask(RegisterSet::Volatile());
>  }
>  
>  void
> +MacroAssembler::tracelogStart(Register logger, Register start)

start doesn't seem really appropriate here neither.

@@ +1543,5 @@
>      PopRegsInMask(RegisterSet::Volatile());
>  }
>  
>  void
> +MacroAssembler::tracelogStop(Register logger, uint32_t stop)

same here for stop

@@ +1566,5 @@
> +    PopRegsInMask(RegisterSet::Volatile());
> +}
> +
> +void
> +MacroAssembler::tracelogStop(Register logger, Register stop)

same here for stop

::: js/src/jit/shared/CodeGenerator-shared.h
@@ +454,5 @@
> +    }
> +    bool emitTracelogScriptStop() {
> +        return emitTracelogScript(/* start =*/ false);
> +    }
> +    bool emitTracelogStart(uint32_t start) {

argument name is ambiguous, especially as start is also in the comment below for the bool parameter. I'd like either startTimestamp instead of start (argument), or isStart instead of start (bool).

@@ +457,5 @@
> +    }
> +    bool emitTracelogStart(uint32_t start) {
> +        return emitTracelogTree(/* start =*/ true, start);
> +    }
> +    bool emitTracelogStop(uint32_t stop) {

same here with stop

::: js/src/jsgc.cpp
@@ +5007,5 @@
>  void
>  js::MinorGC(JSRuntime *rt, JS::gcreason::Reason reason)
>  {
>  #ifdef JSGC_GENERATIONAL
> +    TraceLogging *logger = js_TraceLoggers.forMainThread(rt);

undefined?

@@ +5020,5 @@
>  {
>      // Alternate to the runtime-taking form above which allows marking type
>      // objects as needing pretenuring.
>  #ifdef JSGC_GENERATIONAL
> +    TraceLogging *logger = js_TraceLoggers.forMainThread(rt);

same here

::: js/src/vm/Interpreter.cpp
@@ +1792,5 @@
>      {
> +        // No information about which engine exactely stopped,
> +        // could be interpreter, Baseline or IonMonkey
> +        TraceLogStop(logger);
> +        TraceLogStop(logger);

Could you add a comment explaining why we have two calls here? IIUC there's one for the script and one for the engine kind.

::: js/src/vm/RegExpObject.cpp
@@ +613,5 @@
>      }
>  
>  #if ENABLE_YARR_JIT
>      if (!codeBlock.isFallBack()) {
> +        AutoTraceLog logJIT(logger, TraceLogger::YarrJIT);

Shouldn't it get wrapped inside a temporary block as for logCompile above?

@@ +635,5 @@
>      ScopedMatchPairs matches(&cx->tempLifoAlloc());
>      if (!matches.initArray(pairCount()))
>          return RegExpRunStatus_Error;
>  
> +    AutoTraceLog logInterpret(logger, TraceLogger::YarrInterpret);

same here
Attachment #8393480 - Flags: review?(benj)
(Assignee)

Comment 11

5 years ago
Created attachment 8395082 [details] [diff] [review]
tracelogger_improvements

Thanks for the quick review!

(In reply to Benjamin Bouvier [:bbouvier] from comment #10)
> Also, it might be nice to check that we push stack entries in a consistent
> fashion (script first, then engine, or the other way around, but
> consistently across the patch). I kinda remember I've seen some places where
> it wasn't the case.

Kinda hard to enforce. As soon as the function "prepared" is called, we don't know anymore which textIds are scripts.

> @@ +108,5 @@
> > +
> > +    JS_ASSERT(loggerId < 999);
> > +
> > +    char dictFilename[sizeof TRACE_LOG_DIR "tl-dict.100.json"];
> > +    sprintf(dictFilename, TRACE_LOG_DIR "tl-dict.%d.json", loggerId);
> 
> For this call and all other sprintf calls, could you check that the return
> value is >0?

Since buffer is long enough and it can have an encoding error (no multi-byte and wide characters). This cannot fail actually... So there is no real reason to check output...

> 
> @@ +110,5 @@
> > +
> > +    char dictFilename[sizeof TRACE_LOG_DIR "tl-dict.100.json"];
> > +    sprintf(dictFilename, TRACE_LOG_DIR "tl-dict.%d.json", loggerId);
> > +    dictFile = fopen(dictFilename, "w");
> > +    if (!dictFile)
> 
> How about factoring out the closing procedure already present in
> ~TraceLogger(), making it return false in all cases and call from all places
> where it can fail here and from ~TraceLogger?

Hmmm. ~TraceLogger does much more than just closing. I feel more confident about this.


> @@ +37,5 @@
> > + *  - events: Name of the file containing a flat list of log events saved
> > + *            in binary format.
> > + *            (64bit: Time Stamp Counter, 32bit index to dict)
> > + *  - tree:   Name of the file containing the events with duration. The content
> > + *            is already saved in a tree. This is also saved in a binary file.
> 
> Do you mean "as a tree"? Or might be worth precising "in a tree data
> structure". Had to read it a few times before getting it.
> 
> @@ +38,5 @@
> > + *            in binary format.
> > + *            (64bit: Time Stamp Counter, 32bit index to dict)
> > + *  - tree:   Name of the file containing the events with duration. The content
> > + *            is already saved in a tree. This is also saved in a binary file.
> > + *  - treeFormat: The format how the tree is saved. By default "64,64,31,1,32".
> 
> What about "the format used to encode a tree node"?
> To save a tree node?

I kept 'tree' instead of tree node. Since it is about the whole tree format, not only one particular node. But I changed the wording to tree data structure.

> @@ +158,5 @@
> > +        MOZ_ASSERT(current_ >= uint32_t(-i));
> > +        return data()[current_ + i];
> > +    }
> > +
> > +    void push(T& data) {
> 
> nit: T &data
> 
> Actually it seems unused.

It is, since they now all use pushUninitialized(). I left it in, for convenience?

> ::: js/src/vm/RegExpObject.cpp
> @@ +613,5 @@
> >      }
> >  
> >  #if ENABLE_YARR_JIT
> >      if (!codeBlock.isFallBack()) {
> > +        AutoTraceLog logJIT(logger, TraceLogger::YarrJIT);
> 
> Shouldn't it get wrapped inside a temporary block as for logCompile above?

It is in a if-statement. So the AutoTraceLog goes out of scope and the end of the conditional.
Attachment #8393480 - Attachment is obsolete: true
Attachment #8395082 - Flags: review?(benj)
Comment on attachment 8395082 [details] [diff] [review]
tracelogger_improvements

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

Thanks, looks good! r+ with the next few remarks fixed.

(In reply to Hannes Verschore [:h4writer] from comment #11)
> Created attachment 8395082 [details] [diff] [review]
> tracelogger_improvements
> 
> > @@ +158,5 @@
> > > +        MOZ_ASSERT(current_ >= uint32_t(-i));
> > > +        return data()[current_ + i];
> > > +    }
> > > +
> > > +    void push(T& data) {
> > 
> > nit: T &data
> > 
> > Actually it seems unused.
> 
> It is, since they now all use pushUninitialized(). I left it in, for
> convenience?

Alright, but if you want to have it generic, it might as well being in mfbt. If you'd like to, could you open a bug for upstreaming it?

> 
> > ::: js/src/vm/RegExpObject.cpp
> > @@ +613,5 @@
> > >      }
> > >  
> > >  #if ENABLE_YARR_JIT
> > >      if (!codeBlock.isFallBack()) {
> > > +        AutoTraceLog logJIT(logger, TraceLogger::YarrJIT);
> > 
> > Shouldn't it get wrapped inside a temporary block as for logCompile above?
> 
> It is in a if-statement. So the AutoTraceLog goes out of scope and the end
> of the conditional.

True, but it does more than just executing the regexp code (call to MatchPair and so on). Do we want to save that as a part of YARR execution?

::: js/src/TraceLogging.cpp
@@ +272,5 @@
> +    return textId;
> +}
> +
> +uint32_t
> +TraceLogger::createTextId(const JS::ReadOnlyCompileOptions &script)

nit: s/script/options or compileOptions?

::: js/src/TraceLogging.h
@@ +92,5 @@
> + *
> + *    There are also some text IDs created beforehand. They are located in
> + *    Tracelogger::TextId.
> + * 3) Log the timestamp of an event:
> + *    - TraceLogLogTimestamp(logger, textId);

TraceLogTimestamp? Sounds weird to have twice 'log', even if it looks more consistent with other TraceLog* functions.

@@ +319,5 @@
> +
> +  private:
> +    void assertNoQuotes(const char *text) {
> +#ifdef DEBUG
> +        const char *quote = strchr(text, (int)'"');

Do you need the conversion to int here? char is just another name for short (or the other way around).

@@ +377,5 @@
> +        return logger->createTextId(script);
> +#endif
> +    return TraceLogger::TL_Error;
> +}
> +inline uint32_t TraceLogCreateTextId(TraceLogger *logger, const JS::ReadOnlyCompileOptions &script) {

nit: s/script/options?
Attachment #8395082 - Flags: review?(benj) → review+
(Assignee)

Comment 13

4 years ago
Comment on attachment 8395082 [details] [diff] [review]
tracelogger_improvements

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

::: js/src/TraceLogging.h
@@ +225,5 @@
> +
> +      LAST
> +    };
> +
> +#if JS_TRACE_LOGGING

if vs ifdef????

::: js/src/jit/IonMacroAssembler.cpp
@@ +1419,5 @@
> +
> +void
> +MacroAssembler::tracelogStop(Register logger, Register textId)
> +{
> +#ifdef DEBUG:

remote ":" behind DEBUG
(Assignee)

Comment 14

4 years ago
Comment on attachment 8395082 [details] [diff] [review]
tracelogger_improvements

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

::: js/src/TraceLogging.cpp
@@ +153,5 @@
> +        fprintf(stderr, "TraceLogging: Error while writing.\n");
> +
> +    // Eagerly create the default textIds, to match their Tracelogger::TextId.
> +    for (uint32_t i = 0; i < LAST; i++) {
> +        uint32_t textId = createTextId(text[i]);

DebugOnly<>
(Assignee)

Updated

4 years ago
Blocks: 989152
(Assignee)

Comment 15

4 years ago
Created attachment 8402645 [details] [diff] [review]
Move to js/src/vm/

This is the last patch needed before committing. This just moves Tracelogging to the vm folder.
Attachment #8402645 - Flags: review?(till)
Comment on attachment 8402645 [details] [diff] [review]
Move to js/src/vm/

Most certainly
Attachment #8402645 - Flags: review?(till) → review+
Depends on: 994181
Depends on: 994163
And one more fix to have it compiling. Hope bug 994181 isn't also on the way...

https://hg.mozilla.org/integration/mozilla-inbound/rev/9eb226f6ac34
It's looking like this or one of the other commits in the push broke the gaia-integration tests:
https://tbpl.mozilla.org/?tree=Mozilla-Inbound&jobname=gaia-integration&fromchange=22feaebc0b2c&tochange=a8121fe54033

The only other culprit is the merge, which was green on mozilla-central (albeit it could have been a bad merge).

Do you have a try push I can look at for elimination purposes? :-)

Updated

4 years ago
Flags: needinfo?(hv1989)
(Assignee)

Comment 21

4 years ago
This was my try run (contains almost everything except moving of Tracelogging.cpp and Tracelogging.h to vm subdir)
https://tbpl.mozilla.org/?tree=Try&rev=55f3b3c1f217
Flags: needinfo?(hv1989)
Turns out it was caused by bug 974197 and something brought across in the merge; sorry for the noise :-)
(Assignee)

Updated

4 years ago
Blocks: 996509
You need to log in before you can comment on or make changes to this bug.