JDK-8186673 : ReferenceProcessing logging is broken
  • Type: Bug
  • Component: hotspot
  • Sub-Component: gc
  • Priority: P4
  • Status: Closed
  • Resolution: Duplicate
  • Submitted: 2017-08-23
  • Updated: 2017-08-23
  • Resolved: 2017-08-23
Related Reports
Duplicate :  
Description
See the following output:
[10,209s][debug][gc,phases,ref] GC(23)     Reference Processing: 10,2ms
[10,209s][debug][gc,phases,ref] GC(23)       SoftReference: 0,1ms
[10,209s][debug][gc,phases,ref] GC(23)         Balance queues: 0,0ms
[10,209s][debug][gc,phases,ref] GC(23)         Phase1: 0,1ms
[10,209s][trace][gc,phases,ref] GC(23)           Process lists (ms)        Min:  0,0, Avg:  0,0, Max:  0,0, Diff:  0,0, Sum:  0,0, Workers: 2
[10,209s][debug][gc,phases,ref] GC(23)         Phase2: 0,1ms
[10,209s][trace][gc,phases,ref] GC(23)           Process lists (ms)        Min:  0,0, Avg:  0,0, Max:  0,0, Diff:  0,0, Sum:  0,0, Workers: 2
[10,209s][debug][gc,phases,ref] GC(23)         Phase3: 0,1ms
[10,209s][trace][gc,phases,ref] GC(23)           Process lists (ms)        Min:  0,0, Avg:  0,0, Max:  0,0, Diff:  0,0, Sum:  0,0, Workers: 2
[10,209s][debug][gc,phases,ref] GC(23)         Discovered: 0
[10,209s][debug][gc,phases,ref] GC(23)         Cleared: 0
[10,209s][debug][gc,phases,ref] GC(23)       WeakReference: 0,1ms
[10,209s][debug][gc,phases,ref] GC(23)         Balance queues: 0,0ms
[10,209s][debug][gc,phases,ref] GC(23)         Phase2: 5,9ms
[10,209s][trace][gc,phases,ref] GC(23)           Process lists (ms)        Min:  5,8, Avg:  5,8, Max:  5,8, Diff:  0,1, Sum: 11,6, Workers: 2
[10,209s][debug][gc,phases,ref] GC(23)         Phase3: 3,4ms
[10,209s][trace][gc,phases,ref] GC(23)           Process lists (ms)        Min:  3,2, Avg:  3,3, Max:  3,3, Diff:  0,0, Sum:  6,5, Workers: 2
[10,209s][debug][gc,phases,ref] GC(23)         Discovered: 1000000
[10,209s][debug][gc,phases,ref] GC(23)         Cleared: 0
[10,209s][debug][gc,phases,ref] GC(23)       FinalReference: 0,1ms
[10,209s][debug][gc,phases,ref] GC(23)         Balance queues: 0,0ms
[10,209s][debug][gc,phases,ref] GC(23)         Phase2: 0,1ms
[10,209s][trace][gc,phases,ref] GC(23)           Process lists (ms)        Min:  0,0, Avg:  0,0, Max:  0,0, Diff:  0,0, Sum:  0,0, Workers: 2
[10,209s][debug][gc,phases,ref] GC(23)         Phase3: 0,1ms
[10,209s][trace][gc,phases,ref] GC(23)           Process lists (ms)        Min:  0,0, Avg:  0,0, Max:  0,0, Diff:  0,0, Sum:  0,0, Workers: 2
[10,209s][debug][gc,phases,ref] GC(23)         Discovered: 0
[10,209s][debug][gc,phases,ref] GC(23)         Cleared: 0
[10,209s][debug][gc,phases,ref] GC(23)       PhantomReference: 5,9ms
[10,209s][debug][gc,phases,ref] GC(23)         Balance queues: 0,0ms
[10,209s][debug][gc,phases,ref] GC(23)         Phase2: 0,1ms
[10,209s][trace][gc,phases,ref] GC(23)           Process lists (ms)        Min:  0,0, Avg:  0,0, Max:  0,0, Diff:  0,0, Sum:  0,0, Workers: 2
[10,209s][debug][gc,phases,ref] GC(23)         Phase3: 0,1ms
[10,210s][trace][gc,phases,ref] GC(23)           Process lists (ms)        Min:  0,0, Avg:  0,0, Max:  0,0, Diff:  0,0, Sum:  0,0, Workers: 2
[10,210s][debug][gc,phases,ref] GC(23)         Discovered: 0
[10,210s][debug][gc,phases,ref] GC(23)         Cleared: 0
[10,210s][debug][gc,phases,ref] GC(23)     Reference Enqueuing: 5,2ms
[10,210s][debug][gc,phases,ref] GC(23)       Reference Counts:  Soft: 0  Weak: 1000000  Final: 0  Phantom: 0

The entire WeakReference phase is shorter than it's Phase2 sub-phase:
[10,209s][debug][gc,phases,ref] GC(23)       WeakReference: 0,1ms
[10,209s][debug][gc,phases,ref] GC(23)         Balance queues: 0,0ms
[10,209s][debug][gc,phases,ref] GC(23)         Phase2: 5,9ms

and the PhantomReference phase reports similar values to WeakReference:Phase2:
[10,209s][debug][gc,phases,ref] GC(23)       PhantomReference: 5,9ms

The bug seems to be in:
double ReferenceProcessorPhaseTimes::ref_proc_time_ms(ReferenceType ref_type) const {
  ASSERT_REF_TYPE(ref_type);
  return _par_phase_time_ms[ref_type_2_index(ref_type)];
}

Where _par_phase_time_ms is used instead of _ref_proc_time_ms. 

The code should probably read:
double ReferenceProcessorPhaseTimes::ref_proc_time_ms(ReferenceType ref_type) const {
  ASSERT_REF_TYPE(ref_type);
  return _ref_proc_time_ms[ref_type_2_index(ref_type)];
}