Во время интеграции моего проекта с Ehcache (с декоратором BlockingCache, который внутри использует ReentrantLock) я обнаружил странное поведение на одной машине. Время от времени потоки, ожидающие получения блокировки через вызов ReentrantLock.tryLock(timeout,TimeUnit) в течение времени, превышающего TIMEOUT, не прерываются по тайм-ауту (с результатом "false"). JVM оставила их позади, и они заблокированы до тех пор, пока эта блокировка не будет снята другим потоком. Вкратце: время от времени ReentrantLock.tryLock(длительный тайм-аут, блок TimeUnit) ведет себя как ReentrantLock.lock().
Такая ситуация возникает только на одной машине со спецификацией:
- Windows Server 2003 R2 (5.2.3790 SP2, сборка 3790)
- vmware esx 3.5
- xeon x5675 (2 процессора x86 6, модель 44, степпинг 2, GenuineIntel)
Я запускал на jre 1.6(1.6.0_31, 1.6.0_37)
Я протестировал его на двух других машинах, и он работает отлично (эта странная проблема не может быть воспроизведена там).
Вот мой тестовый код: он запускает второй поток, который удерживает блокировку в течение 5 секунд. Основной поток пытается получить его (с тайм-аутом = 50 мс). Время от времени (он ломается примерно 14 раз за 1000 итераций на машине) основной поток не отключается по тайм-ауту через 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:203 мс 1:203 мс 2:203 мс 3:203 мс 4:203 мс 5
вс 26 мая 10:36:22 EDT 2013 5
вс 26 мая 10:37:22 EDT 2013 5
вс 26 мая 10:38:22 EDT 2013 ..................... // 20 часов спустя (журнал был вырезан здесь) 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) Client VM (смешанный режим 20.6-b01, совместное использование):
"Thread-0" prio=6 tid=0x02b78400 nid=0xdf0 ожидание по условию [0x02ebf000] java.lang.Thread.State: TIMED_WAITING (ожидание) в java.lang.Thread.sleep(собственный метод) в TestLock2$1.run( TestLock2.java:26)
Демон «Детектор нехватки памяти» prio=6 tid=0x02b5a400 nid=0x218c runnable [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 runnable [0x00000000] java.lang.Thread.State: RUNNABLE
Демон "Finalizer" prio=8 tid=0x02b4c000 nid=0x13bc в Object.wait() [0x02cdf000] java.lang.Thread.State: WAITING (на объектном мониторе) в java.lang.Object.wait(собственный метод) - ожидание on ‹0x22991148> (java.lang.ref.ReferenceQueue$Lock) в java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118) — заблокировано ‹0x22991148> (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 в Object.wait() [0x02c8f000] java.lang.Thread.State: WAITING (на мониторе объекта) в java.lang.Object.wait (собственный метод) - ожидание ‹0x22991048> (java.lang.ref.Reference$Lock) в java.lang.Object.wait(Object.java:485) в java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116 ) - заблокировано ‹0x22991048> (a java.lang.ref.Reference$Lock)
"main" prio=6 tid=0x002a6c00 nid=0x1fd4 ожидание по условию [0x0090f000] java.lang.Thread.State: TIMED_WAITING (парковка) в sun.misc.Unsafe.park(собственный метод) - парковка для ожидания ‹0x229c10d8> (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 Thread" prio=10 tid=0x02b0a800 nid=0x11d0 работает
«Поток периодических задач VM» prio=10 tid=0x02b65400 nid=0x1efc ожидает выполнения условия
Глобальные ссылки JNI: 975
Любые идеи?
