Parse errors when log level is set to finest

[steinybot]

I was trying to parse some GC logs that were made in an older version of Java 7:

> java -version
java version "1.7.0_21"
Java(TM) SE Runtime Environment (build 1.7.0_21-b11)
Java HotSpot(TM) 64-Bit Server VM (build 23.21-b01, mixed mode)

Using the following options:

-XX:+PrintGCTimeStamps
-XX:+PrintGCDetails
-Xloggc:log/gc.log

This contained entries like:

INFO   | jvm 1    | 2015/05/03 16:12:38 | 357996.729: [GC pause (mixed), 0.23787900 secs]
INFO   | jvm 1    | 2015/05/03 16:12:38 |    [Parallel Time: 143.7 ms]
INFO   | jvm 1    | 2015/05/03 16:12:38 |       [GC Worker Start (ms):  357996730.7  357996730.8  357996730.8  357996730.8
INFO   | jvm 1    | 2015/05/03 16:12:38 |        Avg: 357996730.8, Min: 357996730.7, Max: 357996730.8, Diff:   0.2]

GCViewer fails to parse these as it doesn't seem to understand the information for individual worker threads.

I also tried the same options on a later Java 7 version:

> java -version
java version "1.8.0_45"
Java(TM) SE Runtime Environment (build 1.8.0_45-b15)
Java HotSpot(TM) 64-Bit Server VM (build 25.45-b02, mixed mode)

This doesn't have the information for individual worker threads (but there are other problems which I'll raise separately).

I think I have tracked down the difference to the -XX:G1LogLevel option. Even though I haven't set this option I eventually found some description on http://www.oracle.com/technetwork/tutorials/tutorials-1876574.html. According to that, setting the -XX:+PrintGCDetails option should set the log level to finer. For some reason the log level in the previous version was finest.

So this is a request to support the finest log level. I actually don't care about the individual worker threads I just want to be able to load the log file. I am currently combining the lines together and it seems to ignore the individual worker thread information.

[ecki]

Just to make sure, the INFO jvm1...| part is not usually contained in a gc log file. This looks more like a stdout dump. You are not feeding those to gcviewer, right?

Can you somewhere provide a reasonable long sample log file for download to have a look at.

[steinybot]

I haven't gotten around to making actual tests but I have created a fork that includes two large test files (https://github.com/Steiny69/GCViewer/commit/67d968983bf153409199a1c10c9c1819a5125a3a).

There are two files in there:

1. SampleOracle1_7_0PrintGCDetails.txt - This is what the logs contained with the INFO | jvm 1 | ... parts removed
2. SampleOracle1_7_0PrintGCDetails_NoSplit.txt - This is the same as the other but I have removed the new lines between entries that were split. The split seems to occur between the individual worker thread times and the aggregated times.

GCViewer still throws a bunch of errors when loading SampleOracle1_7_0PrintGCDetails_NoSplit.txt:

WARNING [DataReaderSun1_6_0G1]: com.tagtraum.perf.gcviewer.imp.ParseException: java.lang.StringIndexOutOfBoundsException: String index out of range: 69 Line 67064: 1034124.147: [GC pause (young)1034124.159: [GC concurrent-mark-start]
WARNING [DataReaderSun1_6_0G1]: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'Termination Attempts' Line 67075:          [Termination Attempts : 1 1 1 1 Sum: 4, Avg: 1, Min: 1, Max: 1, Diff: 0]
WARNING [DataReaderSun1_6_0G1]: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'Complete CSet Marking' Line 67079:    [Complete CSet Marking:   0.0 ms]

I was going to raise this separately but may as well add those details here since I have included the files to reproduce. It may be related to the way I removed the new lines so may not be a real issue.

[steinybot]

No I'm not loading those into GCViewer. All the other stats get parsed
fine. Sorry I forgot to strip those out before posting.
On 7/06/2015 5:59 am, "Bernd" notifications@github.com wrote:

Just to make sure, the INFO jvm1...| part is not usually contained in a
gc log file. This looks more like a stdout dump. You are not feeding those
to gcviewer, right?

Can you somewhere provide a reasonable long sample log file for download
to have a look at.

—
Reply to this email directly or view it on GitHub
#137 (comment).

[chewiebug]

Hi Steiny,

I have analysed the two samples you provided and played aroud a little bit with -XX:G1LogLevel=finest. In general, GCViewer parses those logs fine. There are a few situations, GCViewer can't handle, but they are not related to your loglevel. They are caused by events, that are mixed in the log.

Your log warning in SampleOracle1_8_0PrintGCDetails_NoSplit.txt contains good example of those (the one you refer to above). In the logfile you find (starting with line 67063):

1034124.147: [GC pause (young)1034124.159: [GC concurrent-root-region-scan-end, 0.0137120]
1034124.159: [GC concurrent-mark-start]
   [Root Region Scan Waiting:  11.7 ms]

The first line contains the beginning of a "GC pause (young)" event. Starting with the second timestamp, it is interrupted by a concurrent event (GC concurrent-root-region-scan-end). The next line (63064, where GCViewer complains) again contains a concurrent event, where GCViewer wound have expected the next line of "GC pause (young)", which only comes one line 63065.

GCViewer is able to handle the first mixed in concurrent event, but not the second. That's where it complains.

In the case of SampleOracle1_7_0PrintGCDetails.txt indeed the additional linebreaks in the middle of the Full GC events make GCViewer complain. The only other bunch of warnings, that is issued, is again the situation of the ...NoSplit.txt file.

There is only one small thing for this first file, I can improve - reduce the number of warnings, that are issued, when encoutering the mixed situation (filter the lines starting with "avg" and "Termination Attempts", and "Complete CSet Marking".

I'll do that eventually (mention it here). I won't do anything about the additional linebreaks in the middle of the Full GC events, because they are not part of a normal G1 log file.

Best regards,
Jörg