There is always the next JVM behaving badly. And you know by heart that if you just could have had those few startup options exposing some more information about what is going on, you might have stood a chance of actually fixing the goddamn thing. But nope, exactly the flag you need (be it -XX:+HeapDumpOnOutOfMemoryError or -XX:+PrintGCDetails) is always missing.
So you shrug in grief, kill the suffering JVM, alter the startup parameters and pray that the problematic situation is reproduced after restart. Sometimes it does and now you might have enough evidence to actually go ahead and start fixing the underlying root cause.
The problem with the approach described is obvious – instead of a single outage, you need to go through an extra restart just to pick up those pesky debug options. As a matter of fact, there is a workaround available, adding which to your arsenal can prove to be beneficial on occasions.
jinfo
There is a nice little utility well hidden in JDK bundles. jinfo is a command-line utility to harvest configuration information from a running Java process. The interesting part however, is that with the -flag option, the jinfo utility can dynamically adjust the value of certain Java VM flags for the specified Java process. The list of such flags is limited, but still helpful on occasions. The full list of such flags on your JVM can be checked via the following command:
my-precious me$ java -XX:+PrintFlagsFinal -version|grep manageable
intx CMSAbortablePrecleanWaitMillis = 100 {manageable}
intx CMSWaitDuration = 2000 {manageable}
bool HeapDumpAfterFullGC = false {manageable}
bool HeapDumpBeforeFullGC = false {manageable}
bool HeapDumpOnOutOfMemoryError = false {manageable}
... cut for brevity ...
bool PrintGC = false {manageable}
bool PrintGCDateStamps = false {manageable}
bool PrintGCDetails = false {manageable}
bool PrintGCTimeStamps = false {manageable}The -XX:+PrintFlagsFinal lists all the JVM options, out of which the “manageable” options are currently of interest. These are dynamically writeable through the JDK management interface (com.sun.management.HotSpotDiagnosticMXBean API). The very same MBean is also published through JConsole. To my liking, the command-line version is a lot more convenient though.
Example how to use jinfo
As an example of how to use jinfo, let us dynamically turn on the GC logging on a running JVM:
my-precious me$ jps 12278 HighAllocationRate 12279 Jps 12269 JConsole my-precious me$ jinfo -flag +PrintGCDetails 12278 my-precious me$ jinfo -flag +PrintGC 12278 my-precious me$
The utility turned on the GC logging by turning on the -XX:+PrintGC and -XX:+PrintGCDetails options. The minor difference to the behaviour of command line parameters is in the fact that you have to specify both PrintGCDetails and PrintGC options via jinfo. In case you were setting the parameters via startup script, just -XX:+PrintGCDetails is necessary as it automatically turns on the -XX:+PrintGC.
Nevertheless, checking the standard output, the GC log of the 12278 PID started rolling nicely:
... [GC (Allocation Failure) [PSYoungGen: 876416K->102624K(909312K)] 1094420K->320820K(1161216K), 0.2173131 secs] [Times: user=0.74 sys=0.00, real=0.22 secs] ... [GC (Allocation Failure) [PSYoungGen: 890304K->102240K(917504K)] 1108924K->320956K(1169408K), 0.2446639 secs] [Times: user=0.82 sys=0.01, real=0.25 secs] ...
Turning the logging off is similar – you just need to invoke the jinfo -flag -PrintGCDetails 12278 and jinfo -flag -PrintGC 12278 commands to get rid of the log messages.
Equipping you with this knowledge, I can only hope it will save you a day or two down your troubleshooting career. Assuming you are not one of the happy users of performance monitoring tools such as Plumbr, in case of which you would not face such need in the first place.
| Reference: | Turning on GC logging at runtime from our JCG partner Nikita Salnikov Tarnovski at the Plumbr Blog blog. |
