Unable to parse G1 log with -XX:+PrintAdaptiveSizePolicy -XX:+PrintReferenceGC

[haridsv]

Here is a sample JVM log:

2013-09-11T00:20:09.714+0000: 4953.111: [GC pause (young) 4953.111: [G1Ergonomics (CSet Construction) start choosing CSet, predicted base time: 65.07 ms, remaining time: 184.93 ms, target pause time: 250.00 ms]
 4953.111: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 860 regions, survivors: 24 regions, predicted young region time: 41.41 ms]
 4953.111: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 860 regions, survivors: 24 regions, old: 0 regions, predicted pause time: 106.48 ms, target pause time: 250.00 ms]
4953.172: [SoftReference, 0 refs, 0.0000050 secs]4953.172: [WeakReference, 113 refs, 0.0000280 secs]4953.172: [FinalReference, 427 refs, 0.0003110 secs]4953.173: [PhantomReference, 0 refs, 0.0000020 secs]4953.173: [JNI Weak Reference, 0.0000040 secs], 0.06735500 secs]
   [Parallel Time:  59.2 ms]
      [GC Worker Start (ms):  4953111.9  4953112.0  4953112.0  4953112.0  4953112.1  4953112.1  4953112.1  4953112.2  4953112.2  4953112.2  4953112.2  4953112.3  4953112.3  4953112.3  4953112.3  4953112.3  4953112.3  4953112.4
       Avg: 4953112.2, Min: 4953111.9, Max: 4953112.4, Diff:   0.4]
      [Ext Root Scanning (ms):  10.3  9.9  10.0  10.2  18.0  9.8  10.6  10.0  9.7  10.3  9.8  10.2  9.6  9.4  15.8  9.6  10.1  11.5
       Avg:  10.8, Min:   9.4, Max:  18.0, Diff:   8.6]
      [Update RS (ms):  29.1  29.4  29.5  29.2  22.0  29.4  28.7  29.4  29.4  28.9  29.4  29.1  29.6  30.5  22.7  29.6  29.2  27.3
       Avg:  28.5, Min:  22.0, Max:  30.5, Diff:   8.5]
         [Processed Buffers : 64 53 51 50 36 50 61 49 65 65 51 47 51 57 46 49 49 55
          Sum: 949, Avg: 52, Min: 36, Max: 65, Diff: 29]
      [Scan RS (ms):  0.9  1.0  0.8  0.8  0.9  0.9  0.8  0.8  0.9  0.9  1.0  0.8  0.9  0.2  0.7  1.0  0.6  0.5
       Avg:   0.8, Min:   0.2, Max:   1.0, Diff:   0.8]
      [Object Copy (ms):  6.9  6.9  7.0  7.1  6.2  7.0  6.9  6.9  7.0  6.9  6.8  6.8  6.8  6.8  7.7  6.7  6.9  7.5
       Avg:   6.9, Min:   6.2, Max:   7.7, Diff:   1.5]
      [Termination (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0, Diff:   0.0]
         [Termination Attempts : 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1
          Sum: 18, Avg: 1, Min: 1, Max: 1, Diff: 0]
      [GC Worker End (ms):  4953159.5  4953159.3  4953159.2  4953159.3  4953159.5  4953159.4  4953159.5  4953159.5  4953159.2  4953159.5  4953159.4  4953159.4  4953159.3  4953159.3  4953159.3  4953159.3  4953159.3  4953159.5
       Avg: 4953159.4, Min: 4953159.2, Max: 4953159.5, Diff:   0.3]
      [GC Worker (ms):  47.6  47.3  47.3  47.3  47.4  47.2  47.4  47.3  47.0  47.3  47.1  47.1  47.0  47.0  47.0  46.9  47.0  47.1
       Avg:  47.2, Min:  46.9, Max:  47.6, Diff:   0.6]
      [GC Worker Other (ms):  11.9  11.9  12.0  12.0  12.0  12.1  12.1  12.1  12.2  12.2  12.2  12.2  12.2  12.2  12.3  12.3  12.3  12.3
       Avg:  12.1, Min:  11.9, Max:  12.3, Diff:   0.4]
   [Clear CT:   0.9 ms]
   [Other:   7.3 ms]
      [Choose CSet:   0.1 ms]
      [Ref Proc:   1.7 ms]
      [Ref Enq:   0.0 ms]
      [Free CSet:   4.7 ms]
   [Eden: 1720M(2360M)->0B(2186M) Survivors: 48M->24M Heap: 3792M(4900M)->2050M(4900M)]
 [Times: user=0.88 sys=0.01, real=0.07 secs]

And here is the GCViewer log:

Sep 12, 2013 3:39:53 PM com.tagtraum.perf.gcviewer.imp.DataReaderFacade loadModel
INFO: GCViewer version 1.33-SNAPSHOT (2013-09-12T02:07:47-0700)
Sep 12, 2013 3:39:54 PM com.tagtraum.perf.gcviewer.imp.DataReaderFactory getDataReaderBySample
INFO: File format: Sun 1.6.x G1 collector
Sep 12, 2013 3:39:54 PM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0G1 read
INFO: Reading Sun 1.6.x / 1.7.x G1 format...
Sep 12, 2013 3:39:54 PM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0G1 read
WARNING: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'SoftReference' Line 4: 2013-09-11T00:20:09.714+0000: 4953.111: [GC pause (young)4953.172: [SoftReference, 0 refs, 0.0000050 secs]4953.172: [WeakReference, 113 refs, 0.0000280 secs]4953.172: [FinalReference, 427 refs, 0.0003110 secs]4953.173: [PhantomReference, 0 refs, 0.0000020 secs]4953.173: [JNI Weak Reference, 0.0000040 secs], 0.06735500 secs]
Sep 12, 2013 3:39:54 PM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0G1 read
WARNING: com.tagtraum.perf.gcviewer.imp.ParseException: java.lang.NumberFormatException: For input string: "[Parallel Time" Line 5:    [Parallel Time:  59.2 ms]
Sep 12, 2013 3:39:54 PM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0G1 read
WARNING: com.tagtraum.perf.gcviewer.imp.ParseException: java.lang.NumberFormatException: For input string: "[GC Worker Start (ms)" Line 6:       [GC Worker Start (ms):  4953111.9  4953112.0  4953112.0  4953112.0  4953112.1  4953112.1  4953112.1  4953112.2  4953112.2  4953112.2  4953112.2  4953112.3  4953112.3  4953112.3  4953112.3  4953112.3  4953112.3  4953112.4
Sep 12, 2013 3:39:54 PM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0G1 read
WARNING: com.tagtraum.perf.gcviewer.imp.ParseException: java.lang.NumberFormatException: For input string: "Avg" Line 7:        Avg: 4953112.2, Min: 4953111.9, Max: 4953112.4, Diff:   0.4]
Sep 12, 2013 3:39:54 PM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0G1 read
WARNING: com.tagtraum.perf.gcviewer.imp.ParseException: java.lang.NumberFormatException: For input string: "[Ext Root Scanning (ms)" Line 8:       [Ext Root Scanning (ms):  10.3  9.9  10.0  10.2  18.0  9.8  10.6  10.0  9.7  10.3  9.8  10.2  9.6  9.4  15.8  9.6  10.1  11.5
Sep 12, 2013 3:39:54 PM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0G1 read
WARNING: com.tagtraum.perf.gcviewer.imp.ParseException: java.lang.NumberFormatException: For input string: "Avg" Line 9:        Avg:  10.8, Min:   9.4, Max:  18.0, Diff:   8.6]
Sep 12, 2013 3:39:54 PM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0G1 read
WARNING: com.tagtraum.perf.gcviewer.imp.ParseException: java.lang.NumberFormatException: For input string: "[Update RS (ms)" Line 10:       [Update RS (ms):  29.1  29.4  29.5  29.2  22.0  29.4  28.7  29.4  29.4  28.9  29.4  29.1  29.6  30.5  22.7  29.6  29.2  27.3
Sep 12, 2013 3:39:54 PM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0G1 read
WARNING: com.tagtraum.perf.gcviewer.imp.ParseException: java.lang.NumberFormatException: For input string: "Avg" Line 11:        Avg:  28.5, Min:  22.0, Max:  30.5, Diff:   8.5]
Sep 12, 2013 3:39:54 PM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0G1 read
WARNING: com.tagtraum.perf.gcviewer.imp.ParseException: java.lang.NumberFormatException: For input string: "[Processed Buffers" Line 12:          [Processed Buffers : 64 53 51 50 36 50 61 49 65 65 51 47 51 57 46 49 49 55
Sep 12, 2013 3:39:54 PM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0G1 read
WARNING: com.tagtraum.perf.gcviewer.imp.ParseException: java.lang.NumberFormatException: For input string: "Sum" Line 13:           Sum: 949, Avg: 52, Min: 36, Max: 65, Diff: 29]
Sep 12, 2013 3:39:54 PM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0G1 read
WARNING: com.tagtraum.perf.gcviewer.imp.ParseException: java.lang.NumberFormatException: For input string: "[Scan RS (ms)" Line 14:       [Scan RS (ms):  0.9  1.0  0.8  0.8  0.9  0.9  0.8  0.8  0.9  0.9  1.0  0.8  0.9  0.2  0.7  1.0  0.6  0.5
Sep 12, 2013 3:39:54 PM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0G1 read
WARNING: com.tagtraum.perf.gcviewer.imp.ParseException: java.lang.NumberFormatException: For input string: "Avg" Line 15:        Avg:   0.8, Min:   0.2, Max:   1.0, Diff:   0.8]
Sep 12, 2013 3:39:54 PM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0G1 read
WARNING: com.tagtraum.perf.gcviewer.imp.ParseException: java.lang.NumberFormatException: For input string: "[Object Copy (ms)" Line 16:       [Object Copy (ms):  6.9  6.9  7.0  7.1  6.2  7.0  6.9  6.9  7.0  6.9  6.8  6.8  6.8  6.8  7.7  6.7  6.9  7.5
Sep 12, 2013 3:39:54 PM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0G1 read
WARNING: com.tagtraum.perf.gcviewer.imp.ParseException: java.lang.NumberFormatException: For input string: "Avg" Line 17:        Avg:   6.9, Min:   6.2, Max:   7.7, Diff:   1.5]
Sep 12, 2013 3:39:54 PM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0G1 read
WARNING: com.tagtraum.perf.gcviewer.imp.ParseException: java.lang.NumberFormatException: For input string: "[Termination (ms)" Line 18:       [Termination (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
Sep 12, 2013 3:39:54 PM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0G1 read
WARNING: com.tagtraum.perf.gcviewer.imp.ParseException: java.lang.NumberFormatException: For input string: "Avg" Line 19:        Avg:   0.0, Min:   0.0, Max:   0.0, Diff:   0.0]
Sep 12, 2013 3:39:54 PM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0G1 read
WARNING: com.tagtraum.perf.gcviewer.imp.ParseException: java.lang.NumberFormatException: For input string: "[Termination Attempts" Line 20:          [Termination Attempts : 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1
Sep 12, 2013 3:39:54 PM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0G1 read
WARNING: com.tagtraum.perf.gcviewer.imp.ParseException: java.lang.NumberFormatException: For input string: "Sum" Line 21:           Sum: 18, Avg: 1, Min: 1, Max: 1, Diff: 0]
Sep 12, 2013 3:39:54 PM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0G1 read
WARNING: com.tagtraum.perf.gcviewer.imp.ParseException: java.lang.NumberFormatException: For input string: "[GC Worker End (ms)" Line 22:       [GC Worker End (ms):  4953159.5  4953159.3  4953159.2  4953159.3  4953159.5  4953159.4  4953159.5  4953159.5  4953159.2  4953159.5  4953159.4  4953159.4  4953159.3  4953159.3  4953159.3  4953159.3  4953159.3  4953159.5
Sep 12, 2013 3:39:54 PM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0G1 read
WARNING: com.tagtraum.perf.gcviewer.imp.ParseException: java.lang.NumberFormatException: For input string: "Avg" Line 23:        Avg: 4953159.4, Min: 4953159.2, Max: 4953159.5, Diff:   0.3]
Sep 12, 2013 3:39:54 PM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0G1 read
WARNING: com.tagtraum.perf.gcviewer.imp.ParseException: java.lang.NumberFormatException: For input string: "[GC Worker (ms)" Line 24:       [GC Worker (ms):  47.6  47.3  47.3  47.3  47.4  47.2  47.4  47.3  47.0  47.3  47.1  47.1  47.0  47.0  47.0  46.9  47.0  47.1
Sep 12, 2013 3:39:54 PM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0G1 read
WARNING: com.tagtraum.perf.gcviewer.imp.ParseException: java.lang.NumberFormatException: For input string: "Avg" Line 25:        Avg:  47.2, Min:  46.9, Max:  47.6, Diff:   0.6]
Sep 12, 2013 3:39:54 PM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0G1 read
WARNING: com.tagtraum.perf.gcviewer.imp.ParseException: java.lang.NumberFormatException: For input string: "[GC Worker Other (ms)" Line 26:       [GC Worker Other (ms):  11.9  11.9  12.0  12.0  12.0  12.1  12.1  12.1  12.2  12.2  12.2  12.2  12.2  12.2  12.3  12.3  12.3  12.3
Sep 12, 2013 3:39:54 PM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0G1 read
WARNING: com.tagtraum.perf.gcviewer.imp.ParseException: java.lang.NumberFormatException: For input string: "Avg" Line 27:        Avg:  12.1, Min:  11.9, Max:  12.3, Diff:   0.4]
Sep 12, 2013 3:39:54 PM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0G1 read
WARNING: com.tagtraum.perf.gcviewer.imp.ParseException: java.lang.NumberFormatException: For input string: "[Clear CT" Line 28:    [Clear CT:   0.9 ms]
Sep 12, 2013 3:39:54 PM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0G1 read
WARNING: com.tagtraum.perf.gcviewer.imp.ParseException: java.lang.NumberFormatException: For input string: "[Other" Line 29:    [Other:   7.3 ms]
Sep 12, 2013 3:39:54 PM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0G1 read
WARNING: com.tagtraum.perf.gcviewer.imp.ParseException: java.lang.NumberFormatException: For input string: "[Choose CSet" Line 30:       [Choose CSet:   0.1 ms]
Sep 12, 2013 3:39:54 PM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0G1 read
WARNING: com.tagtraum.perf.gcviewer.imp.ParseException: java.lang.NumberFormatException: For input string: "[Ref Proc" Line 31:       [Ref Proc:   1.7 ms]
Sep 12, 2013 3:39:54 PM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0G1 read
WARNING: com.tagtraum.perf.gcviewer.imp.ParseException: java.lang.NumberFormatException: For input string: "[Ref Enq" Line 32:       [Ref Enq:   0.0 ms]
Sep 12, 2013 3:39:54 PM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0G1 read
WARNING: com.tagtraum.perf.gcviewer.imp.ParseException: java.lang.NumberFormatException: For input string: "[Free CSet" Line 33:       [Free CSet:   4.7 ms]
Sep 12, 2013 3:39:54 PM com.tagtraum.perf.gcviewer.imp.DataReaderSun1_6_0G1 read
INFO: Done reading.

[chewiebug]

Hi Hari,

The sample you posted above now can be parsed by GCViewer. Parsing of real logs with G1, -XX:+PrintAdaptiveSIzePolicy and -XX:+PrintReferenceGC will most probably still throw some errors but much less than before. GCViewer is not able to cope with all the "garbage" that the G1 logger outputs (especially stop-the-world events mixed with concurrent events).

Is this usable for you?

Regards, Jörg

[haridsv]

Sorry about the late response. I just updated my local repo and verified that the parsing errors are gone. I can verify that the pause, total heap, young heap and promotion numbers are correct. However, it is not clear where the tenured numbers come from as can be seen here:

Could you please explain?

[chewiebug]

Hi Hari,

Thank you for testing!

Tenured numbers are calculated if they are not explicitly present in a
log file. For G1 tenured is total heap size - (eden + survivors).

Means for your example:

[Eden: 1720M(2360M)->0B(2186M) Survivors: 48M->24M Heap: 3792M(4900M)->2050M(4900M)]

Young = Eden + Survivors = 2186 + 24 = 2210M
Tenured = Heap - Young = 4900 - 2210 = 2690M

Best regards, Jörg

[chewiebug]

Hi Hari,

I close this issue, since I believe that it works now as it should. If you disagree, please reopen the issue. Thank you for reporting this issue.

Regards, Jörg