Monitoring Java thread contention

In multi-threaded Java applications it is possible to see some thread contention due to some design or coding problem. Nevertheless if we can pinpoint the contention then it will be easy to find a way to solve the problem. Here we will see how to identify where the contention is and what the lock behind that contention is.

Using  DTrace's monitor probes we can track the contention. Here you can download the Java source code that I used.

In the code you can see that I am using a plain Java Object as a monitor object (also called as lock object).

Object monitorObject = new Object(); // our intrinsic lock

Inside the run() method of my MyCpuIntensiveTask, a executor thread will obtain this lock object before doing some CPU intensive calculation. By the mean time all the other executor threads will be waiting for the lock. Once the first thread exists the synchronized block one of the waiting thread will be granted the lock and so on....

DTrace has the following monitor related probes.

•     monitor-contended-enter
•     monitor-contended-entered
•     monitor-contended-exit
•     monitor-wait
•     monitor-waited
•     monitor-notify
•     monitor-notifyAll

The following is the DTrace script (using two of the probes) that I have used to test my Java code.

monitor-contended-enter
{
this->threadid = arg0;
this->monitorid = arg1;
this->monitorclass = (string)copyin(arg2, arg3+1);
printf("Thread %d trying to acquire monitor %d of type %s", this->threadid, this->monitorid, this->monitorclass);
}

monitor-contended-entered
{
this->threadid = arg0;
this->monitorid = arg1;
this->monitorclass = (string)copyin(arg2, arg3+1);
printf("Thread %d acquired monitor %d of type %s", this->threadid, this->monitorid, this->monitorclass);
}

• monitor-contended-enter - will be fired when a thread is trying to acquire a lock which is already held be another thread.

• monitor-contended-entered - will be fired when a blocked thread enters successfully after acquiring the lock.

The following is the Java code's output. As you can see Thread-7 wasn't blocked since it was the first one to acquire the lock, whereas the others (8,9,10,11) were blocked for some time.

ram@opensolaris:~$ java -XX:+DTraceMonitorProbes -XX:+ExtendedDTraceProbes ThreadContention
Thread 7 trying to acquire lock.
Thread 7 entered.
Thread 8 trying to acquire lock.
Thread 9 trying to acquire lock.
Thread 10 trying to acquire lock.
Thread 11 trying to acquire lock.
Thread 7 exiting.
Thread 11 entered.
Thread 11 exiting.
Thread 10 entered.
Thread 10 exiting.
Thread 9 entered.
Thread 9 exiting.
Thread 8 entered.
Thread 8 exiting.

Exactly the same information is provided by the DTrace script as well but in a more detailed manner. Here we can see the monitor object to acquire which the threads were contending. 135291856 is the id of the object that the threads were trying to acquire. It is of type java/lang/Object. Ofcourse we can use an Integer or any other Java object as a lock.

ram@opensolaris:~# dtrace -s threadContentionMonitor.d
dtrace: script 'threadContentionMonitor.d' matched 2 probes
CPU     ID                    FUNCTION:NAME
  0   5076 __1cNObjectMonitorFenter6MpnGThread__v_:monitor-contended-enter Thread 8 trying to acquire monitor 135291856 of type java/lang/Object
  0   5076 __1cNObjectMonitorFenter6MpnGThread__v_:monitor-contended-enter Thread 9 trying to acquire monitor 135291856 of type java/lang/Object
  0   5076 __1cNObjectMonitorFenter6MpnGThread__v_:monitor-contended-enter Thread 10 trying to acquire monitor 135291856 of type java/lang/Object
  0   5076 __1cNObjectMonitorFenter6MpnGThread__v_:monitor-contended-enter Thread 11 trying to acquire monitor 135291856 of type java/lang/Object
  0   5077 __1cNObjectMonitorFenter6MpnGThread__v_:monitor-contended-entered Thread 11 acquired monitor 135291856 of type java/lang/Object
  0   5077 __1cNObjectMonitorFenter6MpnGThread__v_:monitor-contended-entered Thread 10 acquired monitor 135291856 of type java/lang/Object
  0   5077 __1cNObjectMonitorFenter6MpnGThread__v_:monitor-contended-entered Thread 9 acquired monitor 135291856 of type java/lang/Object
  0   5077 __1cNObjectMonitorFenter6MpnGThread__v_:monitor-contended-entered Thread 8 acquired monitor 135291856 of type java/lang/Object