1342714 - Eliminate the cost of performance monitoring (js::AutoStopwatch) from scrolling google spreadsheets

Status: RESOLVED FIXED

(Toolkit :: Performance Monitoring, defect)

Description

[(no longer active)]

At least on OSX, the thread_info() syscall from http://searchfox.org/mozilla-central/rev/93f1641e394cfbdfbeed44e81f7dab0f2aff7b6f/toolkit/components/perfmonitoring/nsPerformanceStats.cpp#1296 shows up in profiles (so does the mach_thread_self() call.)

Also js::RunScript is pretty hot here, and I suspect it's hot on other GSuites pages as well.  There's no reason to pay this cost all the time.

Comment 1

[(no longer active)]

Attachment: Disable performance monitoring by default

Comment 2

[David Teller [:Yoric] - still alive but not very active]

Comment on attachment 8841284 [details] [diff] [review]
Disable performance monitoring by default

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

If we disable performance monitoring, this will break the add-on watcher (including add-on performance telemetry), as well as about:performance, so there is a need to maintain monitoring.

Are you sure that this actually shows up in GSuite? Normally, this code is called at most once per tick-involving-js. If this code is a problem, I can think of the following avenues:

- somehow reduce the number of times we call performance monitoring (e.g. introduce sampling);
- somehow get rid of the thread_info call (e.g. use per-process info instead of per-thread info, or only use per-thread info once in a while to correct per-process info).

Comment 3

[(no longer active)]

(In reply to David Teller [:Yoric] (please use "needinfo") from comment #2)
> If we disable performance monitoring, this will break the add-on watcher
> (including add-on performance telemetry), as well as about:performance, so
> there is a need to maintain monitoring.
> 
> Are you sure that this actually shows up in GSuite? 

Yes, 100%.

> Normally, this code is
> called at most once per tick-involving-js. If this code is a problem, I can
> think of the following avenues:

What ensures this?  AFAICT this is called in js::RunScript() every time, which, as I said, is hot code: <http://searchfox.org/mozilla-central/rev/90d1cbb4fd3dc249cdc11fe5c3e0394d22d9c680/js/src/vm/Interpreter.cpp#361>.

> - somehow reduce the number of times we call performance monitoring (e.g.
> introduce sampling);
> - somehow get rid of the thread_info call (e.g. use per-process info instead
> of per-thread info, or only use per-thread info once in a while to correct
> per-process info).

No, what we need to ensure is to make sure js::AutoStopwatch doesn't show up *at all* when scrolling a google spreadsheet (bug 
1342713).  (There's other stuff besides thread_info there that shows up too, although thread_info seems to be the most expensive part).  My patch achieves that goal.

Can you please provide a different patch that achieves the same result without the downsides you mentioned?  Thanks!

Comment 4

[David Teller [:Yoric] - still alive but not very active]

> What ensures this?  AFAICT this is called in js::RunScript() every time, which, as I said, is hot code: <http://searchfox.org/mozilla-central/rev/90d1cbb4fd3dc249cdc11fe5c3e0394d22d9c680/js/src/vm/Interpreter.cpp#361>.

We are still talking about `thread_info`, right?

It's called by `nsPerformanceStatsService::StopwatchStartCallback` and `nsPerformanceStatsService::StopwatchCommitCallback`  (see nsPerformanceStats.cpp), which are called respectively here https://dxr.mozilla.org/mozilla-central/source/js/src/vm/Stopwatch.cpp#54-67 and here https://dxr.mozilla.org/mozilla-central/source/js/src/vm/Stopwatch.cpp#137-167. There is a guard to ensure that we're not calling each more than once per tick.

At this stage, your profile is unclear to me. Do you have reasons to believe that it is called more than once per tick? If so, my best hypothesis so far is that the iteration number (setup through https://dxr.mozilla.org/mozilla-central/source/js/xpconnect/src/XPCJSContext.cpp#3660 ) is somehow wrong.


> No, what we need to ensure is to make sure js::AutoStopwatch doesn't show up *at all* when scrolling a google spreadsheet (bug 1342713).  (There's other stuff besides thread_info there that shows up too, although thread_info seems to be the most expensive part).  My patch achieves that goal.

Do you have a profile at hand? Discussing in the abstract is a bit complicated.

Comment 5

[(no longer active)]

(In reply to David Teller [:Yoric] (please use "needinfo") from comment #4)
> > What ensures this?  AFAICT this is called in js::RunScript() every time, which, as I said, is hot code: <http://searchfox.org/mozilla-central/rev/90d1cbb4fd3dc249cdc11fe5c3e0394d22d9c680/js/src/vm/Interpreter.cpp#361>.
> 
> We are still talking about `thread_info`, right?

No, I'm talking about the overhead of performance monitoring (the code I linked to.)

> It's called by `nsPerformanceStatsService::StopwatchStartCallback` and
> `nsPerformanceStatsService::StopwatchCommitCallback`  (see
> nsPerformanceStats.cpp), which are called respectively here
> https://dxr.mozilla.org/mozilla-central/source/js/src/vm/Stopwatch.cpp#54-67
> and here
> https://dxr.mozilla.org/mozilla-central/source/js/src/vm/Stopwatch.cpp#137-
> 167. There is a guard to ensure that we're not calling each more than once
> per tick.
> 
> At this stage, your profile is unclear to me. Do you have reasons to believe
> that it is called more than once per tick? If so, my best hypothesis so far
> is that the iteration number (setup through
> https://dxr.mozilla.org/mozilla-central/source/js/xpconnect/src/XPCJSContext.
> cpp#3660 ) is somehow wrong.

I'm not sure how many times it's called unfortunately.  All I know at this point is that it shows up in the profile when scrolling a google spreadsheet.  It may be because we're running it too many times, or the expected number of times but it's just too slow.

Have you tried to profile this?

> > No, what we need to ensure is to make sure js::AutoStopwatch doesn't show up *at all* when scrolling a google spreadsheet (bug 1342713).  (There's other stuff besides thread_info there that shows up too, although thread_info seems to be the most expensive part).  My patch achieves that goal.
> 
> Do you have a profile at hand? Discussing in the abstract is a bit
> complicated.

Sure, but it's an Instruments profile so there is no great way to share it.  I can upload a screenshot...

Comment 6

[(no longer active)]

Attachment: Profile screenshot

Comment 7

[(no longer active)]

Attachment: Another profile

This one shows the relative cost of this with one of the culprits behind bug 1338802 which is the main reason why we're slow on this test case.  That is the js::detail::HashTable... frame (the first one) with a self weight of 38ms.

Comment 8

[David Teller [:Yoric] - still alive but not very active]

> Have you tried to profile this?

Before I landed this code, ~18 months ago, I spent several days profiling it on every site that I could think of (I'm almost sure that GSuite was included) and AutoStopwatch didn't show up. Nor did it show up on Talos, Arewefastyet, etc.

I haven't re-profiled since then, though.

> Sure, but it's an Instruments profile so there is no great way to share it.  I can upload a screenshot...

Ah, and Instruments doesn't show usage counters. That would have been helpful here to determine whether thread_info is somehow called too often. Is there any way you could delve one or two depths further in `AutoStopwatch::AutoStopwatch` in your profiles, to find out exactly what's wrong with this constructor?

> This one shows the relative cost of this with one of the culprits behind bug 1338802 which is the main reason why we're slow on this test case.  That is the js::detail::HashTable... frame (the first one) with a self weight of 38ms.

If I read this correctly, in that case, it's about ~20% wrt to the biggest culprit, right? If that's meaningful, for the moment, the best strategy I can think of atm is to somehow not monitor every tick.

Comment 9

[(no longer active)]

(In reply to David Teller [:Yoric] (please use "needinfo") from comment #8)
> > Have you tried to profile this?
> 
> Before I landed this code, ~18 months ago, I spent several days profiling it
> on every site that I could think of (I'm almost sure that GSuite was
> included) and AutoStopwatch didn't show up. Nor did it show up on Talos,
> Arewefastyet, etc.
> 
> I haven't re-profiled since then, though.

Oh no sorry I meant with the Google spreadsheet scrolling test case.  I was asking since Instruments makes it next to impossible to share the profile in any decent way.  I'm pretty sure this is easy to repro, since I see it every time.

> > Sure, but it's an Instruments profile so there is no great way to share it.  I can upload a screenshot...
> 
> Ah, and Instruments doesn't show usage counters. That would have been
> helpful here to determine whether thread_info is somehow called too often.
> Is there any way you could delve one or two depths further in
> `AutoStopwatch::AutoStopwatch` in your profiles, to find out exactly what's
> wrong with this constructor?

The screenshots were sorted bottom up, those are the leaf frames.

Usually Instruments can show which lines are hot, although sometimes the feature doesn't work that well.  In these profiles nothing shows as particularly hot either in the ctor or in the dtor, it just seems that they're being called...  (But I don't trust Instruments here 100% so take this with a grain of salt.)

> > This one shows the relative cost of this with one of the culprits behind bug 1338802 which is the main reason why we're slow on this test case.  That is the js::detail::HashTable... frame (the first one) with a self weight of 38ms.
> 
> If I read this correctly, in that case, it's about ~20% wrt to the biggest
> culprit, right? If that's meaningful, for the moment, the best strategy I
> can think of atm is to somehow not monitor every tick.

You understand this code a lot better than I do, so I'd be more than happy to trust your judgement.  :-)

Comment 10

[(no longer active)]

Another profile: https://perfht.ml/2nATQGR  From running this test case: https://jakearchibald.github.io/service-worker-benchmark/

David, can you please propose a plan on how you would like you deal with this?  I keep seeing this in various profiles, and I'd like to ensure that we are going to have an actively worked on plan here.  Thank you!

Comment 11

[David Teller [:Yoric] - still alive but not very active]

Unfortunately, for the moment, I'm actively working on something that also has high priority and is entirely unrelated, so I can make no promise.

Ehsan, there is one thing that would provide a simple experience, if you have time. In https://dxr.mozilla.org/mozilla-central/source/toolkit/components/perfmonitoring/nsPerformanceStats.cpp?q=nsPerformanceStats.cpp&redirect_type=direct#1288, could you simply replace the `#if defined(XP_MACOSX)` with a `#if 0` and see if there are performance improvements? This would considerably degrade the precision of performance stats on MacOS, but I realize that your work has higher impact than precise performance stats.

Comment 12

[Jean Gong :jgong]

Hello David, we have raised the priority on this bug and it needs get fixed based on the priority of the Quantum Flow.  Can you give let me know if you can start on this ASAP?  Thanks!

Comment 13

[David Teller [:Yoric] - still alive but not very active]

I believe that I can start running experiments next week. No ETA yet, that will depend on the result of experiments.

Comment 14

[Jean Gong :jgong]

Apologies. I cleared the whiteboard by accident.

Comment 15

[(no longer active)]

Yoric and I discussed this today on IRC.  Clearing the needinfo.

Comment 16

[David Teller [:Yoric] - still alive but not very active]

Attachment: Bug 1342714 - Reducing allocations in AutoStopwatch;

This patch fixes two related issues.

1. The AutoStopwatch uses a stack-allocated `mozilla::Vector` to
communicate with its callback during each compartment switch. This
vector was designed to allow its contents to be stack-allocated but
they turned out to be accidentally heap-allocated.


2. During each tick, the stopwatch fills a vector
`recentGroups_`. This vector always started with minimal capacity and
had to grow repeatedly as groups were added, causing repeated
reallocations. This patch preallocates `recentGroups_` to have the
same capacity as the previous tick. We expect that this should
eventually reach a stable size that closely matches the actual needs
of the process.

Review commit: https://reviewboard.mozilla.org/r/123058/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/123058/

Comment 17

[David Teller [:Yoric] - still alive but not very active]

I did a quick profiling with the attached patch, scrolling continuously on a Google Spreadsheet for a few seconds. AutoStopwatch was profiled as contributing ~300µs of the total, so I'm reasonably optimistic about this patch.

Comment 18

[Jan de Mooij [:jandem]]

Can we just always use the Vector that can store 8 elements inline? Even if we expect many elements, that's still an improvement because we avoid some realloc calls. Having separate small and large cases just makes things more confusing IMO.

Comment 19

[David Teller [:Yoric] - still alive but not very active]

(In reply to Jan de Mooij [:jandem] from comment #18)
> Can we just always use the Vector that can store 8 elements inline? Even if
> we expect many elements, that's still an improvement because we avoid some
> realloc calls. Having separate small and large cases just makes things more
> confusing IMO.

Well, for the large vector, we rely upon `swap` at the end of the tick, and this operation is not implemented if there is inline storage. We could replace it with a manual loop + move, but that's slower and more bug-prone. So, unless you insist, I'd rather keep the separation between small and large cases.

Comment 20

[Nathan Froyd [:froydnj]]

Comment on attachment 8850459 [details]
Bug 1342714 - Reducing allocations in AutoStopwatch;

https://reviewboard.mozilla.org/r/123058/#review125960

I'm kind of inclined to agree with Jan here.  Implementing the necessary code around the bit in `PerformanceMonitoring::commit` would be a single line:

```
  PerformanceGroupVector recentGroups(Move(recentGroups_));
```

and the only other use of `swap` below could do the same thing, or convert to using `nsTArray`/`nsAutoTArray` or whatever.

::: toolkit/components/perfmonitoring/nsPerformanceStats.cpp:782
(Diff revision 1)
>    mTopGroup->Dispose();
>    mTopGroup = nullptr;
>  
>    // Copy references to the groups to a vector to ensure that we do
>    // not modify the hashtable while iterating it.
> -  GroupVector groups;
> +  LargeGroupVector groups;

Seems like you would want to use something with stack-allocated storage here, though I'm not sure that using the typedefs really makes things clearer, since the important thing is the stable storage of the pointers, not the smallness/largeness/groupness of the vector.

::: toolkit/components/perfmonitoring/nsPerformanceStats.cpp:1137
(Diff revision 1)
> +  // Sanity check: make sure that we're not causing heap allocations here.
> +  MOZ_ASSERT(out.length() <= out.sMaxInlineStorage);

This seems like a really weird check.  What's the point of doing this?  We don't actually care whether we're overflowing the buffer here...

::: toolkit/components/perfmonitoring/nsPerformanceStats.cpp:1367
(Diff revision 1)
> -  GroupVector alerts;
> +  LargeGroupVector alerts;
>    mPendingAlerts.swap(alerts);

If `mPendingAlerts` were an `nsAutoTArray`, calling swap here would be perfectly acceptable.

Comment 21

[David Teller [:Yoric] - still alive but not very active]

Comment on attachment 8850459 [details]
Bug 1342714 - Reducing allocations in AutoStopwatch;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/123058/diff/1-2/

Comment 22

[David Teller [:Yoric] - still alive but not very active]

Comment on attachment 8850459 [details]
Bug 1342714 - Reducing allocations in AutoStopwatch;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/123058/diff/2-3/

Comment 23

[David Teller [:Yoric] - still alive but not very active]

Comment on attachment 8850459 [details]
Bug 1342714 - Reducing allocations in AutoStopwatch;

https://reviewboard.mozilla.org/r/123058/#review125960

Good idea, I hadn't noticed the `mozilla::Vector`'s move constructor.

> Seems like you would want to use something with stack-allocated storage here, though I'm not sure that using the typedefs really makes things clearer, since the important thing is the stable storage of the pointers, not the smallness/largeness/groupness of the vector.

Fair enough.

> This seems like a really weird check.  What's the point of doing this?  We don't actually care whether we're overflowing the buffer here...

Well, if we exceed the inline buffer, pretty much every single time we enter this compartment, we'll end up heap-allocating. That's the most likely culprit for the performance issue encountered here, so we want to make sure that we don't do this accidentally.

> If `mPendingAlerts` were an `nsAutoTArray`, calling swap here would be perfectly acceptable.

Should I file a bug to suggest that someone should finish implementing `Vector::swap`?

Comment 24

[Nathan Froyd [:froydnj]]

Comment on attachment 8850459 [details]
Bug 1342714 - Reducing allocations in AutoStopwatch;

https://reviewboard.mozilla.org/r/123058/#review126326

Thanks for making the suggested changes.  A few comments about the comments below.

::: js/src/vm/Stopwatch.cpp:158
(Diff revision 3)
> -    PerformanceGroupVector recentGroups;
> -    recentGroups_.swap(recentGroups);
> +    // Unless `recentGroups_.length() <= 8`, the `Move` operation below
> +    // is constant-time.

I'm unsure that this comment is actually helpful: why is this particular operation worth calling out vs. all the other things we're doing?  The expected, common case is that `recentGroups_.length() <= 8`, too, so the comment is saying that the exceptional situation is constant-time...what about the common case?

I'm also not wild about the comment embedding a magic constant from the `PerformanceGroupVector` typedef that might get out of sync with the typedef.

::: toolkit/components/perfmonitoring/nsPerformanceStats.cpp:1366
(Diff revision 3)
> -  mPendingAlerts.swap(alerts);
> +  // Unless `mPendingAlerts.length() <= 8`, the `Move` operation below
> +  // is constant-time.

Same comment here as in the JS code.

Comment 25

[Jan de Mooij [:jandem]]

Comment on attachment 8850459 [details]
Bug 1342714 - Reducing allocations in AutoStopwatch;

https://reviewboard.mozilla.org/r/123058/#review126354

::: js/src/vm/Stopwatch.cpp:24
(Diff revision 3)
>  
>  #include "gc/Zone.h"
>  #include "vm/Runtime.h"
>  
> +// Maximal initialization size, in elements for the vector of groups.
> +#define MAX_GROUPS_INIT_CAPACITY 1024

Nit: I'd prefer the more modern

static const size_t MAX_GROUPS_INIT_CAPACITY = 1024;

Then you also don't need the size_t-cast below. (Personally I'd also move it into the function that uses it: having the constant far away makes it easy to forget removing it if we ever remove the consumer for some reason.)

::: js/src/vm/Stopwatch.cpp:158
(Diff revision 3)
> -    PerformanceGroupVector recentGroups;
> -    recentGroups_.swap(recentGroups);
> +    // Unless `recentGroups_.length() <= 8`, the `Move` operation below
> +    // is constant-time.

Agreed with Nathan, but also: moving <= 8 elements is pretty close to constant-time (IMO O(n) vs O(1) only matters when n can be large), so I'd just not mention it.

Comment 26

[David Teller [:Yoric] - still alive but not very active]

Comment on attachment 8850459 [details]
Bug 1342714 - Reducing allocations in AutoStopwatch;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/123058/diff/3-4/

Comment 27

[David Teller [:Yoric] - still alive but not very active]

Comment on attachment 8850459 [details]
Bug 1342714 - Reducing allocations in AutoStopwatch;

https://reviewboard.mozilla.org/r/123058/#review126326

> I'm unsure that this comment is actually helpful: why is this particular operation worth calling out vs. all the other things we're doing?  The expected, common case is that `recentGroups_.length() <= 8`, too, so the comment is saying that the exceptional situation is constant-time...what about the common case?
> 
> I'm also not wild about the comment embedding a magic constant from the `PerformanceGroupVector` typedef that might get out of sync with the typedef.

Actually, in this case, we expect that it's going to be much longer. If you're confused by the different uses of `PerformanceGroupVector`, recall that I was just r-ed attempting to give them two different type names :)

Comment 28

[David Teller [:Yoric] - still alive but not very active]

Comment on attachment 8850459 [details]
Bug 1342714 - Reducing allocations in AutoStopwatch;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/123058/diff/4-5/

Comment 29

[David Teller [:Yoric] - still alive but not very active]

Comment on attachment 8850459 [details]
Bug 1342714 - Reducing allocations in AutoStopwatch;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/123058/diff/5-6/

Comment 30

[David Teller [:Yoric] - still alive but not very active]

Comment on attachment 8850459 [details]
Bug 1342714 - Reducing allocations in AutoStopwatch;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/123058/diff/6-7/

Comment 31

[David Teller [:Yoric] - still alive but not very active]

Comment on attachment 8850459 [details]
Bug 1342714 - Reducing allocations in AutoStopwatch;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/123058/diff/7-8/

Comment 32

[David Teller [:Yoric] - still alive but not very active]

Comment on attachment 8850459 [details]
Bug 1342714 - Reducing allocations in AutoStopwatch;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/123058/diff/8-9/

Comment 33

[David Teller [:Yoric] - still alive but not very active]

Comment on attachment 8850459 [details]
Bug 1342714 - Reducing allocations in AutoStopwatch;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/123058/diff/9-10/

Comment 34

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/cf506c806cb5
Reducing allocations in AutoStopwatch;r=froydnj,jandem

Comment 35

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

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