Closed Bug 1298541 Opened 3 years ago Closed 3 years ago

TraceLogger: Support logging of generators

Categories

(Core :: JavaScript Engine, defect)

defect
Not set

Tracking

()

RESOLVED FIXED
mozilla51
Tracking Status
firefox51 --- fixed

People

(Reporter: sfink, Assigned: h4writer)

References

(Blocks 1 open bug)

Details

Attachments

(6 files, 6 obsolete files)

2.55 KB, patch
bbouvier
: review+
Details | Diff | Splinter Review
1.15 KB, patch
bbouvier
: review+
Details | Diff | Splinter Review
2.60 KB, patch
bbouvier
: review+
Details | Diff | Splinter Review
5.39 KB, patch
bbouvier
: review+
Details | Diff | Splinter Review
22.89 KB, patch
bbouvier
: review+
Details | Diff | Splinter Review
4.23 KB, patch
h4writer
: review+
Details | Diff | Splinter Review
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.
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.)
(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
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?
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.
Attached patch TL diagnostics (obsolete) — Splinter Review
Assignee: nobody → sphink
Status: NEW → ASSIGNED
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.
@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.
Assignee: sphink → hv1989
Attachment #8786750 - Flags: review?(bbouvier)
Need this to work properly for the testcase of the fix.
Attachment #8786753 - Flags: review?(bbouvier)
Attached patch Part 3: Fix for the Interpreter (obsolete) — Splinter Review
Attachment #8786756 - Flags: review?(bbouvier)
Attachment #8786554 - Attachment is obsolete: true
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.
Attachment #8786756 - Attachment description: Part 3: Fix → Part 3: Fix for the Interpreter
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) {
Attached patch Part 5: WIP: Fix for Baseline (obsolete) — Splinter Review
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?
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.
Attachment #8786750 - Attachment is obsolete: true
Attachment #8786750 - Flags: review?(bbouvier)
Attachment #8787148 - Flags: review?(bbouvier)
Attachment #8786753 - Attachment is obsolete: true
Attachment #8786753 - Flags: review?(bbouvier)
Attachment #8787149 - Flags: review?(bbouvier)
Attachment #8786756 - Attachment is obsolete: true
Attachment #8786756 - Flags: review?(bbouvier)
Attachment #8787150 - Flags: review?(bbouvier)
Attachment #8786776 - Attachment is obsolete: true
Attachment #8786776 - Flags: review?(bbouvier)
Attachment #8787151 - Flags: review?(bbouvier)
Attachment #8787152 - Flags: review?(bbouvier)
Attachment #8786992 - Attachment is obsolete: true
(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!
Blocks: 1299813
Summary: TraceLogger: unable to find script → TraceLogger: Support logging of generators
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`
Attachment #8787148 - Flags: review?(bbouvier) → review+
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.
Attachment #8787149 - Flags: review?(bbouvier) → review+
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?
Attachment #8787150 - Flags: review?(bbouvier) → review+
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?
Attachment #8787151 - Flags: review?(bbouvier) → review+
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
Attachment #8787152 - Flags: review?(bbouvier) → review+
Attached patch cleanups.patchSplinter Review
Small cleanups while I was reviewing the patch.
Attachment #8787584 - Flags: review?(hv1989)
(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.
(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.
(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.
Pushed by hv1989@gmail.com:
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 on attachment 8787584 [details] [diff] [review]
cleanups.patch

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

Looks good
Attachment #8787584 - Flags: review?(hv1989) → review+
Depends on: 1300515
Pushed by bbouvier@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/d5def12cf1f8
Small cleanups to TraceLoggerDrain methods; r=h4writer
Depends on: 1306923
Depends on: 1322614
You need to log in before you can comment on or make changes to this bug.