RFR(xs): 8186465: Each j.l.Reference elapsed time log is incorrect

[sangheon.kim]

Hi Stefan,

Thank you for the review!

On 08/23/2017 02:08 PM, Stefan Karlsson wrote:
> Hi Sangheon,
>
> On 2017-08-23 23:04, sangheon.kim wrote:
>> Hi all,
>>
>> Could I have some reviews for this tiny fix?
>> The problem is each j.l.References has wrong time log as related 
>> function is using wrong variable.
>> Actually it should be using '_ref_proc_time_ms' but accidentally 
>> using '_par_phase_time_ms'. Setter is using correct one but getter is 
>> referring wrong one.
>>
>> CR: https://bugs.openjdk.java.net/browse/JDK-8186465
>> webrev: http://cr.openjdk.java.net/~sangheki/8186465/webrev.0/
>> Testing: manually checked log values
>
> Looks good, but I think you should add a regression test for this. 
> Maybe the test could at least verify that the sub-phases are not 
> larger than the enclosing phase?
Sure, done!

Added a new sub-test in TestPrintReferences.java to see:
1. Reference Processing time >= Soft + Weak + Final + Phantom Reference 
processing time
2. Each References >= phase 1(for Soft) + phase 2 + phase 3

webrev: http://cr.openjdk.java.net/~sangheki/8186465/webrev.0/
Testing: JPRT, manual test to see sub-phases are not larger than the 
enclosing phase.

FYI, from my local run:
Reference Processing: 115.6ms > 115.5 + 0 + 0 + 0
    SoftReference: 115.5ms > 115.4 (36.5 + 37.2 + 41.7)
      Phase1: 36.5ms
      Phase2: 37.2ms
      Phase3: 41.7ms
      Discovered: 459095
      Cleared: 0
    WeakReference: 0.0ms
      Phase2: 0.0ms
      Phase3: 0.0ms
      Discovered: 0
      Cleared: 0
   FinalReference: 0.0ms
      Phase2: 0.0ms
      Phase3: 0.0ms
      Discovered: 1
      Cleared: 1
    PhantomReference: 0.0ms
      Phase2: 0.0ms
      Phase3: 0.0ms
      Discovered: 0
      Cleared: 0

Thanks,
Sangheon


>
> Thanks,
> StefanK
>
>>
>> Thanks,
>> Sangheon
>
>