doctau / garbagecat Goto Github PK

http://code.google.com/a/eclipselabs.org/p/garbagecat/issues/detail?id=28

Log lines that have "GC time would exceed GCTimeLimit" and "GC time is exceeding GCTimeLimit" messages are not being recognized. Here is a sample:

25207.640: [Full GC [PSYoungGen: 1762560K->89633K(2185856K)] [ParOldGen: 2971644K->2971645K(2971648K)] 4734204K->3061278K(5157504K) [PSPermGen: 309869K->309857K(310208K)] GC time would exceed GCTimeLimit of 70%
, 8.9429330 secs] [Times: user=109.45 sys=0.30, real=8.94 secs]

The message itself seems to be mal-formed, perhaps there is a bug in JDK (using 1.6.0_21_x64). We run with -XX:GCTimeLimit=70 and -XX:GCHeapFreeLimit=40 options.

The attached zip file has the original log file with application timestamps prefix, so I ran with --preprocess, which didn't fix the above lines and so are reported as unrecognized. I then worked around by reformatting those lines to confirm to the regular Full GC lines (in Vim, run this substitution: :%s/(Full GC.))(] [Times:. real=)(.*) secs/\1], \300000 secs\2\3 secs/) .

The "GCTimeLimit" messages are a sure sign of bottlenecks (in fact, the JVM exited due to this in this case), so would not want to see these lines excluded.

http://code.google.com/a/eclipselabs.org/p/garbagecat/issues/detail?id=1

If MaxMetaspaceSize is set smaller than CompressedClassSpaceSize, the JVM auto adjusts CompressedClassSpaceSize as follows: CompressedClassSpaceSize = MaxMetaspaceSize - (2 * InitialBootClassLoaderMetaspaceSize).

If CompressedClassSpaceSize is not available, assume 1g default.

http://code.google.com/a/eclipselabs.org/p/garbagecat/issues/detail?id=35

Handle this logging:

3970.585: [GC[YG occupancy: 153169 K (471872 K)]3970.585: [Rescan (parallel) , 0.0205830 secs]3970.606: [weak refs processing, 0.0125640 secs]3970.619: [scrub string table, 0.0057870 secs] [1 CMS-remark: 2822060K(5619712K)] 2975230K(6091584K), 0.0402070 secs] [Times: user=0.15 sys=0.00, real=0.04 secs]

http://code.google.com/a/eclipselabs.org/p/garbagecat/issues/detail?id=23

http://code.google.com/a/eclipselabs.org/p/garbagecat/issues/detail?id=2

Preprocessing will not handle a combined CmsConcurrentEvent and ApplicationStoppedTimeEvent followed by an ApplicationConcurrentTimeEvent, and on the 3rd line the times data for the CmsConcurrentEvent.

For example, these 3 lines:

324217.024: [CMS-concurrent-abortable-preclean: 0.015/0.073 secs]Total time for which application threads were stopped: 0.0125060 seconds
Application time: 0.0001900 seconds
[Times: user=0.05 sys=0.00, real=0.08 secs]

Will be preprocessed into these 2 lines:
Total time for which application threads were stopped: 0.0125060 seconds
324217.024: [CMS-concurrent-abortable-preclean: 0.015/0.073 secs]Application time: 0.0001900 seconds
[Times: user=0.05 sys=0.00, real=0.08 secs]

Resulting in the times data not being associated with the CmsConcurrent event and stranded on a line and reported as an unidentified log line.