Java在線問題排查利器之Btrace&Greys

Norberto98E 7年前發布 | 31K 次閱讀 BTrace Java Java開發

１. 前言

前段時間升級了urs新的遠程cookie校驗模式。功能上線后，發現涉及用戶cookie 校驗的接口，有時會報接口超時。通過日志埋點方式，確認了與urs提供的jar包內的新驗證方法有關。通過反編譯，看到相關方法執行過程中涉及參數校驗、參數組裝、遠程訪問校驗、本地校驗等步驟，究竟哪個步驟出了問題？

一種方式是讓urs幫忙提供一個新的jar包，在關鍵步驟處加日志，記錄執行時間，另一種方法，就是使用一些在線分析工具。顯然第二種方式更方便快捷。本文主要介紹兩款在線問題排的工具： Btrace 和 Greys 。

2. 工具簡介

Btrace和 Greys 都比較適合對生成環境的問題進行排查，都屬于“事后工具” ，即服務已經上線了，無法再通過打印日志等方式埋點分析。這時可以使用這些工具，來跟蹤代碼執行耗時、堆棧情況等。

原理

都是基于動態字節碼修改技術(Hotswap)來實現運行時 java 程序的跟蹤和替換。

利用了Java SE 6 新特性Instrumentation 。

使用場景

  • 分析哪些方法慢，查詢具體的故障點；
  • 查看方法的參數、返回值；
  • 查看對象屬性等；

Btrace 和 Greys

Btrace 和 Greys 都屬于工具，本文以實例，介紹如何使用，不再對其本身進行介紹，如果想進一步了解，可以直接去下面的鏈接：

類型 介紹
Btrace https://github.com/btraceio/btrace/wiki
Greys介紹 https://yq.aliyun.com/articles/2390

3. 實例-使用工具排查問題

urs新提供了遠程cookie的校驗jar包，其中關鍵的方法為遠程調用方法

CookieDecoder.requestDecode(**)，我們主要對這個方法進行跟蹤。

3.1 使用Btrace

由于我們的tomcat 在 appuser 用戶下，為了有相應權限，我們的操作都在 appuser 用戶下進行。

大體步驟分為：

  • 下載解壓 btrace 工具；
  • 編寫監控腳本；
  • 設置jdk/btrace 環境變量，上傳腳本，編譯
  • 獲取tomcat 進程號
  • 啟動監控
  • 查看詳情

具體操作：

（1）下載btrace工具 btrace-bin-1.3.9.tgz 并解壓縮

（2） 編寫一個監控腳本（java代碼 UrsInterfaceCalls.java），

即需要監控的具體類和方法

@BTrace                         // 備注1
public class UrsInterfaceCalls{



/**
 * 備注2
 * 本代碼用于監控 CookieDecoder 中 requestDecode 方法的執行時間，如果執行時間大于 500ms，則打印花費的時間和堆棧
 * @param duration
 */
@OnMethod(
        clazz="com.netease.urs.CookieDecoder",
        method="requestDecode",
        location=@Location(Kind.RETURN))    // 備注2
public static void requestDecode( @Duration long duration ) {   // 備注3
    //備注4
    if(duration /1000000 > 500){
        println("==CookieDecoder requestDecode spend: " + duration /1000000 + " ms");
        jstack();
    }
}

/**
 * 本代碼用于監控 CustomHttpComponent 中 execute 方法的執行時間，如果執行時間大于 500ms，則打印花費的時間和堆棧
 * @param duration
 */
@OnMethod(
        clazz="com.netease.urs.http.CustomHttpComponent",
        method="execute",
        location=@Location(Kind.RETURN))
public static void execute( @Duration long duration ) {
    if(duration /1000000 > 500){
        println("==ursCookieHttp doExecute spend: " + duration /1000000 + " ms");
        jstack();
    }
}



}
</code></pre> 
  
簡要說明
 
  
本監控類，寫了兩個監控方法:
 
  
一個是監聽CookieDecoder.requestDecode()的執行時間，如果大于 500ms，則打印日志，并打印相關堆棧；
 
  
另一個監聽CustomHttpComponent.execute()的執行時間。
 
  
備注1：添加注釋 @BTrace ，代表本腳本將使用btrace相關功能；
 
  
備注2：攔截方法定義 ，@OnMethod 可以指定 clazz 、 method、location。由此組成了在什么時機（location 決定）監控某個類/某些類（clazz 決定）下的某個方法/某些方法(method 決定)。
 
  
@OnMethod(clazz="com.netease.urs.CookieDecoder",method="requestDecode",location=@Location(Kind.RETURN))

 
  
意思是監控CookieDecoder.requestDecode() ，在執行結束后（location=@Location(Kind.RETURN) 執行相關操作。
 
  
備注3：@Duration 代表方法執行時間，納秒。
 
  
備注4：只打印 耗時超過500ms的信息及堆棧，防止記錄打印大多。
 
  
方法注解說明
 
  
     
   
  • @OnMethod:指定使用當前注解的方法應該在什么情況下觸發： 
    
       
     
    • claszz屬性指定要匹配的類的全限定類名,可以用正則表達式;
      •  
     
    • method屬性指定要匹配的方法名稱,可以用正則表達式;
      •  
     
    • type屬性void(java.lang.String)可以用于匹配:public void funcName(String param) 中的方法入參；
      •  
     
    • location屬性用@Location來表明,匹配了clazz,method情況,在方法執行的何時去執行腳本(前,后,異常,行,某個方法調用)
      •  
    
     </li> 
   <li>@OnTimer:指定一個定時任務</li> 
   <li>@OnExit:當腳本運行Sys.exit(code)時觸發</li> 
   <li>@OnError:當腳本運行拋出異常時觸發</li> 
   <li>@OnEvent:腳本運行時Ctrl+C可以發送事件</li> 
   <li>@OnLowMemory:讓你指定一個閥值,內存低于閥值觸發</li> 
   <li>@OnProbe:可以用一個xml文件來描述你想在什么時候觸發該方法</li> 
  </ul> 
  
    方法參數注解說明
     
  
       
   
    • @Self:目標對象本身
      •  
   
    • @Retrun:目標程序方法返回值(Kind.RETURN)
      •  
   
    • @ProbeClassName:目標類名
      •  
   
    • @ProbeMethodName:目標方法名
      •  
   
    • @targetInstance:@Location指定的clazz,method的目標(Kind.CALL)
      •  
   
    • @targetMethodOrField:@Location指定的clazz,method的目標的方法或字段(Kind.CALL)
      •  
   
    • @Duration:目標方法執行時間,單位是納秒,需要與 Kind.RETURN 或者 Kind.ERROR 一起使用
      •  
  
     
  
    （3）設置jdk/btrace 環境變量
     
  
    export JAVA_HOME=/home/jdk1.8.0
export JRE_HOME=/home/jdk1.8.0/jre
export CLASSPATH=.:${JAVA_HOME}/lib:${JRE_HOME}/lib
export PATH=$JAVA_HOME/bin:$PATH
    

    export BTRACE_HOME=/home/appuser/bTrace
export PATH=$BTRACE_HOME/bin:$PATH
</code></pre> 
  
    上傳監控腳本 UrsInterfaceCalls.java 到服務器；
     
  
    可以用 btracec 進行預編譯，以保證代碼無誤
     
  
    （4）獲取tomcat的執行進程號 ps aux |grep “/fa.163.com”
     
  
     
  
    （5）進入UrsInterfaceCalls.java所在目錄，啟動btrace監控，監聽指定進程號19504（即jvm的進程號）
     
  
    sh btrace -p 2021 19054  UrsInterfaceCalls.java

     
  
    -p 2021 ：指定一個端口號，防止多個執行導致端口沖突；
     
  
    19054 ：要監聽的進程號
     
  
    UrsInterfaceCalls.java ：監聽腳本
     
  
    （6）查看結果
     
  
    如果方法執行超過500ms，會打印日志，同時打印堆棧；
     
  
    ==CookieDecoder requestDecode spend: 525 ms
com.netease.urs.CookieDecoder.requestDecode(CookieDecoder.java:64)
com.netease.urs.ntescode.validate_cookie_online(ntescode.java:49)
com.netease.common.util.CookieUtil.getUserInfoFromUrsRemoteCookie(CookieUtil.java:317)
com.netease.lottery.service.util.CookieUtilServiceImpl.getUserInfoFromUrsRemoteCookie(CookieUtilServiceImpl.java:88)
com.netease.lottery.service.util.CookieUtilServiceImpl$$FastClassByCGLIB$$1bd66cf1.invoke(<generated>)
org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
    

    .......
    

    org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1708)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
java.lang.Thread.run(Thread.java:745)
</code></pre> 
  
    如果要定位具體耗時，需要對各個關鍵方法，都添加監控腳本。
     
  
    3.2 使用Greys
     
  
    使用greys，無需編寫 腳步，它是命令交互式的，直接輸入命令指定監控的類、方法。
     
  
    但是每次只能監控一個方法，不能像 Btrace，可以同時監控多個方法。
     
  
    使用過程大體步驟：
     
  
       
   
    • 下載解壓 Greys工具，安裝；
      •  
   
    • 設置jdk 環境變量
      •  
   
    • 獲取tomcat 進程號
      •  
   
    • 啟動監控
      •  
   
    • 查看詳情
      •  
  
     
  
    具體步驟：
     
  
    （1）下載最新版本的Greys、解壓后，執行安裝命令
     
  
    sh ./install-local.sh

     
  
    （2）設置環境變量
     
  
    export JAVA_HOME=/home/jdk1.8.0
export JRE_HOME=/home/jdk1.8.0/jre
export CLASSPATH=.:${JAVA_HOME}/lib:${JRE_HOME}/lib
export PATH=$JAVA_HOME/bin:$PATH

     
  
    （3）查詢 jvm的進程號，進入greys安裝目錄，啟動Greys
     
  
    ./greys.sh 10437

     
  
    10437 為 jvm的進程號
     
  
    （4）啟動后，就可以通過交互式命令方式，對指定的類、方法進行分析。
     
  
    使用help 可以看到各種命令。
     
  
     
  
    （5）使用 trace命令 跟蹤指定類、方法的執行時間、參數、返回值情況；
     
  
    使用 help trace，查詢使用方式
     
  
     
  
    例如：跟蹤CookieDecoder類中 requestDecode()方法耗時超過500ms 的方法執行情況：
     
  
    trace  -n 2  com.netease.urs.CookieDecoder  requestDecode    '#cost>500'

     
  
    -n 2 ：代表只打印2次就退出（防止刷屏，影響性能）；
     
  
    com.netease.urs.CookieDecoder ：監聽的類名
     
  
    requestDecode :監聽的方法名
     
  
    ‘#cost>500’ : 打印條件為 耗時超過 500ms
     
  
    執行后，會顯示：
     
  
    ga?>trace  -n 2  com.netease.urs.CookieDecoder  requestDecode    '#cost>10'
Press Ctrl+D to abort.
Affect(class-cnt:1 , method-cnt:2) cost in 262 ms.

     
  
    代表動態修改了一個類，對兩個方法（例如方法重載）進行監控，修改花費262毫秒。
     
  
    如果出現滿足條件的情況，則我們會看到打印結果：
     
  
    `---+Tracing for : thread_name="http-nio-8003-exec-8" thread_id=0x7a;is_daemon=true;priority=5;
    `---+[5283,5283ms]com.netease.urs.CookieDecoder:requestDecode()
        +---[1,0ms]java.lang.System:nanoTime()
        +---[2,1ms]org.apache.http.client.methods.HttpPost:<init>(@39)
        +---[2,0ms]java.lang.StringBuffer:<init>(@41)
        +---[2,0ms]java.lang.StringBuffer:append(@42)
        +---[2,0ms]java.net.URLEncoder:encode(@43)
        +---[2,0ms]java.lang.StringBuffer:append(@43)
        +---[2,0ms]java.lang.StringBuffer:append(@44)
        +---[2,0ms]java.lang.StringBuffer:append(@45)
        +---[2,0ms]java.lang.StringBuffer:append(@46)
        +---[2,0ms]java.lang.StringBuffer:append(@47)
        +---[2,0ms]java.lang.StringBuffer:append(@48)
        +---[2,0ms]java.lang.Integer:<init>(@49)
        +---[2,0ms]java.lang.Integer:<init>(@49)
        +---[2,0ms]java.lang.reflect.Method:invoke(@49)
        +---[2,0ms]java.lang.StringBuffer:append(@49)
        +---[2,0ms]java.lang.StringBuffer:toString(@50)
        +---[2,0ms]org.apache.http.entity.StringEntity:<init>(@50)
        +---[2,0ms]org.apache.http.entity.StringEntity:setContentType(@51)
        +---[2,0ms]org.apache.http.client.methods.HttpPost:setEntity(@52)
        +---[2,0ms]org.apache.http.client.methods.HttpPost:getParams(@53)
        +---[2,0ms]org.apache.http.params.HttpParams:setIntParameter(@55)
        +---[2,0ms]org.apache.http.params.HttpParams:setIntParameter(@58)
        +---[5282,5280ms]com.netease.urs.http.CustomHttpComponent:execute(@60)
        +---[5283,0ms]org.apache.http.HttpResponse:getEntity(@61)
        +---[5283,0ms]org.apache.http.util.EntityUtils:toString(@62)
        +---[5283,0ms]com.netease.urs.util.LogUtil:debug(@63)
        +---[5283,0ms]org.apache.http.client.methods.HttpPost:releaseConnection(@71)
        +---[5283,0ms]java.lang.System:nanoTime(@64)
        `---[5283,0ms]com.netease.urs.CookieDecoder:$btrace$com$netease$fa$trace$UrsInterfaceCalls$2$requestDecode(@64)

     
  
    可以看到，主要耗時在
     
  
    +---[5282,5280ms]com.netease.urs.http.CustomHttpComponent:execute(@60)

     
  
    只要一層一層跟蹤下去，就可以最終定位問題。
     
  
    （6）退出前可以使用 reset 恢復增強類（即被動態修改的代碼）
     
  
    （7）最后，使用shutdown 關閉greys 并退出
     
  
    4.總結說明
     
  
    （1） 相比兩個工具，btrace 需要手寫腳步，每次更新都要重新上傳再執行，而greys 支持命令式交互，無需手寫腳本；
     
  
    （2）btrace 腳步中，可以寫多個監聽類和方法，但是greys 命令同時只能輸入一個。（但是greys 可以支持多個用戶操作，所如果想同時監控多個方法，只能開多窗口）
     
  
    （3）btrace 要確保監控腳本的正確性，使用前最好預編譯，防止動態增強后影響在線功能；
     
  
    （4）監控時，設置合適的條件，例如在 greys實例中，花費時間大于 N ms才輸出，且只打印2個。
     
  
    （5）greys 中只能顯示1層的方法調用情況，無法直接跟蹤到最底層；只能自己一層一層往下跟進。
     
  
     
     
  
    來自：http://tech.lede.com/2017/10/11/rd/server/javaToolsBTrace/
     
  
     
 本文由用戶 Norberto98E 自行上傳分享，僅供網友學習交流。所有權歸原作者，若您的權利被侵害，請聯系管理員。
 轉載本站原創文章，請注明出處，并保留原始鏈接、圖片水印。
 本站是一個以用戶分享為主的開源技術平臺，歡迎各類分享！