RFR(XL): 8203469: Faster safepoints

[Aleksey Shipilev]

On 1/16/19 10:45 AM, Robbin Ehn wrote:
> I added a new logging line in this patch, e.g. :
> [93.734s][info][safepoint,stats] Deoptimize: Synchronization: 4899 Operation: 457865 - Total: 462764
> Application: 8270801 (ns)
> 
> Which might be useful (it is for me), let me know if it's needs reformatting or is missing
> information etc.. or useless.

Um. I think this is inconsistent with the regular PrintSafepointStatistics safepoint logging that
logs "sync", "block", "vm op", and "cleanup". The new message seems to tell "Synchronization" =
"sync" + "block", and "Operation" = "vm op" + "cleanup"?

I say we call it what it is:

[93.734s][info][safepoint,stats] Safepoint "Deoptimize", Time since last: 8270801 ns; Reaching
safepoint: 4899 ns; At safepoint: 457865 ns; Total: 462764 ns

Also note the temporal ordering: first the timestamp for application stopped time, then time
intervals for stopping/stopped, then totals.

> We also don't measure the early prolog with:
>  380   Universe::heap()->safepoint_synchronize_begin();
>  381
>  382   // By getting the Threads_lock, we assure that no threads are about to start or
>  383   // exit. It is released again in SafepointSynchronize::end().
>  384   Threads_lock->lock();
> 
> I had a measurement there but it was never any time spent there, something to keep in mind at least.

Oh. Can we (should we) move the call to RuntimeService::record_safepoint_begin() before these? I'd
imagine CollectedHeap::safepoint_synchronize_begin() might take a while in some implementations, and
Threads_lock acquisition can be contended as well. It's fine to make it in a separate issue to avoid
tainting this one with artificial "regression".

Cheers,
-Aleksey