778979 - Provide line number information to SPS for profiling

Status: RESOLVED FIXED

(Core :: JavaScript Engine, defect)

Description

[u443197]

Currently SPS only knows about function definitions and what functions are on the stack when a sample is taken. It would be better if SPS also knew about where all the callsites were located and the currently running function's current line number.

This would mean that each frame of the backtrace would have two bits of information:
  1. where the function was defined
  2. where the function currently is (either executing or where the callsite was located)

The goal is to support something where the source code of a function can be fully annotated with how long it took to execute each line.

Comment 1

[u443197]

Attachment: Part 1: Change sps's StackEntry to inherit from js::ProfileEntry

This struct was going to get a few more field, and it started to not make sense to have two things, so I made the SPS version derive from the JS version

Comment 2

[u443197]

Attachment: Part 2: Add a line number to js::ProfileEntry and integrate with SPS

Comment 3

[u443197]

Attachment: Part 3: change the meaning of enableSPSProfilingAssertions

Uncovered this during testing, turned out the function wasn't doing much...

Comment 4

[u443197]

Attachment: Part 4: Track the line number in the JS engine

The top entry is still allowed to be 0, but that will change soon.

Comment 5

[u443197]

Attachment: Part 1: change the meaning of enableSPSProfilingAssertions

Comment 6

[u443197]

Attachment: Part 2: Change sps's StackEntry to inherit from js::ProfileEntry and add a line number

Comment 7

[u443197]

Attachment: Part 3: Track the line number in the JS engine

Comment 8

[u443197]

Attachment: Part 2: Change sps's StackEntry to inherit from js::ProfileEntry and add a line number

I ran the v8 benchmarks with profiling turned on, and it turned out that performance was getting slaughtered more than I was expecting. It turned out that the interpreter tracking the line number instead of the pc took a lot of work and was really slowing down the interpreter.

I've updated the SPS/JS patches so the SPS tracks the line number (for C++), and JS tracks the pc. The translation still works at sample time regardless.

The v8 score from no profiling => profiling was 632 => 603. Not a small amount, but better than 632 => 520...

Comment 9

[u443197]

Attachment: Part 3: Track the line number in the JS engine

Comment 10

[Brian Hackett [Laid off!]]

(In reply to Alex Crichton [:acrichto] from comment #8)
> The v8 score from no profiling => profiling was 632 => 603. Not a small
> amount, but better than 632 => 520...

Is this in a debug or release build?

Comment 11

[u443197]

In a build where I just ran '../configure', with no flags. I assumed that was release.

Comment 12

[Brian Hackett [Laid off!]]

Comment on attachment 649455 [details] [diff] [review]
Part 1: change the meaning of enableSPSProfilingAssertions

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

::: js/src/builtin/TestingFunctions.cpp
@@ +843,5 @@
>      JS_FN_HELP("enableSPSProfilingAssertions", EnableSPSProfilingAssertions, 1, 0,
> +"enableSPSProfilingAssertions(slow)",
> +"  Enables SPS instrumentation and corresponding assertions. If 'slow' is\n"
> +"  true, then even slower assertions are enabled for all generated JIT code.\n"
> +"  When false, the only difference is that instrumentation is enabled."),

The last sentence here is confusing.

Comment 13

[u443197]

Attachment: Part 4: provide an ip -> line translation mechanism

This is the method of actually translating the stack of ProfileEntry objects into line numbers. The only relevant one is the top stack entry, because all others will have a script/pc listed.

The top one maintains mappings of JIT code to pc to perform the mapping. Right now it's incredibly slow to do a lookup, so there's definitely room for improvement there.

Comment 14

[(no longer active)]

Comment on attachment 649508 [details] [diff] [review]
Part 2: Change sps's StackEntry to inherit from js::ProfileEntry and add a line number

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

::: js/src/jsfriendapi.h
@@ +554,5 @@
>   * For more detailed information, see vm/SPSProfiler.h
>   */
> +class ProfileEntry {
> +    const char *string; // Descriptive string of this entry
> +    void *sp;           // Relevant stack pointer for the entry

Why is it safe to make these two non-volatile?

@@ +560,3 @@
>      /*
> +     * Not currently used, but is here for padding (to a power-of-two size) and
> +     * for later expansion into profiling other possible statistics

Hrm, I don't quite understand why we need this padding.  Is binary backwards compatibility a concern here?

@@ +568,5 @@
> +        jsbytecode *pc_;  // when a js entry, contains the pc. NULL = running
> +    };
> +
> +  public:
> +    bool js() volatile { return sp == NULL; }

If you really want to drop volatile from the above members, why would any of these methods need to be volatile?

::: tools/profiler/sps_sampler.h
@@ +312,5 @@
> +  uint32_t stackSize()
> +  {
> +    if (mStackPointer >= mozilla::ArrayLength(mStack))
> +        return mozilla::ArrayLength(mStack);
> +    return mStackPointer;

Nit: Can't you just use NS_MIN here?  Also, please make this method const.

Comment 15

[u443197]

(In reply to Ehsan Akhgari [:ehsan] from comment #14)

> Why is it safe to make these two non-volatile?

I'm not 100% sure how volatile works with the placement of the keyword, but from the SPS side of things I believe that these two fields being 'volatile' is just redundant. The entire mStack field in the ProfileStack structure is declared as volatile, so I figured that would apply to all of the structures and fields within.

In the JS engine, the fields aren't explicitly marked volatile, so the relevant 'push' operation casts the pointers to their volatile versions.

> Hrm, I don't quite understand why we need this padding.  Is binary backwards
> compatibility a concern here?

Not binary compatibility, but rather future extensibility. I was hoping to use these bytes as a region for flags, but it turned out that I needed them for a JSScript* pointer anyway to extract the line number. Regardless the main reason in the first place was to have the size of the structure be a power of 2 because that makes it very easy for JIT code to calculate the address of where to store things.

> If you really want to drop volatile from the above members, why would any of
> these methods need to be volatile?

In SPS, the ProfileStack marks all StackEntry structures as volatile, and C++ gets angry at me calling non-volatile methods on these volatile structures.

Comment 16

[Brian Hackett [Laid off!]]

Comment on attachment 649509 [details] [diff] [review]
Part 3: Track the line number in the JS engine

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

::: js/src/methodjit/BaseAssembler.h
@@ +77,5 @@
>        : base(base), bytes(bytes)
>      { }
>  };
>  
> +class SPSInstrumentation {

Can you add documentation for this class and its members.  It's not obvious at all what a lot of these are for, and in the case of script_/pc_, what they point to.

::: js/src/methodjit/Compiler.cpp
@@ +4004,5 @@
>  
>      finishBarrier(barrier, REJOIN_FALLTHROUGH, 0);
> +    RegisterID reg = frame.allocReg();
> +    sps.reenter(masm, reg);
> +    frame.freeReg(reg);

Unused registers should not be allocated if sps is disabled, this will interfere with regalloc and could cause unnecessary spills.  Ditto for the several uses below.

::: js/src/vm/SPSProfiler.h
@@ +95,5 @@
> + * As an invariant, if the pc is NULL, then the JIT is currently executing
> + * generated code. Otherwise execution is in another JS function or in C++. With
> + * this in place, only the top entry of the stack can ever have NULL as its pc.
> + * Additionally with this invariant, it is possible to maintain mappings of JIT
> + * code to pcx which can be accessed safely because they will only be accessed

typo

Comment 17

[Brian Hackett [Laid off!]]

Comment on attachment 649901 [details] [diff] [review]
Part 4: provide an ip -> line translation mechanism

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

::: js/src/jsprobes.h
@@ -201,5 @@
> - * Observer class for JIT code allocation/deallocation. Currently, this only
> - * handles the method JIT, and does not get notifications when JIT code is
> - * changed (patched) with no new allocation.
> - */
> -class JITWatcher {

Is this stuff just not used at all, in any configuration?

::: js/src/vm/SPSProfiler.cpp
@@ +247,5 @@
> +     * When translating ip => pc, first all inline frames are checked for
> +     * ownership of the specified ip. This is because the opcode of the call in
> +     * the main function will span the ip and would be otherwise falsely
> +     * returned. If this fails, then the pcLengths array is walked over to
> +     * determine which pc the ip corresponds to.

Inlined frames can contain other inline frames, so won't this apply in that case too?  You should be able to avoid spurious hits by visiting inlineFrames in reverse, which should see the innermost frames before the ones they are nested in.

@@ +292,5 @@
> +        JMChunkInfo *info = e.front().value;
> +        jsbytecode *pc = info->convert(chunk->pcLengths, ip);
> +        if (pc != NULL)
> +            return pc;
> +    }

The profiler knows which is the topmost script, right?  Shouldn't it work to just try to convert() for chunks compiled for that script?

Comment 18

[u443197]

(In reply to Brian Hackett (:bhackett) from comment #17)

> Is this stuff just not used at all, in any configuration?

I grepped the code base for it and couldn't find any use case. I thought it was just cluttering up where I was using it, so I removed it. If someone's using it and the code isn't committed, this might break though.

Comment 19

[(no longer active)]

(In reply to comment #15)
> (In reply to Ehsan Akhgari [:ehsan] from comment #14)
> 
> > Why is it safe to make these two non-volatile?
> 
> I'm not 100% sure how volatile works with the placement of the keyword, but
> from the SPS side of things I believe that these two fields being 'volatile' is
> just redundant. The entire mStack field in the ProfileStack structure is
> declared as volatile, so I figured that would apply to all of the structures
> and fields within.
> 
> In the JS engine, the fields aren't explicitly marked volatile, so the relevant
> 'push' operation casts the pointers to their volatile versions.

Still I would prefer if you would retain volatile on these pointers and try to remove them in another bug (I don't know what the original reason for making them volatile was but the comment there seems to describe it.)

> > Hrm, I don't quite understand why we need this padding.  Is binary backwards
> > compatibility a concern here?
> 
> Not binary compatibility, but rather future extensibility. I was hoping to use
> these bytes as a region for flags, but it turned out that I needed them for a
> JSScript* pointer anyway to extract the line number. Regardless the main reason
> in the first place was to have the size of the structure be a power of 2
> because that makes it very easy for JIT code to calculate the address of where
> to store things.

OK, this sounds fine, but I think you need to document this in the code to make this obvious to people reading it.

> > If you really want to drop volatile from the above members, why would any of
> > these methods need to be volatile?
> 
> In SPS, the ProfileStack marks all StackEntry structures as volatile, and C++
> gets angry at me calling non-volatile methods on these volatile structures.

Ah right.  This is worth to be commented as well.

Comment 20

[(no longer active)]

Comment on attachment 649508 [details] [diff] [review]
Part 2: Change sps's StackEntry to inherit from js::ProfileEntry and add a line number

r=me with my comments addressed.

Comment 21

[u443197]

Attachment: Part 4: provide an ip -> line translation mechanism

The changes to translation were non-trivial, so I wanted to make sure I'm not doing anything insane related to inline scripts.

Comment 22

[u443197]

Attachment: Part 5: Expose the line number in the JSON output of SPS

Comment 23

[(no longer active)]

Comment on attachment 650724 [details] [diff] [review]
Part 5: Expose the line number in the JSON output of SPS

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

::: tools/profiler/TableTicker.cpp
@@ +645,2 @@
>  {
> +  int lineno = UINT_MAX;

Did you mean to declare lineno as unsigned, or use INT_MAX?

@@ +665,5 @@
>        // Cast to *((void**) to pass the text data to a void*
>        aProfile.addTag(ProfileEntry('d', *((void**)(&text[0]))));
>      }
> +    if (entry.js()) {
> +      if (entry.pc() == NULL) {

Nit: if (!entry.pc()) {

@@ +669,5 @@
> +      if (entry.pc() == NULL) {
> +        // The JIT only allows the top-most entry to have a NULL pc
> +        MOZ_ASSERT(&entry == &stack->mStack[stack->stackSize() - 1]);
> +        // If stack-walking was disabled, then that's just unfortunate
> +        if (lastpc != NULL) {

Nit: if (lastpc) {

@@ +687,1 @@
>    }

So, at this point it's possible to lineno to be (U)INT_MAX, right?  Do we really want to add an 'n' tag in that case?

@@ +848,5 @@
>    // 's' tag denotes the start of a sample block
>    // followed by 0 or more 'c' tags.
>    aProfile.addTag(ProfileEntry('s', "(root)"));
>    for (uint32_t i = 0; i < aStack->stackSize(); i++) {
> +    addProfileEntry(aStack->mStack[i], aProfile, aStack, NULL);

Nit: nullptr.

Comment 24

[u443197]

Attachment: Part 5: Expose the line number in the JSON output of SPS (v2)

(In reply to Ehsan Akhgari [:ehsan] from comment #23)

> Did you mean to declare lineno as unsigned, or use INT_MAX?

It was uint32_t, but forgot to change this. I meant to initialize to -1, and I now skip adding the 'n' tag if it's -1

Comment 25

[(no longer active)]

Comment on attachment 650932 [details] [diff] [review]
Part 5: Expose the line number in the JSON output of SPS (v2)

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

Looks good!

::: tools/profiler/TableTicker.cpp
@@ +673,5 @@
> +        if (lastpc) {
> +          jsbytecode *jspc = js::ProfilingGetPC(stack->mRuntime, entry.script(),
> +                                                lastpc);
> +          if (jspc)
> +            lineno = JS_PCToLineNumber(NULL, entry.script(), jspc);

Nit: braces around if here and elsewhere.

Comment 26

[u443197]

https://hg.mozilla.org/integration/mozilla-inbound/rev/985ce4db8635
https://hg.mozilla.org/integration/mozilla-inbound/rev/6b1ab2486190
https://hg.mozilla.org/integration/mozilla-inbound/rev/519084424637
https://hg.mozilla.org/integration/mozilla-inbound/rev/fa3f3fd7e190
https://hg.mozilla.org/integration/mozilla-inbound/rev/e89e79c1560b

Comment 27

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/985ce4db8635
https://hg.mozilla.org/mozilla-central/rev/6b1ab2486190
https://hg.mozilla.org/mozilla-central/rev/519084424637
https://hg.mozilla.org/mozilla-central/rev/fa3f3fd7e190
https://hg.mozilla.org/mozilla-central/rev/e89e79c1560b

Comment 28

[Vladimir Vukicevic [:vlad] [:vladv] (needinfo me, slow to respond)]

I suspect this broke profiling on Android/ARM; see bug 782659.

Comment 29

[Vladimir Vukicevic [:vlad] [:vladv] (needinfo me, slow to respond)]

Ignore that; this isn't the cause.

Comment 30

[Vladimir Vukicevic [:vlad] [:vladv] (needinfo me, slow to respond)]

Ignore that ignoring; it's definitely the cause (I was very confused when I tested last time, but I did a build just before this landed and just after to confirm).

Alex, can you back this out and reland when there's a fix?