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)];
}
[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)];
}
- duplicates
-
JDK-8186465 Each j.l.Reference elapsed time log is incorrect
- Resolved