1298541 - TraceLogger: Support logging of generators

Status: RESOLVED FIXED

(Core :: JavaScript Engine, defect)

Description

[Steve Fink [:sfink] [:s:]]

I have a test case where I'm looking at the performance of loading https://docs.google.com/document/d/14xhE4RtUOnqjXGR7JpOuEl2vMMWUPEu0iKrF3j1-iLI/edit

According to the devtools, I'm spending a chunk of time in a script "edit:12". It looks like that's really

https://docs.google.com/document/d/14xhE4RtUOnqjXGR7JpOuEl2vMMWUPEu0iKrF3j1-iLI/edit:12:0

or perhaps a different column number.

Anyway, the time spent in the second invocation of something from that (long, minified) line in Firefox is >500ms, and Chrome runs it in about 270ms. (I'm not 100% sure they're really doing the same thing; I only have the file and line number to go on, and the pattern of long script executions that mostly match up. But that's not really the point for this bug.)

My *dict.0.json has a whole bunch of entries matching that line number. All are duplicates of two distinct entries, from columsn 0 and 162. But if I dump out the *tree.0.json file, I don't see any of those textIds. I don't understand how it could have created textmap entries for them without emitting any events.

I'm attempting to trace through a sample run. It claims to be emitting an event. I'll have to cross-check the file offsets or something.

Comment 1

[Hannes Verschore [:h4writer]]

One important thing to note is that for TraceLogger we don't record "inlined functions".
(In most cases that would result in too much data).

That means that 

function foo1() {
   while (...)
      foo2();
}
function foo2() {
   while (...)
      foo3();
}
function foo3() {
   
}

We will see:
foo1, foo2 and foo3 in Interpreter and Baseline, but when going to IonMonkey we will most likely only see foo1, since foo2 and foo3 will be inlined in foo1.

That is shortcut I made that makes it easier for "JS engine devs" (but annoying for "JS devs"). When seeing foo1 takes a lot of time in IonMonkey, it means the IonScript compiled for "foo1" takes a lot of time. Therefore it might be good to look at that IonScript and the MIR/LIR/assembly to see how we can improve it.

(Another reason I did this, is because it is hard to distinguish script bounderies if we start hoisting MIR. Where does the inlined functions start/stop.)

Comment 2

[Hannes Verschore [:h4writer]]

(In reply to Steve Fink [:sfink] [:s:] from comment #0)
> My *dict.0.json has a whole bunch of entries matching that line number. All
> are duplicates of two distinct entries, from columsn 0 and 162. But if I
> dump out the *tree.0.json file, I don't see any of those textIds. I don't
> understand how it could have created textmap entries for them without
> emitting any events.

That is strange. In most cases the event is created at the moment we need it. Except for Baseline and IonMonkey. There we bake the payload into the script at compile time. But even then I would assume we at least execute that script once? Very strange.

That we have a lot of the same entries in dict.0.json is caused by bug 1280648. I just pushed a patch to review to enable this caching again in bug 1281156 which should decrease the amount of duplicate entries in dict.0.json

Comment 3

[Steve Fink [:sfink] [:s:]]

I don't think this is a problem with inlining. The function in question is the toplevel entry point. And it calls lots of other things.

In trying to debug this, I *think* I've found that the problem is that the TraceLoggerGraph code is popping too far off the stack and disabling itself, so it's only recording the beginning of the run.

I added an assert that basically boils down to stackDepth++ in TraceLoggerThread::startEvent and stackDepth-- in TraceLoggerThread::stopEvent, and sure enough, after 51732 events the pushes and pops are not matched (as in, I see a stopEvent with an empty stack.)

This happens in both opt and debug builds. The stopEvent it detects the stack underflow on is a TraceLogger_Engine called from the exit: label of Interpret. (But there have been lots of Baseline <-> IonMonkey transitions previously, which is probably what messed things up.) Just to confirm: this is not expected, right? I looked to see if the JITs go through startEvent/stopEvent, and it *looks* to me like they do (and my stack shows lots of TraceLogger_IonMonkey and TraceLogger_Baseline events in the past).

I see failures in lots of shell tests, too, eg:

js/src/tests% TLLOG=Default  TLOPTIONS=EnableMainThread,EnableOffThread /home/sfink/src/mozilla/obj-js-debug/dist/bin/js --no-baseline -f shell.js -f js1_7/shell.js -f js1_7/regress/shell.js -f js1_7/regress/regress-453411.js
BUGNUMBER: 453411
STATUS: Do not assert with JIT: !cx->executingTrace|!tm->onTrace
Assertion failure: stackDepth > 0, at /home/sfink/src/mozilla/js/src/vm/TraceLogging.cpp:526

and that's with JIT disabled. So I'm wondering if my assert is invalid?

Comment 4

[Steve Fink [:sfink] [:s:]]

For the record, my mismatched push/pop pair with the above test case is where I push id 90 "js1_7/regress/regress-453411.js" and then pop id 107 "self-hosted". (But there's a whole bunch of balanced pushing/popping in between.)

I'm uploading my patch that checks this.

Comment 5

[Steve Fink [:sfink] [:s:]]

Attachment: TL diagnostics

Comment 6

[Hannes Verschore [:h4writer]]

Not sure if it is quite important to fix this specific one. Since this is forced on version(170).
Doesn't mean there cannot be other places were we hit this.

Comment 7

[Hannes Verschore [:h4writer]]

Attachment: Part 1: During DEBUG check that we always maintain "start" and "stop" type

@sfink: in order for you to focus on using TraceLogger instead of fixing. Taking over.

@bbouvier: This used to be part of TL, but got no place anymore after the split into TraceLogger and TraceLoggerGraph. Adding these debug checks again, since they help to find issues in TraceLogger.

Comment 8

[Hannes Verschore [:h4writer]]

Attachment: Part 2: When requesting the "Script start/stop" don't include the "Internal" events.

Need this to work properly for the testcase of the fix.

Comment 9

[Hannes Verschore [:h4writer]]

Attachment: Part 3: Fix for the Interpreter

Comment 10

[Hannes Verschore [:h4writer]]

Attachment: Part 4: Enable jit-tests/tests/tracelogger/drainTraceLogger.js again

Comment 11

[Hannes Verschore [:h4writer]]

Comment on attachment 8786776 [details] [diff] [review]
Part 4: Enable jit-tests/tests/tracelogger/drainTraceLogger.js again

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

::: js/src/vm/TraceLogging.h
@@ +227,5 @@
>              *num = events.size();
>              start = events.data();
>          }
>  
> +        printf("%d %d %d\n", *lastIteration, *lastSize, *num);

Remove debugging spew.

Comment 12

[Hannes Verschore [:h4writer]]

Comment on attachment 8786750 [details] [diff] [review]
Part 1: During DEBUG check that we always maintain "start" and "stop" type

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

::: js/src/vm/TraceLogging.cpp
@@ +491,5 @@
>      if (!traceLoggerState->isTextIdEnabled(id))
>         return;
>  
> +#ifdef DEBUG
> +    {

if (enabled > 0) {

@@ +524,5 @@
>      if (!traceLoggerState->isTextIdEnabled(id))
>          return;
>  
> +
> +#ifdef DEBUG

if (enabled > 0) {

Comment 13

[Hannes Verschore [:h4writer]]

Attachment: Part 5: WIP: Fix for Baseline

This fixes it locally for me. Though could be nicer. I'll refactor tomorrow.
Also doesn't support multiple JSOP_RESUME statements in a script. Not sure if that is possible?

Comment 14

[Steve Fink [:sfink] [:s:]]

Ouch, that looks like it must have been unpleasant to fix.

When I apply all of those patches and run the jstests, I get lots of failures at

Assertion failure: new_off < code->instructionsSize(), at /home/sfink/src/mozilla/js/src/jit/IonCaches.cpp:77

for example, with

TLLOG=Default  TLOPTIONS=EnableMainThread,EnableOffThread /home/sfink/src/mozilla/obj-js-debug/dist/bin/js -f shell.js -f ecma_7/shell.js -f ecma_7/String/shell.js -f ecma_7/String/string-pad-start-end.js

I'm rebasing on inbound right now to verify... oh, weird, that changed it to a plain crash in the line

            Assembler::ToggleToCmp(resume);

in BaselineScript::initTraceLogger. resume.raw_ is a bogus pointer there.

Comment 15

[Hannes Verschore [:h4writer]]

Attachment: Part 1: During DEBUG check that we always maintain "start" and "stop" type

Comment 16

[Hannes Verschore [:h4writer]]

Attachment: Part 2: When requesting the "Script start/stop" don't include the "Internal" events.

Comment 17

[Hannes Verschore [:h4writer]]

Attachment: Part 3: Fix for the interpreter

Comment 18

[Hannes Verschore [:h4writer]]

Attachment: Part 4: Enable jit-tests/tests/tracelogger/drainTraceLogger.js again

Comment 19

[Hannes Verschore [:h4writer]]

Attachment: Part 5: Fix for Baseline

Comment 20

[Hannes Verschore [:h4writer]]

(In reply to Steve Fink [:sfink] [:s:] from comment #14)
> Ouch, that looks like it must have been unpleasant to fix.
> 
> When I apply all of those patches and run the jstests, I get lots of
> failures at
> 
> Assertion failure: new_off < code->instructionsSize(), at
> /home/sfink/src/mozilla/js/src/jit/IonCaches.cpp:77
> 
> for example, with
> 
> TLLOG=Default  TLOPTIONS=EnableMainThread,EnableOffThread
> /home/sfink/src/mozilla/obj-js-debug/dist/bin/js -f shell.js -f
> ecma_7/shell.js -f ecma_7/String/shell.js -f
> ecma_7/String/string-pad-start-end.js
> 
> I'm rebasing on inbound right now to verify... oh, weird, that changed it to
> a plain crash in the line
> 
>             Assembler::ToggleToCmp(resume);
> 
> in BaselineScript::initTraceLogger. resume.raw_ is a bogus pointer there.

IIRC that fix should have been in the WIP I posted. Though there was another possible issue. Which is now fixed. With all patches:

 TLLOG=Default  TLOPTIONS=EnableMainThread,EnableOffThread $JS/dist/bin/js -f shell.js -f ecma_7/shell.js -f ecma_7/String/shell.js -f ecma_7/String/string-pad-start-end.js
 PASSED!

Comment 21

[Benjamin Bouvier [:bbouvier] (inactive)]

Comment on attachment 8787148 [details] [diff] [review]
Part 1: During DEBUG check that we always maintain "start" and "stop" type

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

Sweet

::: js/src/vm/TraceLogging.cpp
@@ +534,5 @@
> +            MOZ_ASSERT(prev >= TraceLogger_Last);
> +        } else if (id >= TraceLogger_Last) {
> +            MOZ_ASSERT(prev >= TraceLogger_Last);
> +            MOZ_ASSERT_IF(prev != id, strcmp(eventText(id), eventText(prev)) == 0);
> +        } else  {

nit: two spaces after `else`

Comment 22

[Benjamin Bouvier [:bbouvier] (inactive)]

Comment on attachment 8787149 [details] [diff] [review]
Part 2: When requesting the "Script start/stop" don't include the "Internal" events.

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

Does this need to be added to drainTraceLogger too? If so, it'd be nice to have a way to share more code between the two methods.

Comment 23

[Benjamin Bouvier [:bbouvier] (inactive)]

Comment on attachment 8787150 [details] [diff] [review]
Part 3: Fix for the interpreter

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

::: js/src/jit-test/tests/tracelogger/bug1298541.js
@@ +22,5 @@
> +    var objs = du.drainTraceLoggerScriptCalls();
> +    var scripts = 0;
> +    var stops = 0;
> +    for (var i = 0; i < objs.length; i++) {
> +            print(JSON.stringify(objs[i]))

nit: indentation is off here

@@ +28,5 @@
> +            scripts++;
> +        } else if (objs[i].logType == "Stop") {
> +            stops++;
> +        } else {
> +            assertEq(true, false);

can just throw instead

@@ +37,5 @@
> +}
> +
> +function test()
> +{
> +  for (var i in (function(){ for (var j=0;j<4;++j) { yield ""; } })());

Doesn't this need to be function* to be a modern generator?

Comment 24

[Benjamin Bouvier [:bbouvier] (inactive)]

Comment on attachment 8787151 [details] [diff] [review]
Part 4: Enable jit-tests/tests/tracelogger/drainTraceLogger.js again

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

::: js/src/jit-test/tests/tracelogger/drainTraceLogger.js
@@ -6,4 @@
>              scripts++;
>              assertEq("fileName" in objs[i], true); 
>              assertEq("lineNumber" in objs[i], true); 
>              assertEq("columnNumber" in objs[i], true); 

pre-existing: three lines with trailing space

@@ +53,4 @@
>  
>      // Test basic script.
>      for (var i=0; i<20; i++)
>          foo1();

pre-existing: there is no enclosing TL, right? So this doesn't do a thing?

@@ +69,1 @@
>      

pre-existing: trailing spaces

@@ +69,4 @@
>      
>      // Test basic script.
>      for (var i=0; i<20; i++)
>          foo1();

(same)

@@ +84,2 @@
>      TestDrainTraceLoggerInvariants(objs);
> +    assertEq(3, GetMaxScriptDepth(objs));

Can you comment this value in the assertEq text?

assertEq(3, GetMaxScriptDepth(objs), "start + script + script");

@@ +84,3 @@
>      TestDrainTraceLoggerInvariants(objs);
> +    assertEq(3, GetMaxScriptDepth(objs));
> +    assertEq(4*100 + 1, objs.length);

Can you also comment the values here? (guess is 4 == start + script + script + stop, and the +1 is because of the first Start)

::: js/src/vm/Debugger.cpp
@@ +655,5 @@
> +#ifdef JS_TRACE_LOGGING
> +    TraceLoggerThread* logger = TraceLoggerForMainThread(cx->runtime());
> +    if (logger) {
> +#ifdef NIGHTLY_BUILD
> +        logger->updateIterationAndSize(&traceLoggerLastDrainedIteration, &traceLoggerLastDrainedSize);

Maybe for another bug, but it'd be sweet to have a struct traceLogger (with all the needed fields) in the Debugger, rather than plenty of long names.

@@ +658,5 @@
> +#ifdef NIGHTLY_BUILD
> +        logger->updateIterationAndSize(&traceLoggerLastDrainedIteration, &traceLoggerLastDrainedSize);
> +#endif
> +        logger->updateIterationAndSize(&traceLoggerScriptedCallsLastDrainedIteration,
> +                                       &traceLoggerScriptedCallsLastDrainedSize);

This should set traceLoggerScriptedCallsLastDrainedIteration := traceLoggerLastDrainedIteration (ditto for the second variable). Can you call the method only once and reuse the results, instead of calling twice?

::: js/src/vm/TraceLogging.h
@@ +232,4 @@
>          return start;
>      }
>  
> +    void updateIterationAndSize(uint32_t* iteration, uint32_t* size) {

Considering that this doesn't any internal value (which can be confirmed by marking this method const), the naming seems off. How about two const methods iteration() and size(), instead?

Comment 25

[Benjamin Bouvier [:bbouvier] (inactive)]

Comment on attachment 8787152 [details] [diff] [review]
Part 5: Fix for Baseline

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

::: js/src/jit/BaselineJIT.cpp
@@ +456,5 @@
>  
>      script->yieldEntriesOffset_ = yieldEntries ? offsetCursor : 0;
>      offsetCursor += paddedYieldEntriesSize;
>  
> +    script->traceLoggerToggleOffsetsOffset_ = tlEntriesSize ?  offsetCursor : 0;

nit: extra space after ?

@@ +980,5 @@
>      traceLoggerScriptEvent_ = TraceLoggerEvent(logger, TraceLogger_Scripts, script);
>  
> +    MOZ_ASSERT(offsets.length() == numTraceLoggerToggleOffsets_);
> +    for (size_t i = 0; i < offsets.length(); i++) {
> +        traceLoggerToggleOffsets()[i] = offsets[i].offset();

nit: no braces needed

::: js/src/jit/BaselineJIT.h
@@ +432,5 @@
>          return flags_ & PROFILER_INSTRUMENTATION_ON;
>      }
>  
>  #ifdef JS_TRACE_LOGGING
> +    void initTraceLogger(JSRuntime* runtime, JSScript* script, Vector<CodeOffset>& offsets);

nit: const Vector<CodeOffset>& offsets

Comment 26

[Benjamin Bouvier [:bbouvier] (inactive)]

Attachment: cleanups.patch

Small cleanups while I was reviewing the patch.

Comment 27

[Hannes Verschore [:h4writer]]

(In reply to Benjamin Bouvier [:bbouvier] from comment #22)
> Comment on attachment 8787149 [details] [diff] [review]
> Part 2: When requesting the "Script start/stop" don't include the "Internal"
> events.
> 
> Review of attachment 8787149 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Does this need to be added to drainTraceLogger too? If so, it'd be nice to
> have a way to share more code between the two methods.

Good question, but no. drainTraceLogger will return every event, while drainTraceLoggerScriptCalls should only report the script events.

Comment 28

[Hannes Verschore [:h4writer]]

(In reply to Benjamin Bouvier [:bbouvier] from comment #23)
> @@ +37,5 @@
> > +}
> > +
> > +function test()
> > +{
> > +  for (var i in (function(){ for (var j=0;j<4;++j) { yield ""; } })());
> 
> Doesn't this need to be function* to be a modern generator?

This specific testcase uses the legacy generator. That's why version(170) is needed.

Comment 29

[Hannes Verschore [:h4writer]]

(In reply to Benjamin Bouvier [:bbouvier] from comment #24)
> @@ +658,5 @@
> > +#ifdef NIGHTLY_BUILD
> > +        logger->updateIterationAndSize(&traceLoggerLastDrainedIteration, &traceLoggerLastDrainedSize);
> > +#endif
> > +        logger->updateIterationAndSize(&traceLoggerScriptedCallsLastDrainedIteration,
> > +                                       &traceLoggerScriptedCallsLastDrainedSize);
> 
> This should set traceLoggerScriptedCallsLastDrainedIteration :=
> traceLoggerLastDrainedIteration (ditto for the second variable). Can you
> call the method only once and reuse the results, instead of calling twice?

Yes that should be possible, though it seems less complicated to just call it twice?

> ::: js/src/vm/TraceLogging.h
> @@ +232,4 @@
> >          return start;
> >      }
> >  
> > +    void updateIterationAndSize(uint32_t* iteration, uint32_t* size) {
> 
> Considering that this doesn't any internal value (which can be confirmed by
> marking this method const), the naming seems off. How about two const
> methods iteration() and size(), instead?

I'm gonna call it getIterationAndSize. But in the long run we should indeed make a TLTracePosition or something.

Comment 30

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/9bf32cd7b3e5
Tracelogger: Part 1: Add debugging to check start and stop correspond, r=bbouvier
https://hg.mozilla.org/integration/mozilla-inbound/rev/f352fb065d2e
Tracelogger: Part 2: Debugger::drainTraceLoggerScriptCalls should only return Script events, r=bbouvier
https://hg.mozilla.org/integration/mozilla-inbound/rev/6586e827265a
Tracelogger: Part 3: Trace generator resume in the Interpreter, r=bbouvier
https://hg.mozilla.org/integration/mozilla-inbound/rev/035fb1b13529
Tracelogger: Part 4: Enable jit-tests/tests/tracelogger/drainTraceLogger.js again, r=bbouvier
https://hg.mozilla.org/integration/mozilla-inbound/rev/2b1c3cb1a648
Tracelogger: Part 5: Trace generator resume in Baseline, r=bbouvier

Comment 31

[Hannes Verschore [:h4writer]]

Comment on attachment 8787584 [details] [diff] [review]
cleanups.patch

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

Looks good

Comment 32

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/9bf32cd7b3e5
https://hg.mozilla.org/mozilla-central/rev/f352fb065d2e
https://hg.mozilla.org/mozilla-central/rev/6586e827265a
https://hg.mozilla.org/mozilla-central/rev/035fb1b13529
https://hg.mozilla.org/mozilla-central/rev/2b1c3cb1a648

Comment 33

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/d5def12cf1f8
Small cleanups to TraceLoggerDrain methods; r=h4writer

Comment 34

[Carsten Book [:Tomcat]]

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