利用JVM在線調試工具排查線上問題

時間  2019-11-05
標籤 利用 jvm 在線 調試 工具 排查 線上 問題 欄目 Java 简体版
原文   原文鏈接

在生產上咱們常常會碰到一些很差排查的問題，例如線程安全問題，用最簡單的threaddump或者heapdump很差查到問題緣由。爲了排查這些問題，有時咱們會臨時加一些日誌，好比在一些關鍵的函數裏打印出入參，而後從新打包發佈，若是打了日誌仍是沒找到問題，繼續加日誌，從新打包發佈。對於上線流程複雜並且審覈比較嚴的公司，從改代碼到上線須要層層的流轉，會大大影響問題排查的進度。java

這個時候咱們可使用可以在線調試的工具幫助咱們查找問題，例如btrace，能夠動態的插入代碼，極大提升咱們查找問題的效率。本文經過生產案例介紹如何用這一類工具快速定位傳統方法很差定位的問題。mysql

問題描述

服務器在高併發的狀況下cpu消耗很高，響應速度變慢，打threaddump，發現建立了大量的Timer-xxx線程，狀態都是runnable，可是沒有函數堆棧，也就是剛建立了還沒執行。打heapdump看，仍是很差發現問題，也只能看到一堆沒有堆棧的線程。
利用JVM在線調試工具排查線上問題git

查了代碼，發現近期改的地方沒有主動建立Timer的地方，因此大機率是第三方jar包建立的，怎麼才能找到是誰建立的線程。用這種靜態的分析方法已經不太好用了，由於不論是ThreadDump仍是HeapDump，抓住的都是一個快照，ThreadDump主要用來看線程的狀態，HeapDump主要是看內存裏的東西，還能夠看線程裏調用鏈上的棧的內容（僅限於對象，基本類型看不到）。github

咱們要知道誰建立的線程，只要知道誰調用了Thread類的start方法便可。假如咱們在ThreadDump裏看到以下的stacktrace:web

java.lang.Thread.start()
com.xxx.SomeClass.startNewThread();
…

那咱們就知道是誰建立了新線程，可是遺憾的是start方法太快，而ThreadDump很難抓到，start調用結束後就有一個新的stacktrace了。大部分狀況下ThreadDump只會抓到比較慢的函數，最多見的是socket.read()這樣的，還有一些須要屢次循環的。sql

必須藉助功能更強大的工具進行分析，好比Btrace，能夠動態的插入字節碼，可使咱們動態的在線查找問題。Btrace是比較基礎的工具，須要本身寫代碼插入，原理就是字節碼加強，或者叫Instrumentation，相似於AOP，經過插入一些代碼進行調試分析，包括不少性能監控工具，也是經過這個原理進行無侵入的埋點。數據庫

Btrace和Arthas簡介及使用示例

BTrace是Java的安全可靠的動態跟蹤工具。 它的工做原理是經過 instrument + asm 來對正在運行的java程序中的class類進行動態加強。使用Btrace時須要寫btrace腳本，也就是Java代碼，這些代碼會被植入運行的JVM中，若是寫的很差，可能會把JVM搞崩潰。apache

Arthas是阿里開源的一款工具，跟Btrace的原理同樣，它用起來更簡單，把最經常使用的功能都作了封裝，不須要本身寫代碼了，使用起來比較簡單，可是靈活性不如BTrace。安全

用Btrace舉兩個例子，無法用threaddump和heapdump快速定位問題的狀況。服務器

1.用btrace查看stacktrace

假如咱們有如下代碼，f函數會一直不停的建立Timer，而Timer會啓動新線程，大量的線程致使OOM，咱們須要查到是誰建立的線程。

public class Test {
       public static void main(String[] args) throws InterruptedException {
              f();
       }      
       public static void f() throws InterruptedException {     
              for(int i = 0; i < 10000; i++) {
                     new Timer(true);
                     Thread.sleep(1000);
              }
       }      
}

打一個threaddump，無法發現f與新線程的關係。

"Timer-31" daemon prio=5 tid=0x00007fc74a894800 nid=0x6407 in Object.wait() [0x00007000017db000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000007d596be10> (a java.util.TaskQueue)
    at java.lang.Object.wait(Object.java:503)
    at java.util.TimerThread.mainLoop(Timer.java:526)
    - locked <0x00000007d596be10> (a java.util.TaskQueue)
    at java.util.TimerThread.run(Timer.java:505)

   Locked ownable synchronizers:
    - None
"main" prio=5 tid=0x00007fc74a80b000 nid=0x1703 waiting on condition [0x0000700000219000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at test.Test.f(Test.java:13)
    at test.Test.main(Test.java:8)

   Locked ownable synchronizers:
    - None

能夠用Btrace查找是誰建立的。用Btrace須要寫腳本，如下腳本就是在java.lang.Thread類的start方法被調用的時候執行onnewThread方法，打印5行堆棧。

import com.sun.btrace.annotations.*;
import static com.sun.btrace.BTraceUtils.*;

@BTrace public class ThreadStart {
    @OnMethod(
        clazz="java.lang.Thread",
        method="start"
    )
    public static void onnewThread(@Self Thread t) {
        println("");
        Threads.jstack(5);
    }
}

而後在指定的進程號上執行腳本，獲得下面的輸出。

localhost:btrace-bin-1.3.11.3 $ ./bin/btrace 95428 ThreadStart.java
/Users/Downloads/btrace-bin-1.3.11.3

java.lang.Thread.start(Thread.java)
java.util.Timer.<init>(Timer.java:176)
java.util.Timer.<init>(Timer.java:146)
test.Test.f(Test.java:12)
test.Test.main(Test.java:8)

java.lang.Thread.start(Thread.java)
java.util.Timer.<init>(Timer.java:176)
java.util.Timer.<init>(Timer.java:146)
test.Test.f(Test.java:12)
test.Test.main(Test.java:8)

java.lang.Thread.start(Thread.java)
java.util.Timer.<init>(Timer.java:176)
java.util.Timer.<init>(Timer.java:146)
test.Test.f(Test.java:12)
test.Test.main(Test.java:8)

經過調用堆棧，就能找到是誰建立的線程了。

2.用btrace查看函數參數

下面的代碼，xx是一個業務邏輯函數，它的入參通過了嚴格的校驗，若是傳入參數過大，可能會處理時間特別長，咱們如今懷疑參數檢查出了問題，致使有些時候函數時間特別長。

public class Test {
    public static void main(String[] args) throws InterruptedException {
        ExecutorService pool = Executors.newFixedThreadPool(10);
        for(int i = 0; i < 100000; i++) {
            final int x = new Random().nextInt(5000);
            pool.execute(new Runnable() {
                @Override
                public void run() {
                    xx(x,String.valueOf(x%5));
                }           
            });
        }
    }   
    public static void xx(int x , String y) {
        try {
            Thread.sleep(x);
        } catch (InterruptedException e) {}
    }
}

打一個heapdump，能夠看到函數堆棧以及入參，查看一下慢線程的入參：

利用JVM在線調試工具排查線上問題

在heapdump裏，咱們只能看到xx的一個入參，可是代碼裏明明有兩個。這是由於heapdump只能看到對象類型，而不能看到基本類型，由於是heapdump而不是stackdump，是從gc root對象開始把全部可達對象給抓出來了，因此int類型的參數被忽略了，若是咱們傳的是Integer，就能在heapdump裏看到。

咱們用btrace在返回的地方植入代碼，若是函數時間超過3s，就打印一下參數，看看是否是參數不正常致使的。代碼以下：

import com.sun.btrace.annotations.*;
import static com.sun.btrace.BTraceUtils.*;
@BTrace
public class Params {
    @OnMethod(clazz = "test.Test", method = "xx", location = @Location(Kind.RETURN))
    public static void argPrint(int param1 ,String param2, @Duration long duration) {
        if(duration > 3000000000L) { //單位是ns
                println(param1);
        }
    }
}

運行結果以下：

localhost:btrace-bin-1.3.11.3 $ ./bin/btrace 53936 Params.java 
/Users/Downloads/btrace-bin-1.3.11.3
3298
4247
3527
3734
…

能夠看到btrace的功能很強大，可是咱們每次查找問題，都須要寫一些代碼，這樣的方式比較靈活，可是也麻煩，並且更危險，由於插入字節碼自己就有風險。咱們能夠提早把一些通用的腳本寫好，例如查找執行時間過長的函數，或者用其餘整合了多種功能的工具，例如阿里的arthas，跟btrace原理是同樣的，可是功能更多，不須要再寫代碼，不過對於特別不常見的需求仍是用btrace寫代碼比較好。

3.用Arthas替代btrace

上述兩個問題均可以用arthas解決，調用堆棧的方法在下面Timer問題分析裏面會介紹。

用arthas實現上面的參數查看，鏈接這個進程，而後用下面標紅的watch指令打印test.Test函數耗時大於3000ms時的參數。

localhost:Downloads $ java -jar arthas-boot.jar 76420
[INFO] arthas-boot version: 3.1.1
[INFO] arthas home: /Users/.arthas/lib/3.1.1/arthas
[INFO] Try to attach process 76420
[INFO] Attach process 76420 success.
[INFO] arthas-client connect 127.0.0.1 3658
  ,---.  ,------. ,--------.,--.  ,--.  ,---.   ,---.                           
 /  O  \ |  .--. ''--.  .--'|  '--'  | /  O  \ '   .-'                          
|  .-.  ||  '--'.'   |  |   |  .--.  ||  .-.  |`.  `-.                          
|  | |  ||  |\  \    |  |   |  |  |  ||  | |  |.-'    |                         
`--' `--'`--' '--'   `--'   `--'  `--'`--' `--'`-----'                          

wiki      https://alibaba.github.io/arthas                                      
tutorials https://alibaba.github.io/arthas/arthas-tutorials                     
version   3.1.1                                                                 
pid       76420                                                                 
time      2019-08-19 17:54:14                                                   

$ watch test.Test xx params '#cost>3000'
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 55 ms.
ts=2019-08-19 17:54:29; [cost=3049.163ms] result=@Object[][
    @Integer[3045],
    @String[0],
]
ts=2019-08-19 17:54:30; [cost=3287.747ms] result=@Object[][
    @Integer[3287],
    @String[2],

雖然arthas比btrace方便，可是兩個都不安全，能不用盡可能不用，用了的話最好重啓應用。

大量Timer線程問題分析

1.用arthas找到是誰建立的線程

找到jvm進程的進程號，而後使用arthas連到這個線程上，注意最好用同一個jdk版本，不然可能出問題。

weblogic@host:~/arthas> /usr/java/jdk1.7.0_80/bin/java -jar arthas-boot.jar 22316
[INFO] arthas-boot version: 3.1.1
[INFO] arthas home: /home/weblogic/arthas
[INFO] Try to attach process 22316
[INFO] Attach process 22316 success.
[INFO] arthas-client connect 127.0.0.1 3658
  ,---.  ,------. ,--------.,--.  ,--.  ,---.   ,---.                           
 /  O  \ |  .--. ''--.  .--'|  '--'  | /  O  \ '   .-'                          
|  .-.  ||  '--'.'   |  |   |  .--.  ||  .-.  |`.  `-.                          
|  | |  ||  |\  \    |  |   |  |  |  ||  | |  |.-'    |                         
`--' `--'`--' '--'   `--'   `--'  `--'`--' `--'`-----'                          

wiki      https://alibaba.github.io/arthas                                      
tutorials https://alibaba.github.io/arthas/arthas-tutorials                     
version   3.1.1                                                                 
pid       22316                                                                 
time      2019-08-02 17:43:18                                                   

$

而後用stack命令查看Thread.start的調用堆棧。

$ stack java.lang.Thread start
No class or method is affected, try:
1. sm CLASS_NAME METHOD_NAME to make sure the method you are tracing actually exists (it might be in your parent class).
2. reset CLASS_NAME and try again, your method body might be too large.
3. check arthas log: /home/weblogic/logs/arthas/arthas.log
4. visit https://github.com/alibaba/arthas/issues/47 for more details.

提示沒找到這個類或者方法，這是由於java.lang.Thread屬於基礎類，不建議修改它的字節碼，若是確實須要，須要修改一個選項，把unsafe選項設爲true。

$ options unsafe true
 NAME    BEFORE-VALUE  AFTER-VALUE                                                                                                             
-----------------------------------                                                                                                            
 unsafe  false         true
$stack java.lang.Thread start
.....
ts=2019-08-02 18:13:11;thread_name=[ACTIVE] ExecuteThread: '17' for queue: 'weblogic.kernel.Default (self-tuning)';id=2e;is_daemon=true;priority=5;TCCL=weblogic.utils.classloaders.ChangeAwareClassLoader@40d0d36f
    @java.util.Timer.<init>()
        at java.util.Timer.<init>(Timer.java:146)
        at com.ibm.db2.jcc.am.io.a(io.java:4953)
        at com.ibm.db2.jcc.am.io.Zb(io.java:5019)
        at com.ibm.db2.jcc.am.jo.b(jo.java:4058)
        at com.ibm.db2.jcc.am.jo.hc(jo.java:2732)
        at com.ibm.db2.jcc.am.jo.execute(jo.java:2715)
        at weblogic.jdbc.wrapper.PreparedStatement.execute(PreparedStatement.java:105)
        at org.apache.ibatis.executor.statement.PreparedStatementHandler.query(PreparedStatementHandler.java:57)
        at org.apache.ibatis.executor.statement.RoutingStatementHandler.query(RoutingStatementHandler.java:70)
        at org.apache.ibatis.executor.SimpleExecutor.doQuery(SimpleExecutor.java:57)
        at org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(BaseExecutor.java:267)
        at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:141)
        at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:98)
        at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:73)
        at org.apache.ibatis.executor.keygen.SelectKeyGenerator.processGeneratedKeys(SelectKeyGenerator.java:65)
        at org.apache.ibatis.executor.keygen.SelectKeyGenerator.processBefore(SelectKeyGenerator.java:41)
        at org.apache.ibatis.executor.statement.PreparedStatementHandler.parameterize(PreparedStatementHandler.java:80)
        at org.apache.ibatis.executor.statement.RoutingStatementHandler.parameterize(RoutingStatementHandler.java:58)
        at org.apache.ibatis.executor.BatchExecutor.doUpdate(BatchExecutor.java:68)
        at org.apache.ibatis.executor.BaseExecutor.update(BaseExecutor.java:108)
......

2.問題分析與驗證

看代碼是db2的驅動建立的線程，反編譯看一下代碼。應用經過weblogic提供的jndi訪問數據庫，數據源是weblogic建立的，在weblogic的lib目錄裏，有兩個驅動，db2jcc4.jar和db2jcc.jar，到網上查，這二者的區別在於：

Question

IBM Data Server driver for JDBC and SQLJ(JCC) has both db2jcc.jar and db2jcc4.jar. What is the difference between those 2 files, db2jcc.jar and db2jcc4.jar?

Answer

Both of them are DB2 JDBC driver jar files and are Type 4 drivers.

db2jcc.jar includes functions in the JDBC 3.0 and earlier specifications. If you plan to use those functions, include the db2jcc.jar in the application CLASSPATH.

db2jcc4.jar includes functions in JDBC 4.0 and later, as well as JDBC 3.0 and earlier specifications. If you plan to use those functions, include the db2jcc4.jar in the application CLASSPATH.

經過stacktrace裏的代碼行數，肯定加載的是db2jcc.jar這個jar包。建立線程的代碼以下：
利用JVM在線調試工具排查線上問題

網上搜索這個參數，這個選項配成1的時候，每次查詢都要啓動一個探測超時的Timer，若是選項是2的話，就每一個鏈接一個Timer。

timerLevelForQueryTimeout can be disabled by setting it to a value

of -1 (com.ibm.db2.jcc.DB2BaseDataSource.QUERYTIMEOUT_DISABLED)

The property "timerLevelForQueryTimeout" is used to indicate the

driver if it needs to create a timer object for each statement

execution or one per connection common to all statements created

under that connection. If this property is set to QUERYTIMEOUT_STATEMENT_LEVEL then the timer object is created before every execution of the statement and then destroyed after the execution.

Where the value QUERYTIMEOUT_CONNECTION_LEVEL creates one timer object per

connection and all the statement created on that connection share

that timer object for their executions. When you have lot of

statements on a connection it is better to use a common timer on a

connection otherwise it will end up creating lot of timer object and

can cause out of memory. This property can also be set like any

other property either on the datasource or in a URL.

DB2的jar包都通過了混淆，查看起來比較麻煩，最終肯定了這個選項在DB2BaseDataSource類裏，實際使用的是DB2SimpleDataSource 。

咱們用jdbc寫一段代碼進行驗證，使用DB2的數據源

public static void main(String[] args) throws ClassNotFoundException, SQLException, InterruptedException {

        Connection conn = null;
        PreparedStatement ps = null;
        ResultSet rs = null;
        String name=ManagementFactory.getRuntimeMXBean().getName();
        System.out.println(name); //把線程號打出來讓arthas使用

        Thread.sleep(40000);
        System.out.println(name);

        DB2SimpleDataSource ds = new DB2SimpleDataSource();
        ds.setUser("xxx");
        ds.setPassword("xxx");
        ds.setServerName("xxx");
        ds.setPortNumber(60000);
        ds.setDatabaseName("xxx");
        ds.setDriverType(4);

        //ds.setTimerLevelForQueryTimeOut(1); //改變選項
        //ds.setCommandTimeout(5000); //至關於設置了全局queryTimeOut
        ds.setConnectionTimeout(5000);
        //ds.timerLevelForQueryTimeOut = 1;
        System.out.println(ds.timerLevelForQueryTimeOut);

        conn = ds.getConnection();

        String sql = "select * from test";
        ps = conn.prepareStatement(sql);
        ps.setQueryTimeout(5000); //爲單條語句設置queryTimeOut
        ps.executeQuery();
        ps.executeQuery();
        //Thread.sleep(100000);

    }

用以上代碼驗證，發現只有設置了setCommandTimeout或者對於statement設置了setQueryTimeout的時候纔會每次都啓動一個Timer。setCommandTimeout至關於設置了全局的queryTimeout。

用arthas驗證結果以下：

利用JVM在線調試工具排查線上問題

Weblogic上部署了多個應用，可是隻有一個應用有這個問題，經過分析數據源的配置，發如今mybatis的參數裏有一個
利用JVM在線調試工具排查線上問題

這個配置的單位是秒，也不知道開發人員怎麼想的，設置了25000秒，若是sql變慢了，就會致使大量的Timer線程出現。

3.深刻研究與解決方案

這個queryTimeOut究竟是幹啥用的呢？

通常網絡鏈接會有兩個超時時間，connectionTimeout和readTimeout，這兩個超時都是由操做系統實現。connectionTimeout是在創建鏈接的時候的超時事件，這個比較容易理解。

而readTimeout，是指的等待對方數據到達的超時時間。

byte[] buf = new byte[128];
while(true) {
int byteRead = socket.read(buf); //socket會阻塞在這個地方，若是過了readtimeout尚未接到數據，就超時了
If(byteRead < 0) {
  Break;
}
}

假如咱們的應用全部的sql都應該在1s內返回，若是超了1s多是有問題了，這個時候超過1s有兩種可能：

(1)網絡問題致使讀超時

(2)Sql出了問題，例如被sql注入了，where條件裏出現了1=1，致使原來只用讀取1k數據，如今要讀取3G數據，而這3G數據不可能1s內返回，它們不停的read，也就是上述的死循環會執行好久，可是不會出現readTimeout。

第二種狀況是無法經過網絡層的超時來實現的，解決的方法就是單起一個線程，在必定時間後打斷讀取數據的線程。僞代碼以下：

byte[] buf = new byte[128];
//建立一個timer，在queryTimeout到的時候執行
Timer timer = new Timer();
timer.schedule(new TimerThread(), queryTimeout); //TimerThread裏面的實現就是打斷主線程
while(true) {
    //超時，被計時器打斷
    if(Thread.isInterrupted()) {
    break;
    System.out.println(「query Time out」);
    }
    int byteRead = socket.read(buf); //socket會阻塞在這個地方，若是過了readtimeout尚未接到數據，就超時了
    if(byteRead < 0) {
    break;
    }
}
timer.cancel(); //正常返回，中斷計時器

queryTimeout是jdbc的一個參數，而各類數據庫驅動能夠有本身的實現，大部分都是起一個線程來控制，固然也能夠選擇不使用這個機制，只靠網絡層的超時機制。

Db2驅動在默認狀況下，若是設置了queryTimeout，會爲每一個statement起一個timer，這個對資源的消耗很大，能夠把選項設置爲2，這樣就是每一個connection一個timer。由於一個connection同一時間只能給一個線程用，因此這樣是沒有問題的。

在weblogic里加入下面的參數就能夠了。
利用JVM在線調試工具排查線上問題

這個參數到底要不要用，怎麼用，還得根據場景不一樣來區分，mysql也有這方面的坑，

https://blog.csdn.net/aa283818932/article/details/40379211

這一篇文章講了jdbc的各類超時，講的比較好。

https://www.cubrid.org/blog/understanding-jdbc-internals-and-timeout-configuration

相關文章
相關標籤/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公眾號
   歡迎關注本站公眾號,獲取更多信息
聯繫我們 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程