Status

()

defect
P3
normal
RESOLVED FIXED
3 years ago
3 years ago

People

(Reporter: evilpie, Assigned: evilpie)

Tracking

(Blocks 1 bug)

unspecified
mozilla54
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox54 fixed)

Details

Attachments

(3 attachments, 5 obsolete attachments)

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)
Assignee: nobody → evilpies
Posted patch Tracing Patch (obsolete) — Splinter Review
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)
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.
This looks promising!
Priority: -- → P3
Posted patch WIP v2 (obsolete) — Splinter Review
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.
Attachment #8826931 - Attachment is obsolete: true
Is there something we could do in JS_Shutdown? Maybe we can check what TraceLogger does?
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.
(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
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...)
(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.)
Can we get this into tree? As starter maybe some IONFLAGS=cacheir that will log this info to a file (like IONFLAGS=logs) ?
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.
Attachment #8833108 - Flags: review?(hv1989)
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.
Attachment #8833110 - Flags: review?(hv1989)
Comment on attachment 8833110 [details] [diff] [review]
Make JSONSpewer inherit from JSONPrinter

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

Nice!
Attachment #8833110 - Flags: review?(hv1989) → review+
Attachment #8833108 - Flags: review?(hv1989) → review+
Keywords: leave-open
Pushed by evilpies@gmail.com:
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
Posted patch WIP v3 (obsolete) — Splinter Review
Rebased on current m-i. Sadly this doesn't contain the "in" patch.
Attachment #8826951 - Attachment is obsolete: true
Attachment #8830049 - Attachment is obsolete: true
Attachment #8834468 - Attachment is patch: true
Posted patch v1 - Introduce CacheIRSpewer (obsolete) — Splinter Review
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.
Attachment #8834468 - Attachment is obsolete: true
Attachment #8834592 - Flags: review?(hv1989)
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 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.
Attachment #8834592 - Flags: review?(hv1989) → review+
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.
Attachment #8834592 - Attachment is obsolete: true
Attachment #8834859 - Flags: review?(hv1989)
Attachment #8834859 - Attachment is patch: true
Comment on attachment 8834859 [details] [diff] [review]
v2 - Introduce CacheIRSpewer

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

LGTM (only looked to the In changes)
Attachment #8834859 - Flags: review?(hv1989) → review+
Keywords: leave-open
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.
https://hg.mozilla.org/mozilla-central/rev/5c031de2ce90
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla54
You need to log in before you can comment on or make changes to this bug.