Add more safe points in compiler

Add more safe points in compiler.

The Scavenge (young-gen) GCs on the main thread have to wait for other
threads to check in at a safe point. We were seeing big waits here, often
20ms, occasionally up to 180ms where the main thread is idling, waiting
for the optimizing compiler.  By adding more safe points the wait is
reduced and is now rarely over 10ms, often under 1ms.

This also changes the --verbose-gc output to be better aligned with the
column headings, and to add the time needed to get to
the safe point to the output, eg:

[ GC(784211551): Scavenge(new space), 18, 2.209, 76.009, 32768, 0, 32768, 32768, 0, 0, 144912, 154425, 152064, 154880, 0, 0, 46.984, 2.752, 7.407, 18.657, 0.033, 5421, 0, 0, 0, ]
                                                 ^^^^^^ Scavenge time                                                        ^^^^^^  safe point time.

R=vegorov@google.com
BUG=

Committed: https://github.com/dart-lang/sdk/commit/fc2fcf9bc8adeb051cecac1d349c9209594de3dd

[Vyacheslav Egorov (Google), 2017-03-23 10:24:02]

https://codereview.chromium.org/2771013002/diff/1/runtime/vm/compiler.cc
File runtime/vm/compiler.cc (right):

https://codereview.chromium.org/2771013002/diff/1/runtime/vm/compiler.cc#newc...
runtime/vm/compiler.cc:842: SafepointOperationScope safepoint_scope(thread());
Here and below:

I think you need 

thread()->CheckForSafepoint() 

instead: you want to enter safepoint if one is requested, you don't want to
safepoint other threads.

[Cutch, 2017-03-23 13:47:28]

Why is this needed?

What bug is this fixing?

[siva, 2017-03-23 18:05:01]

asiva@google.com changed reviewers:
+ asiva@google.com

[siva, 2017-03-23 18:05:02]

DBC

https://codereview.chromium.org/2771013002/diff/40001/runtime/vm/pages.h
File runtime/vm/pages.h (right):

https://codereview.chromium.org/2771013002/diff/40001/runtime/vm/pages.h#newc...
runtime/vm/pages.h:331: kSweepLargePages = 4,
Might be a better to add the new time slot as the last entry of the times
section.

People who have been staring at verbose GC logs could have gotten used to the
first four entries being marking/resetting/sweeping etc.

https://codereview.chromium.org/2771013002/diff/40001/runtime/vm/zone.cc
File runtime/vm/zone.cc (right):

https://codereview.chromium.org/2771013002/diff/40001/runtime/vm/zone.cc#newc...
runtime/vm/zone.cc:84: current->CheckForSafepoint();
Why is this check needed here? We may run into issues when it is necessary to do
a new Zone inside a NoSafepointScope block.

[erikcorry, 2017-03-27 10:12:54]

Description was changed from

==========
Add more safe points in compiler

We still need some inside the inliner, but that's coming in a later change.
This also changes the --verbose-gc output to add the time needed to get to
the safe point to the output, eg:

[ GC(784211551): Scavenge(new space), 18, 2.209, 76.009, 32768, 0, 32768, 32768,
0, 0, 144912, 154425, 152064, 154880, 0, 0, 46.984, 2.752, 7.407, 18.657, 0.033,
5421, 0, 0, 0, ]
                                                 ^^^^^^ Scavenge time           
                                            ^^^^^^  safe point time.

R=vegorov@google.com
BUG=
==========

to

==========
Add more safe points in compiler.

The Scavenge (young-gen) GCs on the main thread have to wait for other
threads to check in at a safe point. We were seeing big waits here, often
20ms, occasionally up to 180ms where the main thread is idling, waiting
for the optimizing compiler.  By adding more safe points the wait is
reduced and is now rarely over 10ms, often under 1ms.

This also changes the --verbose-gc output to be better aligned with the
column headings, and to add the time needed to get to
the safe point to the output, eg:

[ GC(784211551): Scavenge(new space), 18, 2.209, 76.009, 32768, 0, 32768, 32768,
0, 0, 144912, 154425, 152064, 154880, 0, 0, 46.984, 2.752, 7.407, 18.657, 0.033,
5421, 0, 0, 0, ]
                                                 ^^^^^^ Scavenge time           
                                            ^^^^^^  safe point time.

R=vegorov@google.com
BUG=
==========

[erikcorry, 2017-03-27 10:23:28]

Description updated.

https://codereview.chromium.org/2771013002/diff/1/runtime/vm/compiler.cc
File runtime/vm/compiler.cc (right):

https://codereview.chromium.org/2771013002/diff/1/runtime/vm/compiler.cc#newc...
runtime/vm/compiler.cc:842: SafepointOperationScope safepoint_scope(thread());
On 2017/03/23 10:24:02, Vyacheslav Egorov (Google) wrote:
> Here and below:
> 
> I think you need 
> 
> thread()->CheckForSafepoint() 
> 
> instead: you want to enter safepoint if one is requested, you don't want to
> safepoint other threads.

Done.

https://codereview.chromium.org/2771013002/diff/40001/runtime/vm/pages.h
File runtime/vm/pages.h (right):

https://codereview.chromium.org/2771013002/diff/40001/runtime/vm/pages.h#newc...
runtime/vm/pages.h:331: kSweepLargePages = 4,
On 2017/03/23 18:05:01, siva wrote:
> Might be a better to add the new time slot as the last entry of the times
> section.
> 
> People who have been staring at verbose GC logs could have gotten used to the
> first four entries being marking/resetting/sweeping etc.

I think it makes most sense to have them in the order they actually happen, and
safe-point waiting happens first.

But it's true that the output is hard to read. I propose padding better so that
the columns more or less line up with the header.  See new version at
https://screenshot.googleplex.com/GrM71QDzLFp vs old version at
https://screenshot.googleplex.com/CExFc3619EC

https://codereview.chromium.org/2771013002/diff/40001/runtime/vm/zone.cc
File runtime/vm/zone.cc (right):

https://codereview.chromium.org/2771013002/diff/40001/runtime/vm/zone.cc#newc...
runtime/vm/zone.cc:84: current->CheckForSafepoint();
On 2017/03/23 18:05:01, siva wrote:
> Why is this check needed here? We may run into issues when it is necessary to
do
> a new Zone inside a NoSafepointScope block.

Good catch.  This one was great for keeping down the wait time, but it's not
safe unless we make NoSafePointScope into a release-mode thing and check for it.
 Removed.

[Vyacheslav Egorov (Google), 2017-03-27 14:11:51]

lgtm

https://codereview.chromium.org/2771013002/diff/60001/runtime/vm/code_generat...
File runtime/vm/code_generator.cc (right):

https://codereview.chromium.org/2771013002/diff/60001/runtime/vm/code_generat...
runtime/vm/code_generator.cc:1733: // Unfortunately, while we were compiling,
the background compiler may
The comment is inaccurate: it is background compiler that disables the
unoptimized code. see Function::InstallOptimizedCode - there is a hack there
that prevents disabling of the unoptimized code when we are installing for OSR.

https://codereview.chromium.org/2771013002/diff/60001/runtime/vm/flow_graph.cc
File runtime/vm/flow_graph.cc (right):

https://codereview.chromium.org/2771013002/diff/60001/runtime/vm/flow_graph.c...
runtime/vm/flow_graph.cc:1319: thread()->CheckForSafepoint();
It seems strange to have a safepoint-per-block only here even though there are
more optimizations that iterate graph block by block.

[erikcorry, 2017-03-30 14:10:19]

I had to rebase this one after https://codereview.chromium.org/2781483005/
landed.

PTAL

https://codereview.chromium.org/2771013002/diff/60001/runtime/vm/code_generat...
File runtime/vm/code_generator.cc (right):

https://codereview.chromium.org/2771013002/diff/60001/runtime/vm/code_generat...
runtime/vm/code_generator.cc:1733: // Unfortunately, while we were compiling,
the background compiler may
On 2017/03/27 14:11:51, Vyacheslav Egorov (Google) wrote:
> The comment is inaccurate: it is background compiler that disables the
> unoptimized code. see Function::InstallOptimizedCode - there is a hack there
> that prevents disabling of the unoptimized code when we are installing for
OSR.

I now made more serious changes to this section in
https://codereview.chromium.org/2781483005/ so it should be more solid.

https://codereview.chromium.org/2771013002/diff/60001/runtime/vm/flow_graph.cc
File runtime/vm/flow_graph.cc (right):

https://codereview.chromium.org/2771013002/diff/60001/runtime/vm/flow_graph.c...
runtime/vm/flow_graph.cc:1319: thread()->CheckForSafepoint();
On 2017/03/27 14:11:51, Vyacheslav Egorov (Google) wrote:
> It seems strange to have a safepoint-per-block only here even though there are
> more optimizations that iterate graph block by block.

I just picked the ones that showed up as slow for now.  With the new
--verbose-gc format we can keep an eye on it better.

[erikcorry, 2017-03-31 09:19:55]

Description was changed from

==========
Add more safe points in compiler.

The Scavenge (young-gen) GCs on the main thread have to wait for other
threads to check in at a safe point. We were seeing big waits here, often
20ms, occasionally up to 180ms where the main thread is idling, waiting
for the optimizing compiler.  By adding more safe points the wait is
reduced and is now rarely over 10ms, often under 1ms.

This also changes the --verbose-gc output to be better aligned with the
column headings, and to add the time needed to get to
the safe point to the output, eg:

[ GC(784211551): Scavenge(new space), 18, 2.209, 76.009, 32768, 0, 32768, 32768,
0, 0, 144912, 154425, 152064, 154880, 0, 0, 46.984, 2.752, 7.407, 18.657, 0.033,
5421, 0, 0, 0, ]
                                                 ^^^^^^ Scavenge time           
                                            ^^^^^^  safe point time.

R=vegorov@google.com
BUG=
==========

to

==========
Add more safe points in compiler.

The Scavenge (young-gen) GCs on the main thread have to wait for other
threads to check in at a safe point. We were seeing big waits here, often
20ms, occasionally up to 180ms where the main thread is idling, waiting
for the optimizing compiler.  By adding more safe points the wait is
reduced and is now rarely over 10ms, often under 1ms.

This also changes the --verbose-gc output to be better aligned with the
column headings, and to add the time needed to get to
the safe point to the output, eg:

[ GC(784211551): Scavenge(new space), 18, 2.209, 76.009, 32768, 0, 32768, 32768,
0, 0, 144912, 154425, 152064, 154880, 0, 0, 46.984, 2.752, 7.407, 18.657, 0.033,
5421, 0, 0, 0, ]
                                                 ^^^^^^ Scavenge time           
                                            ^^^^^^  safe point time.

R=vegorov@google.com
BUG=

Committed:
https://github.com/dart-lang/sdk/commit/fc2fcf9bc8adeb051cecac1d349c9209594de3dd
==========

[erikcorry, 2017-03-31 09:19:56]

Committed patchset #5 (id:80001) manually as
fc2fcf9bc8adeb051cecac1d349c9209594de3dd (presubmit successful).