在我的项目与 Ehcache 集成期间（使用 BlockingCache 装饰器，它在内部使用 ReentrantLock）我在一台机器上发现了一些奇怪的行为。有时，等待通过 ReentrantLock.tryLock(timeout,TimeUnit) 获取锁的线程不会超时（结果为“假”）。JVM 将它们抛在脑后，它们一直处于阻塞状态，直到该锁被另一个线程释放。简而言之：有时 ReentrantLock.tryLock(long timeout, TimeUnit unit) 的行为类似于 ReentrantLock.lock()。
这种情况只发生在一台机器上，规格如下：
- windows server 2003 R2 (5.2.3790 SP2 build 3790)
- vmware esx 3.5
- xeon x5675 (2x cpu x86 6 Model 44 Stepping 2 GenuineIntel)
我在 jre 1.6(1.6.0_31, 1.6.0_37) 上运行它
我在另外两台机器上测试过，效果很好（这个奇怪的问题不能在那里重现）。
这是我的测试代码：它启动第二个线程，该线程保持锁定 5 秒。主线程尝试获取它（timeout=50ms）。有时（在机器上进行 1000 次迭代，它会中断大约 14 次）主线程在 50 毫秒后不会超时，而是等到第二个线程释放锁（= 5 秒）。
@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");
}
}
}
输出是
0:203ms 1:203ms 2:203ms 3:203ms 4:203ms 5
2013 年 5 月 26 日星期日 10:36:22 EDT 2013 年 5月 26 日星期日
10:37:22 EDT 2013 5 5
月 26 日星期日 10:38:22 EDT 2013 .. .................... // 20 小时后（日志已在此处剪切） 2013 年 5 月 27 日星期一
06:00:26 EDT 2013 年 5
月 27 日星期一 06:01:26 EDT 2013 5
月 27 日星期一 06:02:26 EDT 2013 5
月 27 日星期一 06:03:26 EDT 2013
和线程转储：
2013-05-27 04:51:51 全线程转储 Java HotSpot(TM) 客户端 VM（20.6-b01 混合模式，共享）：
“Thread-0”prio=6 tid=0x02b78400 nid=0xdf0 等待条件 [0x02ebf000] java.lang.Thread.State: TIMED_WAITING (sleeping) at java.lang.Thread.sleep(Native Method) at TestLock2$1.run( TestLock2.java:26)
“内存不足检测器”守护进程 prio=6 tid=0x02b5a400 nid=0x218c 可运行 [0x00000000] java.lang.Thread.State: RUNNABLE
“C1 CompilerThread0”守护进程prio=10 tid=0x02b55400 nid=0x7a4 等待条件[0x00000000] java.lang.Thread.State: RUNNABLE
“附加侦听器”守护进程 prio=10 tid=0x02b52c00 nid=0x2450 等待条件 [0x00000000] java.lang.Thread.State: RUNNABLE
“信号调度程序”守护进程 prio=10 tid=0x02b51800 nid=0x11d4 可运行 [0x00000000] java.lang.Thread.State: RUNNABLE
“终结器”守护进程 prio=8 tid=0x02b4c000 nid=0x13bc in Object.wait() [0x02cdf000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - 等待在 <0x22991148> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118) - 锁定 <0x22991148> (a java.lang.ref.ReferenceQueue$Lock)在 java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134) 在 java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)
“引用处理程序”守护进程 prio=10 tid=0x02b47400 nid=0x2634 in Object.wait() [0x02c8f000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) -在 java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116) 的 java.lang.Object.wait(Object.java:485) 等待 <0x22991048> (a java.lang.ref.Reference$Lock) ) - 锁定 <0x22991048> (一个 java.lang.ref.Reference$Lock)
"main" prio=6 tid=0x002a6c00 nid=0x1fd4 等待条件 [0x0090f000] java.lang.Thread.State: TIMED_WAITING (parking) at sun.misc.Unsafe.park(Native Method) - 停车等待 <0x229c10d8> (a java.util.concurrent.locks.ReentrantLock$NonfairSync) 在 java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:196) 在 java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireNanos(AbstractQueuedSynchronizer.java: 905) 在 java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireNanos(AbstractQueuedSynchronizer.java:1224) 在 java.util.concurrent.locks.ReentrantLock.tryLock(ReentrantLock.java:416) 在 TestLock2.testOne(TestLock2.java:58) ) 在 TestLock2.test(TestLock2.java:44) 在 TestLock2.main(TestLock2.java:10)
“VM 线程”prio=10 tid=0x02b0a800 nid=0x11d0 可运行
“VM 周期性任务线程”prio=10 tid=0x02b65400 nid=0x1efc 等待条件
JNI 全局引用：975
有任何想法吗？