Saturday Apr 12, 2008

Utility to compare Class Histograms

We use the Class Histograms generated by -XX:+PrintClassHistogram jvm option quite often to diagnose memory leak issues. But we have to manually compare the histogram entries to analyze the difference between entries and the growth in heap.

I have written a utility in Java that reads the histograms from the file containing these histogram dumps and shows them in a graphical interface. One can click on these histograms and view them in this utility and can also compare any two histograms.

How it works:
- Compile the source java files located here: CompareHistogram Source

or just take the compiled jar file from here: CompareHistograms.jar

and Launch CompareHistograms class file. This will bring up the main window of the tool.
java CompareHistograms or java -jar CompareHistograms.jar
- Select the file containing histograms File->Open Histogram File. You will see this file in the "Histogram File" text field.
- It will show the histograms present in the file.
- Double click any histogram to view it.
- Select any two entries and click the "Compare Histograms" button to compare histograms.
- The histograms and histogram diffs can be exported to text files using Tools->Export Histogram menu item.

Sunday Mar 09, 2008

How to create VC++ project for HotSpot workspace

I am sure very few people would know that on Windows platform, we can create a VC++ project for the HotSpot workspace in JDK sources. It is very useful as it gives me the ability to view and browse HotSpot source code and also build it at a simple click from Visual Studio IDE. It is also very helpful in debugging hotspot issues which can be reproduced on Windows with a simple testcase(and not just at customer site :) )

So let's see how we can create this project for OpenJDK hotspot workspace on 32bit platform and open it in Visual Studio.

There is a batch file 'create.bat' in \\build\\windows\\ folder which creates the VC++ project for hotspot workspace on Windows. Before we run this batch, we need to set two environment variables.

- The 32-bit OpenJDK Windows build requires Microsoft Visual Studio .NET 2003 (VS2003) Professional Edition compiler. Once the compiler is installed, we need to run VCVARS32.BAT to set the compiler environment variables

Setting environment for using Microsoft Visual Studio .NET 2003 tools.
(If you have another version of Visual Studio or Visual C++ installed and wish
to use its tools from the command line, run vcvars32.bat for that version.)

- Set the Path to include installed jdk bin folder (jdk6 or jdk7)
set PATH=D:\\Java\\jdk1.6.0_03\\bin;%PATH%

Now, run create.bat

Usage: create HotSpotWorkSpace HotSpotBuildSpace HotSpotJDKDist

This is the interactive build setup script (as opposed to the batch
build execution script). It creates HotSpotBuildSpace if necessary,
copies the appropriate files out of HotSpotWorkSpace into it, and
builds and runs MakeDeps in it. This has the side-effect of creating
the file in the build space, which is then used in Visual C++.
The HotSpotJDKDist defines place where JVM binaries should be placed.
Environment variable FORCE_MSC_VER allows to override MSVC version autodetection.

The generated project file depends upon the include databases. If
those are changed then MakeDeps is rerun.

NOTE that it is now NOT safe to modify any of the files in the build
space, since they may be overwritten whenever this script is run or
nmake is run in that directory.

Passing those required arguments:

D:\\openjdk7\\openjdk\\hotspot\\build\\windows>create.bat D:\\openjdk7\\openjdk\\hotspot d:\\hotspot\\build d:\\hotspot\\bin
Will generate VC7 project
NOTE: Using the following settings:
javac -g -d d:\\hotspot\\build\\jvmtifiles D:\\openjdk7\\openjdk\\hotspot/src/share/vm/prims/
Generating d:\\hotspot\\build\\jvmtifiles/jvmtiEnv.hpp
Generating d:\\hotspot\\build\\jvmtifiles/jvmtiEnter.cpp
..... cut the output here ....
creating c1_ValueType.cpp
writing grand include file

writing dependencies file

Writing .vcproj file...
rm -f ad_x86_32.cpp ad_x86_32.hpp ad_x86_32_clone.cpp ad_x86_32_expand.cpp ad_x86_
d_x86_32_peephole.cpp ad_x86_32_pipeline.cpp adGlobals_x86_32.hpp dfa_x86_32.cpp
adlc -q -T -U_LP64

This creates vm.vcproj file in d:\\hotspot\\build folder.

Open this in Visual Studio .Net and have fun!

Sunday Feb 24, 2008

Debugging JVM hang with 'dbx'

Recently worked on a JVM hang problem, so posting here the steps followed in debugging this issue with dbx.

Customer was facing hard hang on a Solaris-x86 machine with jdk 1.5.0_08 and the process was not even responding to kill -3. They sent us a core file of the hung process.

For dbx to have the debug information, I re-built the product version of 1.5.0_08 with -g flag and loaded and used this new with dbx. With that, dbx was able to get all the debug information for the core file that was generated with a without any debug info.

The pstack on the core file showed that VMThread is trying to acquire Threads_lock, main thread is waiting on a condition on Threads_lock and another thread 3992 was also trying to grab Threads_lock, so this lock seemed to be causing the deadlock.

----------------- lwp# 1 / thread# 1 --------------------
fef4009b lwp_park (0, 0, 0)
fef3a909 cond_wait_queue (807c540, 807c528, 0, 0) + 3b
fef3ae02 _cond_wait (807c540, 807c528) + 66
fef3ae44 cond_wait (807c540, 807c528) + 21
fe92fc64 __1cHMonitorEwait6Mil_i_ (807c4d0, 0, 0) + 2a4
fecf526b __1cHThreadsKdestroy_vm6F_i_ (8073fb9, 0, 806dc14, fee4d33c, fee4a2a0, 10004) + 7b
feb66ea3 jni_DestroyJavaVM (fee43560) + 123
08051f8e main (2, 807017c, 80432b4) + bfb
080512fa ???????? (86, 8043468, 804346d, 8043494, 80434a8, 80434c6)
----------------- lwp# 11 / thread# 11 --------------------
fef4009b lwp_park (0, 0, 0)
fef399bb slow_lock (fbc92000, 807c528, 0) + 3d
fef39ab1 mutex_lock_impl (807c528, 0) + ec
fef39bbd mutex_lock (807c528) + 1a
fe8c9a00 __1cFMutexElock6MpnGThread__v_ (807c4d0, 8261480) + c0
fe8cc1fe __1cFMutexElock6M_v_ (807c4d0) + 4e
fe996295 __1cUSafepointSynchronizeFbegin6F_v_ (fee493fc, 8261480, fedee000, f8199b74, 3, f8199bbc) + 85
fea659c4 __1cIVMThreadEloop6M_v_ (8261480) + 134
fea66478 __1cIVMThreadDrun6M_v_ (8261480) + 88
fecbe0f2 __1cG_start6Fpv_0_ (8261480) + d2
fef3fd52 _thr_setup (fbc92000) + 4e
fef40040 _lwp_start (fbc92000, 0, 0, f8199ff8, fef40040, fbc92000)
----------------- lwp# 3992 / thread# 3992 --------------------
fef4009b lwp_park (0, 0, 0)
fef399bb slow_lock (6c173c00, 807c528, 0) + 3d
fef39ab1 mutex_lock_impl (807c528, 0) + ec
fef39bbd mutex_lock (807c528) + 1a
fe8ea95e __1cFMutexbClock_without_safepoint_check6M_v_ (807c4d0) + 7e
fe95c56e __1cUSafepointSynchronizeFblock6FpnKJavaThread__v_ (a27f780) + ee
fecb6825 __1cGParkerEpark6Mix_v_ (a27f908, 0, d964b198, 45) + 1e5
fed0963d Unsafe_Park (a27f840, 6807aba4, 0, d964b198, 45, 9480bcb8) + 1dd
f876f2f9 ???????? (0, 0, a27c330, 0, 9ae69a8, 0)
00000000 ???????? (fecf6330, fea09d40, fea03c80, fe964f40, fe91cc40, fe939c50)
00000000 ???????? (fffffd2c, 3badd9be, f468fe16, e78b7254, fe1dbbcc, 0)
00000000 ???????? ()

Now let's look at the Threads_lock in dbx.

(dbx) print -fx Threads_lock
Threads_lock = 0x807c4d0

(dbx) print -r \*((Monitor\*)0x807c4d0)
\*((class Monitor \*) 0x807c4d0) = {
Monitor::Mutex::_lock_count = 0
Monitor::Mutex::_lock_event = 0x807c500
Monitor::Mutex::_suppress_signal = 0
Monitor::Mutex::_owner = 0x97b0978 <----------------
Monitor::Mutex::_name = 0xfed97a0f "Threads_lock"
Monitor::Mutex::INVALID_THREAD = 0
Monitor::_event = (nil)
Monitor::_counter = 0
Monitor::_waiters = 1
Monitor::_tickets = 0

(dbx) print -r \*((Thread\*)0x97b0978)
\*((class Thread \*) 0x97b0978) = {
Thread::ThreadShadow::_pending_exception = (nil)
Thread::_exception_file = (nil)
Thread::_exception_line = 0
Thread::_real_malloc_address = 0x97b0d28
Thread::_rawmonitor_list = (nil)
Thread::_SR_lock = 0x9b7b890
Thread::_vm_suspend_depth = 0
Thread::_suspend_flags = 0
Thread::_active_handles = 0x97b0b48
Thread::_free_handle_block = (nil)
Thread::_last_handle_mark = 0x65c92618
Thread::_oops_do_parity = 0
Thread::_highest_lock = 0x65c92cb8 "x\^I{\^I\\xe8\^K{\^I\\xb0\\xd6\\x82\\xf4\\xa0H\\xbeu"
Thread::_unboosted_priority = NoPriority
Thread::_tlab = {
Thread::ThreadLocalAllocBuffer::_start = 0x762476d8
Thread::ThreadLocalAllocBuffer::_top = 0x7624c750
Thread::ThreadLocalAllocBuffer::_end = 0x76257308
Thread::ThreadLocalAllocBuffer::_size = 14078U
Thread::ThreadLocalAllocBuffer::_refill_waste_limit = 219U
Thread::ThreadLocalAllocBuffer::_number_of_refills = 6U
Thread::ThreadLocalAllocBuffer::_fast_refill_waste = 0
Thread::ThreadLocalAllocBuffer::_slow_refill_waste = 202U
Thread::ThreadLocalAllocBuffer::_gc_waste = 0
Thread::ThreadLocalAllocBuffer::_slow_allocations = 0
Thread::ThreadLocalAllocBuffer::_allocation_fraction = {
Thread::ThreadLocalAllocBuffer::AdaptiveWeightedAverage::_average = 0.006992618
Thread::ThreadLocalAllocBuffer::AdaptiveWeightedAverage::_sample_count = 1U
Thread::ThreadLocalAllocBuffer::AdaptiveWeightedAverage::_weight = 35U
Thread::ThreadLocalAllocBuffer::AdaptiveWeightedAverage::_last_sample = 0.006992618
Thread::ThreadLocalAllocBuffer::_target_refills = 50
Thread::ThreadLocalAllocBuffer::_global_stats = 136222936
Thread::_vm_operation_started_count = 1
Thread::_vm_operation_completed_count = 1
Thread::_current_pending_monitor = (nil)
Thread::_current_pending_monitor_is_from_java = 1
Thread::_current_waiting_monitor = (nil)
Thread::_osthread = 0x97b0b00 <-------------
Thread::_resource_area = 0x8c55f50
Thread::_handle_area = 0x98dafc0
Thread::_stack_base = 0x65c93000 ""
Thread::_stack_size = 262144U
Thread::_self_raw_id = 1731617792U

(dbx) print -r \*((OSThread\*)0x97b0b00)
\*((class OSThread \*) 0x97b0b00) = {
OSThread::_start_proc = (nil)
OSThread::_start_parm = (nil)
OSThread::_state = RUNNABLE
OSThread::_interrupted = 0
OSThread::_thread_id = 11982U
OSThread::_lwp_id = 11982U
OSThread::_caller_sigmask = {
OSThread::__sigbits = (4U, 0, 0, 0)
OSThread::_vm_created_thread = 1
OSThread::_current_callback = (nil)
OSThread::_current_callback_lock = (nil)
OSThread::_interrupt_event = 0x97b07d8
OSThread::_saved_interrupt_thread_state = _thread_new

This shows that owner of Threads_lock is thread with id 11982. Stack trace of this thread.

(dbx) thread t@11982
t@11982 (l@11982) stopped in __lwp_park at 0xfef4009b
0xfef4009b: __lwp_park+0x000b: jae __lwp_park+0x19 [ 0xfef400a9, .+0xe ]
(dbx) where
current thread: t@11982
=>[1] __lwp_park(0x0, 0x0), at 0xfef4009b
[2] mutex_lock_queue(0x67366400, 0x0, 0x88a0598, 0x0), at 0xfef3911f
[3] slow_lock(0x67366400, 0x88a0598, 0x0), at 0xfef399bb
[4] mutex_lock_impl(0x88a0598, 0x0), at 0xfef39ab1
[5] __mutex_lock(0x88a0598), at 0xfef39bbd
[6] Mutex::wait_for_lock_blocking_implementation(0xa27f908, 0x97b0978), at 0xfe9d93ba
[7] Mutex::lock(0xa27f908, 0x97b0978), at 0xfe8c99ea
[8] Mutex::lock(0xa27f908), at 0xfe8cc1fe
[9] Parker::unpark(0xa27f908), at 0xfecb69bb
[10] os::interrupt(0xa27f780), at 0xfecbf6bb
[11] Thread::interrupt(0xa27f780), at 0xfecf2ed9
[12] JVM_Interrupt(0x97b0a38, 0x65c923fc, 0x65c923d0, 0x0, 0x65c923fc, 0xf4873020, 0x0, 0xf482f600, 0x65c923fc, 0x65c92424,
0xf8202b6b, 0x0, 0xf8206399, 0x9593fdc0, 0x1, 0x0, 0x65c92400, 0xf482db6b, 0x65c92438, 0xf4873020), at 0xfeb92255
[13] 0xf820843a(0x0, 0xf8206399, 0x9593fdc0, 0x1, 0x0, 0x65c92400), at 0xf820843a
[14] 0xf8202b6b(0x0, 0x0, 0x97f59c18, 0x9593fdc0, 0x65c9243c, 0xf5746e95), at 0xf8202b6b
[15] 0xf8202b6b(0x967a0c40, 0x9, 0x968f6eb8, 0x65c92464, 0xf57472be, 0x65c92498), at 0xf8202b6b
[16] 0xf8202b6b(0x0, 0x968f6eb8, 0x967a0c40, 0x65c9249c, 0xf5845a0c, 0x65c924c4), at 0xf8202b6b
[17] 0xf8202b6b(0x1b58, 0x967a0c40, 0x65c924c8, 0xf5845674, 0x65c92524, 0xf58a1f78), at 0xf8202b6b
[18] 0xf8202b6b(0x7624c168, 0x7624c138, 0x7624c108, 0x7624c0d8, 0x7624bee8, 0x7624bd00), at 0xf8202b6b

It is trying to acquire Monitor 0xa27f908

Now, look at this Monitor:
(dbx) print -r \*((Monitor\*)0xa27f908)
\*((class Monitor \*) 0xa27f908) = {
Monitor::Mutex::_lock_count = 0
Monitor::Mutex::_lock_event = 0x88a0570 <-----------
Monitor::Mutex::_suppress_signal = 0
Monitor::Mutex::_owner = (nil)
Monitor::Mutex::_name = 0xfed97c99 "Park Semaphore"
Monitor::Mutex::INVALID_THREAD = 0
Monitor::_event = (nil)
Monitor::_counter = 0
Monitor::_waiters = 0
Monitor::_tickets = 0
(dbx) print -r \*((Event\*)0x88a0570)
More than one identifier 'Event'.
Select one of the following:
0) Cancel
1) class os::Solaris::Event
2) class Solaris::Event
> 1
\*((class os::Solaris::Event \*) 0x88a0570) = {
Event::_count = 0
Event::_nParked = 0
Event::CachePad = (-6.7529205832009e-205, -6.6220952168053e-205, -1.2786650622506e-204, -1.9668306807887e-204)
Event::_mutex = (
Event::_lwp_mutex::flags = {
Event::_lwp_mutex::flag1 = 4U
Event::_lwp_mutex::flag2 = '\\0'
Event::_lwp_mutex::ceiling = '\\0'
Event::_lwp_mutex::mbcp_type_un = {
Event::_lwp_mutex::bcptype = 0
Event::_lwp_mutex::mtype_rcount = {
Event::_lwp_mutex::count_type1 = '\\0'
Event::_lwp_mutex::count_type2 = '\\0'
Event::_lwp_mutex::magic = 19800U
Event::_lwp_mutex::lock = {
Event::_lwp_mutex::lock64 = {
Event::_lwp_mutex::pad = ""
Event::_lwp_mutex::lock32 = {
Event::_lwp_mutex::ownerpid = 0
Event::_lwp_mutex::lockword = 16842752U
Event::_lwp_mutex::owner64 = 72339069014638592ULL
Event::_lwp_mutex::data = 1813462016ULL

Event::_cond = (
Event::_lwp_cond::flags = {
Event::_lwp_cond::flag = ""
Event::_lwp_cond::type = 0
Event::_lwp_cond::magic = 17238U
Event::_lwp_cond::data = 0

Event::FreeNext = (nil)
Event::Immortal = 0

Here _lwp_mutex->data which is 0x6C173C00 is the owner thread (ulwp_t)

looking at it:
(dbx) x 0x6C173C00/30X
0x6c173c00: 0x6c173c00 0x00000000 0x00000000 0x00000000
0x6c173c10: 0x00000000 0x00000000 0x00000000 0x00000000
0x6c173c20: 0x00000000 0x00000000 0x00000000 0xfef6b740
0x6c173c30: 0x00000000 0x00000000 0x6c174000 0x6c173800
0x6c173c40: 0x00000000 0x00000000 0x00000000 0x6803b000
0x6c173c50: 0x00040000 0x00000000 0x6807b000 0x00040000
0x6c173c60: 0x6803b000 0x00040000 0x00000000 0x00000398
0x6c173c70: 0x00000f98 0x0000007f

0x00000f98 (which is 3992) is the thread id holding this Event::mutex

Now looking at thread 3992:
(dbx) thread t@3992
t@3992 (l@3992) stopped in __lwp_park at 0xfef4009b
0xfef4009b: __lwp_park+0x000b: jae __lwp_park+0x19 [ 0xfef400a9, .+0xe ]
(dbx) where
current thread: t@3992
=>[1] __lwp_park(0x0, 0x0), at 0xfef4009b
[2] mutex_lock_queue(0x6c173c00, 0x0, 0x807c528, 0x0), at 0xfef3911f
[3] slow_lock(0x6c173c00, 0x807c528, 0x0), at 0xfef399bb
[4] mutex_lock_impl(0x807c528, 0x0), at 0xfef39ab1
[5] __mutex_lock(0x807c528), at 0xfef39bbd
[6] Mutex::lock_without_safepoint_check(0x807c4d0), at 0xfe8ea95e
[7] SafepointSynchronize::block(0xa27f780), at 0xfe95c56e
[8] Parker::park(0xa27f908, 0x0, 0xd964b198, 0x45), at 0xfecb6825
[9] Unsafe_Park(0xa27f840, 0x6807aba4, 0x0, 0xd964b198, 0x45, 0x9480bcb8), at 0xfed0963d

It is waiting to lock Threads_lock.

So threads 11982 and 3992 have a deadlock.

Thread 11982 – holds Thread_lock and waiting to acquire Monitor 0xa27f908
Thread 3992 – holds lock on 0xa27f908 and waiting to acquire Threads_lock

This problem has been fixed with 6601725 in 5.0u15 and mustang.

Monday Feb 11, 2008

CR 6454676

This fix for CR 6454676 (Need -XX:+HeapDumpOnCtrlBreak to trigger heap dump on ctrl-break or ctrl-\\) was made available in 1.4.2_18 and 5.0u14. But a format string used in this fix got currupted due to SCCS mis-interpretation and caused the following bug.

6615248: SCCS tag interpetation makes code invalid

And due to this regression, HeapDumpOnCtrlBreak does not work correctly in 5.0u14. This problem has been fixed in 1.4.2_18 and 5.0u17.

Sunday Dec 09, 2007

'jhat' sources in OpenJDK

'jhat' source code is available in OpenJDK. Open 'jdk' project in NetBeans and expand 'Sources For All Platforms'. You can find the sources of 'jhat' in these packages:

It is possile to just build jhat.jar instead of building the whole jdk. In, you will find ant makefile build.xml. This can be used to build jhat.

Tuesday Dec 04, 2007

Heap Dump using -XX:+HeapDumpOnCtrlBreak

Heap Dumps are useful for Java Object Heap analysis. HeapDumpOnCtrlBreak jvm option would be available in upcoming 5.0 and 1.4.2 update releases that can be used to dump heap when a SIGQUIT signal is sent to the running process. One more feature would be available - if this option is used along with -XX:+PrintClassHistogram then both these tasks will be performed in one single VM Operation so that the Class Histogram and the Heap Dump represent the same snapshot of the process.

Friday Nov 30, 2007

Building OpenJDK on Windows with NetBeans

Trying to build OpenJDK on Windows ? Here are some simple steps that may help...

Here are the softwares required for the build.

- Download OpenJDK from and unzip the contents
- Download and install jdk 6.0 from and jdk 7.0 from
- Download and install openjdk binary plugs from
- Install Microsoft Visual Studio .NET 2003 Professional
- Install Cygwin from Make sure you install it in dos/text mode. Along with the default installation, we need to install Devel, Interpreters and Utils pakages. For the build, we need make 3.80, so if the cygwin make in not 3.80, download make bundle from and untar it in a separate folder.
- Download and install findbugs from
- Download and install Ant from
- Install Microsoft DirectX 9.0 SDK
- Download and install Microsoft Unicode library
- Install Freetype 2.3.4 from
- Install NetBeans 6.0 from

To build OpenJDK with NetBeans, open 'jdk' project in openjdk/jdk/make/netbeans/ with NetBeans. But first open a command window (cmd.exe) and set the path for following installed softwares:

set PATH=d:/utilities/usr/bin;d:\\devtools\\cygwin\\bin;D:\\devtools\\findbugs-1.3.0\\bin;

Here, d:/utilities/usr/bin contains make 3.80. Also, it is setting the path for cygwin, FindBugs and ant.

then run vsvars32.bat of Microsoft Visual Studio .NET:

Now launch Netbeans from this command window.

In Netbeans, click on File->Open Project. Browse to openjdk/jdk/make/netbeans/ and select 'jdk'.

In openjdk/jdk/make/netbeans/common/make.xml file, change the location of bin/make to your 3.80 make.

<target name="" if="">
<property name="platform" value="windows"/>
<property name="make" value="d:/utilities/usr/bin/make"/>

In file, set the following environment variables:


ALT_BOOTDIR=D:/Java/jdk1.6.0_03 \\
ALT_BINARY_PLUGS_PATH=D:/devtools/openjdk-binary-plugs \\
ALT_JDK_IMPORT_PATH=d:/devtools/jdk1.7.0 \\
ALT_DXSDK_PATH=d:/devtools/dxsdk9 \\
ALT_COMPILER_PATH=D:/Progra~1/Micros~1.NET/Vc7/bin \\
ALT_MSDEVTOOLS_PATH= D:/Progra~1/Micros~1.NET/Common7/Tools/Bin \\
ALT_MSVCR71_DLL_PATH= D:/Progra~1/Micros~1.NET/SDK/v1.1/Bin \\
ALT_FREETYPE_LIB_PATH=d:/devtools/freetype-2.3.4/lib \\
ALT_FREETYPE_HEADERS_PATH=d:/devtools/freetype-2.3.4/include \\
ALT_UNICOWS_LIB_PATH=d:/devtools/unicows \\
ALT_UNICOWS_DLL_PATH=d:/devtools/unicows \\
SHLVL=1 \\

And that's all we need to do. Start the build (press F11 or right click on jdk project and click Build)

Thursday Jul 05, 2007

How to programmatically obtain GC information

Here's a small program which uses GarbageCollectorMXBean MBean to programmatically obtain the GC information of the running java process. Call it's printGCInfo in your applcation whenever you want to get the last GC information.
import java.util.Iterator;
import java.util.Map;
import java.util.Set;

public class GCInformation {
    private static final String GC_BEAN_NAME =
    private static volatile GarbageCollectorMXBean gcMBean;
    /\*\* Creates a new instance of GCInformation \*/
    public GCInformation() {
    // initialize the GC MBean field
    private static void initGCMBean() {
        if (gcMBean == null) {
            synchronized (GCInformation.class) {
                if (gcMBean == null) {
                    gcMBean = getGCMBean();
    // get the GarbageCollectorMXBean MBean from the
    // platform MBean server
    private static GarbageCollectorMXBean getGCMBean() {
        try {
            MBeanServer server = ManagementFactory.getPlatformMBeanServer();
            GarbageCollectorMXBean bean = 
                GC_BEAN_NAME, GarbageCollectorMXBean.class);
            return bean;
        } catch (RuntimeException re) {
            throw re;
        } catch (Exception exp) {
            throw new RuntimeException(exp);
     \* Call this method from your application whenever you 
     \* want to get the last gc info
    static boolean printGCInfo() {
        // initialize GC MBean
        try {
            GcInfo gci = gcMBean.getLastGcInfo();
            long id = gci.getId();
            long startTime = gci.getStartTime();
            long endTime = gci.getEndTime();
            long duration = gci.getDuration();
            if (startTime == endTime) {
                return false;   // no gc
            System.out.println("GC ID: "+id);
            System.out.println("Start Time: "+startTime);
            System.out.println("End Time: "+endTime);
            System.out.println("Duration: "+duration);
            Map mapBefore = gci.getMemoryUsageBeforeGc();
            Map mapAfter = gci.getMemoryUsageAfterGc();

            System.out.println("Before GC Memory Usage Details....");
            Set memType = mapBefore.keySet();
            Iterator it = memType.iterator();
            while(it.hasNext()) {
                String type = (String);
                MemoryUsage mu1 = mapBefore.get(type);
                System.out.print("Initial Size: "+mu1.getInit());
                System.out.print(" Used: "+ mu1.getUsed());
                System.out.print(" Max: "+mu1.getMax());
                System.out.print(" Committed: "+mu1.getCommitted());
                System.out.println(" ");
            System.out.println("After GC Memory Usage Details....");
            memType = mapAfter.keySet();
            it = memType.iterator();
            while(it.hasNext()) {
                String type = (String);
                MemoryUsage mu2 = mapAfter.get(type);
                System.out.print("Initial Size: "+mu2.getInit());
                System.out.print(" Used: "+ mu2.getUsed());
                System.out.print(" Max: "+mu2.getMax());
                System.out.print(" Committed: "+mu2.getCommitted());
                System.out.println(" ");
        } catch (RuntimeException re) {
            throw re;
        } catch (Exception exp) {
            throw new RuntimeException(exp);
        return true;
     \* @param args the command line arguments
    public static void main(String[] args) {
        // Print the last gc information
        boolean ret = printGCInfo();        
Note that the GarbageCollector name used here is "ConcurrentMarkSweep" because I was running my appication with Concurrent Mark Sweep collector. Please use the appropriate Collector name from the list of Collector names I had posted in my previous entry.

Monday May 21, 2007

Collector names for GarbageCollectorMXBean MXBean

While trying to use GarbageCollectorMXBean to obtain GC information about a running process, I had to look around to find out the correct name strings for various Garbage Collectors.

This is what I did to obtain an instance of GarbageCollectorMXBean:
  MBeanServer server = ManagementFactory.getPlatformMBeanServer();
  GarbageCollectorMXBean bean = ManagementFactory.newPlatformMXBeanProxy(server,
             GC_BEAN_NAME, GarbageCollectorMXBean.class);

where GC_BEAN_NAME is the ObjectName for uniquely identifying the MXBean for a garbage collector within an MBeanServer and it is of the form:
    java.lang:type=GarbageCollector,name=collector's name  

Now, what is the correct string for collector's name?

Here are the name strings for various collectors in VM:

You can run a simple java program with different collectors and using the below code snippet, can see the full object names of all the available GarbageCollectorMXBean MXBeans.
MBeanServer mbs = ManagementFactory.getPlatformMBeanServer();
Set names = mbs.queryNames(null, null);
System.out.println(names.toString().replace(", ",

Sunday May 13, 2007

Automatic Imports addition using NetBeans

NetBeans has a very useful keyboard shortcut: Alt+Shift+F. Upon pressing these keys, NetBeans adds all the required import statements at the top of the source file.

Friday May 11, 2007

JVMTI agent to print reference paths

To get started on JVMTI please read JVMTI reference guide JVMTI reference guide and a very good article on JVMTI Programming here

Here I will briefly describe how I used JVMTI to write an agent which prints the reference paths of instances of a given class in the running process.

The global data structure used in this agent:
/\* Global agent data structure \*/
typedef struct {
    /\* JVMTI Environment \*/
    jvmtiEnv      \*jvmti;

    /\* Data access Lock \*/
    jrawMonitorID  lock;

    /\* Fields to store the Options passed to the agent\*/
    char\* classname;   
    int  max_count;    

    /\* boolen to indicate if dump is in progress \*/	
    jboolean dumpInProgress;
    JavaVM\* jvm;
    jclass  klass;
    jlong  klassTag;
} GlobalAgentData;

This agent prints these reference paths when a SIGQUIT signal is sent to the process. For this, In Agent_OnLoad() function, set the callback for DataDumpRequest and enable the event notification for JVMTI_EVENT_DATA_DUMP_REQUEST event.
JNIEXPORT jint JNICALL Agent_OnLoad(JavaVM \*jvm, char \*options, void \*reserved)
  callbacks.DataDumpRequest = &dataDumpRequest;

With the above code, when the process receives SIGQUIT (ctrl+\\ on solaris and ctrl+break on windows) signal, dataDumpRequest() function of this agent would get invoked.

Let's see how this function looks:
static void JNICALL dataDumpRequest(jvmtiEnv \*jvmti)
  enter_critical_section(jvmti); {
    if ( !gdata->dumpInProgress ) {
      gdata->dumpInProgress = JNI_TRUE;
      gdata->klassTag = 1;
      gdata->jvmti->SetTag(gdata->klass, gdata->klassTag);
      jint count = 0;
      void\* user_data = NULL;

      // iterate over all the reachable objects in heap
      jvmti->IterateOverReachableObjects(&heap_root_callback, &stack_ref_callback,
                 &object_ref_callback, user_data);

      // print ref paths
      RefPaths\* list = ref_paths;
      int max = gdata->max_count;

      printf("Reference paths of instances of %s ....\\n", gdata->classname);
      while ((list != NULL) && (max >= 0) ) {
        ObjectInfo\* object = (ObjectInfo\*)list->path;
        printf("\\n\\nReference Path:");
        list = list->next;

      // unset tags
      jvmti->IterateOverReachableObjects(&heap_root_callback, &stack_ref_callback,
            &object_ref_clean_callback, user_data);

      // delete object info list
      ObjectInfoList\* list1 = objList;
      while (list1) {
        ObjectInfoList\* node = list1;
        list1 = list1->next;
      objList = NULL;
      // delete ref paths list
      list = ref_paths;
      RefPaths\* path;

      while (list != NULL) {
        path = list;
        list = list->next;
      ref_paths = NULL;

      gdata->klassTag = 1;
      gdata->dumpInProgress = JNI_FALSE;
  } exit_critical_section(jvmti);	
Here, we first set the tag of the class gdata->klass which was set to the classname passed as parameter to the agent. Then we call IterateOverReachableObjects function to go over all the reachable objects in heap. IterateOverReachableObjects function iterates over the root objects and all objects that are directly and indirectly reachable from the root objects. In dataDumpRequest we are making two calls to IterateOverReachableObjects, first one to create a list of reachable objects and their referrers and the second one to unset the tags set in the first call.

IterateOverReachableObjects accepts three callbacks, callback which gets called when any root object is visited, callback which gets called when any stack object is visited and a callback when any object reference is visited. This sample agent does not do anything in the root and stack callbacks.

Now let's see what the object reference callback does:
static jvmtiIterationControl JNICALL
object_ref_callback(jvmtiObjectReferenceKind reference_kind,
		jlong class_tag, jlong size, jlong\* tag_ptr,
		jlong referrer_tag, jint referrer_index, void \*user_data)
  ObjectInfo\* obj_info = NULL;
  // if this object's tag is set which can be for the class we want to create
  // reference paths for or if we are visiting this object again.
  if (\*tag_ptr != NULL) { 
    if (gdata->klassTag == 1) {
      if (\*tag_ptr == gdata->klassTag) {
        obj_info = new ObjectInfo();
	memset(obj_info, 0 , sizeof(ObjectInfo));
	obj_info->size = size;
	obj_info->visited = 1;
	obj_info->kind = reference_kind;

	\*tag_ptr = (jlong)(ptrdiff_t)(void\*)obj_info;
	gdata->klassTag = \*tag_ptr;
    } else {
      obj_info = (ObjectInfo\*)\*tag_ptr;
      if (obj_info->visited == 1)
  // if tag is not present, then create ObjectInfo and set it as it's tag.
  else {
    obj_info = new ObjectInfo();
    memset(obj_info, 0 , sizeof(ObjectInfo));
    obj_info->size = size;
    obj_info->visited = 1;
    obj_info->kind = reference_kind;

    \*tag_ptr = (jlong)(ptrdiff_t)(void\*)obj_info;

    //Add the new ObjectInfo to ObjectInfo's list
    if (objList == NULL) {
      objList = new ObjectInfoList();
      objList->obj = obj_info;
      objList->next = NULL;
    } else {
      ObjectInfoList\* list = objList;
      while (list->next != NULL) {
        list = list->next;
      ObjectInfoList\* objinfo = new ObjectInfoList();
      objinfo->obj = obj_info;
      objinfo->next = NULL;

      list->next = objinfo;
  // If this object has the referrer then put it in the referrers list
  if (referrer_tag != NULL) {
    if (obj_info->referrers == NULL) {
      obj_info->referrers = new Referrer();
      obj_info->referrers->tag = referrer_tag;
      obj_info->referrers->refereeTag = \*tag_ptr;
      obj_info->referrers->next = NULL;
    } else {
      Referrer\* referrer = obj_info->referrers;
      while (referrer->next != NULL) {
        referrer = referrer->next;
      Referrer\* ref = new Referrer();
      ref->tag = referrer_tag;
      ref->refereeTag = \*tag_ptr;
      ref->next = NULL;
      referrer->next = ref;			

  if (class_tag == gdata->klassTag) {


Here the ObjectInfo class represents an object in the heap. We tag every visited reference with the ObjectInfo pointer and when it's refree is visited, the referer_tag contains this ObjectInfo pointer. So by using tag_ptr and referer_tag, this callback creates list of reference paths (RefPaths) of all the instances of the given class.

After returning from the callback, function dfsPrintRefPaths prints prints these reference paths. Then we make another call to IterateOverReachableObjects to unset the tags we had set in the first iteration.

The full code of this agent can be downloaded from here.

How this works:
Build ref_paths.cpp into a shared library. Copy the library refpaths.dll or in the current working directory or set the LD_LIBRARY_PATH on solaris and PATH env variable on Windows to the loaction of this library.

Start your java program with options:
java -agentlib:refpaths=classname="java/lang/String",max=40 TestClass

where -agentlib:refpaths specifies that 'refpaths' is the jvmti based shared library
and following that are the arguments passed to this agent.
o classname - name of the class for which we want to print the ref-paths
o max - the maximum number of instances

The above commnad will print the 40 ref-paths of instances of java/lang/String class.

To print the ref-paths at any point, send Sigquit signal to the running process
and it will print the paths though which the requested instances are reachable.

The output of ref-paths printed by this agent looks like this:
Reference Path:
- Instance Field: /E:/jre1.5.0_10/lib/ext/dnsns.jar
- Array Element: file:/E:/jre1.5.0_10/lib/ext/dnsns.jar
- Instance Field: [Ljava.lang.Object;@1c78e57
- Instance Field: [file:/E:/jre1.5.0_10/lib/ext/dnsns.jar, file:/E:/jre1.5.0_10/lib/ext/localedata.jar, file:/E:/jre1.5.0_10/lib/ext/sunjce_provider.jar, file:/E:/jre1.5.0_10/lib/ext/sunpkcs11.jar]
- Instance Field: sun.misc.URLClassPath@5224ee
- Instance Field: sun.misc.Launcher$ExtClassLoader@92e78c
- ClassLoader: sun.misc.Launcher$AppClassLoader@a39137
- class TestClass

Reference Path:
- Instance Field: file:/E:/jre1.5.0_10/lib/ext/sunpkcs11.jar!/
- Instance Field: jar:file:/E:/jre1.5.0_10/lib/ext/sunpkcs11.jar!/
- Array Element: sun.misc.URLClassPath$JarLoader@f6a746
- Instance Field: [Ljava.lang.Object;@15ff48b
- Instance Field: [sun.misc.URLClassPath$JarLoader@affc70, sun.misc.URLClassPath
- Instance Field: sun.misc.URLClassPath@5224ee
- Instance Field: sun.misc.Launcher$ExtClassLoader@92e78c
- ClassLoader: sun.misc.Launcher$AppClassLoader@a39137
- class TestClass

where any entry is reachable through the entry below it.

Thursday May 10, 2007

jmap with CMS

Hotspot Servicability Agent, the backbone of jmap tool had a bug due to which jmap was not able to generate correct histogram and heap dump of applications running with Concurrent Mark Sweep collector. This bug 6311411 has been fixed in 5.0u12 and 6.0u2. So starting with these releases, jmap works fine with CMS collector.

Thursday Mar 23, 2006

Understanding CMS GC Logs

CMS GC with -XX:+PrintGCDetails and -XX:+PrintGCTimeStamps prints a lot of information. Understanding this information can help in fine tuning various parameters of the application and CMS to achieve best performance.

Let's have a look at some of the CMS logs generated with 1.4.2_10:

39.910: [GC 39.910: [ParNew: 261760K->0K(261952K), 0.2314667 secs] 262017K->26386K(1048384K), 0.2318679 secs]

Young generation (ParNew) collection. Young generation capacity is 261952K and after the collection its occupancy drops down from 261760K to 0. This collection took 0.2318679 secs.

40.146: [GC [1 CMS-initial-mark: 26386K(786432K)] 26404K(1048384K), 0.0074495 secs]

Beginning of tenured generation collection with CMS collector. This is initial Marking phase of CMS where all the objects directly reachable from roots are marked and this is done with all the mutator threads stopped.

Capacity of tenured generation space is 786432K and CMS was triggered at the occupancy of 26386K.

40.154: [CMS-concurrent-mark-start]

Start of concurrent marking phase.
In Concurrent Marking phase, threads stopped in the first phase are started again and all the objects transitively reachable from the objects marked in first phase are marked here.

40.683: [CMS-concurrent-mark: 0.521/0.529 secs]

Concurrent marking took total 0.521 seconds cpu time and 0.529 seconds wall time that includes the yield to other threads also.

40.683: [CMS-concurrent-preclean-start]

Start of precleaning.
Precleaning is also a concurrent phase. Here in this phase we look at the objects in CMS heap which got updated by promotions from young generation or new allocations or got updated by mutators while we were doing the concurrent marking in the previous concurrent marking phase. By rescanning those objects concurrently, the precleaning phase helps reduce the work in the next stop-the-world “remark” phase.

40.701: [CMS-concurrent-preclean: 0.017/0.018 secs]

Concurrent precleaning took 0.017 secs total cpu time and 0.018 wall time.

40.704: [GC40.704: [Rescan (parallel) , 0.1790103 secs]40.883: [weak refs processing, 0.0100966 secs] [1 CMS-remark: 26386K(786432K)] 52644K(1048384K), 0.1897792 secs]

Stop-the-world phase. This phase rescans any residual updated objects in CMS heap, retraces from the roots and also processes Reference objects. Here the rescanning work took 0.1790103 secs and weak reference objects processing took 0.0100966 secs. This phase took total 0.1897792 secs to complete.

40.894: [CMS-concurrent-sweep-start]

Start of sweeping of dead/non-marked objects. Sweeping is concurrent phase performed with all other threads running.

41.020: [CMS-concurrent-sweep: 0.126/0.126 secs]

Sweeping took 0.126 secs.

41.020: [CMS-concurrent-reset-start]

Start of reset.

41.147: [CMS-concurrent-reset: 0.127/0.127 secs]

In this phase, the CMS data structures are reinitialized so that a new cycle may begin at a later time. In this case, it took 0.127 secs.

This was how a normal CMS cycle runs. Now let us look at some other CMS log entries:

197.976: [GC 197.976: [ParNew: 260872K->260872K(261952K), 0.0000688 secs]197.976: [CMS197.981: [CMS-concurrent-sweep: 0.516/0.531 secs]
(concurrent mode failure): 402978K->248977K(786432K), 2.3728734 secs] 663850K->248977K(1048384K), 2.3733725 secs]

This shows that a ParNew collection was requested, but it was not attempted because it was estimated that there was not enough space in the CMS generation to promote the worst case surviving young generation objects. We name this failure as “full promotion guarantee failure”.

Due to this, Concurrent Mode of CMS is interrupted and a Full GC is invoked at 197.981. This mark-sweep-compact stop-the-world Full GC took 2.3733725 secs and the CMS generation space occupancy dropped from 402978K to 248977K.

The concurrent mode failure can either be avoided by increasing the tenured generation size or initiating the CMS collection at a lesser heap occupancy by setting CMSInitiatingOccupancyFraction to a lower value and setting UseCMSInitiatingOccupancyOnly to true. The value for CMSInitiatingOccupancyFraction should be chosen appropriately because setting it to a very low value will result in too frequent CMS collections.

Sometimes we see these promotion failures even when the logs show that there is enough free space in tenured generation. The reason is 'fragmentation' - the free space available in tenured generation is not contiguous, and promotions from young generation require a contiguous free block to be available in tenured generation. CMS collector is a non-compacting collector, so can cause fragmentation of space for some type of applications. In his blog, Jon talks in detail on how to deal with this fragmentation problem:

Starting with 1.5, for the CMS collector, the promotion guarantee check is done differently. Instead of assuming that the promotions would be worst case i.e. all of the surviving young generation objects would get promoted into old gen, the expected promotion is estimated based on recent history of promotions. This estimation is usually much smaller than the worst case promotion and hence requires less free space to be available in old generation. And if the promotion in a scavenge attempt fails, then the young generation is left in a consistent state and a stop-the-world mark-compact collection is invoked. To get the same functionality with UseSerialGC you need to explicitly specify the switch -XX:+HandlePromotionFailure.

283.736: [Full GC 283.736: [ParNew: 261599K->261599K(261952K), 0.0000615 secs] 826554K->826554K(1048384K), 0.0003259 secs]
GC locker: Trying a full collection because scavenge failed
283.736: [Full GC 283.736: [ParNew: 261599K->261599K(261952K), 0.0000288 secs]

Stop-the-world GC happening when a JNI Critical section is released. Here again the young generation collection failed due to “full promotion guarantee failure” and then the Full GC is being invoked.

CMS can also be run in incremental mode (i-cms), enabled with -XX:+CMSIncrementalMode. In this mode, CMS collector does not hold the processor for the entire long concurrent phases but periodically stops them and yields the processor back to other threads in application. It divides the work to be done in concurrent phases in small chunks(called duty cycle) and schedules them between minor collections. This is very useful for applications that need low pause times and are run on machines with small number of processors.

Some logs showing the incremental CMS.

2803.125: [GC 2803.125: [ParNew: 408832K->0K(409216K), 0.5371950 secs] 611130K->206985K(1048192K) icms_dc=4 , 0.5373720 secs]
2824.209: [GC 2824.209: [ParNew: 408832K->0K(409216K), 0.6755540 secs] 615806K->211897K(1048192K) icms_dc=4 , 0.6757740 secs]

Here, the scavenges took respectively 537 ms and 675 ms. In between these two scavenges, iCMS ran for a brief period as indicated by the icms_dc value, which indicates a duty-cycle. In this case the duty cycle was 4%. A simple calculation shows that the iCMS incremental step lasted for 4/100 \* (2824.209 - 2803.125 - 0.537) = 821 ms, i.e. 4% of the time between the two scavenges.

Starting with 1.5, CMS has one more phase – concurrent abortable preclean. Abortable preclean is run between a 'concurrent preclean' and 'remark' until we have the desired occupancy in eden. This phase is added to help schedule the 'remark' phase so as to avoid back-to-back pauses for a scavenge closely followed by a CMS remark pause. In order to maximally separate a scavenge from a CMS remark pause, we attempt to schedule the CMS remark pause roughly mid-way between scavenges.

There is a second reason why we do this. Immediately following a scavenge there are likely a large number of grey objects that need rescanning. The abortable preclean phase tries to deal with such newly grey objects thus reducing a subsequent CMS remark pause.

The scheduling of 'remark' phase can be controlled by two jvm options CMSScheduleRemarkEdenSizeThreshold and CMSScheduleRemarkEdenPenetration. The defaults for these are 2m and 50% respectively. The first parameter determines the Eden size below which no attempt is made to schedule the CMS remark pause because the pay off is expected to be minuscule. The second parameter indicates the Eden occupancy at which a CMS remark is attempted.

After 'concurrent preclean' if the Eden occupancy is above CMSScheduleRemarkEdenSizeThreshold, we start 'concurrent abortable preclean' and continue precleanig until we have CMSScheduleRemarkEdenPenetration percentage occupancy in eden, otherwise we schedule 'remark' phase immediately.

7688.150: [CMS-concurrent-preclean-start]
7688.186: [CMS-concurrent-preclean: 0.034/0.035 secs]
7688.186: [CMS-concurrent-abortable-preclean-start]
7688.465: [GC 7688.465: [ParNew: 1040940K->1464K(1044544K), 0.0165840 secs] 1343593K->304365K(2093120K), 0.0167509 secs]
7690.093: [CMS-concurrent-abortable-preclean: 1.012/1.907 secs]
7690.095: [GC[YG occupancy: 522484 K (1044544 K)]7690.095: [Rescan (parallel) , 0.3665541 secs]7690.462: [weak refs processing, 0.0003850 secs] [1 CMS-remark: 302901K(1048576K)] 825385K(2093120K), 0.3670690 secs]

In the above log, after a preclean, 'abortable preclean' starts. After the young generation collection, the young gen occupancy drops down from 1040940K to 1464K. When young gen occupancy reaches 522484K which is 50% of the total capacity, precleaning is aborted and 'remark' phase is started.

Note that in 1.5, young generation occupancy also gets printed in the final remark phase.

For more detailed information and tips on GC tuning, please refer to the following documents:




« April 2014