１. 前言

前段時間升級了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/wikiGreys介紹 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 // 備注1public 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//備注4if(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 決定)。

@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.0export JRE_HOME=/home/jdk1.8.0/jreexport CLASSPATH=.:${JAVA_HOME}/lib:${JRE_HOME}/libexport PATH=$JAVA_HOME/bin:$PATHexport BTRACE_HOME=/home/appuser/bTraceexport PATH=$BTRACE_HOME/bin:$PATH

上傳監控腳本 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 mscom.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、解壓后，執行安裝命令

sh ./install-local.sh

（2）設置環境變量

export JAVA_HOME=/home/jdk1.8.0export JRE_HOME=/home/jdk1.8.0/jreexport CLASSPATH=.:${JAVA_HOME}/lib:${JRE_HOME}/libexport 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/