JDK1.6 parser cannot skip CMSStatistics=2 lines about gcviewer

[chewiebug]

Hi Bernd,

Could you please test my fix with one of your log files?

Regards, Jörg

[chewiebug]

bernds comment to the above commit

Hmm, it improved things and I have some of the log files which are not parsed with no errors, and I also see both CMS STW Events with the same count.

However I have one file which produces some warnings, here are the warnings produced:

WARNING [AbstractDataReaderSun]: unknown memoryunit '-' in line 2012-09-27T10:35:13.591-0800: [GC[YG occupancy: 10342869 K (15099520 K)]2012-09-27T10:35:13.644-0800: [CMS-concurrent-sweep: 0.013/0.029 secs] (CMS-concurrent-sweep yielded 6551 times)
WARNING [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.ParseException: Error parsing entry (java.lang.NumberFormatException: 2012-09-27T10:35:13.591-0800: [GC[YG occupancy: 10342869 K (15099520 K)]2012-09-27T10:35:13.644-0800: [CMS-concurrent-sweep: 0.013/0.029 secs] (CMS-concurrent-sweep yielded 6551 times)) Line 7: 2012-09-27T10:35:13.591-0800: [GC[YG occupancy: 10342869 K (15099520 K)]2012-09-27T10:35:13.644-0800: [CMS-concurrent-sweep: 0.013/0.029 secs] (CMS-concurrent-sweep yielded 6551 times)
WARNING [AbstractDataReaderSun]: unknown memoryunit '-' in line 2012-09-27T10:36:08.081-0800: [GC[YG occupancy: 3366851 K (15099520 K)]2012-09-27T10:36:08.360-0800: [CMS-concurrent-sweep: 0.075/0.077 secs] (CMS-concurrent-sweep yielded 29 times)
WARNING [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.ParseException: Error parsing entry (java.lang.NumberFormatException: 2012-09-27T10:36:08.081-0800: [GC[YG occupancy: 3366851 K (15099520 K)]2012-09-27T10:36:08.360-0800: [CMS-concurrent-sweep: 0.075/0.077 secs] (CMS-concurrent-sweep yielded 29 times)) Line 19: 2012-09-27T10:36:08.081-0800: [GC[YG occupancy: 3366851 K (15099520 K)]2012-09-27T10:36:08.360-0800: [CMS-concurrent-sweep: 0.075/0.077 secs] (CMS-concurrent-sweep yielded 29 times)
INFO [DataReaderSun1_6_0]: Done reading.

and here are parsed gc log lines:

2012-09-27T10:35:13.250-0800: [GC [ParNew: 1073746K->8056K(15099520K), 0.0198690 secs] 1073746K->8056K(48653952K), 0.0200020 secs] [Times: user=0.13 sys=0.01, real=0.02 secs] 
2012-09-27T10:35:13.271-0800: [GC [1 CMS-initial-mark: 0K(33554432K)] 8056K(48653952K), 0.0093810 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2012-09-27T10:35:13.333-0800: [CMS-concurrent-mark: 0.025/0.053 secs] (CMS-concurrent-mark yielded 24 times)
2012-09-27T10:35:13.448-0800: [CMS-concurrent-preclean: 0.114/0.115 secs] (CMS-concurrent-preclean yielded 85 times)
 [1 iterations, 1 waits, 19 cards)] 2012-09-27T10:35:13.589-0800: [CMS-concurrent-abortable-preclean: 0.124/0.141 secs] (CMS-concurrent-abortable-preclean yielded 4273 times)
2012-09-27T10:35:13.591-0800: [GC[YG occupancy: 10342869 K (15099520 K)]2012-09-27T10:35:13.591-0800: [GC [ParNew: 10342869K->14005K(15099520K), 0.0122450 secs] 10342869K->14005K(48653952K), 0.0124520 secs] [Times: user=0.27 sys=0.01, real=0.01 secs] 
2012-09-27T10:35:13.644-0800: [CMS-concurrent-sweep: 0.013/0.029 secs] (CMS-concurrent-sweep yielded 6551 times)
2012-09-27T10:35:14.032-0800: [CMS-concurrent-reset: 0.386/0.388 secs] (CMS-concurrent-reset yielded 5 times)
2012-09-27T10:35:25.958-0800: [GC [ParNew: 13435829K->84502K(15099520K), 0.0303790 secs] 13435829K->84502K(48653952K), 0.0307270 secs] [Times: user=0.66 sys=0.18, real=0.03 secs] 
2012-09-27T10:35:32.961-0800: [GC [ParNew: 13505917K->170281K(15099520K), 0.0469210 secs] 13505917K->170281K(48653952K), 0.0473510 secs] [Times: user=1.50 sys=0.43, real=0.05 secs] 
2012-09-27T10:35:41.126-0800: [GC [ParNew: 13592105K->255293K(15099520K), 0.1072250 secs] 13592105K->263521K(48653952K), 0.1077610 secs] [Times: user=1.32 sys=0.16, real=0.10 secs] 
2012-09-27T10:35:51.151-0800: [GC [ParNew: 13677117K->331384K(15099520K), 0.0487500 secs] 13685345K->340716K(48653952K), 0.0492990 secs] [Times: user=1.38 sys=0.24, real=0.04 secs] 
2012-09-27T10:35:58.106-0800: [GC [1 CMS-initial-mark: 9331K(33554432K)] 8166192K(48653952K), 1.7910680 secs] [Times: user=1.77 sys=0.00, real=1.79 secs] 
2012-09-27T10:35:59.961-0800: [CMS-concurrent-mark: 0.036/0.059 secs] (CMS-concurrent-mark yielded 18 times)
2012-09-27T10:36:00.103-0800: [CMS-concurrent-preclean: 0.139/0.142 secs] (CMS-concurrent-preclean yielded 0 times)
2012-09-27T10:36:04.037-0800: [GC [ParNew: 13753208K->385654K(15099520K), 0.3407720 secs] 13762540K->466944K(48653952K), 0.3416910 secs] [Times: user=2.26 sys=0.33, real=0.34 secs] 
 CMS: abort preclean due to time  [3 iterations, 0 waits, 181035 cards)] 2012-09-27T10:36:08.080-0800: [CMS-concurrent-abortable-preclean: 7.404/7.977 secs] (CMS-concurrent-abortable-preclean yielded 232855 times)
2012-09-27T10:36:08.081-0800: [GC[YG occupancy: 3366851 K (15099520 K)]2012-09-27T10:36:08.081-0800: [GC [ParNew: 3366851K->369888K(15099520K), 0.1387480 secs] 3448141K->511931K(48653952K), 0.1395510 secs] [Times: user=1.66 sys=0.18, real=0.14 secs] 
2012-09-27T10:36:08.360-0800: [CMS-concurrent-sweep: 0.075/0.077 secs] (CMS-concurrent-sweep yielded 29 times)
2012-09-27T10:36:08.517-0800: [CMS-concurrent-reset: 0.149/0.157 secs] (CMS-concurrent-reset yielded 6 times)
2012-09-27T10:37:25.246-0800: [GC [ParNew: 13791744K->1500886K(15099520K), 15.1588390 secs] 13933770K->1694355K(48653952K), 15.1622180 secs] [Times: user=8.56 sys=789.17, real=15.17 secs]

[chewiebug]

Hi Bernd

Good Test, thank you! It looks like you combined -XX:PrintCMSStatistics=2 with -XX:CMSScavengeBeforeRemark. I have pushed a commit that is able to parse this combination.

The sample lines you posted could still not be parsed, however. I miss most of the remark event in it. I'd expect at least one more line after a line containing YG occupancy containing the rest of the information about the remark event. Could it be that you dropped a few lines of the original log when posting your finding?

Regards, Jörg

[chewiebug]

Hi Bernd,

I close this issue having pushed a fix to github. If you still find warnings parsing logs with -XX:PrintCMSStatistics=2 please reopen the issue.

Regards, Jörg