ReentrantLock.TryLock（长超时，TimeUnit单元）在无法获取锁时不会超时

Question

在我的项目与Ehcache集成期间（与BlockingCache装饰器集成，它在内部使用ReentrantLock），我在一台机器上发现了一些奇怪的行为。有时，等待通过ReentrantLock.tryLock(timeout，TimeUnit)-调用大于timeout的时间获取锁的线程不会被超时（结果为“false”）。JVM将它们留在后面，它们被阻塞，直到另一个线程释放这个锁。简而言之：ReentrantLock.tryLock（长超时，TimeUnit单元）的行为与ReentrantLock.Lock（）类似。

null

@Test
public void test() throws Exception {
    System.out.println("debug___");
    int failCount = 0;
    final int REPEAT_TIMES = 50 * 1000;
    for (int i = 0; i < REPEAT_TIMES; i++) {
        System.out.println("");
        try {
            testOne(i);
            System.out.println("debug___" + i + ":ok");
        } catch (Throwable e) {
            failCount++;
            System.err.println(i + ":" + e.getMessage());
            System.out.println(i + ":" + e.getMessage());
            System.out.println("debug___" + i + ":fail");
        }

    }

    System.out.println("fails:" + failCount);
    Assert.assertEquals("Failed " + failCount + "/" + REPEAT_TIMES, 0, failCount);
}

public void testOne(final int i)  throws Exception{
    final StringBuilder sb = new StringBuilder();
    try {
        final ReentrantLock lock = new ReentrantLock();
        final Semaphore s = new Semaphore(0);

        Thread t1 = new Thread() {
            @Override
            public void run() {

                try {
                    sb.append(i + ":" + 1).append("\n");
                    boolean locked = lock.tryLock(1000, TimeUnit.MILLISECONDS);
                    sb.append(i + ":" + 2 + " " + locked).append("\n");
                    s.release();
                    sb.append(i + ":" + 3).append("\n");
                    Thread.sleep(5000); // !!! release lock after 5s
                    sb.append(i + ":" + 4 + " \n");
                    lock.unlock();
                    Thread.sleep(2000);
                } catch (Throwable e) {
                    e.printStackTrace();
                }

            }
        };

        t1.start();
        sb.append(i + ":" + "m1").append("\n");
        s.acquire();
        sb.append(i + ":" + "m2").append("\n");

        long start = System.currentTimeMillis();

        boolean tryLock = lock.tryLock(50, TimeUnit.MILLISECONDS); // try acquire lock for 50ms

        long stop = System.currentTimeMillis();
        long diff = stop - start;

        if (tryLock)
            throw new IllegalStateException("it is really bad.... blocked for a [ms]:" + diff);
    } finally {
        System.out.print(sb.toString());
    }

}

更新

下面是阻止机器的第二个测试：

import java.util.concurrent.locks.*;
import java.util.concurrent.*;

public class TestLock2 {
final ReentrantLock lock = new ReentrantLock();
volatile int inx = 0;

public static void main(String[] a) throws Exception {
    TestLock2 t = new TestLock2();
    t.test();
}

public void log(String s) {
    System.out.println(s);
    System.err.println(s);
}

public void test() throws Exception {
    Thread t1 = new Thread() {
        @Override
        public void run() {
            lock.lock();
            System.out.println("ok");
            while (true) {
                try {
                    Thread.sleep(60 * 1000);
                    log(inx
                            + "                                                     "
                            + new java.util.Date());
                } catch (Exception e) {
                }
            }
        }
    };
    t1.start();
    Thread.sleep(500); // wait for lock to be locked

    System.out.println("debug___");
    int failCount = 0;
    final int REPEAT_TIMES = 20000;
    for (int i = 0; i < REPEAT_TIMES; i++) {
        try {
            inx = i;
            testOne(i);
        } catch (Throwable e) {
            failCount++;
            log(i + ":" + e.getLocalizedMessage());
            log("debug___" + i + ":fail");
        }
    }
    log("Failed " + failCount + "/" + REPEAT_TIMES);
}

public void testOne(final int i) throws Exception {
    long start = System.currentTimeMillis();

    try {
        boolean tryLock = lock.tryLock(200, TimeUnit.MILLISECONDS);
    } finally {
        long diff = System.currentTimeMillis() - start;
        log(i + ":" + diff + "ms");
    }
}

}

“C1 CompilerThread0”后台进程prio=10 tid=0x02b55400 nid=0x7a4正在等待条件[0x00000000]java.lang.Thread.State：可运行

“附加侦听器”后台进程prio=10 tid=0x02b52c00 nid=0x2450等待条件[0x00000000]java.lang.Thread.State：RUNNABLE

“Signal Dispatcher”后台进程prio=10 tid=0x02b51800 nid=0x11d4 runnable[0x00000000]java.lang.Thread.State：runnable

Answer 1

一种可能的解释可以是，在主进程获得系统时间并且线程将开始Hibernate之后，系统进程调度程序将您的进程从执行中移除。5秒后，继续执行：线程已经Hibernate5秒，主线程获得锁。不过有点奇怪。

无论如何，我建议您使用一个探查器，它将让您看到真正发生了什么。