诡异的http请求返回499的case排查

前天的时候碰到了这个超级诡异的case,现象是在本机curl一个本机的静态页面,nginx返回499,google了下知道499的原因通常是服务端处理时间过长,导致客户端关闭了连接造成的,因此问题的核心就是要排查为什么服务端处理时间过长。

curl访问的静态页面是从nginx代理访问到jboss的,于是直接改为用jboss的端口去curl那个静态页面,仍然是非常的慢,因此看起来问题出在了jboss端的处理。

要看为什么处理时间过长,主要就看java进程在做什么,于是jstack看了下线程都在做什么,jstack后看到了所有的jboss处理线程全部都被占满了,这显然是导致为什么curl一个静态页面都那么慢的原因。

继续看看为什么处理线程全被占满了,从堆栈信息来看,所有的线程几乎都在同一个步骤,诡异的是线程的信息状态,我第一次看到这样的线程信息:
“http-0.0.0.0-7001-228” daemon prio=10 tid=0x00007f7b9a1d0000 nid=0xae5c in Object.wait() [0x00000000619ec000]
java.lang.Thread.State: RUNNABLE
这个线程信息的诡异就在于动作是在Object.wait,但Thread的state却是Runnable….

先不管这个,继续根据堆栈执行到的那一行代码去排查,当时猜测的是八成是死循环之类的造成的,不过cpu消耗不高,因此也不太像,反编译代码后看到确实不可能是死循环,因为那行代码对应的就是类似这样的一个调用:
Object result = FinalClass.staticMethod(xxx);
这就相当诡异了,看起来无论如何都不应该停在这一步,要停也应该停在staticMethod里面的堆栈…

于是瞎蒙,继续用pstack来查查,pstack后看到对应的这些线程是停在了以下的步骤:
Thread 306 (Thread 0x4fada940 (LWP 69941)):
#0 0x0000003d6640af59 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x00007f234fb3138b in os::PlatformEvent::park() () from libjvm.so
#2 0x00007f234fb0ffc5 in ObjectMonitor::wait(long, bool, Thread*) () from libjvm.so
#3 0x00007f234fa748eb in ObjectSynchronizer::waitUninterruptibly(Handle, long, Thread*) () from libjvm.so
#4 0x00007f234fa4ce66 in instanceKlass::initialize(Thread*) () from libjvm.so
#5 0x00007f234fba30a7 in LinkResolver::resolve_static_call(CallInfo&, KlassHandle&, symbolHandle, symbolHandle, KlassHandle, bool,
bool, Thread*) () from libjvm.so
#6 0x00007f234fa3da96 in LinkResolver::resolve_invokestatic(CallInfo&, constantPoolHandle, int, Thread*) () from libjvm.so
#7 0x00007f234fa3c514 in InterpreterRuntime::resolve_invoke(JavaThread*, Bytecodes::Code) () from libjvm.so

看到这个就可以解释为什么之前线程上的信息是in Object.wait,至于为什么jstack上看到Thread的State是Runnable,原因是那里是根据java stack来看的,看不到native stack上的状况(在比较高的一些jdk版本上可通过执行jstack -m直接将java stack和native stack一起打印出来,那样会方便很多),否则的话只能自己通过pstack + jstack,并结合线程id这个来做对应关系。

从pstack的堆栈,可以解释为什么java stack停在了FinalClass.staticMethod那行,因为这个时候才刚开始初始化这个static类,多个线程初始化static类时,只有一个会执行,其他的都会在等待中,但这里没法解释的是为什么一直在wait….

后来就这个问题求助了下@rednaxelafx ,因为没有现场了,猜测可能是classloader的deadlock bug,具体见rednaxelafx写的这个case
从这个case描述来看,只有jdk 7/+才彻底解决了这个问题。

关于这个case的排查,只能说目前猜测是这样的,因为现在没法重现,所以也不能完全确认,rednaxelafx给我对这个case如果重现的排查的建议值得学习,就是如重现,可以先做下core dump,这样之后定位就会很好做了。
如果是class loader deadlock的bug,那就不太好解决了,基本上只能自己强行先做上面提到的FinalClass的装载,避免掉多线程同时来做这件事时的竞争问题。

ps: 最近又碰到了两起并发场景下错误使用HashMap导致的cpu耗光的case,其中一个case中代码是这样写的:
if (this.newCacheMap.get(key) == null) {
this.newCacheMap.put(key, Integer.valueOf(1));
return null;
}
// do sth through rpc…
怎么改比较合适呢,我的建议是将newCacheMap换为ConcurrentHashMap,然后把代码修改为:
if (this.newCacheMap.get(key) == null) {
if(this.newCacheMap.putIfAbsent(key, Integer.valueOf(1)) == null){
return null;
}
}

———微信互动——–
问:记得你之前说过cms gc更适用于64 bit系统,原因是?
答:其实原因是32 bit的系统上,例如linux单个进程最多用3g的空间,在3g这种heap大小的情况下,cms gc压根就没任何优势,ParallelOldGC就OK了,因此说了上面这话,不过即使是64 bit其实也需要看heap size多大,我的建议是在可接受的fgc暂停时间的情况下,都不应该选cms gc,cms gc实现的复杂度(这和它的目标有关系)决定了它的稳定性很难和Parallel GC去比,另外cms gc的碎片问题绝对是让人头疼的问题。

问:OutOfMemoryError: requested …bytes for Chunk::new. Out of swap space,这个能做个专题么?
答:这个在我以前写的《常见Java问题的排查方法》中有写到过,所以就不再专门讲了,简单来说,造成这个的可能原因是地址空间耗尽(64 bit上基本不可能),另外一个就真的是内存耗尽,具体的解决方法去看看我的那篇排查方法的blog吧,在http://bluedavy.me上。

=============================
欢迎关注微信公众号:hellojavacases
关于此微信号:
用于分享Java的一些小知识点,Java问题排查的Cases,Java业界的动态,以及和大家一起互动讨论一些Java的场景和问题。

公众号上发布的消息都存放在http://hellojava.info上。