Tuesday, March 22, 2011

Thread Top

Hi,
I have finally found time to write a small tool which can help profiling Java applications.
Its name is threadTop and it connects to your application via JMX.
It can measure

  •   thread contention 
  •   thread CPU usage
I think it can be very useful when combined with jstack.
Waiting for your feedback :

Tuesday, March 15, 2011

Controlling GC logs at runtime

GC logging can be controlled using the following command line options:
  • -XX:+PrintGC (same as -verbose:gc) - Displays basic GC details 
  • -XX:+PrintGCDetails  - Displays advanced GC details 
  • -XX:+PrintGCTimeStamps - Displays the time stamp for every GC event  reported
  • -XX:+PrintGCDateStamps -  Displays the date for every GC event  reported  
  • -Xloggc:c:\gc.log     - Writes GC logging to the specified file.
It is usually recommended to run with -XX:+PrintGC -XX:+PrintGCTimeStamps -Xloggc:c:\gc.log even in production. The amount of data written to those files is not huge and it can help to analyze GC throughput ,pause time and even to expose bugs in the GC mechanism.
On the other hand these files are not managed by a "log4j style" rolling appender and will not be trimmed by default. So what would we choose ?
The good news is that logging GC can be configured at runtime. It can be enabled and disabled at will via JMX.
The JMX object com.sun.management:type=HotSpotDiagnostic has an attribute named DiagnosticOptions. This attribute contains 12 boolean sub-attributes (as for Java 1.6.0_24). All of them are very interesting but for the GC logging we need to take a look on 4 of them:
  • PrintGC
  • PrintGCDetails
  • PrintGCTimeStamps
  • PrintGCDateStamps

The bad news is that -Xloggc   cannot be configured via JMX so you will need to configure it on startup.


All these can be modified using jconsole or VisualVM using the operation setVMOption.

My recommendation is that even if you do not want to log GC by default add the following params to your command line -Xloggc:c:\gc.log -XX:-PrintGC -XX:+PrintGCTimeStamps 
(Notice that the PrintGC has a -  sign before it)
When you will need to analyze GC just turn on PrintGC and possible the PrintGCDetails.


Thursday, March 3, 2011

-XX:PrintFLSStatistics=1

When trying to understand what is going on with GC logging on G1GC. I found an undocumented JVM param that can really help when using CMS. -XX:PrintFLSStatistics=1 will report extra data for every GC:

8.790: [ParNew: 72703K->6341K(76672K), 0.0067245 secs] 72703K->6341K(816832K)After GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 94724096
Max   Chunk Size: 94724096
Number of Blocks: 1
Av.  Block  Size: 94724096
Tree      Height: 1
After GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 0
Max   Chunk Size: 0
Number of Blocks: 0
Tree      Height: 0
, 0.0068238 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]  

This can really help when trying to understand CMS concurrent mode failure due to fragmentation

Pity it is not reporting data in a single line though :-)