如何抓获JVM crash的幕后黑手？（二）

        其实通过上一篇所讲的core dump方法可以比较方便找到jvm crash问题所在，但这种方法适合crash比较频繁，容易获取到core dump文件，如果没有这个文件，那怎么可以查到问题呢。现在回过头想想通过跟踪crash时的apache日志，其实也能找到造成crash的请求，下面是某次crash时的日志：

[07/Jan/2012:07:52:40 +0800] "GET /a.xhtml HTTP/1.1" 200 2521 "-" "Mozilla/5.0 "  "a=-; b=-; c=-" -
[07/Jan/2012:07:52:47 +0800] "POST /a.xhtml HTTP/1.1" 503 323 "-" "Opera/9.80 "  "a=-; b=-; c=-" -
[07/Jan/2012:07:52:47 +0800] "POST /b.xhtml HTTP/1.0" 503 323 "-" "-" -  "a=-; b=-; c=-" -
[07/Jan/2012:07:52:51 +0800] "GET /a.xhtml HTTP/1.1" 503 323 "-" "Mozilla/5.0 "  "a=-; b=-; c=-" -
[07/Jan/2012:07:52:52 +0800] "GET /b.xhtml HTTP/1.1" 503 323 "-" "Mozilla/5.0 "  "a=-; b=-; c=-" -
[07/Jan/2012:07:52:48 +0800] "GET /c.do HTTP/1.1" 503 323 "-" "Mozilla/5.0 "  "a=-; b=-; c=-" -
[07/Jan/2012:07:52:52 +0800] "GET /c.do HTTP/1.1" 503 323 "-" "NokiaE63/UCWEB8.1.0.104/28/800"  "a=-; b=-; c=-" -
[07/Jan/2012:07:52:42 +0800] "POST /a.xhtml HTTP/1.1" 503 323 "-" "MAUI_WAP_Browser"  "a=-; b=-; c=-" -
[07/Jan/2012:07:50:26 +0800] "POST /e.xhtml HTTP/1.1" 503 323 "-" "MAUI_WAP_Browser"  "a=-; b=-; c=-" -
[07/Jan/2012:07:52:42 +0800] "GET /c.do HTTP/1.1" 503 323 "-" "MQQBrowser/2.9/Mozilla/5.0 "  "a=-; b=-; c=-" -
[07/Jan/2012:07:52:40 +0800] "GET /c.do HTTP/1.1" 503 323 "-" "MQQBrowser/2.0 "  "a=-; b=-; c=-" -

       这里apache通过接收请求转发给jboss处理，从上面的日志可以看出07:50:26的这个请求比较特殊，没按时间先后排列，属于“插队”的请求。apache日志中打印出的时间是接收到请求时的时间，但日志是等到请求处理完后才打印，那么这个请求从7:50:26秒进来，处理了2分多钟，我们应该首先怀疑它；另外一个值得注意的是请求的状态，除了第一个请求是200状态外，其他都是503错误，这说明“插队”的请求不是瞬间就让应用crash的，上面列出的第一个请求7:52:40进来的，还是可以正常执行完返回，同时这个“插队”的请求在即将导致应用crash时，也会影响其他请求的处理，反映到apache日志上就是503状态（处于第一个请求和“插队”的请求之间的请求）。所以在apache日志中找出应用crash时刻的所有请求，然后在其中查找那个“插队”比较明显的请求（apache日志总的来说是按时间先后顺序排列的，也会有秒级别的差异，但像出现分钟级别的顺序错乱就需要引起重视），同时结合业务日志进一步确定代码的执行顺序，找出问题。     

       总之，碰到这种应用意外终止的情况，需要根据日志（内存日志、apache日志、应用日志）找到蛛丝马迹方能抓到幕后黑手。这貌似一句废话