Monday, January 25, 2010

jucprofiler : java.util.concurrent locks profiling


1.   Introduction

Performance analysis is an important aspect of the application development process.  It is typically done by a specialist whose main goal is to improve the code performance on a given platform.  This problem becomes even more difficult when dealing with concurrent/multi-threaded applications running on multicore platforms.   In such cases, one not only has to worry about code performance but also about the scalability of the code.  Different types of code profiling tools are used to help with the overall performance analysis process.


With the introduction of the java.util.concurrent (JUC) package in Java 5, a new type of lock was introduced into the Java lanaguage.  There are no tools available in either IBM or externally to profile JUC locks and provide detailed contention information like those provided by JLM for regular Java locks.  Also, usage of the JUC package is becoming more and more popular as more application are either developed or fine tuned to run better on multicore systems.  This absence of a JUC lock profiling tool is the motivation behind the development of our lock tool.

2.   Short Overview of jucprofiler

In juc lock, thread will “stop” execution by following two cases,
1 When a thread A tries to acquire a juc lock, while this lock has been acquired by other thread.  Then thread A has to “stop” its execution, and wait until this lock is released, or time out.
2. When a thread A invokes one of “wait” APIs of java.util.concurrent.locks.Condition, thread A “stop” its execution, until other thread notifies it, or time out.
Let us note the time usage in first case as Contention Time, the second case as Wait Time,

Juc profiler is designed and implemented to capture the time usage of two kinds. 

In order to capture the juc lock runtime data, several juc classes are instrumented offline, and replace original classes in JRE.  Before jucprofiler is used in the first time, user has to run a command to generate PreInstrument.jar.  This step can only be done once, if JRE is not changed.  If users change to another JRE, users have to remove PreInstrument.jar, and re-run this command to generate PreInstrument.jar again.

2.1.1.    Contention Time

We record the allocation of java.util.concurrent.locks.AbstractQueuedSynchronizer and java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject, and assign unique id to them.  For the time usage on lock, we capture the time usage of invoking park(blocker) and parkNanos(blocker, nanos) in class java.util.concurrent.locks.LockSupport, when these two methods are invoked in different places,


Class
Methods
Call Site
java.util.concurrent.locks.LockSupport
park (Object);
parkAndCheckInterrupt() in class AbstractQueuedSynchronizer

parkNanos(Object blocker, long nanos)
doAcquireNanos(int arg, long nanosTimeout)
doAcquireSharedNanos(int arg, long nanosTimeout) in class AbstractQueuedSynchronizer

2.1.2.    Wait Time



Class
Methods
Call Site
java.util.concurrent.locks.LockSupport
park (Object);
Other methods than parkAndCheckInterrupt() in class AbstractQueuedSynchronizer

parkNanos(Object blocker, long nanos)
Other methods than doAcquireNanos(int arg, long nanosTimeout)
doAcquireSharedNanos(int arg, long nanosTimeout) in class AbstractQueuedSynchronizer



3.   How to use jucprofiler

3.1. Run juc profiler

JUC profiler can be used for any java program on JDK 6.  Setting parameters to run, supposing juc profiler is installed in directory $JUCP.


java -Xbootclasspath/p:$JUCP/BCIRuntime.jar:$JUCP/PreInstrument.jar -javaagent:$JUCP/BCIAgent.jar=logger=trace:callStackDepth=10:allocationStackDepth=0:libPath=$JUCP:traceJUC=on -cp .:derby.jar JavaDBDemo
 



After finish running Juc profiler with your program, a trace file named "BCIAgent.***.bci.trace" will be generated, which "***" is a unique time stamp for this execution.



3.2. Trace post process


Run command shown below to get Juc profiling result.

$ java -Xmx1000m -jar $JUCP/BCITraceReader.jar {tracefile} {resultOutputFile}

Where, {tracefile} is the full path of trace file or directory contains trace files, such as BCIAgent.***.bci.trace. {resultOutputFile} is an optional option to set file to store the analysis results, if omitting this option, the analysis results will be printed in console.

Note: The post analysis process to trace file may suffer from some memory overhead, it's better to increase process heap size via -Xmx Java option. In our experiment, analyzing a 160M trace may consume 800M memory.

3.3. Understand profiling result

As figure shown below, the plain text output includes kinds of information, such as lock name, lock contention count and time, lock hold time and count, lock allocation stack trace, duration and stack trace of each lock contention, etc. The result can help user find out the Juc lock contention bottleneck in program.

Before “LEGEND” section, the profiling result report first summarizes all juc lock contentions in program, descending sorted by lock contention count, then contention time. Each summary row item belongs to one of two different types, “AQS” for individual juc lock and “CHM” for ConcurrentHashMap. Since a ConcurrentHashMap is divided by several Segment(s) for elements storage and each Segment is protected by a different juc lock, a ConcurrentHashMap can be viewed as a composition of juc locks from lock perspective. E.g. “CHM@8” below has contention count 276 and contention time 39457000, means that total contention count of all segments locks in “CHM@8” is 276, total contention time of all segments locks in “CHM@8” is 39457000 nanoseconds. This locks grouping helps programmers to identity in which ConcurrentHashMap object the most serious juc lock contentions occur. On the other side, look at the individual juc lock “AQS@1790”, it doesn’t belong to any ConcurrentHashMap object and this lock is used explicitly in program. Note that because lock hold events are not enabled in the example trace, 0 is put in columns HOLD-COUNT and HOLD-TIME.

After “LEGEND” section, the profiling result reports details of each juc lock contention. As result snippet below, for ConcurrentHashMap “CHM@8”, lock contention happens in two segment locks “Lock [AQS@135]” and “Lock [AQS@146]”. For “Lock [AQS@135]”, it contends in one place, follows by contention count, contention time, and full stack back trace of the contention. So does “Lock [AQS@146]”. These details help programmers to locate the lock contention in program and clearly understand which segments of ConcurrentHashMap contend most.


Lock [AQS@135]:

-----------------------------------------------------------------------------------------------------------
Lock Contention 1
CONTD-COUNT: 25
CONTD-TIME: 10827000
Call Stack:
java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:758)
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:789)
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1125)
java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:197)
java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:273)
java.util.concurrent.ConcurrentHashMap$Segment.remove(ConcurrentHashMap.java:530)
java.util.concurrent.ConcurrentHashMap.remove(ConcurrentHashMap.java:934)
org.apache.derby.impl.services.locks.ConcurrentLockSet.unlock(ConcurrentLockSet.java:740)
org.apache.derby.impl.services.locks.ConcurrentLockSet.unlockReference(ConcurrentLockSet.java:784)
org.apache.derby.impl.services.locks.LockSpace.unlockReference(LockSpace.java:275)

End of Lock [AQS@135]:
**************************************************************************************************************


Lock Contention 1
CONTD-COUNT: 22
CONTD-TIME: 2009000
Call Stack:
java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:758)
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:789)
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1125)
java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:197)
java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:273)
java.util.concurrent.ConcurrentHashMap$Segment.remove(ConcurrentHashMap.java:530)
java.util.concurrent.ConcurrentHashMap.remove(ConcurrentHashMap.java:934)
org.apache.derby.impl.services.locks.ConcurrentLockSet.unlock(ConcurrentLockSet.java:740)
org.apache.derby.impl.services.locks.ConcurrentLockSet.unlockReference(ConcurrentLockSet.java:784)
org.apache.derby.impl.services.locks.LockSpace.unlockReference(LockSpace.java:275)



 
Multicore Software Development Tookit Version_2.1

j.u.c Lock Profiler Report

                NAME    CONTD-COUNT          CONTD-TIME     HOLD-COUNT           HOLD-TIME
               CHM@8            276            39457000              0                   0
            AQS@1790             36             4029000              0                   0
             AQS@131             17              630000              0                   0
=================================================================================================
 LEGEND:
                NAME : Name of juc lock(AQS) or ConcurrentHashMap(CHM), format: @
         CONTD-COUNT : Total count of lock contention
          CONTD-TIME : Total time of lock contention in nanosecond
          HOLD-COUNT : Total count of lock hold
           HOLD-TIME : Total time of lock hold in nanosecond
==================================================================================================

ConcurrentHashMap [CHM@8]:

-----------------------------------------------------------------------------------------------------------
Lock [AQS@135]:

-----------------------------------------------------------------------------------------------------------
Lock Contention 1
CONTD-COUNT: 25
CONTD-TIME: 10827000
Call Stack:
java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:758)
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:789)
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1125)
java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:197)
java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:273)
java.util.concurrent.ConcurrentHashMap$Segment.remove(ConcurrentHashMap.java:530)
java.util.concurrent.ConcurrentHashMap.remove(ConcurrentHashMap.java:934)
org.apache.derby.impl.services.locks.ConcurrentLockSet.unlock(ConcurrentLockSet.java:740)
org.apache.derby.impl.services.locks.ConcurrentLockSet.unlockReference(ConcurrentLockSet.java:784)
org.apache.derby.impl.services.locks.LockSpace.unlockReference(LockSpace.java:275)

End of Lock [AQS@135]:
**************************************************************************************************************




Lock [AQS@146]:

-----------------------------------------------------------------------------------------------------------
Lock Contention 1
CONTD-COUNT: 22
CONTD-TIME: 2009000
Call Stack:
java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:758)
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:789)
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1125)
java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:197)
java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:273)
java.util.concurrent.ConcurrentHashMap$Segment.remove(ConcurrentHashMap.java:530)
java.util.concurrent.ConcurrentHashMap.remove(ConcurrentHashMap.java:934)
org.apache.derby.impl.services.locks.ConcurrentLockSet.unlock(ConcurrentLockSet.java:740)
org.apache.derby.impl.services.locks.ConcurrentLockSet.unlockReference(ConcurrentLockSet.java:784)
org.apache.derby.impl.services.locks.LockSpace.unlockReference(LockSpace.java:275)




3.4. Open trace file in Visual Analyzer

There are some views developed in Eclipse to show jucprofiler trace file with tables and figures, which is called Visual Analzyer.  Currently, there are two views for jucprofiler, one is “J.U.C statistics” view, and the other is “J.U.C synchornization view”.

“J.U.C statistics” view is shown as below.  Two columns in right-most are “Contention Times” and “Contention Counts”.  “Allocation Stack” column is about the allcation call site of JUC locks.






“J.U.C synchronization” view is shown as below.  The first lane is Time, indicating when this lock contention occurs.  The second lane is Thread, indicating which thread occurs lock contention.  The third lane is Monitor, indicating which JUC lock is contented.  The last lane is Method, indicating where does the lock contend.



3.5. Online control

During the runing, juc profiler will create a ControlServer listening on port 2009. User can use ControlClient to connect that port and control the behavior of juc profiler, e.g. the trace can be turned on and off on-the-fly,

$ java -cp BCIRuntime.jar com.ibm.msdk.bciruntime.control.ControlClient HOST -m [b|i] -b START -e END

HOST: host name that ControlClient wants to connect to, default is localhost.

-m [b|i]: Mode of ControlClient. b means batch mode, while i means interative mode. In default is interative mode.

-b START: if mode is set to batch mode, START is the time(second) you want to start profiling.

-e END: END is the duration time(second) you want to profiling.

3.5.1.    Interactive mode

A simple shell is provided, and user can type command juc.on and juc.off to turn on and off juc profiler. For example, java -cp BCIRuntime.jar com.ibm.msdk.bciruntime.control.ControlClient, ControlClient will connect to localhost, and open a shell to control juc profiler.


$ java -cp BCIRuntime.jar com.ibm.msdk.bciruntime.control.ControlClient
jucprofiler control> juc.on
juc.on
jucprofiler t control> start
start
jucprofiler control>; stop
stop
jucprofiler control> juc.off
juc.off

 


3.5.2.    Batch mode


$ java -cp BCIRuntime.jar com.ibm.msdk.bciruntime.control.ControlClient localhost -m b -b 2 -e 10
Start tracing in 2 seconds
Start tracing
Stop tracing in 10 seconds
Stop tracing
quit
 

commands can be executed in batch mode. For example, java -cp BCIRuntime.jar com.ibm.msdk.bciruntime.control.ControlClient mtrat-test.dyndns.org -m b -b 10 -e 10, means ControlClient will connect to machine mtrat-test.dyndns.org, start profiler after 10 seconds, and profiling 10 seconds.

4.   Conclusions

With the popularity of multicores, more and more concurrent/multi-threaded Java applications will be developed.  We need better tools for profiling such concurrent applications.  The jucprofiler described in this article fulfills one of the key gaps in Java profiling tools. 
 Both jucprofiler and VisualAnalzyer can be downloaded from http://www.alphaworks.ibm.com/tech/msdk