Parsing problem with G1 and PrintGCDateStamps

[adfaedv]

When using G1 with the PrintGCDateStamps an parsing error occures. Using the default option with time since JVM restart everything works fine.

Errorlog:
INFO [DataReaderFacade]: GCViewer version 1.32-SNAPSHOT (2012-12-09 16:40)
INFO [DataReaderFactory]: File format: Sun 1.6.x G1 collector
INFO [DataReaderSun1_6_0G1]: Reading Sun 1.6.x / 1.7.x G1 format...
WARNING [DataReaderSun1_6_0G1]: com.tagtraum.perf.gcviewer.imp.ParseException: Error parsing entry. Line 1: 2013-01-17T13:40:06.537+0000: [GC pause (young), 0.01019300 secs]
WARNING [DataReaderSun1_6_0G1]: com.tagtraum.perf.gcviewer.imp.ParseException: java.lang.NumberFormatException: For input string: "[Parallel Time" Line 2: [Parallel Time: 9.3 ms]
...

Example:
2013-01-17T13:40:06.537+0000: [GC pause (young), 0.01019300 secs]
[Parallel Time: 9.3 ms]
[GC Worker Start Time (ms): 1375.6 1375.7 1379.8 1379.8 1379.9 1379.9 1380.0 1380.0
Avg: 1378.8, Min: 1375.6, Max: 1380.0, Diff: 4.4]
[Update RS (ms): 0.3 0.1 0.3 0.5 0.6 1.4 0.2 0.5
Avg: 0.5, Min: 0.1, Max: 1.4, Diff: 1.4]
[Processed Buffers : 1 1 3 1 2 1 1 3
Sum: 13, Avg: 1, Min: 1, Max: 3, Diff: 2]
[Ext Root Scanning (ms): 4.9 5.9 1.2 1.2 1.0 1.0 1.3 1.1
Avg: 2.2, Min: 1.0, Max: 5.9, Diff: 4.9]
[Mark Stack Scanning (ms): 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]
[Scan RS (ms): 0.2 0.5 0.3 0.2 0.4 0.0 0.4 0.2
Avg: 0.3, Min: 0.0, Max: 0.5, Diff: 0.5]
[Object Copy (ms): 3.3 2.3 2.8 2.6 2.5 2.0 2.5 2.6
Avg: 2.6, Min: 2.0, Max: 3.3, Diff: 1.3]
[Termination (ms): 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 2 1 2 2 3 1
Sum: 13, Avg: 1, Min: 1, Max: 3, Diff: 2]
[GC Worker End Time (ms): 1384.4 1384.4 1384.4 1384.4 1384.4 1384.4 1384.4 1384.4
Avg: 1384.4, Min: 1384.4, Max: 1384.4, Diff: 0.0]
[GC Worker Times (ms): 8.8 8.7 4.6 4.6 4.5 4.5 4.4 4.4
Avg: 5.6, Min: 4.4, Max: 8.8, Diff: 4.4]
[Other: 3.8 ms]
[Clear CT: 0.7 ms]
[Other: 0.2 ms]
[Choose CSet: 0.0 ms]
[ 11M->7217K(5120M)]
[Times: user=0.04 sys=0.01, real=0.01 secs]

Example which works:
0.522: [GC pause (young), 0.00891500 secs]
[Parallel Time: 8.0 ms]
[GC Worker Start Time (ms): 1703.7 1703.8 1703.8 1703.8 1703.9 1704.0 1704.0 1704.0
Avg: 1703.9, Min: 1703.7, Max: 1704.0, Diff: 0.3]
[Update RS (ms): 1.0 0.7 1.0 0.6 0.9 0.9 1.1 0.8
Avg: 0.8, Min: 0.6, Max: 1.1, Diff: 0.5]
[Processed Buffers : 2 1 2 1 2 2 2 2
Sum: 14, Avg: 1, Min: 1, Max: 2, Diff: 1]
[Ext Root Scanning (ms): 1.3 1.6 0.8 1.4 1.1 1.0 1.0 1.0
Avg: 1.1, Min: 0.8, Max: 1.6, Diff: 0.8]
[Mark Stack Scanning (ms): 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]
[Scan RS (ms): 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]
[Object Copy (ms): 2.2 1.0 1.5 4.1 1.3 1.3 1.0 1.3
Avg: 1.7, Min: 1.0, Max: 4.1, Diff: 3.0]
[Termination (ms): 1.9 2.9 2.9 0.0 2.9 2.9 2.9 4.1
Avg: 2.5, Min: 0.0, Max: 4.1, Diff: 4.1]
[Termination Attempts : 1 1 1 1 2 1 2 2
Sum: 11, Avg: 1, Min: 1, Max: 2, Diff: 1]
[GC Worker End Time (ms): 1710.0 1710.0 1710.0 1710.0 1710.0 1710.0 1710.0 1711.2
Avg: 1710.1, Min: 1710.0, Max: 1711.2, Diff: 1.3]
[GC Worker Times (ms): 6.3 6.2 6.2 6.1 6.1 6.0 6.0 7.2
Avg: 6.3, Min: 6.0, Max: 7.2, Diff: 1.2]
[Other: 1.8 ms]
[Clear CT: 0.7 ms]
[Other: 0.2 ms]
[Choose CSet: 0.0 ms]
[ 27M->8564K(5120M)]
[Times: user=0.03 sys=0.02, real=0.01 secs]

[chewiebug]

Hmm, this shouldn't fail. What's the exact version of java that you are using?

Regards, Jörg

 -------- Original-Nachricht --------
 Datum: Tue, 22 Jan 2013 09:36:17 -0800
 Von: adfaedv notifications@github.com
 An: chewiebug/GCViewer GCViewer@noreply.github.com
 Betreff: [GCViewer] Parsing problem with G1 and PrintGCDateStamps (#51)
 &#xA

[adfaedv]

Hi Jörg,
Java version is:
java version "1.7.0"
Java(TM) SE Runtime Environment (build 1.7.0-b147)
Java HotSpot(TM) 64-Bit Server VM (build 21.0-b17, mixed mode)

and the Java options are
-XX:+PrintGCDetails -XX:+PrintGCDateStamps

As sad - if I replace the date stamps e.g. "2013-01-17T13:40:06.537+0000" with time since restart e.g. "0.522" everything works fine so I suppose it's a timestamp parsing problem?

Cheers,
Daniel

[chewiebug]

Hi Daniel,

Thank you for the jdk version - are you using a very early version of
1.7? Usually I see something like "1.7.0_11".

Yes, it is a timestamp parsing problem, I have been able to reproduce
the problem using
-XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:-PrintGCTimeStamps
(explicitly omitting timestamps).

That is not supported yet. It works if you have -XX:+PrintGCDateStamps
-XX:+PrintGCTimeStamps (both stamps). I considered this low priority
because -XX:+PrintGCTimeStamps is the default setting.

Regards, Jörg

[chewiebug]

This ssue should be fixed now (commit a87d4d). Latest SNAPSHOT contains the change.

Regards, Jörg