error parsing log line UnknownGcTypeException about gcviewer

[charlesporter]

here is a complete list of flags:
-Xmx8219m -Xms8219m -XX:MaxPermSize=1024m
-XX:NewRatio=4
-XX:+UseCompressedOops
-XX:+UseConcMarkSweepGC
-XX:+UseParNewGC
-XX:GCTimeRatio=2
-XX:+CMSScavengeBeforeRemark
-XX:+CMSClassUnloadingEnabled
-XX:CMSInitiatingOccupancyFraction=50
-XX:ParallelGCThreads=5
-XX:+PrintCommandLineFlags
-XX:+PrintFlagsFinal
-XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=/home//tomcat/logs
-XX:+PrintTenuringDistribution
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
-Xloggc:/home/tomcat/logs/gc.2012-03-07.09:29.log

[chewiebug]

Hi Charles,

I am able to reproduce the exception. It is the -XX:+CMSScavengeBeforeRemark that produces output the parser can't handle. In the gc log two events are mixed up: "Remark" and the "Scavenge before remark" event.

Start of remark event including scavenge
2.036: [GC[YG occupancy: 235954 K (235968 K)]2.036: [GC 2.036: [ParNew: 235954K->30K(235968K), 0.0004961 secs] 317153K->81260K(395712K), 0.0005481 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

rest of remark event
2.037: [Rescan (parallel) , 0.0002425 secs]2.037: [weak refs processing, 0.0000041 secs]2.037: [class unloading, 0.0000938 secs]2.037: [scrub symbol & string tables, 0.0003138 secs] [1 CMS-remark: 81230K(159744K)] 81260K(395712K), 0.0013653 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

I'll see what I can do about this one.

Regards, Jörg

[charlesporter]

thanks

On Wed, Mar 7, 2012 at 1:34 PM, chewiebug
[email protected]
wrote:

Hi Charles,

I am able to reproduce the exception. It is the -XX:+CMSScavengeBeforeRemark that produces output the parser can't handle. In the gc log two events are mixed up: "Remark" and the "Scavenge before remark" event.

Start of remark event including scavenge
2.036: [GC[YG occupancy: 235954 K (235968 K)]2.036: [GC 2.036: [ParNew: 235954K->30K(235968K), 0.0004961 secs] 317153K->81260K(395712K), 0.0005481 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

rest of remark event
2.037: [Rescan (parallel) , 0.0002425 secs]2.037: [weak refs processing, 0.0000041 secs]2.037: [class unloading, 0.0000938 secs]2.037: [scrub symbol & string tables, 0.0003138 secs] [1 CMS-remark: 81230K(159744K)] 81260K(395712K), 0.0013653 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

I'll see what I can do about this one.

Regards, Jörg

---

Reply to this email directly or view it on GitHub:
#18 (comment)

[chewiebug]

Hi Charles,

I have fixed parsing of -XX:+CMSScavengeBeforeRemark. Now you should be able to parse the log files you tried to when you detected the bug.

Could you please confirm that the bug is fixed?

Regards, Jörg

[charlesporter]

Jorg:

Sorry this took so long
(BTW the original bug was not an urgent problem for me, I just wanted you to let you know about it)

The fix works for the original problem log file, but throws a null pointer exception on the following log file content:
(You may consider this a non-issue, because I injected the newlines before each of these three lines in the file )
8.823: [Rescan (parallel) , 0.0179610 secs]
8.841: [weak refs processing, 0.0003610 secs]
8.841: [class unloading, 0.0089450 secs]

2012-03-07T09:29:28.379-0800: 3.301: [GC [1 CMS-initial-mark: 0K(6733056K)] 215641K(8247936K), 0.0897370 secs] [Times: user=0.09 sys=0.00, real=0.09 secs]
2012-03-07T09:29:28.469-0800: 3.391: [CMS-concurrent-mark-start]
2012-03-07T09:29:28.698-0800: 3.619: [CMS-concurrent-mark: 0.035/0.228 secs] [Times: user=0.37 sys=0.04, real=0.23 secs]
2012-03-07T09:29:28.698-0800: 3.619: [CMS-concurrent-preclean-start]
2012-03-07T09:29:28.759-0800: 3.680: [CMS-concurrent-preclean: 0.058/0.061 secs] [Times: user=0.13 sys=0.01, real=0.06 secs]
2012-03-07T09:29:28.759-0800: 3.680: [CMS-concurrent-abortable-preclean-start]
CMS: abort preclean due to time 2012-03-07T09:29:33.855-0800: 8.776: [CMS-concurrent-abortable-preclean: 2.306/5.096 secs] [Times: user=9.27 sys=0.41, real=5.10 secs]
2012-03-07T09:29:33.855-0800: 8.777: [GC[YG occupancy: 458035 K (1514880 K)]2012-03-07T09:29:33.855-0800: 8.777: [GC 8.777: [ParNew
Desired survivor size 86179840 bytes, new threshold 4 (max 4)

• age 1: 16530104 bytes, 16530104 total
  : 458035K->16217K(1514880K), 0.0457580 secs] 458035K->16217K(8247936K), 0.0458450 secs] [Times: user=0.14 sys=0.02, real=0.04 secs]
  8.823: [Rescan (parallel) , 0.0179610 secs]
  8.841: [weak refs processing, 0.0003610 secs]
  8.841: [class unloading, 0.0089450 secs]
  2012-03-07T09:29:33.935-0800: 8.857: [CMS-concurrent-sweep-start]
  2012-03-07T09:29:33.953-0800: 8.875: [CMS-concurrent-sweep: 0.015/0.018 secs] [Times: user=0.05 sys=0.00, real=0.02 secs]
  2012-03-07T09:29:33.954-0800: 8.875: [CMS-concurrent-reset-start]
  2012-03-07T09:29:34.044-0800: 8.966: [CMS-concurrent-reset: 0.090/0.091 secs] [Times: user=0.09 sys=0.08, real=0.09 secs]
  2012-03-07T09:29:45.866-0800: 20.788: [GC 20.788: [ParNew
  Desired survivor size 86179840 bytes, new threshold 1 (max 4)
• age 1: 161097888 bytes, 161097888 total
• age 2: 11257072 bytes, 172354960 total
  : 1362777K->168320K(1514880K), 3.3703920 secs] 1362777K->465066K(8247936K), 3.3704830 secs] [Times: user=12.55 sys=1.36, real=3.37 secs]
  2012-03-07T09:29:52.144-0800: 27.066: [Full GC (System) 27.066: [CMS: 296746K->437737K(6733056K), 3.1834800 secs] 1033854K->437737K(8247936K), [CMS Perm : 58276K->58227K(74260K)], 3.1837350 secs] [Times: user=3.67 sys=0.07, real=3.18 secs]
  2012-03-07T09:30:22.068-0800: 56.990: [GC 56.990: [ParNew
  Desired survivor size 86179840 bytes, new threshold 1 (max 4)
• age 1: 130167888 bytes, 130167888 total
  : 1346688K->168320K(1515008K), 1.0819150 secs] 1784425K->690852K(8248064K), 1.0820210 secs] [Times: user=2.40 sys=0.12, real=1.08 secs]
  2012-03-07T09:30:52.360-0800: 87.282: [GC 87.282: [ParNew
  Desired survivor size 86179840 bytes, new threshold 1 (max 4)
• age 1: 136183272 bytes, 136183272 total
  : 1515008K->168320K(1515008K), 1.3488660 secs] 2037540K->908858K(8248064K), 1.3489720 secs]

whereas the released version merely complained with this message:

INFO [DataReaderFactory]: File format: Sun 1.6.x
INFO [DataReaderSun1_6_0]: Reading Sun / Oracle 1.4.x / 1.5.x / 1.6.x / 1.7.x format...
WARNING [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'Rescan (parallel) ' Line 12: 8.823: [Rescan (parallel) , 0.0179610 secs]
WARNING [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'weak refs processing' Line 13: 8.841: [weak refs processing, 0.0003610 secs]
WARNING [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'class unloading' Line 14: 8.841: [class unloading, 0.0089450 secs]
INFO [DataReaderSun1_6_0]: Done reading.

-Charles

[chewiebug]

Hi Charles,

No problem for taking your time to answer my question. Thank you for confirming the bug fix.

It is not nice to introduce newlines ;-). The parser tries to get everything which is part of an event onto the same line before interpreting what it is. So manually introduced newlines will be a problem for the parser.

However, I don't like NullPointerExceptions because they are very little verbose. It seems that I have decreased the robustness of the parser. I'll have a look into it again to have the UnknownGcTypeException again - that is what I'd expect the parser to throw in the situation you describe.

Regards, Jörg

[chewiebug]

Hi Charles,

I have checked the code and found the reason for the NullPointerException - it definitely was a bug I didn't want to leave in the code for the next release. So, thank you for telling me.

I still get 3 exceptions when I parse the above example caused by your manually introduced newlines. Those I won't fix since they don't occur in standard gc logs.

Just curious: Why do you introduce the newlines?

Regards, Jörg

[charlesporter]

Jörg-

I added the newlines in hope that I could get either gcviewer or hp's
jmeter to successfully parse the file.
My thinking was that the the parsers might be expecting the timestamps
to occur only at the start of a line. Evidently not the case.

I have also put each timestamped entry on its own line in the past
when using general-purpose charting tools to try to visualize the GC
activity, on the reasoning one timestamp implies one event. This was
really the easiest way to do it before you took over GCViewer and
brought it up to date with the java 6.

I had forgotten that I had done that with the particular file I tested
your fix with it, but a null pointer exception seemed like an overly
harsh response, so I thought you should know about it.

Anyway, I appreciate your efforts and am finding GC viewer to be a
very helpful tool.

-Charles

On Sun, Mar 18, 2012 at 2:01 PM, chewiebug
[email protected]
wrote:

Hi Charles,

I have checked the code and found the reason for the NullPointerException - it definitely was a bug I didn't want to leave in the code for the next release. So, thank you for telling me.

I still get 3 exceptions when I parse the above example caused by your manually introduced newlines. Those I won't fix since they don't occur in standard gc logs.

Just curious: Why do you introduce the newlines?

Regards, Jörg

---

Reply to this email directly or view it on GitHub:
#18 (comment)

[chewiebug]

Hi Charles,

Thank you for the explanation - so, no new feature request ;-).

And thank you also for testing and finding the NullPointerException. That definitely was overly harsh.

Regards, Jörg