1331034 - CacheIR: Debugging Tools

Status: RESOLVED FIXED

(Core :: JavaScript Engine: JIT, defect, P3)

Description

[Tom S [:evilpie]]

Right now we don't have any logging at all in CacheIR. I recently used a simple printf logging approach that just showed cases where we didn't ICs quite successfully. I want to build something that can show which ICs we attach, but also where we can't attach any IC, or when we attach too many stubs.

It would be awesome to have something similar or better to the --trace-ic UI for v8 (https://github.com/v8/v8/blob/master/tools/ic-explorer.html)

Comment 1

[Tom S [:evilpie]]

Attachment: Tracing Patch

This just logs somethings that is almost JSON everytime we attach an IC or don't attach anything at all. We should probably also log why we couldn't attach a certain IC kind, but I wanted to minimize the produced data. I am open to suggestions, the current approach doesn't feel that clean.

https://github.com/evilpie/cacheir-tools contains a simple HTML viewer that makes it easy to spot obvious problems. (Like bug 1331136)

Comment 2

[Tom S [:evilpie]]

Attachment: Screen Shot of the tool analyzing octane pdfjs

Comment 3

[Jan de Mooij [:jandem]]

Awesome. It will be very interesting to analyze the results, especially once we convert the more obscure ICs (GETPROP/GETELEM have more stubs than the others).

(In reply to Tom Schuster [:evilpie] from comment #1)
> We should probably also log why we couldn't
> attach a certain IC kind, but I wanted to minimize the produced data.

Yeah, I'm not sure if that's worth it for now: there will be a ton of data and it also makes the code more verbose. I think logging the input types (and for objects clasp->name, for primitives the equivalent of toSource?) will be sufficient for now. In a lot of cases it should give us a pretty clear idea what's going on. If we do that, what do you think about merging trackOptimizationAttempt() + success() into a single trackOptimization()?

I think if we want to have more detailed information, we should probably use strings instead of enum values, so we don't have to add a new enum value each time we add a |return false;| somewhere.

Comment 4

[Hannes Verschore [:h4writer]]

This looks promising!

Comment 5

[Tom S [:evilpie]]

Attachment: WIP v2

I think this patch looks pretty good overall, but there is one gaping hole: When and how to initialize CacheIRSpewer. I would be super open to suggestions. In the browser the destructor often isn't even called when closing the last window, which also causes corrupt JSON files, I am not even sure this can be solved.

Comment 6

[Jan de Mooij [:jandem]]

Is there something we could do in JS_Shutdown? Maybe we can check what TraceLogger does?

Comment 7

[Jan de Mooij [:jandem]]

Steve, this is going to be very useful for Google Docs and other websites. Tom already found and fixed a number of (often easy to fix now) performance issues on popular websites.

This will become more useful as we convert more ICs to CacheIR. Most of the hard work is done, I think, and we can make a ton of progress here in 54.

Comment 8

[Hannes Verschore [:h4writer]]

(In reply to Jan de Mooij [:jandem] from comment #6)
> Is there something we could do in JS_Shutdown? Maybe we can check what
> TraceLogger does?

See bug 1298831. There is a function that always get called (before killing the child process on release builds): ContentChild::RecvShutdown

Comment 9

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

CC'ing jimb because it's an example of a valuable new logging thingy, done as a one-off because we don't have a common infrastructure. :-) (No pressure...)

Comment 10

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

(In reply to Hannes Verschore [:h4writer] from comment #8)
> (In reply to Jan de Mooij [:jandem] from comment #6)
> > Is there something we could do in JS_Shutdown? Maybe we can check what
> > TraceLogger does?
> 
> See bug 1298831. There is a function that always get called (before killing
> the child process on release builds): ContentChild::RecvShutdown

We need to hook this up for some other things too. Minor GC logging prints out a summary at the end that gets chopped off, too; I still haven't gotten around to fixing that. I was planning on making a general atexit-type thing so we can call all of these cleanups in one place. (Feel free to do that here!)

(In reply to Jan de Mooij [:jandem] from comment #7)
> Steve, this is going to be very useful for Google Docs and other websites.
> Tom already found and fixed a number of (often easy to fix now) performance
> issues on popular websites.
> 
> This will become more useful as we convert more ICs to CacheIR. Most of the
> hard work is done, I think, and we can make a ton of progress here in 54.

Is it worth gathering these logs automatically for the automated Hasal runs we're doing? At least for now? Currently, we are just grabbing the profiles and some high-level performance timing stuff, and upon request they'll add in tracelogs. Is this low enough overhead (and small enough output) that we can just start gathering these unconditionally? (It's ok if it skews the performance a bit; we do separate instrumented runs for gathering these things, rather than having them on all the time. But if it makes things 2x slower, it'll skew the profiles too much.)

Comment 11

[Hannes Verschore [:h4writer]]

Can we get this into tree? As starter maybe some IONFLAGS=cacheir that will log this info to a file (like IONFLAGS=logs) ?

Comment 12

[Tom S [:evilpie]]

Attachment: Introduce a JSONPrinter class

Let's get some of this stuff landed so I don't have to carry around a huge patch for rebasing.

Part 1: I split the parts for creating JSON values out of JSONSpewer into a new JSONPrinter class.

Comment 13

[Tom S [:evilpie]]

Attachment: Make JSONSpewer inherit from JSONPrinter

This makes JSONSpewer inherit from JSONPrinterThis. It also includes a handful of fixes where were manually creating JSON values even though there was existing API for creating them.

Comment 14

[Hannes Verschore [:h4writer]]

Comment on attachment 8833110 [details] [diff] [review]
Make JSONSpewer inherit from JSONPrinter

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

Nice!

Comment 15

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/b9d1cadd93c7
Introduce a JSONPrinter class. r=h4writer
https://hg.mozilla.org/integration/mozilla-inbound/rev/b160587f5a4d
Make JSONSpewer inherit from JSONPrinter. r=h4writer

Comment 16

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/72be1c0102f6
Fix non-unified JS build. r=me

Comment 17

[Phil Ringnalda (:philor)]

https://hg.mozilla.org/mozilla-central/rev/b9d1cadd93c7
https://hg.mozilla.org/mozilla-central/rev/b160587f5a4d
https://hg.mozilla.org/mozilla-central/rev/72be1c0102f6

Comment 18

[Tom S [:evilpie]]

Attachment: WIP v3

Rebased on current m-i. Sadly this doesn't contain the "in" patch.

Comment 19

[Tom S [:evilpie]]

Attachment: v1 - Introduce CacheIRSpewer

So I just took the time to actually finish this and get it in a review-able shape. We initialize CacheIRSpewer in JitSpewer.cpp like the other spewers. Because we only have one CacheIR instance per process I had to introduce a lock, otherwise worker threads damage the JSON output. Everything else is relatively straight forward. I made CacheIRSpewer::beginCache take an IRGenerator reference so that we avoid duplicating code at all the callsites.

Comment 20

[Jan de Mooij [:jandem]]

I just skimmed the CacheIR part. Looks good, maybe rename trackICAttached to trackStubAttached or just trackAttached. In my mind there's one IC per bytecode op and we can attach multiple stubs to it.

Comment 21

[Hannes Verschore [:h4writer]]

Comment on attachment 8834592 [details] [diff] [review]
v1 - Introduce CacheIRSpewer

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

::: js/src/jit/BaselineIC.cpp
@@ +1222,2 @@
>                                 objv, index, rhs);
>          if (gen.tryAttachAddSlotStub(oldGroup, oldShape)) {

We need to call trackNotAttached(); if this fails.

@@ +2659,1 @@
>          }

I'm having problems with seeing these gen.trackNotAttached(); outside of IRGenerator. I have a proposal to fix this, but I'll do that as follow-up bug and see if Jan agrees. I think we can keep it like this for now.

::: js/src/jit/CacheIR.cpp
@@ +1955,5 @@
> +SetPropIRGenerator::trackICAttached(const char* name)
> +{
> +    CacheIRSpewer& sp = GetCacheIRSpewerSingleton();
> +    if (sp.enabled()) {
> +        LockGuard<Mutex> guard(sp.lock());

I think the lock is fine, since we only do it when CacheIRSpewer is enabled. Seems the best way.

::: js/src/jit/CacheIRSpewer.h
@@ +36,5 @@
> +    bool init();
> +    bool enabled() { return json.isSome(); }
> +    Mutex& lock() { return outputLock; }
> +
> +    // These methods can only be called when enabled() is true.

Assert this statement in the following functions.

::: js/src/jit/IonIC.cpp
@@ +113,5 @@
> +    // We should instead log this event!!!!
> +    // if (++failedUpdates_ > MAX_FAILED_UPDATES) {
> +    //     JitSpew(JitSpew_IonIC, "Disable inline cache");
> +    //     disable(zone);
> +    // }

Revert this.

Comment 22

[Tom S [:evilpie]]

Attachment: v2 - Introduce CacheIRSpewer

Addressed review feedback. Jan is right, trackAttached looks nicer together with trackNotAttached. Thanks for pointing out that missing trackNotAttached called, I agree we should do this differently in a followup.

I added support for InIRGenerator and wrapped the CacheIRSpewer references in an ifdef to avoid build failures.

Comment 23

[Hannes Verschore [:h4writer]]

Comment on attachment 8834859 [details] [diff] [review]
v2 - Introduce CacheIRSpewer

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

LGTM (only looked to the In changes)

Comment 24

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/5c031de2ce90
Introduce CacheIRSpewer. r=h4writer

Comment 25

[Tom S [:evilpie]]

To reiterate for everyone interested in using this tool:

You currently have to build with ac_add_options --enable-jitspew, https://evilpie.github.io/cacheir-tools/ can be used to analyze the json files created in /tmp on Linux/Mac, or the current directory on Windows. You might have to disable sandboxing.

Comment 26

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/5c031de2ce90