1045063 - TraceLogging: Don't keep track of stack while disabled

Status: RESOLVED FIXED

(Core :: JavaScript Engine, defect)

Description

[Hannes Verschore [:h4writer]]

In order to decrease performance not to much when tracelogging is disabled. Stop keeping track of the stack in that case.

Comment 1

[Hannes Verschore [:h4writer]]

Attachment: Bug1045063-tracelogger-disable-stack

Comment 2

[Benjamin Bouvier [:bbouvier] (inactive)]

Comment on attachment 8463393 [details] [diff] [review]
Bug1045063-tracelogger-disable-stack

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

Looks good to me, but I am not sure to understand all the chances in Tracelogging.cpp, so just asking more details before r+ing it.

::: js/src/jit/shared/CodeGenerator-shared.cpp
@@ +1010,2 @@
>      RegisterSet regs = RegisterSet::Volatile();
>      Register logger = regs.takeGeneral();

Randomly asking, but could you use the ScratchReg here, to avoid pushing and popping logger? It seems that other instructions in this codegen don't clobber the scratch register.

@@ +1049,2 @@
>      RegisterSet regs = RegisterSet::Volatile();
>      Register logger = regs.takeGeneral();

Ditto.

::: js/src/vm/TraceLogging.cpp
@@ +16,5 @@
>  
>  #include "jit/CompileWrappers.h"
>  #include "vm/Runtime.h"
>  
> +#include "jit/IonFrames-inl.h"

nit: fix include order to avoid a backout :)

@@ +183,5 @@
> +    if (!enable())
> +        return false;
> +
> +    if (enabled == 1) {
> +        js::Activation *act = cx->mainThread().activation();

nit: You could get rid of this js:: prefixing in the file, as you have some using namespace decl at the top. By the way, you could also get rid of all jit:: prefixing by adding |using namespace js::jit;| at the top.

@@ +184,5 @@
> +        return false;
> +
> +    if (enabled == 1) {
> +        js::Activation *act = cx->mainThread().activation();
> +        while (act && (act->cx() != cx || (act->isJit() && !act->asJit()->isActive())))

Could you add a comment explaining what it does? If I understood correctly, it looks for the outermost active JIT activation, or the last active interpreter activation (that, I understood by reading the code below).

@@ -188,5 @@
>  
> -    uint64_t start = rdtsc() - traceLoggers.startupTime;
> -    StackEntry *parent = &stack[0];
> -    for (uint32_t i = 1; i < stack.size(); i++) {
> -        if (!traceLoggers.isTextIdEnabled(stack[i].textId()))

Where did all this code go? Why could you remove it? (this and the next few lines, until we push the TreeEntry below).

@@ +228,5 @@
> +            JS_ASSERT(!fp->runningInJit());
> +
> +            script = fp->script();
> +            engine = Interpreter;
> +            if (script->compartment() != cx->compartment()) { 

nit: trailing whitespace

@@ +257,4 @@
>          return true;
>      }
>  
> +    while (stack.currentId() > 0)

Could you JS_ASSERT(enabled == 1); above that statement please?

@@ -584,5 @@
> -        stackEntry.setTreeId(tree.currentId() + treeOffset);
> -        stackEntry.setLastChildId(0);
> -        stackEntry.setTextId(id);
> -        stackEntry.setActive(false);
> -        return;

Where did this code go? Why could you delete it?

@@ +607,5 @@
>  
>  bool
>  TraceLogger::startEvent(uint32_t id, uint64_t timestamp)
>  {
> +    if (!stack.ensureSpaceBeforeAdd())

maybe set failed to true?

::: js/src/vm/TraceLogging.h
@@ +386,5 @@
>      FILE *dictFile;
>      FILE *treeFile;
>      FILE *eventFile;
>  
> +    uint32_t enabled;

The name suggests it's a bool, but it acts like a count of how many times we called "enable", although I can't find a better name right now. If you have anything better in mind, feel free to change it :)

Comment 3

[Hannes Verschore [:h4writer]]

(In reply to Benjamin Bouvier [:bbouvier] from comment #2)
> Looks good to me, but I am not sure to understand all the chances in
> Tracelogging.cpp, so just asking more details before r+ing it.

sure 

> 
> ::: js/src/jit/shared/CodeGenerator-shared.cpp
> @@ +1010,2 @@
> >      RegisterSet regs = RegisterSet::Volatile();
> >      Register logger = regs.takeGeneral();
> 
> Randomly asking, but could you use the ScratchReg here, to avoid pushing and
> popping logger? It seems that other instructions in this codegen don't
> clobber the scratch register.

IIRC ScratchReg is x64 only. It doesn't exist on ia32. So this wouldn't really work on ia32.

 
> @@ +184,5 @@
> > +        return false;
> > +
> > +    if (enabled == 1) {
> > +        js::Activation *act = cx->mainThread().activation();
> > +        while (act && (act->cx() != cx || (act->isJit() && !act->asJit()->isActive())))
> 
> Could you add a comment explaining what it does? If I understood correctly,
> it looks for the outermost active JIT activation, or the last active
> interpreter activation (that, I understood by reading the code below).

This just gets the top activation (that has the right JSContext *).
So "while (act && act->cx != cx) act = act->prev();".
But if the activation is a JitActivation it can be disabled. In which case we want to skip that. (AsmJS pushes inactive JitActivation. So it doesn't need to actively create new JitActivations for every FFI, but can just flip them on.). 

> @@ -188,5 @@
> >  
> > -    uint64_t start = rdtsc() - traceLoggers.startupTime;
> > -    StackEntry *parent = &stack[0];
> > -    for (uint32_t i = 1; i < stack.size(); i++) {
> > -        if (!traceLoggers.isTextIdEnabled(stack[i].textId()))
> 
> Where did all this code go? Why could you remove it? (this and the next few
> lines, until we push the TreeEntry below).
> @@ -584,5 @@
> > -        stackEntry.setTreeId(tree.currentId() + treeOffset);
> > -        stackEntry.setLastChildId(0);
> > -        stackEntry.setTextId(id);
> > -        stackEntry.setActive(false);
> > -        return;
> 
> Where did this code go? Why could you delete it?

This is the major gain from this bug.

Previously we always kept the full stack with every call to Tracelogger. This way if you enabled the tracelogger it just logged the stack. And we had the full stack in TraceLogger. This bugs adjust this. We don't keep the stack anymore. This takes to much extra time. Esp. since the tracelogger is disabled. We eventually want to land the tracelogger without regressions (if it is disabled).

Now we don't keep the stack anymore and upon enable. When tracelogger gets enabled we ask the JitActivation to give us some more information. So we retrieve the topmost script/engine and log them. (We are only certain about that part. That information should match what Tracelogger will log eventually). This gives us less history. We don't have the full stack anymore. But should bring us closer to have it shipped by default (less regressions when turned off).

Comment 4

[Benjamin Bouvier [:bbouvier] (inactive)]

Comment on attachment 8463393 [details] [diff] [review]
Bug1045063-tracelogger-disable-stack

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

Alright, thanks for the explanation here and on IRC.

Comment 5

[Hannes Verschore [:h4writer]]

Comment on attachment 8463393 [details] [diff] [review]
Bug1045063-tracelogger-disable-stack

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

https://hg.mozilla.org/integration/mozilla-inbound/rev/a2d64173f4c8

::: js/src/vm/TraceLogging.cpp
@@ +16,5 @@
>  
>  #include "jit/CompileWrappers.h"
>  #include "vm/Runtime.h"
>  
> +#include "jit/IonFrames-inl.h"

This is the correct place, IIRC ;)

@@ +607,5 @@
>  
>  bool
>  TraceLogger::startEvent(uint32_t id, uint64_t timestamp)
>  {
> +    if (!stack.ensureSpaceBeforeAdd())

This is done in the function calling this ;)

Comment 6

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/a2d64173f4c8