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. 

2.1. Instrumentation

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

Lock-free Deque in Amino project

At fist, Amino Deque implements the algorithm invented by Maged M. Michael in the great paper "CAS-Based Lock-Free Algorithm for Shared Deques".

The deque is a doublely ended queue. Insertion and deletion can happen at both ends. Internally, this deque is represented as a doubly linked list. For each deque, there is an anchor object which comprise of 2 pointers and 1 flag. The pseudo-code is as shown below:

Anchor{
Node left, right;
enum {STABLE, LEFT, RIGHT} flag;
} anchor;

The key idea of this deque algorithm is to automatically updating this anchor field when deque is being changed. An anchor object occupies more than a machine word. Until now, there is no portable way to automatically updating such an "wide" object in Java. Actually, we don't need a wider "CAS" for implementing lock free deque. The idea is simple:

1. We make Anchor immutable and use an AtomicReference to wrap it
2. Whenever we want to update an anchor, we create a new Anchor object and use AtomicReference.compareAndSwap() to update the anchor automatically.

Above approach behaves differently as a wider "CAS" for some special cases. For example, it will judge equalism by comparing identity. It means even two objects has exactly same internal states, "CAS" will fail in comparison phase.
Besides, there is an object allocated for each updating. Will this be a big overhead? Since memory allocation in Java is relatively cheaper than other languages, this approach works well when frequency is moderate. Performance charts are shown below:



This deque is not completely compatible with standard JDK API. For example, it doesn't support element deletion by iterator.remove(). This is normal to Amino lock-free components. To implement such an unusual method for deque, performance of other frequently used methods such as addFirst()/pollFirst()/addLast()/pollLast() will become much slower than before. That's the reason why Amino library choose not to support such methods. I personally don't think it's a big problem. After all, if a data structure supports deletion in the middle, can it still be called a deque/queue/stack?

Performance of Amino Queue

Now we got the performance result of Amino Queue in an 8-core X86 machine which is running Linux and IBM JDK v6. We compared the performance of Amino's LockFreeQueue and java.util.concurrent.ConcurrentLinkedQueue. Both of the two queues used lock-free algorithm. Amino queue's algorithm comes from the brilliant paper "An Optimistic Approach to Lock-Free FIFO Queues" of Edya Ladan-Mozes and Nir Shavit. Result of the micro-benchmark shows Amino queue has some advantage:


The key idea behind the new algorithm is a novel way of replacing the singly-linked list of Michael and Scott, whose pointers are inserted using a costly compare-and-swap (CAS) operation, by an optimistic doubly-linked list, whose pointers are updated using a simple store, yet can be fixed if a bad ordering of events causes them to be inconsistent.

Performance of Amino Stack

In Amino library, stack is the simplest and yet the most useful component. According to our performance test, Amino's stack is far more faster than a lock-protected stack. Today I rerun the performance test on a 8-core X86-64 machine and result is as shown in below diagrams:










In the performance test, the 1st step is warm-up with 8 threads. That's the reason that first column of every bar charts has a label of "8". After that, we increase the thread number from "1" to "128". The test complete in 1,039.557 second.

The code (Apache license) of LockFreeStack can be downloaded at Amino's SF.net SVN

Performance Improvement in Amino C++ Library

In version 0.5.1, major improvement of Amino C++ library is about performance. Now performance of many data structures are relatively improved. The biggest improvement is the LockFreeList and LockFreeOrderedList. Each of them has made nearly 100% improvements on PPC.

The steps for performance tuning are as follows:

1. Profile all the original data structure under X86 and PPC. ( Use oprofile under X86, tprof under PPC)
2. Analyze the oprofile results and tprof results of *.etm files by VPA (Virtual Performance Analyzer) tool. Find the bottle neck and infer the possible reason.
3. Trace back to source code to fix the bottle necks get from step 2.
4. Retest the data structure with different scale of operation numbers, meanwhile fix bugs if any. Compare the performance with the original one.

All the performance tests have been done on X86 and PowerPC servers after bug fixing and code refine, and the performance is evaluated by the throughput per second. The approximate average improvements of all the C++ data structures are as follows.

Data Structure	Performance Improved
	X86	PPC
LockFreeStack	50%	31%
LockFreeEBStack	30%	N/A
LockFreeQueue	N/A	N/A
LockFreeShavit-Queue	N/A	N/A
LockFreeDeque	33%	298%
LockFreeList	20%	100%
LockFreeOrderedList	N/A	132%
LockFreeSet	40%	90%

Diagram 1 Performance average improvements ratio

Some explanation about the diagram:

1. The figures are approximate ones which only show the improvement degree.
2. LockFreeDeque’s huge improvement on PPC because of its implementation originally is not lock free. This time it was re-implemented in lock free way.
3. Because of the hardware difference, the performance improvement figures are not the same between X86 and PPC.

The performance chart of LockFreeOrderedList:

Diagram 2 Original performance of LockFreeOrderedList on PPC.

Diagram 3 Tuned performance of LockFreeOrderedList on PPC

The main points for improving the performance are as follows:

1.Change the improper memory order type.

As we know, the overhead time of lock free components are mainly on the synchronization of atomic operations, such as CAS, LL/SC, whereas these operations are mainly controlled by the memory ordering types. The memory order has five different types (memory_order_relaxed, memory_order_acquire, memory_order_release, memory_order_acq_rel, memory_order_seq_cs), and the sequential requirements of them becomes stronger as the given sequence. So if misuse the memory order type could waste a lot of time for synchronization.

2.Fixing bugs.

There are some tough bugs existed before I did the performance tuning which could lead to get wrong performance data.
For example, there are peekTop() functions in LockFreeStack, the original implementation didn’t protect the top pointer and get the value of top->data. It’s possible the top pointer had been deleted before the operation of top->data. Because of no protection by SMR, there is no synchronization, so the performance result is wrong.

3.Refine redundant code.

Some codes can be refined to be more succinct while the logic is not changed, especially for the time-consuming loop sections.

~LockFreeQueue() {

- Node* first = head.load(memory_order_relaxed)->next.load(

- memory_order_relaxed);

- while (NULL != first) {

- if (first == tail.load(memory_order_relaxed)) { /*last node in the queue*/

- delete first;

- break;

- }

- Node* next = first->next.load(memory_order_relaxed);

+ Node* first = head.load(memory_order_relaxed);

+ Node* next = NULL;

+ while (NULL != first) {

+ next = (first->next).load(memory_order_relaxed);

delete first;

first = next;

}

-

- delete head.load(memory_order_relaxed);

}




Diagram 4 Code snippets for refine
( “-” means the original code lines, “+” means refined code lines.)
As you can see, after refining, the destructor has reduced 5 lines of code, but the logic is the same.

4.Reduce unnecessary function invocation.

Some times, we can cache the function invocation results by local variables instead of calling the function every time.
For example, each time if we want to use SMR to protect a pointer, we have to call getHPRec(), this function is time consuming and the function return value will be used several times in a big function. If we can have a local variable to cache the value, we can save a lot of time.

5.Utilize good tools.

As we all know, C++ program is memory error prone, so the usage of memory in our library is very critical for the correctness. I can still remember segment fault is very usual.
We can use valgrind to check the memory usage. It’s useful, since I fixed a bug in ebstack destructor with this tool.
We also can use oprofile and tprofile to analyze the bottle neck of our program. It’s easy to use VPA (developed by IBM) to get the time consuming code sections in ASM form.

6.Choose the suitable optimization options.

Before running the performance testing case, it’s necessary to choose the best optimization option of the compiler. Different compilers have different options. I want to mention the XLC on AIX, according to the compile manual, the highest optimization option is -O5, –qinline and -qipa, but when I compile the data structure which contains String, if added the –qipa option, there was segment fault, so I removed this option when compiling data types of String.

All in all, through nearly two month work, the C++ components’ performance has got big improvement. Not only for the performance, but also fixed some tough bugs. At the same time, the SMR has been extended to support aligned memory management.

ANN: Concurrent Building Blocks: 0.5.3 released!

The Amino team is pleased to announce a new release of Concurrent
Building Blocks (Apache License v2).
(1) News in this release:

• Added PPC version of C++ components. Now C++ components support three platforms(X86_32/Linux/GCC, X86_64/Linux/GCC, PPC32/AIX/XLC)
• Fixed several tough bugs
• Dramatically improved performance of C++ components
• Extended SMR for managing aligned memory

(2)The primary goal is to develop concurrent Java/C++ libraries that
can be used by programmers. Components are grouped into four
categories:

• Data Structures
• Parallel Patterns
• Parallel functions
• Atomics and STM

(3) Links

• Download and learn more from http://amino-cbbs.sourceforge.net/
• Discussion: https://groups.google.com/group/aminoprj
• Project Blog: http://aminoprj.blogspot.com/
• SourceForge: https://sourceforge.net/projects/amino-cbbs/
• ssue Tracker: https://sourceforge.net/tracker2/?group_id=209259

And always, your feedbacks are welcome!

Amino Team

MTRAT helps opensource projects find concurrent errors

Developing, testing, and debugging multithreaded programs are still very difficult; it is all too easy to create concurrent programs that appear to work, but fail when it matters most: in production, under heavy load. The most common parallel errors are data race and deadlock. These errors are typically harmful and hard to locate. Multi-Thread Run-time Analysis Tool(MTRAT) is a tool that detects and analyzes potential data race and deadlock conditions that might occur in multithreaded Java programs.

Apache FtpServer is a popular open source Java FTP server. In order to handle multiple requests at the same time, threading and concurrency are introduced in FtpServer core and its dependent library MINA, a network application framework. Let's exploit MTRAT on FtpServer to see what happens and apply MTRAT in FtpServer is easy(my operating system is Linux, so this showcase is done under Linux).

1. Download MTRAT from its webiste http://www.alphaworks.ibm.com/tech/mtrat, and configure it following the user manual. Suppose mtrat is extracted under ~/MTRAT.
   
2. The FtpServer startup script file ftpd.sh locates under bin folder, open ftpd.sh and find "$JAVACMD" -classpath "$FTPD_CLASSPATH" $MAIN_CLASS $@ in last few lines, this command is for invoking FtpServer application. Comment this line with heading "#" and add one statement to replace "$JAVACMD" with "mtrat" like this,
   ~/MTRAT/mtrat/mtrat -x java.*:sun.*:javax.*:com.*:org.eclipse.*
   :org.apache.xerces.*:org.apache.lucene.* -Dcom.ibm.mtrat.dbg.cl=false -Dcom.ibm.mtrat.novolatile=true -Dcom.ibm.mtrat.threadcache=true -Dcom.ibm.mtrat.osm=true -classpath "$FTPD_CLASSPATH" $MAIN_CLASS $@
   #"$JAVACMD" -classpath "$FTPD_CLASSPATH" $MAIN_CLASS $@
   
3. Save ftpd.sh and run it.
   

After Ftpserver launches with MTRAT, we open two new consoles and login as admin and anonymous respectively, then admin uploads a file to ftpserver while anonymous download a file from ftpserver. You will see data races are reported in Ftpserver console.

We submit two data race bugs found by MTRAT, one is in FtpServer([#FTPSERVER-122]Data races are found in FtpStatisticsImpl) while the other is in MINA([#DIRMINA-651]Data Race in org.apache.mina.core.session.AbstractIoSession), and attach the data race report generated by MTRAT.

Positive feedback is received from the Apache community, these two data race bugs are confirmed by the community leader and [#DIRMINA-651] is committed to be fixed in MINA 2.0.0-RC1 while [#FTPSERVER-122] will be fixed after component refactor.

1. "Thanks a lot for the analysis! The reason why I did not fix the race conditions already is that I'm planning to bring FtpServers statistics handling more in line with MINA.
   Anyways, I would much appreciate further analysis on the source code, especially after the statistics implementation is updated."
   -- Niklas Gustavsson
   
2. "Some of these races are in the idle time checking, which is a core functionality in MINA of course. Those we have to fix."
   -- Niklas Gustavsson
   

In addition to data race bugs found in FtpServer, Bug 45608 in Tomcat is confirmed by community too. MTRAT is proven to be practical for real-world application and useful for parallel program developers.

Multi-threaded Runtime Analysis Tool Link

http://www.alphaworks.ibm.com/tech/mtrat