Tracelogging revived

[hv1...@gmail.com]

I took the time to get tracelogging up and running again and create V2 out of it. I think most know tracelogging already, but for those that don't:

Tracelogging traces when which scripts runs and which engine we use for it. Out of the log information I create graphs showing when which engine is run. The graphs are visible on http://alasal.be/ionmonkey/ currently only for Octane.

So what is this reviving about. I had to patch spidermonkey properly again after baseline got added and jeagermonkey was removed. The patch to do this is in https://bugzilla.mozilla.org/show_bug.cgi?id=895019 and will get into mozilla-inbound as soon as it is open for some decent time. Everybody can trace any script by providing the --enable-trace-logging to ../configure (64bit only atm, I don't have enough registers on 32bit). Afterwards when a scripts run the information will be logged to /tmp/tracelogging.log.

I also created a python script to get some meaningful information out of it. Nice graphs ;). But actually much more info can get out of it. It's that file I used to profile octane and find problems in it. The python script that create nice graphs is on https://github.com/haytjes/tracelogger (generate.py).

I want to get this running automatically again. I'm looking into that, but I'll probably need a dedicated machine/hosting for this. Something like arewefastyet. So that's coming ;).

So I now made the graphs for octane, normal and the GGC version.

Some things I noticed on the graphs:
1) Nice work Terrence with GGC. The graphs of raytrace and earley-boyer are much nicer on it

2) There is something strange going on with Splay GGC. We could be much faster on it. It seems like we are stuck in baseline on splay.js:49 for a lot of time! That function is doing nothing but returning a value, but somehow that takes 25% of the execution time (excluding gc). I guess something bogus is happening there. We don't have this issue on Non-GGC branch

3) Deltablue is taking 13% for compiling. That is a lot. Mostly caused by GC throwing all scripts away. We (terrence, nbp and I) have been talking and it would be a nice win if we could keep active scripts after GC's. The consensus was that it shouldn't be that hard and give a nice boost.

4) Pdf.js is still our problem child. We are jumping a lot between baseline and ionmonkey. I still haven't come around to look into it. Some issues are already reported by nbp. But we still have a long way to go with this benchmark.

5) Mandreel is taking a lot of time compiling. Mind this is IonBuilder only! (we run parallel compilation). 17% is spend in IonBuilder and we don't gc. So this is interesting and a nice place for improvement.

6) Gbemu runs way to much in baseline. That is 30%. I think we bail a lot in that benchmark. So we need to find out how to run more in ionmonkey for this benchmark.

7) Code-load runs only in interpreter/baseline. I think that is normal? Can someone confirm?

[Nicholas Nethercote]

> 2) There is something strange going on with Splay GGC. We could be much faster on it. It seems like we are stuck in baseline on splay.js:49 for a lot of time! That function is doing nothing but returning a value, but somehow that takes 25% of the execution time (excluding gc). I guess something bogus is happening there. We don't have this issue on Non-GGC branch

splay generates a tree and then does some operations on it. I bet
that line is part of the tree generation, in which case it's called
many times.

> 7) Code-load runs only in interpreter/baseline. I think that is normal? Can someone confirm?

Sounds reasonable. Code-load is meant to be about parsing and
(initial) compilation speed.

Nick

[Till Schneidereit]

These graphs look amazing! I'm very much looking forward to doing them for
Shumway: I'm sure we can glean some info from them about how to optimize
that codebase, itself.

Three quick comments on the UI:
- the roll out to the bottom from the graph doesn't work, so the
block-tooltips stay around if you move the mouse down from the graph to the
list
- it'd be great to be able to sort the scripts list by the various columns
- I don't know if this easily done, but having invocation counts in
addition to total time would be great for the scripts list


thank you!
till

> _______________________________________________
> dev-tech-js-engine-internals mailing list
> dev-tech-js-en...@lists.mozilla.org
> https://lists.mozilla.org/listinfo/dev-tech-js-engine-internals
>

[David Bruant]

Hmm...

HOLY SHIT THIS IS AWESOME !!!

2013/7/19 <hv1...@gmail.com>

> I also created a python script to get some meaningful information out of
> it. Nice graphs ;). But actually much more info can get out of it. It's
> that file I used to profile octane and find problems in it. The python
> script that create nice graphs is on
> https://github.com/haytjes/tracelogger (generate.py).
>

Any chance this could be made into an addon (or just Firefox devtools)?
Something like : reload the page to get the graphs.
How is the information exposed? (so I understand how an addon could grab it
to display it)

I imagine everyone caring about perf of their website would love to be able
to use such a tool.

Thanks for your work!

David

[Luke Wagner]

This is really really cool!

One thing that I think would be really informative is how much time is spent in C++ stubs called from the baseline/ion. They happen frequently enough that you probably wouldn't want them to be interleaved on the graph, but maybe the time could be summed and attached to the enclosing jit block and then, I dunno, you could change the color of the block to indicate the % of time in stubs?

Cheers,
Luke

[hv1...@gmail.com]

On Friday, July 19, 2013 7:37:28 AM UTC-7, Luke Wagner wrote:
> One thing that I think would be really informative is how much time is spent in C++ stubs called from the baseline/ion. They happen frequently enough that you probably wouldn't want them to be interleaved on the graph, but maybe the time could be summed and attached to the enclosing jit block and then, I dunno, you could change the color of the block to indicate the % of time in stubs?

1) My objective was more to know which engine is responsible for a particular function, since that is hard to get atm. To know which c++ stub is costly you can just run a c profiler, quite easily.
2) Baseline is "only" doing IC's so it wouldn't really make sense to log if it is in an IC...
3) I think that might be just too costly. This is a tracing logger, so we log everything. Atm this gives a slowdown of atleast 5x (I measured once).

If you really want I can do it for ionmonkey, but I'm not sure. If we really want to get more and detailed information, I think we might start to use a sampling profiler instead!

On Friday, July 19, 2013 1:27:30 AM UTC-7, David Bruant wrote:
> Any chance this could be made into an addon (or just Firefox devtools)?
> Something like : reload the page to get the graphs.
> How is the information exposed? (so I understand how an addon could grab it
> to display it)
>
> I imagine everyone caring about perf of their website would love to be able
> to use such a tool.

I can image that.

But I think in that case you might just use SPS. It logs more or less the same information. There is only the need to add logging of which engine is used. So that shouldn't be that hard and it would/should be possible to create the same graphs... The person that created SPS may always contact me about this.

Why I don't use SPS myself:
1) Because I can use python quite easily to get the information out of it that I want, instead of only the information the addon provides.
2) I don't want to build a browser to test/fix performance in the js-engine.

On Friday, July 19, 2013 12:51:55 AM UTC-7, Till Schneidereit wrote:
> These graphs look amazing! I'm very much looking forward to doing them for
> Shumway: I'm sure we can glean some info from them about how to optimize
> that codebase, itself.

Cool :D

> Three quick comments on the UI:
> - the roll out to the bottom from the graph doesn't work, so the
> block-tooltips stay around if you move the mouse down from the graph to the
> list

When it bothers me enough I'll look into it to fix it. Shouldn't be hard. I think it only get removes when going over the background. So if you go over the table they stay.

> - it'd be great to be able to sort the scripts list by the various columns

Possible now ;)

> - I don't know if this easily done, but having invocation counts in
> addition to total time would be great for the scripts list

Visible now. They will appear as soon as I rebuild the graphs. For GGC I just did, because I added a logger for Minor GC

[Till Schneidereit]

On Sat, Jul 20, 2013 at 1:43 AM, <hv1...@gmail.com> wrote:

> On Friday, July 19, 2013 1:27:30 AM UTC-7, David Bruant wrote:
> > Any chance this could be made into an addon (or just Firefox devtools)?
> > Something like : reload the page to get the graphs.
> > How is the information exposed? (so I understand how an addon could grab
> it
> > to display it)
> >
> > I imagine everyone caring about perf of their website would love to be
> able
> > to use such a tool.
>
> I can image that.
>
> But I think in that case you might just use SPS. It logs more or less the
> same information. There is only the need to add logging of which engine is
> used. So that shouldn't be that hard and it would/should be possible to
> create the same graphs... The person that created SPS may always contact me
> about this.
>

I think we should have a devtool for general code-quality analysis.
Something that tells users if their code contains stuff that's hard to
optimize (e.g. by making calls polymorphic or forcing objects into dict
mode), unnecessarily entrains lots of stuff into closures, creates lots of
garbage, or has bad compiletime / runtime ratios. Bhackett's JIT Inspector
could find a home there. I mentioned that in
https://bugzilla.mozilla.org/show_bug.cgi?id=896088, too, and it's
certainly something the devtools people should lead. (CC-ing ejpbruel for
that.)

>
> Why I don't use SPS myself:
> 1) Because I can use python quite easily to get the information out of it
> that I want, instead of only the information the addon provides.
> 2) I don't want to build a browser to test/fix performance in the
> js-engine.
>

I think that the information the Tracelogger gives is, in large parts at
least, orthogonal to what SPS provides. From the SPS output, you can see
where time is spent in the engine and the browser, but you quite often
can't tell *why* it is spent there. Having a list of JS functions with
their compile/invocation count, and compile/run durations gives very
specific information about which of the JS functions to look into.

>
> On Friday, July 19, 2013 12:51:55 AM UTC-7, Till Schneidereit wrote:
> > These graphs look amazing! I'm very much looking forward to doing them
> for
> > Shumway: I'm sure we can glean some info from them about how to optimize
> > that codebase, itself.
>
> Cool :D
>

Indeed! :)
For that to *fully* work, we'd need a way to run it in the browser, though.
We do have quite large parts of the project that we can run in the shell,
but everything that's related to rendering can obviously only run in the
browser. But that's just a nit, really.

>
> > - it'd be great to be able to sort the scripts list by the various
> columns
>
> Possible now ;)
>
> > - I don't know if this easily done, but having invocation counts in
> > addition to total time would be great for the scripts list
>
> Visible now. They will appear as soon as I rebuild the graphs. For GGC I
> just did, because I added a logger for Minor GC

Very, very cool!

I now have additional requests, but please feel free to just ignore them,
they're not important:

- in Octane-Richards-GGC, the 4th-most-costly function (at 6.55%) spends
99.13% of the time in the ion compiler, but only 0.17% executing the JITted
code. How about making cases like that more visible by adding a "compile
time / run time"-ratio column?
- Maybe drop the "script" from all values in "Time spent", to save space?
- The "Time spent" values could actually be their own columns, to enable
sorting by them.
- Exposing places in the entire program where a lot of time is spent in the
interpreter or baseline would be interesting. See the 5th-most-costly
function in Octane-Richards-GGC, spending ~6.4% of the overall program's
time in the interpreter. Maybe enabling the comparison of columns would
work? Like "Total time / Interp time * Ion time".
- Please implement the parts of Excel I forgot to mention. ;)

Seriously, though, such a cool tool!