Getting performance or timing information about an operation in a multithreaded Java application has always been a challenge. The problem has been that most stopwatch functions accounted for the time that the thread took to execute, but included time from other threads executing in parallel in the background. These other threads cause your thread to yield for a period and thus skew your performance statistics. The way around it was to use a performance tool that could track the other threads and calculate an approximation of how long your thread actually took to execute. That was until JDK 1.5 exposed theThreadMXBean. OK, JDK 1.5 came out several years ago, but it’s still useful.

The java.lang.management.ThreadMXBean provides approximate nanosecond statistics of how long a thread has been executing. The bean measures actual CPU time for the thread, so there is none of the usual doubt about whether the time of the thread is being effected by other threads.

The following sample uses the ThreadMXBean to get timing statistics for three different threads. We still use System.currentTimeMillis to collect some traditional stopwatch time, which will be explained later. Comments containing numbers highlighted in red will be explained after the code.

package com.savvyduck.threadtest;

import java.lang.management.ManagementFactory;

import java.lang.management.ThreadMXBean;

public class TimeDemo {

// Time conversion constants

private static final int MS_SECOND = 1000;

private static final int MS_MINUTE = 60000;

private static final int MS_HOUR = 3600000;

private static final int NS_MILLISECOND = 1000000;

public static void main(String[] args) {

// 1

long totalTime = System.currentTimeMillis();

Thread t1 = new Thread(new TimeDemo.WorkTimeThread());

Thread t2 = new Thread(new TimeDemo.SleepThread());

Thread t3 = new Thread(new TimeDemo.SleepStringThread());

t1.start();

t2.start();

t3.start();

// Don't let this thread exit until the other threads finish

// This gives us the total time the application took to run.

try {

// 2

t1.join();

t2.join();

t3.join();

} catch (InterruptedException e) {

e.printStackTrace();

}

System.out.println("Total Time: "

+ getDuration(System.currentTimeMillis() - totalTime));

}

// Converts a time in MS to human readable time

// formatted hours:minutes:seconds.milliseconds

public static String getDuration(long durationMS) {

long tmpTime = durationMS;

long hours = tmpTime / MS_HOUR;

tmpTime -= hours * MS_HOUR;

long minutes = tmpTime / MS_MINUTE;

tmpTime -= minutes * MS_MINUTE;

long seconds = tmpTime / MS_SECOND;

tmpTime -= seconds * MS_SECOND;

return hours + ":" + minutes + ":" + seconds + "." + tmpTime;

}

// Base thread implementation with stop watch functions.

abstract static class BaseThread implements Runnable {

// Starts the stopwatch functions, calls the child class's execute()

// method, then reports the timing when the execute() method finishes.

public void run() {

// 3

long threadId = Thread.currentThread().getId();

System.out.println(threadId + " starting " +this.getClass());

long startTime = System.currentTimeMillis();

ThreadMXBean threadMXBean =

ManagementFactory.getThreadMXBean();

long startTimeInNs = threadMXBean.getCurrentThreadCpuTime();

// Do the "real" work

this.execute();

// 4

if (threadMXBean.isThreadCpuTimeSupported()) {

if (threadMXBean.isThreadCpuTimeEnabled()) {

long threadTime =

threadMXBean.getCurrentThreadCpuTime();

long stopWatchThreadTime = threadTime - startTimeInNs;

System.out.println(threadId + " Total Thread Time: "

+ getDuration(threadTime / NS_MILLISECOND));

System.out

.println(threadId

+ " Stopwatch Thread Time: "

+ getDuration(stopWatchThreadTime

/ NS_MILLISECOND));

} else {

System.out.println(threadId

+ " CPU Time is not enabled");

}

} else {

System.out.println(threadId + " CPU time is not supported");

}

long stopWatchTime = System.currentTimeMillis() - startTime;

System.out.println(threadId + " Traditional Stopwatch Time: "

+ getDuration(stopWatchTime));

}

protected abstract void execute();

}

static class WorkTimeThread extends BaseThread {

@Override

protected void execute() {

long counter = 0;

ThreadMXBean threadMXBean

= ManagementFactory.getThreadMXBean();

long startTimeInNs = threadMXBean.getCurrentThreadCpuTime();

long hashCode = 0;

// 5

while ((threadMXBean.getCurrentThreadCpuTime()

- startTimeInNs)

 / NS_MILLISECOND < 6000) {

counter++;

String tmp = "" + counter;

hashCode = tmp.hashCode();

}

System.out.println(hashCode);

}

}

static class SleepThread extends BaseThread {

@Override

protected void execute() {

try {

// 6

Thread.sleep(2000);

} catch (InterruptedException e) {

e.printStackTrace();

}

}

}

static class SleepStringThread extends BaseThread {

@Override

protected void execute() {

try {

Thread.sleep(2000);

} catch (InterruptedException e) {

e.printStackTrace();

}

// 7

String tmp = "";

long hashCode = 0;

for (int counter = 0; counter < 1000; counter++) {

tmp += counter;

hashCode = tmp.hashCode();

}

System.out.println(hashCode);

}

}

}

We get everything started in the main() method (1) . We start three threads that will test thread timing in a variety of different ways. The sample also grabs a starting time for a traditional System.currentTimeMillis based stopwatch so we can see how long the entire process takes as we are interested in the total execution time of the application as well as each thread. Making sure we get this information is accomplished by joining (2) to our three new threads, which prevents the main() methods thread from exiting before the other three threads.

There are four nested classes. The first is the BaseThread class that implements the run() method of the Runnable interface. The run() method (3) displays a brief message telling us about the derived class and its thread ID as well as creating a tradition and a ThreadMXBean stopwatch. We then call the child class’s execute() method, which does the work that will will gather timing statistics about.

The last stopwatch code (4) checks that the ThreadMXBean’s timing statistics are enabled, does the timing calculation and displays the results. There are several tests to see if the profiling data is available. Some virtual machines may not have implemented complete profiling information so these tests are necessary or thegetCurrentThreadCPUTime() will return a -1, which should be good enough anyway. The code then does a conversion from the nanosecond time back to milliseconds and calls a method for converting that timing values into human readable time.

Let’s look at the various test cases. The WorkingThreadTime performs a simple calculation (5), but it has to execute for 6 seconds. The calculation is just to add some real work to the loop just in case a good optimizer got in there and detected that the loop does nothing and optimizes it away. The loop uses theThreadMXBean.getCurrentCPUTime to ensure that the thread runs for at least 6 seconds.

The SleepThread class just calls Thread.sleep() for 2 seconds (6) and returns. Thesleep() method yields the current thread and doesn’t come back until the end of the duration. It should provide us with different results than the WorkingTimeThread in that the CPU time tied up by the SleepThread should be near zero.

Then we have the SleepStringThread, which also sleeps for a few seconds and then does a simple string calculation (7) in a loop. The idea is to mix a sleep operation and a CPU intensive operation to note the impact on timing statistics.

Running the application produces the following output:

9 starting class com.savvyduck.threadtest.TimeDemo$WorkTimeThread

10 starting class com.savvyduck.threadtest.TimeDemo$SleepThread

11 starting class com.savvyduck.threadtest.TimeDemo$SleepStringThread

10 Total Thread Time: 0:0:0.0

10 Stopwatch Thread Time: 0:0:0.0

10 Traditional Stopwatch Time: 0:0:2.3

-1603650502

11 Total Thread Time: 0:0:0.9

11 Stopwatch Thread Time: 0:0:0.9

11 Traditional Stopwatch Time: 0:0:2.15

2048581106

9 Total Thread Time: 0:0:6.4

9 Stopwatch Thread Time: 0:0:6.0

9 Traditional Stopwatch Time: 0:0:6.119

Total Time: 0:0:6.122

Each line begins with the thread ID to make it easier to understand which thread’s timing statistics are being displayed. The “Total Thread Time” lines show the total amount of time spent in the thread as calculated by ThreadMXBean. This time includes startup information and is interesting, though probably beyond what you may be interested in tracking. The “Stopwatch Thread Time” lines show the time the operation in the thread took to execute. The “Traditional Stopwatch Time” is the same as the “Stopwatch Thread Time” lines except it is calculated using System.getCurrentMillis(). Finally, the “Total Time” line tells us how long the application executed so that we can see why it useful to use the ThreadMXBean at all.

Thread 10 was our sleep thread and we can see that it allocated 0 ms worth of CPU time. However, it did not return for 2 seconds. This raises the importance of using System.getCurrentMillis() that the method is important for understanding how long an operation took from a user perception point of view. The operation took 0 ms form the system point of view, but it still took 2 seconds for the method to return. Those 2 seconds matter to the user in a real world situations, as it may mean that a web page took 2 seconds to return.

Thread 11 was our sleep and string thread. We again see that the thread took awhile to return but the CPU time was higher than 0 thanks to the string operation.

Finally, thread 9 shows that it allocated 6 seconds of CPU time before returning. This helps to show that we can use the results ofThreadMXBean.getCurrentCPUTime to add delays to an application or perform timing operations that are accurate to the thread’s real execution time..

The value of these operations is that we can now distinguish between the time spent performing the work of a given algorithm without the noise of the time spent in other threads. A more concrete example may help to beat the dead horse further.

Web applications are always running in a multithreaded environment. Using stopwatch time to track the time it takes for all major operations helps to show which operations are most adversely effecting users. We may want to make performance modifications if we see a call to some arbitrary method always takes 10 seconds. However, these timing statistics can be false positives if other operations are skewing the time. It may be that another thread is actually very CPU of resource intensive and that may be what is causing the performance problem, however, you’ve been led to the wrong method because of using System.currentTimeMillis. The combination of System.currentTimeMillis() andThreadMXBean.getCurrentThreadCPUTime() though would tell you how long it took for the user to get his data and how much time was spent in the actual thread doing work.

There are several other methods in ThreadMXBean for doing other thread related measurements. Another useful timing operation is getThreadUserTime(). This method shows the time spent in user code rather than total CPU time. Kernel time can throw off some statistics, especially if there is a lot of IO. One may argue that they just want to see how the algorithm ran rather than seeing the total system impact. Getting down to the difference between user and kernel time is valuable if it encourages you to use system resources more wisely, however, you don’t always know which method may require diving into a kernel operation and so it may become a somewhat futile exercise of performance optimization.

Using ThreadMXBean is an accurate way of seeing how long operations take without having to consider other threads in the system. This can clearly help improve the accuracy of your timing information and help the improvement of your application.