Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-8186673

ReferenceProcessing logging is broken

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Duplicate
    • Icon: P4 P4
    • None
    • None
    • hotspot
    • None
    • gc

      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)];
      }

            Unassigned Unassigned
            stefank Stefan Karlsson
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Created:
              Updated:
              Resolved: