java程序 cpu load過高分析過程

1\  jps -v列出所有的java程序 , top找出cpu占用過高的對應的java 程序pid

2\ 使用top -H -p PID 指令檢視對應程序裡的哪個線程占用CPU過高,取該線程pid

3\ 将線程的pid 轉成16進制

4\jstack [程序pid]|grep -A 100 [線程pid的16進制]  dump出jvm該線程的後100行,或者整個輸出到檔案

jstack -l pid > xxxfile      

案例分析       

現象:應用釋出後,過二十分鐘後load突然上升,居高不下. dump記憶體後沒發現有記憶體洩漏,初步懷疑有線程在不斷執行退不出.      

驗證:根據上面的方法找出占用cpu最高的java線程,dump出線程的後100行發現:      

20881-thread-200" daemon prio=10 tid=0x0000000046edb800 nid=0x3bbb runnable [0x0000000044ad6000]
   java.lang.Thread.State: RUNNABLE
   at com.ibatis.sqlmap.engine.execution.SqlExecutor.getFirstResultSet(SqlExecutor.java:341)
   at com.ibatis.sqlmap.engine.execution.SqlExecutor.handleMultipleResults(SqlExecutor.java:299)
   at com.ibatis.sqlmap.engine.execution.SqlExecutor.executeQuery(SqlExecutor.java:190)
   at com.ibatis.sqlmap.engine.mapping.statement.GeneralStatement.sqlExecuteQuery(GeneralStatement.java:205)
   at com.ibatis.sqlmap.engine.mapping.statement.GeneralStatement.executeQueryWithCallback(GeneralStatement.java:173)
   at com.ibatis.sqlmap.engine.mapping.statement.GeneralStatement.executeQueryForObject(GeneralStatement.java:104)
   at com.ibatis.sqlmap.engine.impl.SqlMapExecutorDelegate.queryForObject(SqlMapExecutorDelegate.java:566)
   at com.ibatis.sqlmap.engine.impl.SqlMapExecutorDelegate.queryForObject(SqlMapExecutorDelegate.java:541)
   at com.ibatis.sqlmap.engine.impl.SqlMapSessionImpl.queryForObject(SqlMapSessionImpl.java:106)
   at org.springframework.orm.ibatis.SqlMapClientTemplate$1.doInSqlMapClient(SqlMapClientTemplate.java:273)
   at org.springframework.orm.ibatis.SqlMapClientTemplate.execute(SqlMapClientTemplate.java:209)
   at org.springframework.orm.ibatis.SqlMapClientTemplate.queryForObject(SqlMapClientTemplate.java:271)
           
   

可以看到SqlExecutor.getFirstResultSet在這個地方一直處于runnable.打開源碼如下:

while (hasMoreResults) {
      rs = stmt.getResultSet();
      if (rs != null) {
        break;
      }
      hasMoreResults = moveToNextResultsIfPresent(stmt);
    }
           

debug後發現在這個地方一直死循環

原因:review dao代碼時發現一條update的操作是用selectForObject來跑的,接手過來的曆史代碼傷不起啊,以前跑在oracle的時候不會出現這個問題,這次去o換成mysql後這個隐藏的雷終于爆發了.把相應的select改成update問題解決.

額外注意:問題能在測試環節發現,就不是問題,關鍵在于測試環節測試人員一直沒發現這個問題,到線上一下子就出來了.原因有兩個,一是測試環境走不到這個分支,也就是測試用例不充分;二是測試環境操作有限,死幾個線程問題不大,因為測試環境設定的逾時時間比較短,導緻問題沒有明顯暴露出來,到線上一下子就出來了.