RFR(S) 8246019 PerfClassTraceTime slows down VM start-up

[Ioi Lam]

On 6/17/20 11:02 AM, Jiangli Zhou wrote:
> Hi Ioi,
>
> PerfClassTraceTime is one of the fundamental hotspot features used for
> collecting performance data in cloud services. Developers do look at
> metrics collected by that.

Hi Jiangli,

My patch does not get rid of PerfClassTraceTime. It only changes the 
places where we know that the overhead of the PerfClassTraceTime is far 
greater than the actual time measured.

As I mentioned in another mail, 
https://mail.openjdk.java.net/pipermail/hotspot-runtime-dev/2020-June/040206.html
I am not aware of anyone who has found this timer inside class linking 
to be useful. Since you work in cloud services and also on class loading 
optimizations, if you happen to know someone who found good use of it, 
I'd be curious to know.


> It may produce misleading results with how
> archived classes are handled with this change.

The time collected today is already misleading. It counts the overhead 
of the timer more than the actual time spent inside the timer.

Thanks
- Ioi

> Thanks,
> Jiangli
>
> On Tue, Jun 16, 2020 at 1:48 PM Ioi Lam <ioi.lam at oracle.com> wrote:
>> https://bugs.openjdk.java.net/browse/JDK-8246019
>> http://cr.openjdk.java.net/~iklam/jdk16/8246019-avoid-PerfClassTraceTime.v01/
>>
>> PerfClassTraceTime is (a rarely used feature) for measuring the time
>> spent during class linking and initialization. However, it's quite
>> expensive and it needs to start and stop a bunch of timers. With CDS,
>> it's quite often for the overhead of the timer itself to be much more
>> than the time it's trying to measure, giving unreliable measurement.
>>
>> In this patch, when it's clear that the init and linking will be very
>> quick, I disable the timer and count only the number of invocations.
>> This shows a small improvement in start-up
>>
>> Results of " perf stat -r 100 bin/java -Xshare:on
>> -XX:SharedArchiveFile=jdk2.jsa -Xint -version "
>>
>> 59623970 59341935 (-282035)   -----  41.774  41.591 ( -0.183) -
>> 59623495 59331646 (-291849)   -----  41.696  41.165 ( -0.531) --
>> 59627148 59329526 (-297622)   -----  41.249  41.094 ( -0.155) -
>> 59612439 59340760 (-271679)   ----   41.773  40.657 ( -1.116) -----
>> 59626438 59335681 (-290757)   -----  41.683  40.901 ( -0.782) ----
>> 59618436 59338953 (-279483)   -----  41.861  41.249 ( -0.612) ---
>> 59608782 59340173 (-268609)   ----   41.198  41.508 (  0.310) +
>> 59614612 59325177 (-289435)   -----  41.397  41.738 (  0.341) ++
>> 59615905 59344006 (-271899)   ----   41.921  40.969 ( -0.952) ----
>> 59635867 59333147 (-302720)   -----  41.491  40.836 ( -0.655) ---
>> ================================================
>> 59620708 59336100 (-284608)   -----  41.604  41.169 ( -0.434) --
>> instruction delta =      -284608    -0.4774%
>> time        delta =       -0.434 ms -1.0435%
>>
>> The number of PerfClassTraceTime's used is reduced from 564 to 116 (so
>> we have an overhead of about 715 instructions per use, yikes!).