RFR: JDK-8060017: Report heap sizing time

[Thomas Schatzl]

Hi again,

On Mon, 2015-03-23 at 17:15 +0100, Thomas Schatzl wrote:
> Hi Eric,
> 
> On Thu, 2015-03-19 at 13:15 -0400, Eric Caspole wrote:
> > Thanks Kim I simplified this part.
> > http://cr.openjdk.java.net/~ecaspole/JDK-8060017/04/webrev/
> > Eric
> 
>   - I would prefer instead of repeating the code surrounding the
> expand() call to introduce a new method like expand_and_track_time() or
> expand_during_young_gc().
> 
>   - also, I would somewhat prefer to always print the "Expand Heap"
> message, at least in detail level finest. Keeping current behavior is
> not really a problem with me, but this would also make a test easier :)
> (e.g. expand hotspot/test/gc/g1/TestGCLogMessages.java)
> 
>   - _cur_expand_heap_time_ms seems to be never initialized or reset. At
> least some cursory testing with small benchmarks suspiciously reports
> heap expansion times without any expansion actually occurring (e.g. heap
> size staying the same, and the times themselves being always the same).

  thinking about the change a bit more, I think the current way the heap
expansion time is presented is confusing: it simply adds together all
heap expansion time ever incurred.

However, in our printing we assume that indented times are parts of the
upper level time. E.g.

[Other: 10ms]
  [Expand Heap: 8ms]

means that out of 10ms of Other time, Expand Heap took 8ms outside of
the main evacuation task (what is called "Parallel Time" at the moment).
This can go as far as the reported "Expand Heap" time being larger than
the Other time.

I would prefer if the current scheme would be kept, and "Expand Heap"
times reported separately for the phases they are incurred.

I.e. one "Expand Heap" time for heap expansion after GC, and per-thread
timings during the parallel GC phase.

An option would be to for now just record the heap expansion time to
heap expansion after GC in the VM thread.

Thanks,
  Thomas