976260 - Distinguish between optimization tiers in profiler

Status: RESOLVED FIXED

(Core :: JavaScript Engine: JIT, defect)

Description

[Kannan Vijayan [:djvj]]

Currently when we push pseudostack entries, we emit a string corresponding to the function name and line.  However, this amalgamates all time spent within the function, whether that time was spent interpreting, baseline-executing, or ion-executing.

This information is very relevant for profiling.  For a given function, time spent in Ion-compiled code for the function should be distinguished from time spent in unoptimized code for the function.  We can add a special "optimization tier" tag to the profile string to make this distinction.

Comment 1

[Kannan Vijayan [:djvj]]

Ran across the need for this while profiling some web game stuff on Firefox for Android.  It's a simple patch so might as well land it while I'm one-offing it for my purposes.

Comment 2

[Kannan Vijayan [:djvj]]

Attachment: profiling-optimization-tier-tag.patch

Try: https://tbpl.mozilla.org/?tree=Try&rev=17befc5b6852

Comment 3

[Nicolas B. Pierron [:nbp]]

FYI, jld was working on a patch to simplify how SPS frames are balanced, and this should give us enough information to distinguish between a scripts running under the interpreter or code compiled with baseline&ion.

Comment 4

[Kannan Vijayan [:djvj]]

I'm not familiar with jld's approach here, but this is an immediate need that I'm facing ATM and the resulting information has proven very valuable.  In particular, it immediately pointed out visually that a particular function was spending about a third of its runtime in Baseline, and two thirds in Ion.  Visually cross-referencing it with the activity graph at the top of the profiler allowed me to confirm within a few seconds that the function was getting invalidated a lot (the highlights corresponding to the baseline execution are interleaved with the highlights corresponding to ion execution).

Do you have a bug number for jld's work?

Comment 5

[Kannan Vijayan [:djvj]]

Attachment: profiler-optimization-tiers.patch

Updated patch with bug fixes, and a "dummy pref" boolean on the SPSProfiler object that toggles the behaviour on and off.

Comment 6

[Jed Davis [:jld] ⟨⏰|UTC-7⟩ ⟦he/him⟧]

(In reply to Kannan Vijayan [:djvj] from comment #4)
> I'm not familiar with jld's approach here, but this is an immediate need
> that I'm facing ATM and the resulting information has proven very valuable. 
> In particular, it immediately pointed out visually that a particular
> function was spending about a third of its runtime in Baseline, and two
> thirds in Ion.

The patch I have in bug 914561 doesn't attempt to distinguish Baseline from Ion; it just inserts a frame between the interpreter and the JIT (and deals with interpreter-to-JIT OSR), which as a convenient side-effect separates interpreter frames and JIT frames.

Comment 7

[Kannan Vijayan [:djvj]]

Attachment: profiling-js-events.patch

This patch adds "compiler events" to the profiler.  Currently Invalidations, Bailouts, and Ion-Compilation are registered with the profiler, and show up on the timeline graph.

This has already helped me discover repeated bailouts in some code I was profiling.  Such useful.  Very profile.

Comment 8

[Kannan Vijayan [:djvj]]

Attachment: profiling-optimization-tier-tag.patch

Updated patch for adding optimization tier info to the profiled function's descriptor strings.  This breaks the builtin profiler (and parts of :BenWa's Gecko Profiler) since it changes the string format and breaks some regexes which they use for matching JS frames.  That needs to be fixed before it can be landed.

Comment 9

[Kannan Vijayan [:djvj]]

Comment on attachment 8382624 [details] [diff] [review]
profiling-js-events.patch

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

Tell me if you think there's a better reviewer for this, Jan.  It's a reasonable straightforward patch.  Description below:

The profiler allows the manual registration of events, which are then inserted into the profiling sampler timeline.  This requires calling into some gecko code, but the gecko function is decoupled from the js engine through the use of an callback.

When the profiler initializes, it passes a function pointer to register a callback to the SPSProfiler instance used by the JS engine.  This callback is then used to emit events at various points of JS execution (invalidations, bailouts, and ion-compiles).

See also: attached screenshot of what the resulting Gecko Profiler timeline looks like.

Comment 10

[Kannan Vijayan [:djvj]]

Attachment: ScreenShot.png

Screenshot of profiler js-events, showing a bailout event.

Comment 11

[Nicolas B. Pierron [:nbp]]

(In reply to Kannan Vijayan [:djvj] from comment #10)
> Screenshot of profiler js-events, showing a bailout event.

This is good to have bailout tags, but I think this is hard to read because the green & black are related to the selected frame and not the runtime-execution mode.  The {ION} and {BASELINE} annotations are not easy to read either, and I do not think this is interesting to show that in such view, even if it would make more sense with inverted stacks.

I think these annotations should be muted by default, and separated if asked for.  Also it might be interesting to test this profiling by slicing the histogram horizontally based on the mode of execution, such as (imagine colors instead of letters):

               ccc                 cc cc              cc cc
            iibbbbb            bbIIIIIII          bbIIIIIII
    cccccciiiiiiiiicccccccccciiiiiiiiiiicccccccccbbbbbbbbbbcccccc
ccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccc

(c: C++, i: Interpreter, b: Baseline, I: Ion)

Bailouts annotations might be more meaning full, as they correspond to

      Bailout
       |
   IIIIIbbbb

Comment 12

[Kannan Vijayan [:djvj]]

(In reply to Nicolas B. Pierron [:nbp] from comment #11)
> (In reply to Kannan Vijayan [:djvj] from comment #10)
> > Screenshot of profiler js-events, showing a bailout event.
> 
> This is good to have bailout tags, but I think this is hard to read because
> the green & black are related to the selected frame and not the
> runtime-execution mode.  The {ION} and {BASELINE} annotations are not easy
> to read either, and I do not think this is interesting to show that in such
> view, even if it would make more sense with inverted stacks.

I agree that we can improve presentation.  I spoke yesterday with BenWa about better UIs for this information, and there are definitely options there.

I also agree that the optimization tier annotations are not easy to read, but they're absolutely easier to read than not having any at all.  I disagree that this information is uninteresting.  Not only is it interesting, it's highly useful.

The changes I'm making here are driven specifically by actual profiling work I'm doing on an HTML5 game, and these changes have been immensely useful in finding optimization barriers in the code.  For example, one of the idiomatic profiling activities is simply drilling down the call tree and looking for the split between what functions we're spending time on.  Seeing a {BASELINE} entry on a hot path points very strongly towards functions that are currently impeding optimization.

> I think these annotations should be muted by default, and separated if asked
> for.  Also it might be interesting to test this profiling by slicing the
> histogram horizontally based on the mode of execution, such as (imagine
> colors instead of letters):
> 
>                ccc                 cc cc              cc cc
>             iibbbbb            bbIIIIIII          bbIIIIIII
>     cccccciiiiiiiiicccccccccciiiiiiiiiiicccccccccbbbbbbbbbbcccccc
> ccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccc
> 
> (c: C++, i: Interpreter, b: Baseline, I: Ion)
> 
> Bailouts annotations might be more meaning full, as they correspond to
> 
>       Bailout
>        |
>    IIIIIbbbb

I like this presentation format idea, but it's a larger-scale change that will require a lot of UI prototyping and work.

For now, all I'm suggesting is that we start collecting this information, throw it up there, land that, and then start thinking about how to use it.

In my opinion, the profiler with this patch is strictly better than the profiler without this patch.  The information might not be exposed in the prettiest way, but it's exactly the kind of information people care about when they're trying to find out why their JS is going slow.

Comment 13

[Jan de Mooij [:jandem]]

Comment on attachment 8382624 [details] [diff] [review]
profiling-js-events.patch

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

This looks great, nice idea to integrate it with the profiler. I think both Shu and Luke have ideas on exposing bailouts etc to devtools, you may want to talk to them as well.

For testing, can you add a shell function to register an event marker and have it print to stdout or so? Some people may even find it useful for profiling shell benchmarks :)

::: js/src/jit/BaselineBailouts.cpp
@@ +993,5 @@
> +                                        resumeAfter ? "after" : "at",
> +                                        js_CodeName[op],
> +                                        (int) PCToLineNumber(script, pc),
> +                                        script->filename(),
> +                                        (int) script->lineno());

Nit: C++-style cast: int(PCToLineNumber(...));

::: js/src/jit/CodeGenerator.cpp
@@ +6257,5 @@
>      SetIonScript(script, executionMode, ionScript);
>  
> +    if (cx->runtime()->spsProfiler.enabled()) {
> +        char buf[1024];
> +        JS_snprintf(buf, 1024, "Ion compiled %s:%d", script->filename(), (int) script->lineno());

What if filename() is some long URL, will this call fail or truncate? Maybe we can dynamically allocate a buffer of size len(filename) + 100 or so?

::: js/src/jit/Ion.cpp
@@ +2610,5 @@
> +
> +        // Get the script filename, if any, and its length.
> +        const char *filename = script->filename();
> +        if (filename == nullptr)
> +            filename = "<unknown>";

Can filename really be null? I think we rely on it being non-null elsewhere (and in this patch).

Comment 14

[Kannan Vijayan [:djvj]]

(In reply to Jan de Mooij [:jandem] from comment #13)
> Can filename really be null? I think we rely on it being non-null elsewhere
> (and in this patch).

We don't depend on filename being non-null elsewhere in the file or in the patch.  In the other calls to |filename|, it's passed directly into a printf "%s" format code, which checks for null.  I'll double-check whether we can expect null or not, and change this to an assert if not.

Comment 15

[Kannan Vijayan [:djvj]]

Attachment: profiling-js-events.patch

Comments addressed.  I'm still allowing for the possibility of jsscript->filename() being null since jorendorff indicated it's a possibility (and jimb hasn't been in to confirm yet).

Comment 16

[Jan de Mooij [:jandem]]

Comment on attachment 8383209 [details] [diff] [review]
profiling-js-events.patch

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

Nice.

::: js/src/jit/BaselineBailouts.cpp
@@ +998,5 @@
> +                                  BailoutKindString(bailoutKind),
> +                                  resumeAfter ? "after" : "at",
> +                                  js_CodeName[op],
> +                                  int(PCToLineNumber(script, pc)),
> +                                  script->filename(),

This should be |filename|.

::: js/src/jit/CodeGenerator.cpp
@@ +6263,5 @@
> +        unsigned len = strlen(filename) + 50;
> +        char *buf = js_pod_malloc<char>(len);
> +        if (!buf)
> +            return false;
> +        JS_snprintf(buf, len, "Ion compiled %s:%d", script->filename(), (int) script->lineno());

s/script->filename()/filename

::: js/src/jit/Ion.cpp
@@ +2619,5 @@
> +        size_t lenLineno = 1;
> +        for (uint64_t i = lineno; i /= 10; lenLineno++);
> +
> +        size_t len = lenFilename + 1 + lenLineno;
> +        char buf[1024];

Use dynamic allocation here as well.

Comment 17

[Kannan Vijayan [:djvj]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/84663a25b44e

Comment 18

[Ryan VanderMeulen [:RyanVM]]

Backed out for adding new rooting hazards.
https://hg.mozilla.org/integration/mozilla-inbound/rev/7266f46b4dfc

https://ftp-ssl.mozilla.org/pub/mozilla.org/firefox/tinderbox-builds/mozilla-inbound-linux64-br-haz/20140228124534/hazards.txt.gz

Comment 19

[Kannan Vijayan [:djvj]]

Nth time is the charm:
https://hg.mozilla.org/integration/mozilla-inbound/rev/b37ed02f9f4b

Comment 20

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

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