在产品中有碰到过使用LinkedBlockingQueue.poll时超时很不准的现象,关键是这不是一般的不准,如果只是一点点不准的话也就勉强接受了,例如指定poll的超时时间为100ms,但最终执行.poll这段代码就花费了8000ms的现象,这篇blog就是展示下通过一段小小的代码来重现这样的现象,毕竟没有重现是无法证明为什么会出现这样的现象的。
由于在出现这个现象的时候有看到过OutOfMemory的错,虽然java进程没退出,但猜想可能是这个原因造成的,于是写了下面这段代码:
public static void main(String[] args) throws Exception{
long beginTime=System.currentTimeMillis();
Map<String, byte[]> cache=new HashMap<String, byte[]>();
for (int i = 0; i < 1000000; i++) {
cache.put(String.valueOf(i),new byte[500]);
}
CountDownLatch latch=new CountDownLatch(25);
for (int i = 0; i < 5; i++) {
for (int j = 0; j < 5; j++) {
Thread thread=new Thread(new TestThread(latch));
thread.start();
}
}
latch.await();
long endTime=System.currentTimeMillis();
System.out.println("总共执行时间:"+(endTime-beginTime));
}
static class TestThread implements Runnable{
private CountDownLatch latch;
public TestThread(CountDownLatch latch){
this.latch=latch;
}
public void run(){
BlockingQueue<String> queue=new LinkedBlockingQueue<String>(1);
try{
for (int i = 0; i < 5; i++) {
long beginTime=System.currentTimeMillis();
queue.poll(100, TimeUnit.MILLISECONDS);
long endTime=System.currentTimeMillis();
long consumeTime=endTime-beginTime;
if(consumeTime>200)
System.out.println("获取queue的时间为:"+consumeTime);
@SuppressWarnings("unused")
byte[] bytesNew=new byte[25506000];
}
}
catch(Exception e){
;
}
latch.countDown();
}
}
启动上面程序时,将jvm参数设置为-Xms640M -Xmx640M,运行后,应该会看到有很多queue.poll执行超过200ms的现象,甚至会出现8000ms的现象。
上面整段程序的写法就是用大量的小对象占据old generation,然后启动多个线程,每个线程运行的时候new一个大的对象,让其产生有可能直接从new generation分配到old generation,从而导致Full GC频繁执行,里面的byte数组的大小的原则为:塞满内存,产生Full GC,但又尽量不让应用出现OutOfMemory,或者说不出现过于频繁的OutOfMemory,避免jvm crash。
从上面程序的运行效果来看,当jvm内存消耗的很严重的情况下,poll的超时是没法准的,其实分析下原因,还是挺正常的:
1、jvm内存消耗严重的情况下,Minor GC和Full GC疯狂执行,导致了应用的执行不断的被暂停,因此当线程已经进入poll等待后,这个线程没有机会被执行,导致当其有机会执行时,早就超过了指定的超时时间,因此其超时不准并不是本身的机制导致的,而是jvm GC造成的多次暂停;
2、多次暂停的情况下,jvm需要不断的调度恢复线程,这需要消耗很多的资源,而且切换多了Swap空间很容易不够用,最终导致jvm crash。