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

作者：佚名 2017-10-12 12:24:50

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

1. 背景說明

前段時間升級了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

類型	介紹
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();
		}
    }
}

簡要說明

本監控類，寫了兩個監控方法:
一個是監聽CookieDecoder.requestDecode()的執行時間，如果大于 500ms，則打印日志，并打印相關堆棧；
另一個監聽CustomHttpComponent.execute()的執行時間。

備注1：添加注釋 @BTrace ，代表本腳本將使用btrace相關功能；

備注2：攔截方法定義，@OnMethod 可以指定 clazz 、 method、location。由此組成了在什么時機（location 決定）監控某個類/某些類（clazz 決定）下的某個方法/某些方法(method 決定)。

1	@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情況,在方法執行的何時去執行腳本(前,后,異常,行,某個方法調用)

@OnTimer:指定一個定時任務

@OnExit:當腳本運行Sys.exit(code)時觸發

@OnError:當腳本運行拋出異常時觸發

@OnEvent:腳本運行時Ctrl+C可以發送事件

@OnLowMemory:讓你指定一個閥值,內存低于閥值觸發

@OnProbe:可以用一個xml文件來描述你想在什么時候觸發該方法

方法參數注解說明

@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

上傳監控腳本 UrsInterfaceCalls.java 到服務器；

可以用 btracec 進行預編譯，以保證代碼無誤

（4）獲取tomcat的執行進程號 ps aux |grep “/fa.163.com”

（5）進入UrsInterfaceCalls.java所在目錄，啟動btrace監控，監聽指定進程號19504（即jvm的進程號）

1	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)

如果要定位具體耗時，需要對各個關鍵方法，都添加監控腳本。

3.2 使用Greys

使用greys，無需編寫腳步，它是命令交互式的，直接輸入命令指定監控的類、方法。
但是每次只能監控一個方法，不能像 Btrace，可以同時監控多個方法。

使用過程大體步驟：

下載解壓 Greys工具，安裝；
設置jdk 環境變量
獲取tomcat 進程號
啟動監控
查看詳情

具體步驟：
（1）下載***版本的Greys、解壓后，執行安裝命令

1	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

1	./greys.sh 10437

10437 為 jvm的進程號

（4）啟動后，就可以通過交互式命令方式，對指定的類、方法進行分析。

使用help 可以看到各種命令。

（5）使用 trace命令跟蹤指定類、方法的執行時間、參數、返回值情況；
使用 help trace，查詢使用方式

例如：跟蹤CookieDecoder類中 requestDecode()方法耗時超過500ms 的方法執行情況：

1	trace -n 2 com.netease.urs.CookieDecoder requestDecode '#cost>500'

-n 2 ：代表只打印2次就退出（防止刷屏，影響性能）；
com.netease.urs.CookieDecoder ：監聽的類名
requestDecode :監聽的方法名
‘#cost>500’ : 打印條件為耗時超過 500ms

執行后，會顯示：

1
2
3

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)

可以看到，主要耗時在

1	+---[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層的方法調用情況，無法直接跟蹤到層；只能自己一層一層往下跟進。

【編輯推薦】

Java 虛擬機 OpenJ9 和 Hotspot 的 Benchmark 測試

WordPress 核心 JavaScript 框架選擇討論話題持續進行

10 個最終編譯成 JavaScript 的腳本語言

【分享】Java反序列化漏洞從理解到實踐

Java開發者的福音：使用 Visual Studio Code 調試 Java 應用程序

【責任編輯：張燕妮 TEL：（010）68476606】

責任編輯：張燕妮來源：網易樂得技術團隊

java