性能调优案例分享：jvm crash的原因 2

精选转载

北京茑萝00 2015-12-16 16:31:06

3.core dump分析

有了core dump文件，接下来要做的就是通过命令去解析此文件，定位具体问题了，主要有以下三个命令：

(1)先执行gdb $JAVA_HOME$/bin/java core-java-16427-1325846515,再执行bt,输出结果如下:

Loaded symbols for /opt/.../oracle/lib/libnnz10.so
Reading symbols from /opt/.../install/oracle/10.2.0.3/lib/libociei.so...(no debugging symbols found)...done.
Loaded symbols for /opt/.../oracle/lib/libociei.so
Reading symbols from /usr/lib/gconv/GB18030.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/gconv/GB18030.so
#0 0x4662051e in ttcrd2r ()
   from /opt/.../oracle/lib/libclntsh.so.10.1
(gdb) bt
#0 0x4662051e in ttcrd2r () from /opt/.../oracle/lib/libclntsh.so.10.1
#1 0x46617212 in ttcrbur () from /opt/.../oracle/lib/libclntsh.so.10.1
#2 0x466176e6 in ttcbur () from /opt/.../oracle/lib/libclntsh.so.10.1
#3 0x465ba8c7 in ttcdrv () from /opt/.../oracle/lib/libclntsh.so.10.1
#4 0x464a1bc8 in nioqwa () from /opt/.../oracle/lib/libclntsh.so.10.1
#5 0x4630d618 in upirtrc () from /opt/.../oracle/lib/libclntsh.so.10.1
#6 0x462825f6 in kpurcsc () from /opt/.../oracle/lib/libclntsh.so.10.1
#7 0x46236a0d in kpuexecv8 () from /opt/.../oracle/lib/libclntsh.so.10.1
#8 0x46238ec4 in kpuexec () from /opt/.../oracle/lib/libclntsh.so.10.1
#9 0x463121b6 in OCIStmtExecute () from /opt/.../oracle/lib/libclntsh.so.10.1
#10 0x46e725aa in Java_oracle_jdbc_driver_T2CConnection_t2cClearAllApplicationContext ()
   from /opt/.../install/oracle/10.2.0.3/lib/libocijdbc10.so
#11 0x46e7580f in Java_oracle_jdbc_driver_T2CStatement_t2cDefineExecuteFetch ()
   from /opt/.../install/oracle/10.2.0.3/lib/libocijdbc10.so
#12 0xb125a8b8 in ?? ()
#13 0x47e01bc8 in ?? ()
#14 0x47d46bb0 in ?? ()
#15 0x47d46c40 in ?? ()
#16 0x4babf774 in ?? ()
#17 0x00000000 in ?? ()

通过这个debug命令可以查看到应用crash时正在做什么，这里是在获取jdbc连接，但这个并不代表问题就出在这里，有可能这只是个结果，起因还需要进一步排查。

(2)光有上述信息还不足以定位出问题在哪，可以通过命令jstack $JAVA_HOME$/bin/java core-java-16427-1325846515获取应用crash时的线程堆栈，输出结果如下：

Thread 11586: (state = BLOCKED)
- java.lang.Object.wait(long) @bci=0 (Compiled frame; information may be imprecise)
- java.lang.Object.wait() @bci=2, line=474 (Compiled frame)
- edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingDeque.takeFirst() @bci=20, line=389 (Compiled frame)
- edu.emory.mathcs.backport.java.util.concurrent.LinkedBlockingDeque.take() @bci=1, line=577 (Compiled frame)
- edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run() @bci=18, line=674 (Compiled frame)
Error occurred during stack walking:

Thread 10924: (state = IN_NATIVE)
- oracle.jdbc.driver.T2CStatement.t2cDefineExecuteFetch(oracle.jdbc.driver.OracleStatement, long, int, int, int, int, boolean, boolean, byte[], int, byte, int, int, short[], int, byte[], char[], int, int, short[], byte[], int, int, boolean, boolean, oracle.jdbc.driver.Accessor[], byte[][][], long[], byte[], int, char[], int, short[], int) @bci=0 (Interpreted frame)
- oracle.jdbc.driver.T2CPreparedStatement.doDefineExecuteFetch() @bci=190, line=878 (Interpreted frame)
- oracle.jdbc.driver.T2CPreparedStatement.executeForRows(boolean) @bci=34, line=760 (Interpreted frame)
- oracle.jdbc.driver.OracleStatement.executeMaybeDescribe() @bci=154, line=1062 (Interpreted frame)
- oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout() @bci=102, line=1126 (Interpreted frame)
- oracle.jdbc.driver.OraclePreparedStatement.executeInternal() @bci=94, line=3339 (Interpreted frame)
- oracle.jdbc.driver.OraclePreparedStatement.execute() @bci=17, line=3445 (Interpreted frame)
- org.jboss.resource.adapter.jdbc.CachedPreparedStatement.execute() @bci=4, line=216 (Interpreted frame)
- org.jboss.resource.adapter.jdbc.WrappedPreparedStatement.execute() @bci=12, line=209 (Compiled frame)
- com.ibatis.sqlmap.engine.execution.SqlExecutor.executeQuery(com.ibatis.sqlmap.engine.scope.RequestScope, java.sql.Connection, java.lang.String, java.lang.Object[], int, int, com.ibatis.sqlmap.engine.mapping.statement.RowHandlerCallback) @bci=135, line=180 (Compiled frame)
- com.ibatis.sqlmap.engine.mapping.statement.GeneralStatement.sqlExecuteQuery(com.ibatis.sqlmap.engine.scope.RequestScope, java.sql.Connection, java.lang.String, java.lang.Object[], int, int, com.ibatis.sqlmap.engine.mapping.statement.RowHandlerCallback) @bci=15, line=205 (Interpreted frame)
- com.ibatis.sqlmap.engine.mapping.statement.GeneralStatement.executeQueryWithCallback(com.ibatis.sqlmap.engine.scope.RequestScope, java.sql.Connection, java.lang.Object, java.lang.Object, com.ibatis.sqlmap.client.event.RowHandler, int, int) @bci=169, line=173 (Compiled frame)
- com.ibatis.sqlmap.engine.mapping.statement.GeneralStatement.executeQueryForObject(com.ibatis.sqlmap.engine.scope.RequestScope, com.ibatis.sqlmap.engine.transaction.Transaction, java.lang.Object, java.lang.Object) @bci=28, line=104 (Compiled frame)
- com.ibatis.sqlmap.engine.impl.SqlMapExecutorDelegate.queryForObject(com.ibatis.sqlmap.engine.scope.SessionScope, java.lang.String, java.lang.Object, java.lang.Object) @bci=58, line=561 (Compiled frame)
- com.ibatis.sqlmap.engine.impl.SqlMapExecutorDelegate.queryForObject(com.ibatis.sqlmap.engine.scope.SessionScope, java.lang.String, java.lang.Object) @bci=5, line=536 (Interpreted frame)
- com.ibatis.sqlmap.engine.impl.SqlMapSessionImpl.queryForObject(java.lang.String, java.lang.Object) @bci=10, line=93 (Interpreted frame)
- org.springframework.orm.ibatis.SqlMapClientTemplate$1.doInSqlMapClient(com.ibatis.sqlmap.client.SqlMapExecutor) @bci=9, line=273 (Interpreted frame)
- org.springframework.orm.ibatis.SqlMapClientTemplate.execute(org.springframework.orm.ibatis.SqlMapClientCallback) @bci=242, line=209 (Compiled frame)
- org.springframework.orm.ibatis.SqlMapClientTemplate.queryForObject(java.lang.String, java.lang.Object) @bci=11, line=271 (Compiled frame)
......
- org.springframework.web.servlet.DispatcherServlet.doService(javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse) @bci=219, line=809 (Interpreted frame)
- org.springframework.web.servlet.FrameworkServlet.processRequest(javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse) @bci=10, line=571 (Compiled frame)
- org.springframework.web.servlet.FrameworkServlet.doPost(javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse) @bci=3, line=511 (Interpreted frame)
- javax.servlet.http.HttpServlet.service(javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse) @bci=139, line=717 (Interpreted frame)
- javax.servlet.http.HttpServlet.service(javax.servlet.ServletRequest, javax.servlet.ServletResponse) @bci=30, line=810 (Compiled frame)
- org.apache.catalina.core.ApplicationFilterChain.doFilter(javax.servlet.ServletRequest, javax.servlet.ServletResponse) @bci=101, line=173 (Interpreted frame)
- org.apache.catalina.core.ApplicationDispatcher.invoke(javax.servlet.ServletRequest, javax.servlet.ServletResponse) @bci=396, line=672 (Interpreted frame)
- org.apache.catalina.core.ApplicationDispatcher.processRequest(javax.servlet.ServletRequest, javax.servlet.ServletResponse) @bci=64, line=463 (Interpreted frame)
- org.apache.catalina.core.ApplicationDispatcher.doForward(javax.servlet.ServletRequest, javax.servlet.ServletResponse) @bci=469, line=398 (Interpreted frame)
- org.apache.catalina.core.ApplicationDispatcher.forward(javax.servlet.ServletRequest, javax.servlet.ServletResponse) @bci=55, line=301 (Interpreted frame)

- org.springframework.web.servlet.view.InternalResourceView.renderMergedOutputModel(java.util.Map, javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse) @bci=244, line=240 (Interpreted frame)
- org.springframework.web.servlet.view.AbstractView.render(java.util.Map, javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse) @bci=157, line=252 (Interpreted frame)
- org.springframework.web.servlet.DispatcherServlet.render(org.springframework.web.servlet.ModelAndView, javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse) @bci=225, line=1173 (Compiled frame)
- org.springframework.web.servlet.DispatcherServlet.doService(javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse) @bci=219, line=809 (Interpreted frame)
- org.springframework.web.servlet.FrameworkServlet.processRequest(javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse) @bci=10, line=571 (Compiled frame)
- org.springframework.web.servlet.FrameworkServlet.doPost(javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse) @bci=3, line=511 (Interpreted frame)
- javax.servlet.http.HttpServlet.service(javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse) @bci=139, line=717 (Interpreted frame)
- javax.servlet.http.HttpServlet.service(javax.servlet.ServletRequest, javax.servlet.ServletResponse) @bci=30, line=810 (Compiled frame)
- org.apache.catalina.core.ApplicationFilterChain.doFilter(javax.servlet.ServletRequest, javax.servlet.ServletResponse) @bci=101, line=173 (Interpreted frame)
- org.apache.catalina.core.ApplicationDispatcher.invoke(javax.servlet.ServletRequest, javax.servlet.ServletResponse) @bci=396, line=672 (Interpreted frame)
- org.apache.catalina.core.ApplicationDispatcher.processRequest(javax.servlet.ServletRequest, javax.servlet.ServletResponse) @bci=64, line=463 (Interpreted frame)
- org.apache.catalina.core.ApplicationDispatcher.doForward(javax.servlet.ServletRequest, javax.servlet.ServletResponse) @bci=469, line=398 (Interpreted frame)
- org.apache.catalina.core.ApplicationDispatcher.forward(javax.servlet.ServletRequest, javax.servlet.ServletResponse) @bci=55, line=301 (Interpreted frame)

......

通过这个线程堆栈可以看出问题根本原因是一直在forward，代码出现死循环，总的forward的次数有100多次，直到线程堆栈溢出。这也能说明前面通过gdb命令查看到的获取jdbc连接仅仅是最近的一次循环正在执行的操作而已，不是真正的起因。这个线程的死循环forward同样影响到了其他的线程，导致出现Error occurred during stack walking错误，线程一直处于BLOCKED状态，总之线程堆栈对分析问题原因是非常有帮助的。

(3).可以通过命令jmap $JAVA_HOME$/bin/java core-java-16427-1325846515查看到应用的内存使用，结果如下：

using parallel threads in the new generation.
using thread-local object allocation.
Concurrent Mark-Sweep GC

Heap Configuration:
   MinHeapFreeRatio = 40
   MaxHeapFreeRatio = 70
   MaxHeapSize      = 1342177280 (1280.0MB)
   NewSize          = 134217728 (128.0MB)
   MaxNewSize       = 134217728 (128.0MB)
   OldSize          = 402653184 (384.0MB)
   NewRatio         = 15
   SurvivorRatio    = 1024
   PermSize         = 100663296 (96.0MB)
   MaxPermSize      = 100663296 (96.0MB)

Heap Usage:
New Generation (Eden + 1 Survivor Space):
   capacity = 134152192 (127.9375MB)
   used     = 22525464 (21.481956481933594MB)
   free     = 111626728 (106.4555435180664MB)
   16.790977220856742% used
Eden Space:
   capacity = 134086656 (127.875MB)
   used     = 22525464 (21.481956481933594MB)
   free     = 111561192 (106.3930435180664MB)
   16.799183954591275% used
From Space:
   capacity = 65536 (0.0625MB)
   used     = 0 (0.0MB)
   free     = 65536 (0.0625MB)
   0.0% used
To Space:
   capacity = 65536 (0.0625MB)
   used     = 0 (0.0MB)
   free     = 65536 (0.0625MB)
   0.0% used
concurrent mark-sweep generation:
   capacity = 1207959552 (1152.0MB)
   used     = 764300224 (728.8934936523438MB)
   free     = 443659328 (423.10650634765625MB)

Exception in thread "main" java.lang.OutOfMemoryError: requested 4096 bytes for jbyte in /BUILD_AREA/jdk1.5.0_08/hotspot/src/share/vm/prims/jni.cpp. Out of swap space?

最后一行出现了OOM，这是因为dump出来的文件太大，32位机器支持的最大内存也就2G，所以在解析时出现OOM问题，可以放到64位服务器上进行解析。

4.常见的core dump原因

造成coredump的原因很多，常见的有内存访问越界，非法指针，堆栈溢出等等，也可以通过发送操作系统信号中断应用，比如kill -SIGSEGV <pid>，这是一个无效存储信号。如果想手动生成core dump文件，可以通过gdb -p <pid>生成。