Closed Bug 1072906 Opened 10 years ago Closed 10 years ago

Tracelogger: Add way to enable/disable logging in IM/Baseline

Categories

(Core :: JavaScript Engine: JIT, defect)

x86_64
Linux
defect
Not set
normal

Tracking

()

RESOLVED FIXED
mozilla36

People

(Reporter: h4writer, Assigned: h4writer)

References

Details

Attachments

(2 files, 3 obsolete files)

There are two solutions for this:
1) Like SPS profiler, recompile upon enable/disable
2) Add the code to log already, but behind a jump which we patch whenever we want enable/disable the logging.

I think (1) will be the easiest.
Blocks: 1065722
Attached patch WIP (obsolete) — Splinter Review
TODO:
1) Add option to force createTextId for scripts.
2) Find solution to not overflow textId list
3) Expose the TL_XXX enum to Debugger
Assignee: nobody → hv1989
Make it possible to adjust logged items during execution.
Attachment #8501097 - Attachment is obsolete: true
Tracelogger has different things it can log. And it can be toggled which things should get logged and which shouldn't. The types are an enum in c code. But I should have this for Debugger too.

Now I was wondering where the best place was to add this?
Not sure I understand the difference between "Debugger"/"DebuggerScript"/"DebuggerSource"/"DebuggerFrame"/"DebuggerObject"/"DebuggerEnv" to make an informed decision.

The current list is something like:
>    _(BaselineCompilation)                            \ 
>    _(Engine)                                         \ 
>    _(GC)                                             \ 
>    _(GCAllocation)                                   \ 
>    _(GCSweeping)                                     \ 
>    _(Internal)                                       \ 
>    _(Invalidation)                                   \ 
>    _(IrregexpCompile)                                \ 
>    _(IrregexpExecute)                                \ 
>    _(IonCompilation)                                 \ 
>    _(IonCompilationPaused)                           \ 
>    _(IonLinking)                                     \ 
>    _(MinorGC)                                        \ 
>    _(ParserCompileFunction)                          \ 
>    _(ParserCompileLazy)                              \ 
>    _(ParserCompileScript)                            \ 
>    _(Scripts)                                        \ 
>    _(VM)                                             \ 
>    _(Bailout)                                        \ 
>                                                      \ 
>    /* Specific passes during ion compilation */      \ 
>    _(FoldTests)                                      \ 
>    _(SplitCriticalEdges)                             \ 
>    _(RenumberBlocks)                                 \ 
>    _(ScalarReplacement)                              \ 
>    _(DominatorTree)                                  \ 
>    _(PhiAnalysis)                                    \ 
>    _(MakeLoopsContiguous)                            \ 
>    _(ApplyTypes)                                     \ 
>    _(ParallelSafetyAnalysis)                         \ 
>    _(AliasAnalysis)                                  \ 
>    _(GVN)                                            \ 
>    _(LICM)                                           \ 
>    _(RangeAnalysis)                                  \ 
>    _(LoopUnrolling)                                  \ 
>    _(EffectiveAddressAnalysis)                       \ 
>    _(EliminateDeadCode)                              \ 
>    _(EdgeCaseAnalysis)                               \ 
>    _(EliminateRedundantChecks)                       \ 
>    _(GenerateLIR)                                    \ 
>    _(RegisterAllocation)                             \ 
>    _(GenerateCode)
Note: for now debugger will only use Scripts, but it can use more already. This would enable it to enable more reporters.
Flags: needinfo?(nfitzgerald)
Attachment #8503087 - Flags: review?(jdemooij)
(In reply to Hannes Verschore [:h4writer] from comment #3)
> Tracelogger has different things it can log. And it can be toggled which
> things should get logged and which shouldn't. The types are an enum in c
> code. But I should have this for Debugger too.
> 
> Now I was wondering where the best place was to add this?
> Not sure I understand the difference between
> "Debugger"/"DebuggerScript"/"DebuggerSource"/"DebuggerFrame"/
> "DebuggerObject"/"DebuggerEnv" to make an informed decision.

I think this should be exposed on Debugger's prototype directly, something like:

  Debugger.prototype.startTraceLogging(config)
  Debugger.prototype.endTraceLogging()

Usage:

  dbg.startTraceLogging({
    GC: true,
    minorGC: true,
    ...
  });

I'd like to hear what Jim thinks as well.
Flags: needinfo?(nfitzgerald) → needinfo?(jimb)
Ah interesting. I actually have three functions:

// Enable/disable certain hooks. This prepares baseline/ionmonkey so it can emit these log items.
// This is invalidates ionmonkey code and is quite expensive.
// (This doesn't start logging, but will decrease performance a little bit. (barely noticeable).
//  It is the idea that you can do that as soon as you go to this devtool. And disable as soon as
//  you leave that tab.)
dbg.enableTraceItem(dbg.TraceLogger_GC);

// Start/stop logging. Because we have prepared everything, enabling/disabling is not disruptive and doesn't take a lot of time.
dbg.startTraceLogging();
dbg.endTraceLogging();

the name of "enableTraceItem" isn't quite good yet.
What about:
dbg.prepareTraceLogger({
   GC: true,
   minorGC: true,
   ...
});
Which would be closer to your idea...
What does splitting out the options from the starting of logging provide? It seems to me like one would pretty much always want to do both at the same time.
(In reply to Nick Fitzgerald [:fitzgen] from comment #6)
> What does splitting out the options from the starting of logging provide? It
> seems to me like one would pretty much always want to do both at the same
> time.

For performance measurement this is quite handy to have them separate. You don't want to interfere with performance by invalidating all IonMonkey code every time you enable/disable tracelogger. E.g. if you use start/endTraceLogging in a hot function, to only see code corresponding to that function.
Comment on attachment 8503087 [details] [diff] [review]
Dynamically toggle logged ids in Baseline and IonMonkey

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

Looks good but some questions below. Also do we need similar changes for Ion?

::: js/src/jit/BaselineCompiler.cpp
@@ +773,5 @@
> +    Register loggerReg = regs.takeGeneral();
> +    Register scriptReg = regs.takeGeneral();
> +
> +    masm.Push(loggerReg);
> +    masm.movePtr(ImmPtr(logger), loggerReg);

Can you move this inside the jumped-over code? 99.9% of the time TL will be disabled, so I'd prefer doing no extra work in that case.

@@ +780,5 @@
> +    Label noScriptStart;
> +    tlScriptStartToggleOffset_ = masm.toggledJump(&noScriptStart);
> +    masm.Push(scriptReg);
> +    tlScriptTextIdLabel_ = masm.movWithPatch(ImmWord(uintptr_t(TL_Scripts)), scriptReg);
> +    masm.tracelogStart(loggerReg, scriptReg);

`force = true` here too?

@@ +786,5 @@
> +    masm.bind(&noScriptStart);
> +
> +    // Engine start.
> +    Label noEngineStart;
> +    tlEngineStartToggleOffset_ = masm.toggledJump(&noEngineStart);

Do we really need to toggle the script and engine separately? How much overhead is there from logging both if TL is enabled?

::: js/src/jit/BaselineJIT.h
@@ +361,5 @@
>  
>      void toggleSPS(bool enable);
>  
> +    void toggleTLScript(JSRuntime *runtime, JSScript *script, bool enable);
> +    void toggleTLEngine(bool enable);

Nit: TraceLogger or TraceLogging instead of TL is longer but clearer.

@@ +415,5 @@
>  
> +void
> +ToggleBaselineTLScripts(JSRuntime *runtime, bool enable);
> +void
> +ToggleBaselineTLEngine(JSRuntime *runtime, bool enable);

Same here.

::: js/src/vm/Debugger.cpp
@@ +3044,5 @@
> +    THIS_DEBUGGER(cx, argc, vp, "enableTraceItem", args, dbg);
> +    if (!args.requireAtLeast(cx, "Debugger.enableTraceItem", 1))
> +        return false;
> +
> +    uint32_t id = args[0].toInt32();

We should add some jit-tests. Also the fuzzers probably won't like the unchecked toInt32() here :)
Attachment #8503087 - Flags: review?(jdemooij)
Attached patch Part 2: add prepareTraceLogger (obsolete) — Splinter Review
Adjust enableTraceItem to prepareTraceLogger like suggested in comment 4/5
Attachment #8504066 - Flags: review?(benj)
Comment on attachment 8504066 [details] [diff] [review]
Part 2: add prepareTraceLogger

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

Maybe I should also use prepareTraceLogging, instead of prepareTraceLogger?

::: js/src/vm/Debugger.cpp
@@ +3043,3 @@
>  {
>      THIS_DEBUGGER(cx, argc, vp, "enableTraceItem", args, dbg);
>      if (!args.requireAtLeast(cx, "Debugger.enableTraceItem", 1))

s/enableTraceItem/prepareTraceLogger
Comment on attachment 8504066 [details] [diff] [review]
Part 2: add prepareTraceLogger

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

Nice that we're having this in the debugger! \o/
I think there are a few things to improve first, in this patch.

::: js/src/vm/Debugger.cpp
@@ +3043,3 @@
>  {
>      THIS_DEBUGGER(cx, argc, vp, "enableTraceItem", args, dbg);
>      if (!args.requireAtLeast(cx, "Debugger.enableTraceItem", 1))

yes, twice above. Also, how about "setupTraceLogger"?

@@ +3044,5 @@
>      THIS_DEBUGGER(cx, argc, vp, "enableTraceItem", args, dbg);
>      if (!args.requireAtLeast(cx, "Debugger.enableTraceItem", 1))
>          return false;
>  
> +    RootedValue arg(cx, args[0]);

args[0] is used only once, please inline its use:

RootedObject props(cx, ToObject(cx, args[0]));

@@ +3050,5 @@
> +    if (!props)
> +        return false;
> +
> +    AutoIdVector ids(cx);
> +    if (!GetPropertyKeys(cx, props, JSITER_OWNONLY | JSITER_SYMBOLS, &ids))

you skip symbols in the for loop, so no need to include them in the GetPropertyKeys here

@@ +3053,5 @@
> +    AutoIdVector ids(cx);
> +    if (!GetPropertyKeys(cx, props, JSITER_OWNONLY | JSITER_SYMBOLS, &ids))
> +        return false;
> +
> +    size_t n = ids.length();

could you put it in the loop initializers?

@@ +3056,5 @@
> +
> +    size_t n = ids.length();
> +
> +    for (size_t i = 0; i < n; i++) {
> +        if (!JSID_IS_STRING(ids[i]))

with the above change, can we MOZ_ASSERT instead of skipping on test, here?

@@ +3067,5 @@
> +
> +        uint32_t textId = TLStringToTextId(linear);
> +
> +        if (!TLTextIdIsToggable(textId)) {
> +            args.rval().setBoolean(false);

This means that if we toggle a few existing ids and then a non-existing one, the previous existing ones will be activated. I think we'd prefer to either activate them all, or none of them, what do you think? That would require a vector to store them, though, but that looks finer than such an API.

An alternative would be to return an array of the effectively activated text-ids.

@@ +3079,5 @@
> +
> +        if (textId == TL_Scripts)
> +            jit::ToggleBaselineTLScripts(cx->runtime(), true);
> +        if (textId == TL_Engine)
> +            jit::ToggleBaselineTLEngine(cx->runtime(), true);

These 4 lines above look like they belong to TraceLogEnableTextId; caller shouldn't have to worry about this here.

@@ +3082,5 @@
> +        if (textId == TL_Engine)
> +            jit::ToggleBaselineTLEngine(cx->runtime(), true);
> +    }
> +
> +    ReleaseAllJITCode(cx->runtime()->defaultFreeOp());

Ha, so doing Debugger.prepaceTraceLogger({}); right now will be an effective way to delete jit code. Can you take into account the fact that we've added new text-ids that were not activated beforehands?

::: js/src/vm/TraceLoggingTypes.cpp
@@ +8,5 @@
> +
> +#include "jsstr.h"
> +
> +uint32_t
> +TLStringToTextId(JSLinearString *str)

Why not using a hash-table?
Attachment #8504066 - Flags: review?(benj)
(In reply to Jan de Mooij [:jandem] from comment #8)
> Comment on attachment 8503087 [details] [diff] [review]
> Dynamically toggle logged ids in Baseline and IonMonkey
> 
> Review of attachment 8503087 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Looks good but some questions below. Also do we need similar changes for Ion?

No, we invalidate the IonScript for IonMonkey. During the recompile the right hooks get added.

> @@ +780,5 @@
> > +    Label noScriptStart;
> > +    tlScriptStartToggleOffset_ = masm.toggledJump(&noScriptStart);
> > +    masm.Push(scriptReg);
> > +    tlScriptTextIdLabel_ = masm.movWithPatch(ImmWord(uintptr_t(TL_Scripts)), scriptReg);
> > +    masm.tracelogStart(loggerReg, scriptReg);
> 
> `force = true` here too?

The "force" is used when we do "masm.tracelogStart" with a specific textId. When that particular textId is disabled masm.traceLogStart will not emit anything. The "force" is to make sure we do generate the code.
Here it is used with a Register. In that case we can't check beforehand if that particular textId is enabled. So we always emit code. As a result that variant has no "force" variable. It is always emitted.

> @@ +786,5 @@
> > +    masm.bind(&noScriptStart);
> > +
> > +    // Engine start.
> > +    Label noEngineStart;
> > +    tlEngineStartToggleOffset_ = masm.toggledJump(&noEngineStart);
> 
> Do we really need to toggle the script and engine separately? How much
> overhead is there from logging both if TL is enabled?

We only want to log which item is enabled. So it should be able to toggle them separately. Though there is another check inside "logTimestamp". So we could toggle both on/off and make sure only one of them gets logged. Which I did here.

> 
> ::: js/src/vm/Debugger.cpp
> @@ +3044,5 @@
> > +    THIS_DEBUGGER(cx, argc, vp, "enableTraceItem", args, dbg);
> > +    if (!args.requireAtLeast(cx, "Debugger.enableTraceItem", 1))
> > +        return false;
> > +
> > +    uint32_t id = args[0].toInt32();
> 
> We should add some jit-tests. Also the fuzzers probably won't like the
> unchecked toInt32() here :)

I left it there, since that code is removed in the follow-up patch ;).
But I'll definitely add testcases. It is on my list of things to do before landing this all.
Attachment #8503087 - Attachment is obsolete: true
Attachment #8505451 - Flags: review?(jdemooij)
Attachment #8505481 - Flags: review?(benj)
Attachment #8504066 - Attachment is obsolete: true
Comment on attachment 8505451 [details] [diff] [review]
Part 1: Dynamically toggle logged ids in Baseline and IonMonkey

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

::: js/src/vm/Debugger.cpp
@@ +3053,5 @@
> +    }
> +
> +    args.rval().setBoolean(true);
> +    if (TraceLogTextIdEnabled(id))
> +        return true;

These two lines can be removed.

::: js/src/vm/TraceLogging.cpp
@@ +584,5 @@
>  
> +void
> +TraceLoggerThreadState::enableTextId(JSContext *cx, uint32_t textId)
> +{
> +    MOZ_ASSERT(TLTextIdIsToggable(textId));

Add the following here:

if (enabledTextIds[textId]))
    return;

@@ +603,5 @@
> +}
> +void
> +TraceLoggerThreadState::disableTextId(JSContext *cx, uint32_t textId)
> +{
> +    MOZ_ASSERT(TLTextIdIsToggable(textId));

Add the following here:

if (!enabledTextIds[textId]))
    return;
Comment on attachment 8505481 [details] [diff] [review]
Part 2: add setupTraceLogger

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

::: js/src/vm/Debugger.cpp
@@ +3094,5 @@
> +    MOZ_ASSERT(textIds.length() == values.length());
> +
> +    for (size_t i = 0; i < textIds.length(); i++) {
> +        if (TraceLogTextIdEnabled(textIds[i]) == values[i])
> +            continue;

These two lines can get removed.
Comment on attachment 8505481 [details] [diff] [review]
Part 2: add setupTraceLogger

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

Looks fine, thanks.

::: js/src/vm/Debugger.cpp
@@ +3046,4 @@
>          return false;
>  
> +    RootedValue arg(cx, args[0]);
> +    RootedObject obj(cx, ToObject(cx, arg));

can you please inline the use of arg? I think it's already been mentioned in the previous review, and unless you have a good argument for keeping it, it would simplify code to delete it, and avoid one useless rooting.

RootedObject obj(cx, ToObject(cx, args[0]));

@@ +3051,5 @@
> +        return false;
> +
> +    AutoIdVector ids(cx);
> +    if (!GetPropertyKeys(cx, obj, JSITER_OWNONLY, &ids))
> +        return false;

I know this would be a silly use case of setupTraceLogger, but you could return early here if ids.length() == 0.

@@ +3062,5 @@
> +    if (!values.reserve(ids.length()))
> +        return false;
> +
> +    for (size_t i = 0; i < ids.length(); i++) {
> +        if (!JSID_IS_STRING(ids[i])) {

Can this JSID be something else than a string? jsid can be an int32, per the enum, but i wonder if object keys aren't actually all strings. Could you test this, and if they can't anything else,  MOZ_ASSERT(JSID_IS_STRING(ids[i])); here instead?

@@ +3080,5 @@
> +            return true;
> +        }
> +
> +        RootedValue v(cx);
> +        if (!JSObject::getGeneric(cx, obj, obj, ids[i], &v)) {

Shouldn't we just return false here? getGeneric seems to return false iff it fails (oom and such).

@@ +3090,5 @@
> +        values.append(ToBoolean(v));
> +    }
> +
> +    MOZ_ASSERT(ids.length() == textIds.length());
> +    MOZ_ASSERT(textIds.length() == values.length());

Very sane assertions!

@@ +3099,5 @@
> +
> +        if (values[i])
> +            TraceLogEnableTextId(cx, textIds[i]);
> +        else
> +            TraceLogDisableTextId(cx, textIds[i]);

This calls for TraceLogSetEnabledTextId(JSContext*, uint32_t textId, bool enabled), but that's fine to do it this way now.

::: js/src/vm/TraceLoggingTypes.cpp
@@ +10,5 @@
> +
> +uint32_t
> +TLStringToTextId(JSLinearString *str)
> +{
> +#define NAME(textId) if (js::StringEqualsAscii (str, #textId)) return TraceLogger_ ## textId;

nit: space after StringEqualsAscii isn't needed

::: js/src/vm/TraceLoggingTypes.h
@@ +7,5 @@
>  #ifndef TraceLoggingTypes_h
>  #define TraceLoggingTypes_h
>  
>  #include "jsalloc.h"
> +#include "jsstr.h"

can you just declare JSLinearString here, rather than importing the entire header?

class JSLinearString;
Attachment #8505481 - Flags: review?(benj) → review+
(In reply to Benjamin Bouvier [:bbouvier] from comment #17)
> @@ +3062,5 @@
> > +    if (!values.reserve(ids.length()))
> > +        return false;
> > +
> > +    for (size_t i = 0; i < ids.length(); i++) {
> > +        if (!JSID_IS_STRING(ids[i])) {
> 
> Can this JSID be something else than a string? jsid can be an int32, per the
> enum, but i wonder if object keys aren't actually all strings. Could you
> test this, and if they can't anything else, 
> MOZ_ASSERT(JSID_IS_STRING(ids[i])); here instead?


setupTraceLogger({
 0: true
});

Will give a int32 instead of a string ;)
Comment on attachment 8505451 [details] [diff] [review]
Part 1: Dynamically toggle logged ids in Baseline and IonMonkey

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

Sorry for the delay! r=me with nits addressed.

::: js/src/jit/BaselineJIT.cpp
@@ +859,5 @@
> +    if (enable && !engineEnabled) {
> +        Assembler::ToggleToCmp(enter);
> +        Assembler::ToggleToCmp(exit);
> +    }
> +    if (!enable && !engineEnabled) {

Maybe:

if (!engineEnabled) {
    if (enable) {
        ...
    } else {
        ...
    }
}

To make it a bit easier to see we're doing nothing if engineEnabled?

@@ +880,5 @@
> +
> +    // Enable/Disable the traceLogger prologue and epilogue.
> +    CodeLocationLabel enter(method_, CodeOffsetLabel(traceLoggerEnterToggleOffset_));
> +    CodeLocationLabel exit(method_, CodeOffsetLabel(traceLoggerExitToggleOffset_));
> +    if (enable && !scriptsEnabled) {

Same here.

::: js/src/vm/Debugger.cpp
@@ +3044,5 @@
> +    THIS_DEBUGGER(cx, argc, vp, "enableTraceItem", args, dbg);
> +    if (!args.requireAtLeast(cx, "Debugger.enableTraceItem", 1))
> +        return false;
> +
> +    uint32_t id = args[0].toInt32();

Needs an isInt32() check, but you said that's in another patch?
Attachment #8505451 - Flags: review?(jdemooij) → review+
Yes, Debugger.prototype is probably the best place to put such methods.

I see that the functions are conditional on JS_TRACE_LOGGING. Is that enabled in releases? If so, it should be documented.
Flags: needinfo?(jimb) → needinfo?(hv1989)
Correct, JS_TRACE_LOGGING is enabled in release. Opened bug 1118687 for this.
Flags: needinfo?(hv1989)
You need to log in before you can comment on or make changes to this bug.