java multithreaded application: getting thread blocked time

I am calling开发者_JAVA技巧 threadInfo.getBlockedCount() and getBlockedTime() just before the worker threads die. I get a blocked count of 1, but a blocked time of 0. Does this mean that the thread was blocked but it the blocked time was less than a millisecond?

If the above is true, is there another way to get accurate time for which a thread was blocked?

However, the blocked time of a thread (being blocked) only seems to return a non-zero result if the ThreadMXBean#setThreadContentionMonitoringEnabled(true) is called * before * starting the thread. Otherwise, it'd always return zero (or -1 if the contention monitoring is disabled). The code below demos this:

import java.lang.management.ManagementFactory;
import java.lang.management.ThreadInfo;
import java.lang.management.ThreadMXBean;

public class BlockedTimeMain {
    public static void main(String[] _) throws InterruptedException  {
        ThreadMXBean mbean = ManagementFactory.getThreadMXBean();
        final Object lock = new Object();

        Thread t = new Thread("Foo") {
            @Override public void run() {
                // This will block forever
                synchronized(lock) {
                    // Will never get here
                    System.out.println("Got the lock from " + Thread.currentThread());
                }
            }
        };
        synchronized(lock) {
            t.start();
            mbean.setThreadContentionMonitoringEnabled(true);
            for (int i=0; i < 5; i++) {
                ThreadInfo[] tis = mbean.getThreadInfo(new long[]{t.getId()}, true, true);
                ThreadInfo ti = tis[0];

                if (ti.getThreadId() != t.getId())
                    throw new AssertionError("Unexpected " + t.getId() + " vs " + tis[0].getThreadId());

                System.out.println(t + " " + ti.getThreadState() 
                        + ": blockedTime=" + ti.getBlockedTime() + "/" + ti.getBlockedCount() 
                        + ", waitTime" + ti.getWaitedTime() + "/" + ti.getWaitedCount());
                Thread.sleep(1000);
            }
        }
        System.exit(0);
    }
}

Sample Output:

Thread[Foo,5,main] BLOCKED: blockedTime=0/1, waitTime0/0
Thread[Foo,5,main] BLOCKED: blockedTime=0/1, waitTime0/0
Thread[Foo,5,main] BLOCKED: blockedTime=0/1, waitTime0/0
Thread[Foo,5,main] BLOCKED: blockedTime=0/1, waitTime0/0

Can test it out, with something like:

import java.lang.management.ManagementFactory;
import java.lang.management.ThreadInfo;
import java.lang.management.ThreadMXBean;

public class BlockedTimeMain {
    public static void main(String[] _) throws InterruptedException  {
        ThreadMXBean mbean = ManagementFactory.getThreadMXBean();
        mbean.setThreadContentionMonitoringEnabled(true);
        final Object lock = new Object();

        Thread t = new Thread("Foo") {
            @Override public void run() {
                // This will block forever
                synchronized(lock) {
                    // Will never get here
                    System.out.println("Got the lock from " + Thread.currentThread());
                }
            }
        };
        synchronized(lock) {
            t.start();
            for (;;) {
                ThreadInfo[] tis = mbean.getThreadInfo(new long[]{t.getId()}, true, true);
                ThreadInfo ti = tis[0];

                if (ti.getThreadId() != t.getId())
                    throw new AssertionError("Unexpected " + t.getId() + " vs " + tis[0].getThreadId());

                System.out.println(t + " " + ti.getThreadState() 
                        + ": blockedTime=" + ti.getBlockedTime() + "/" + ti.getBlockedCount() 
                        + ", waitTime" + ti.getWaitedTime() + "/" + ti.getWaitedCount());
                Thread.sleep(1000);
            }
        }
    }
}

Sample Output:

Thread[Foo,5,main] BLOCKED: blockedTime=2/1, waitTime0/0
Thread[Foo,5,main] BLOCKED: blockedTime=1007/1, waitTime0/0
Thread[Foo,5,main] BLOCKED: blockedTime=2012/1, waitTime0/0
Thread[Foo,5,main] BLOCKED: blockedTime=3016/1, waitTime0/0
Thread[Foo,5,main] BLOCKED: blockedTime=4021/1, waitTime0/0
Thread[Foo,5,main] BLOCKED: blockedTime=5025/1, waitTime0/0
Thread[Foo,5,main] BLOCKED: blockedTime=6028/1, waitTime0/0
Thread[Foo,5,main] BLOCKED: blockedTime=7032/1, waitTime0/0
Thread[Foo,5,main] BLOCKED: blockedTime=8035/1, waitTime0/0

Yes it does mean that it was blocked for 0 milliseconds. i.e there was no blocking involved. The thread did not wait for the monitor lock to enter the synchronized block/method.

You are seeing this because you must have written a simple program with one or two threads, and there is no latency. You will need to induce really heavy load on the threads to actually see positive values.

Apparently, that is what it means, and apparently there isn't a way to get the time to a greater precision. (The javadocs say that the blocked time may be measured and (presumably) accumulated with greater precision, but the ThreadInfo API doesn't expose this information, and there doesn't appear to be any other kosher way to get it.)

I say "apparently", because the javadoc actually describes the time values as "the approximate accumulated elapsed time". This leaves open the possibility that this could be a very rough approximation, possibly with the same granularity as the clock values returned by System.getCurrentTimeMillis(). Also, it doesn't say if accumulated times measured with a high precision timer would be rounded or truncated when converted to millisecond values; i.e. whether zero means "less than 1 millisecond" or "less than 0.5 milliseconds".