Skip to content
New issue

Have a question about this project? # for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “#”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? # to your account

Do not flag "application stopped/concurrent time" lines as parsing errors #90

Closed
sergei-ivanov opened this issue Mar 10, 2014 · 3 comments

Comments

@sergei-ivanov
Copy link

I ran my application with the following JVM options:

-XX:+PrintGC
-XX:+PrintGCApplicationConcurrentTime
-XX:+PrintGCApplicationStoppedTime
-XX:+PrintGCDateStamps 
-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps

When I tried to load the result into the GCViewer, it produced a lot of warning messages like those:

INFO [DataReaderFacade]: GCViewer version 1.33 (2013-10-30T18:47:41+0100)
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: 'Application time' Line 1: 2014-03-06T16:37:00.805+0000: 0.308: Application time: 0.3076280 seconds
WARNING [DataReaderSun1_6_0]: com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type: 'Total time for which application threads were stopped' Line 2: 2014-03-06T16:37:00.805+0000: 0.308: Total time for which application threads were stopped: 0.0000910 seconds

The GC output is as follows:

2014-03-06T16:37:00.805+0000: 0.308: Application time: 0.3076280 seconds
2014-03-06T16:37:00.805+0000: 0.308: Total time for which application threads were stopped: 0.0000910 seconds
2014-03-06T16:37:01.043+0000: 0.545: Application time: 0.2377720 seconds
2014-03-06T16:37:01.043+0000: 0.546: Total time for which application threads were stopped: 0.0001160 seconds

It looks like starting with Java7, JVM started to prepend timestamps to all "application stopped/concurrent time" lines. Java8 behaves in a similar way.

At best these log lines should be ignored by GCviewer, but ideally it would be great if it parsed and analysed them. It is not uncommon that the application is stopped for non-GC reason, and it would be great to have some statistics (with charts!) on stop/concurrent times, their distribution and any outliers.

@chewiebug
Copy link
Owner

Hi Sergei,

Thank you for testing this! I'll first filter those lines out so as to
get rid of the parsing problem. Maybe later I'll check if I can include
the information from those "stopped" events. There was an issue earlier
that wanted to have to "stopped time" evaluated as well (#25). Now with
the timestamp information present, it might be easier than I thought in #25.

Best regards,
Jörg

@chewiebug chewiebug added this to the 1.34 milestone Aug 3, 2014
@chewiebug chewiebug self-assigned this Aug 3, 2014
chewiebug added a commit that referenced this issue Aug 3, 2014
…`-XX:+PrintGCApplicationStoppedTime` and show in chart / statistics)

addresses issues
- #106 G1; combination of -XX:+PrintGCApplicationStoppedTime, -XX:+PrintTenuringDistribution, -XX:+PrintAdaptiveSizePolicy
- #91 G1; combination of -XX:+PrintGCApplicationStoppedTime, -XX:+PrintTenuringDistribution
- #90 (Oracle Parser without G1); -XX:+PrintGCApplicationStoppedTime
- #25 G1 and others; evaluate -XX:+PrintGCApplicationStoppedTime
@chewiebug
Copy link
Owner

Hi Sergei,

With my merge, this issues should also be addressed. Does it now work for you?

Best regards,
Jörg

@chewiebug
Copy link
Owner

Assuming that it works, I close this issue. If it shoulnd't please reopen it.

Best regards,
Jörg

# for free to join this conversation on GitHub. Already have an account? # to comment
Projects
None yet
Development

No branches or pull requests

2 participants