BTrace简介及使用
背景
在生產環境中可能經常遇到各種問題，定位問題需要獲取程序運行時的數據信息，如方法參數、返回值、全局變量、堆棧信息等。為了獲取這些數據信息，我們可以通過改寫代碼，增加日志信息的打印，再發布到生產環境。通過這種方式，一方面將增大定位問題的成本和周期，對于緊急問題無法做到及時響應；另一方面重新部署后環境可能已被破壞，很難重新問題的場景。
對于程序員來說最頭大的問題之一就是線上出了故障了，但是我們無法debug來找出問題原因，同時在上線的時候日志級別限定了我們不可能把所有的細節都打印到log上，這個時候故障都等在哪里，能辦的手段無非看源碼，通過仔細看代碼來找出問題，并編譯重新上線解決，這種手段能解決一部分代碼，但是對于一些隱藏較深的bug就無能為力了，例如OOM或是頻繁的full gc，一般是一個很多的對象沒有被釋放或是一個對象被頻繁的創建調用。在一個復雜的項目中，一個OOM問題可能是一個對象被頻繁創建，這種方式指望通過看源碼是很難解決的，但是BTrace可以迅速幫助我們定位到問題所在地。
介紹
Btrace (Byte Trace)是sun推出的一款java 動態、安全追蹤（監控）工具，可以不停機的情況下監控線上情況，并且做到最少的侵入，占用最少的系統資源。BTrace應用較為廣泛的原因應該是其安全性和無侵入性，其中熱交互技術，使得我們無需啟動Agent的情況下動態跟蹤分析，其安全性不會導致對目標Java進程的任何破壞性影響，使得BTrace成為我們線上產品問題定位的利器。無侵入性無需我們對原有代碼做任何修改，降低上線風險和測試成本，并且無需重啟啟動目標Java進程進行Agent加載即可動態分析和跟蹤目標程序，可以說BTrace可以滿足大部分的應用場景。
安裝
- 下載BTrace（https://kenai.com/projects/btrace/downloads/directory/releases），解壓至任意目錄。
- 設置BTRACE_HOME，將bin目錄加至環境變量PATH中。
使用
BTrace主要包含btracec和btracer兩個命令編譯和啟動BTrace腳本:
1. btrace
功能: 用于運行BTrace跟蹤程序。
命令格式:
btrace [-I <include-path>] [-p <port>] [-cp <classpath>] <pid> <btrace-script> [<args>]
- -I:沒有這個表明跳過預編譯
- include-path:指定用來編譯腳本的頭文件路徑(關于預編譯可參考例子ThreadBean.java)
- port:btrace agent端口,默認是2020
- classpath:編譯所需類路徑,一般是指btrace-client.jar等類所在路徑
- pid:java進程id
- btrace-script:btrace腳本可以是.java文件,也可以是.class文件
- args:傳遞給btrace腳本的參數, 在腳本中可以通過$(), $length()來獲取這些參數(定義在BTraceUtils中)
示例:
btrace -cp build/ 1200 AllCalls1.java
參數含義:
include-path指定頭文件的路徑，用于腳本預處理功能，可選；
port指定BTrace agent的服務端監聽端口號，用來監聽clients，默認為2020，可選；
classpath用來指定類加載路徑，默認為當前路徑，可選；
pid表示進程號，可通過jps命令獲取；
btrace-script即為BTrace腳本；btrace腳本如果以.java結尾，會先編譯再提交執行?？墒褂胋tracec命令對腳本進行預編譯。
args是BTrace腳本可選參數，在腳本中可通過"$"和"$length"獲取參數信息。
2. btracec
功能: 用于預編譯BTrace腳本，用于在編譯時期驗證腳本正確性。
btracec [-I <include-path>] [-cp <classpath>] [-d <directory>] <one-or-more-BTrace-.java-files>
參數意義同btrace命令一致，directory表示編譯結果輸出目錄。
3. btracer
功能: btracer命令同時啟動應用程序和BTrace腳本，即在應用程序啟動過程中使用BTrace腳本。而btrace命令針對已運行程序執行BTrace腳本。
命令格式:
btracer <pre-compiled-btrace.class> <application-main-class> <application-args>
參數說明:
pre-compiled-btrace.class表示經過btracec編譯后的BTrace腳本。
application-main-class表示應用程序代碼；
application-args表示應用程序參數。
該命令的等價寫法為:
java -javaagent:btrace-agent.jar=script=<pre-compiled-btrace-script1>[,<pre-compiled-btrace-script1>]* <MainClass> <AppArguments>
局限性
雖然BTrace很強大,但Btrace腳本就是一個普通的用@Btrace注解的Java類,其中包含一個或多個public static void修飾的方法,為了保證對目標程序不造成影響,Btrace腳本對其可以執行的動作做了很多限制，如下：
重要概念
方法上的注解
- @ OnMethod用來指定trace的目標類和方法以及具體位置,被注解的方法在匹配的方法執行到指定的位置會被調用。
1、"clazz"屬性用來指定目標類名,可以指定全限定類名,比如"java.awt.Component",也可以是正則表達式(表達式必須寫在"//"中,比如"/java\\.awt\\..+/")。
2、"method"屬性用來指定被trace的方法.表達式可以參考自帶的例子(NewComponent.java和Classload.java,關于方法的注解可以參考MultiClass.java)。
3、有時候被trace的類和方法可能也使用了注解.用法參考自帶例子WebServiceTracker.java。
4、針對注解也是可以使用正則表達式,比如像這個"@/com\\.acme\\..+/ "，也可以通過指定超類來匹配多個類,比如"+java.lang.Runnable"可以匹配所有實現了java.lang.Runnable接口的類.具體參考自帶例子SubtypeTracer.java。 - @OnTimer定時觸發Trace，時間可以指定，單位為毫秒，具體參考自帶例子Histogram.java。
- @OnError當trace代碼拋異?；蛘咤e誤時，該注解的方法會被執行.如果同一個trace腳本中其他方法拋異常,該注解方法也會被執行。
- @OnExit當trace方法調用內置exit(int)方法(用來結束整個trace程序)時,該注解的方法會被執行.參考自帶例子ProbeExit.java。
- @OnEvent用來截獲"外部"btrace client觸發的事件,比如按Ctrl-C中斷btrace執行時，并且選擇2，或者輸入事件名稱，將執行使用了該注解的方法,該注解的value值為具體事件名稱。具體參考例子HistoOnEvent.java
- @OnLowMemory當內存超過某個設定值將觸發該注解的方法,具體參考MemAlerter.java
- @OnProbe使用外部文件XML來定義trace方法以及具體的位置，具體參考示例SocketTracker1.java和java.net.socket.xml。
參數上的注解
- @Self用來指定被trace方法的this，可參考例子AWTEventTracer.java和AllCalls1.java
- @Return用來指定被trace方法的返回值，可參考例子Classload.java
- @ProbeClassName (since 1.1)用來指定被trace的類名,可參考例子AllMethods.java
- @ProbeMethodName (since 1.1)用來指定被trace的方法名,可參考例子WebServiceTracker.java。
- @TargetInstance (since 1.1)用來指定被trace方法內部被調用到的實例,可參考例子AllCalls2.java
- @TargetMethodOrField (since 1.1)用來指定被trace方法內部被調用的方法名,可參考例子AllCalls1.java和AllCalls2.java。
非注解的方法參數
未使用注解的方法參數一般都是用來做方法簽名匹配用的,他們一般和被trace方法中參數出現的順序一致.不過他們也可以與注解方法交錯使用,如果一個參數類型聲明為*AnyType[]*,則表明它按順序"通吃"方法所有參數.未注解方法需要與*Location*結合使用:
- Kind.ENTRY-被trace方法參數
- Kind.RETURN-被trace方法返回值
- Kind.THROW -拋異常
- Kind.ARRAY_SET, Kind.ARRAY_GET -數組索引
- Kind.CATCH -捕獲異常
- Kind.FIELD_SET -屬性值
- Kind.LINE -行號
- Kind.NEW -類名
- Kind.ERROR -拋異常
屬性上的注解
- @Export該注解的靜態屬性主要用來與jvmstat計數器做關聯， 使用該注解之后，btrace程序就可以向jvmstat客戶端(可以用來統計jvm堆中的內存使用量)暴露trace程序的執行次數， 具體可參考例子ThreadCounter.java。
- @Property使用了該注解的trace腳本將作為MBean的一個屬性，一旦使用該注解， trace腳本就會創建一個MBean并向MBean服務器注冊， 這樣JMX客戶端比如VisualVM， jconsole就可以看到這些BTrace MBean， 如果這些被注解的屬性與被trace程序的屬性關聯， 那么就可以通過VisualVM和jconsole來查看這些屬性了， 具體可參考例子ThreadCounterBean.java和HistogramBean.java。
- @TLS用來將一個腳本變量與一個ThreadLocal變量關聯， 因為ThreadLocal變量是跟線程相關的， 一般用來檢查在同一個線程調用中是否執行到了被trace的方法， 具體可參考例子OnThrow.java和WebServiceTracker.java。
類上的注解
- @com.sun.btrace.annotations.DTrace用來指定btrace腳本與內置在其腳本中的D語言腳本關聯， 具體參考例子DTraceInline.java。
- @com.sun.btrace.annotations.DTraceRef用來指定btrace腳本與另一個D語言腳本文件關聯， 具體參考例子DTraceRefDemo.java。
- @com.sun.btrace.annotations.BTrace用來指定該java類為一個btrace腳本文件。
Samples
1.跟蹤WildFly內存信息，用@OnTimer 這個annotation每隔4秒鐘打印一次內存堆棧信息：
import com.sun.btrace.annotations.BTrace;
import com.sun.btrace.annotations.OnTimer;
import static com.sun.btrace.BTraceUtils.*;
@BTrace
public class TraceMemory {
//heapUsage()/nonHeapUsage() – 打印堆/非堆內存信息，包括init、used、commit、max
@OnTimer(4000)
public static void printM(){
//打印內存信息
println("heap:");
println(heapUsage());
println("no-heap:");
println(nonHeapUsage());
}
}
查找 WildFly pid：
[root@mdwareweb1 test]# jps
7119 Jps
5513 jboss-modules.jar
執行：
btrace 5513 TraceMemory.java
結果：
[root@mdwareweb1 test]# btrace 5513 TraceMemory.java?
heap:
init = 67108864(65536K) used = 70036960(68395K) committed = 209387520(204480K) max = 477233152(466048K)
no-heap:
init = 19136512(18688K) used = 43569672(42548K) committed = 78348288(76512K) max = 318767104(311296K)
heap:
init = 67108864(65536K) used = 70893560(69231K) committed = 209387520(204480K) max = 477233152(466048K)
no-heap:
init = 19136512(18688K) used = 43569672(42548K) committed = 78348288(76512K) max = 318767104(311296K)
heap:
init = 67108864(65536K) used = 70893560(69231K) committed = 209387520(204480K) max = 477233152(466048K)
no-heap:
init = 19136512(18688K) used = 43573768(42552K) committed = 78348288(76512K) max = 318767104(311296K)
2、打印WildFly運行時系統信息：
import static com.sun.btrace.BTraceUtils.*;
import com.sun.btrace.annotations.BTrace;
@BTrace
public class TraceJInfo {
static{
println("java vm properties:===>");
printVmArguments();
println("System properties:===>");
printProperties();
println("OS properties:===>");
printEnv();
exit();
}
}
執行結果：
[root@mdwareweb1 test]# btrace 5513 TraceJInfo.java?
java vm properties:===>
[-D[Standalone], -Xms64m, -Xmx512m, -XX:MaxPermSize=256m, -Djava.net.preferIPv4Stack=true, -Djboss.modules.system.pkgs=org.jboss.byteman, -Djava.awt.headless=true, -Dorg.jboss.boot.log.file=/opt/jboss/wildfly-8.0.0.Final/standalone/log/server.log, -Dlogging.configuration=file:/opt/jboss/wildfly-8.0.0.Final/standalone/configuration/logging.properties]
System properties:===>
org.jboss.security.context.ThreadLocal = true
java.vm.version = 23.25-b01
sun.jnu.encoding = UTF-8
java.vendor.url =?http://java.oracle.com/
java.vm.info = mixed mode
org.apache.xml.security.ignoreLineBreaks = true
jboss.server.name = mdwareweb1
java.awt.headless = true
user.dir = /opt/jboss/wildfly-8.0.0.Final/bin
sun.cpu.isalist =?
logging.configuration =?file:/opt/jboss/wildfly-8.0.0.Final/standalone/configuration/logging.properties
......
3、排查ClassNotFoundException
寫過Java代碼的讀者估計都碰到過ClassNotFoundException/NoClassDefFoundError/NoSuchMethodException(還有一個常見的ClassCastException就不在這里說了)。當碰到ClassNotFoundException/NoClassDefFound時，如果很確定這個class應該是從哪個路徑裝載的，則可以去相應的路徑找下是否有對應的class文件存在，例如web應用通常會在*.war(ear)/WEB-INF/lib或classes目錄下，對于lib下的jar包，可通過寫個小腳本jar -tvf的方式找找；如不確定class是從哪裝載的，則可以先看看日志里是否有堆棧信息，如果有的話則可以看到具體是哪個ClassLoader實現在裝載class，之后則可以通過www.grepcode.com或jar包反編譯看看具體是從哪裝載的class；如果日志中沒有，則可以用btrace來跟蹤下拋出以上兩個異常的堆棧信息，btrace腳本類似如下：
import static com.sun.btrace.BTraceUtils.*;
import com.sun.btrace.annotations.*;
@BTrace public class Trace{
@OnMethod(
clazz="java.lang.ClassNotFoundException",
method="<init>"
)
public static void traceExecute(){
jstack();
}
}
拿到堆棧信息后，可以繼續使用上面的方法進行排查，在確認了class裝載的位置后，則可將相應的class/jar加上即可。
4、排查OutOfMemoryError
盡管JVM是自動管理內存的分配和回收的，但Java程序員們還是會經常碰到各種各樣的內存問題。最常見的第一個問題是java.lang.OutOfMemoryError，估計寫Java的讀者都碰到過。在日志中可能會看到java.lang.OutOfMemoryError: Unable to create new native thread，可以先統計下目前的線程數(例如ps -eLf | grep java -c)，然后可以看看ulimit -u的限制值是多少，如線程數已經達到限制值，如限制值可調整，則可通過調整限制值來解決；如不能調限制值，或者創建的線程已經很多了，那就需要看看線程都是哪里創建出來的，同樣可通過btrace來查出是哪里創建的，腳本類似如下：
import static com.sun.btrace.BTraceUtils.*;
import com.sun.btrace.annotations.*;
@BTrace public class Trace{
@OnMethod(
clazz="java.lang.Thread",
method="start"
)
public static void traceExecute(){
jstack();
}
}
在找到是哪里創建造成了后，之后就可以想辦法解決了，例如這種情況下常見的有可能是用了Executors.newCachedThreadPool這種來創建了一個沒限制大小的線程池。
綜合實例
以下是筆者編寫的一個demo，主要用于測試OOM，當然也會對BTrace的功能進行介紹。
首先，筆者編寫了兩個用于測試的類，如下：
StartObject.java
import java.util.Random;
public class StartObject {
private static int totalTime = 0;
public int work(int sleepTime) throws InterruptedException{
System.out.println("sleep " + sleepTime);
totalTime += sleepTime;
return totalTime;
}
}
HeapOOM.java
import java.util.ArrayList;
import java.util.List;
import java.util.Random;
public class HeapOOM {
public static void main(String agrs[]) throws InterruptedException{
Random random = new Random();
List<Integer> list = new ArrayList<Integer>();
Thread.sleep(10000);
while(true){
int sleepTime = random.nextInt(1000);
list.add(new StartObject().work(sleepTime));
}
}
}
由于筆者將運行時jvm參數設置為：-Xms10m -Xmx10m
因此程序會因為HeapOOM.java中紅色一行代碼不斷創建對象而發生OutOfMemoryError異常。
以下，我們便通過StartObject這個類來查找是在哪不斷新建對象并調用其work方法，于是編寫BTrace腳本如下：
import static com.sun.btrace.BTraceUtils.*;
import com.sun.btrace.annotations.*;
@BTrace
public class TraceObject {
@OnMethod(clazz = "StartObject", method = "work", location = @Location(value = Kind.CALL, clazz = "/.*/", method = "/.*/"))
public static void checkWhoCallMe() {
println("check who ActionObject.work method:");
jstack();
}
}
通過jps查找到HeapOOM執行的pid
執行：btrace [pid] TraceObject.java
在終端我們看到HeapOOM類中執行StratObject.work方法，如此即可找到我們想要的執行對象，從而可以去修改。
若是得到work方法的執行時間的話，腳本如下：
import static com.sun.btrace.BTraceUtils.*;
import com.sun.btrace.annotations.*;
@BTrace
public class TraceObjectCost {
@TLS
static long startTime;
@OnMethod(clazz = "StartObject", method = "work", location = @Location(Kind.RETURN))
public static void start() {
startTime = timeMillis();
}
@OnMethod(clazz = "StartObject", method = "work", location = @Location(Kind.RETURN))
public static void getMethodExecuteCost(int sleepTime,@Return int totalTime) {
String str = str(timeMillis() - startTime);
String strcat = strcat("execute work method cost:", str);
String strcat2 = strcat(strcat, " ms");
println(strcat2);
}
}
若是期望的到一個method哪幾行被執行了的話，腳本如下：
import static com.sun.btrace.BTraceUtils.*;
import com.sun.btrace.annotations.*;
@BTrace
public class TraceObjectLineCall {
@OnMethod(clazz="StartObject",method="work",location=@Location(value=Kind.CALL, clazz="/.*/", method="/.*/"))
public static void lineCall(@Self StartObject self, @TargetMethodOrField String method, @ProbeMethodName String probeMethod){
println(Strings.strcat(method, Strings.strcat(" in ", probeMethod)));
}
}
個人見解
雖然 Btrace 在關鍵時候能起到迅速排查問題的作用，但我個人感覺，這還是不到萬不得已才使用的好。首先，我們代碼上線前，應該充分 review ，充分和相關方進行溝通，以避免不必要的問題發生。其次，我們應該養成記 log 的良好習慣。遇到問題，如果有相關日志可以排查，是最方便的，同時也是最安全，成本最低的一種排查方法。最后，我們可以結合 btrace 和 jdk 自帶的 tool 來排查問題，比如 jstack 、 jstat 等等，快速的定位問題。
?
參考資料
http://kenai.com/projects/btrace/pages/UserGuide
http://learnworld.iteye.com/blog/1402763
http://inter12.iteye.com/blog/1759882
http://www.cnblogs.com/serendipity/archive/2012/05/14/2499840.html
?
附錄
相關實例說明
AWTEventTracer.java -演示了對EventQueue.dispatchEvent()事件進行trace的做法,可以通過instanceof來對事件進行過濾,比如這里只針對focus事件trace.
AllLines.java -演示了如何在被trace的程序到達probe指定的類和指定的行號時執行指定的操作(例子中指定的行號是-1表示任意行).
AllSync.java -演示了如何在進入/退出同步塊進行trace.
ArgArray.java -演示了打印java.io包下所有類的readXXX方法的輸入參數.
Classload.java -演示打印成功加載指定類以及堆棧信息.
CommandArg.java -演示如何獲取btrace命令行參數.
Deadlock.java -演示了@OnTimer注解和內置deadlock()方法的用法
DTraceInline.java -演示@DTrace注解的用法
DTraceDemoRef.java -演示@DTraceRef注解的用法.
FileTracker.java -演示了如何對File{Input/Output}Stream構造函數中初始化打開文件的讀寫文件操作進行trace.
FinalizeTracker.java -演示了如何打印一個類所有的屬性,這個在調試和故障分析中非常有用.這里的例子是打印FileInputStream類的close() /finalize()方法被調用時的信息.
Histogram.java -演示了統計javax.swing.JComponent在一個應用中被創建了多少次.
HistogramBean.java -同上例,只不過演示了如何與JMX集成,這里的map屬性通過使用@Property注解被暴露成一個MBean.
HistoOnEvent.java -同上例,只不過演示了如何在通過按ctrl+c中斷當前腳本時打印出創建次數,而不是定時打印.
JdbcQueries.java -演示了聚合(aggregation)功能.關于聚合功能可參考DTrace.
JInfo.java -演示了內置方法printVmArguments(), printProperties()和printEnv()的用法
JMap.java -演示了內置方法dumpHeap()的用法.即將目標應用的堆信息以二進制的形式dump出來
JStack.java -演示了內置方法jstackAll()的用法,即打印所有線程的堆棧信息.
LogTracer.java -演示了如何深入實例方法(Logger.log)并調用內置方法(field() )打印私有屬性內容.
MemAlerter.java -演示了使用@OnLowMememory注解監控內存使用情況.即堆內存中的年老代達到指定值時打印出內存信息.
Memory.java -演示每隔4s打印一次內存統計信息.
MultiClass.java -演示了通過使用正則表達式對多個類的多個方法進行trace.
NewComponent.java -使用計數器每隔一段時間檢查當前應用中創建java.awt.Component的個數.
OnThrow.java -當拋出異常時,打印出異常堆棧信息.
ProbeExit.java -演示@OnExit注解和內置exit(int)方法的用法
Profiling.java -演示了對profile的支持. //我執行沒成功, BTrace內部有異常
Sizeof.java -演示了內置的sizeof方法的使用.
SocketTracker.java -演示了對socket的creation/bind方法的trace.
SocketTracker1.java -同上,只不過使用了@OnProbe.
SysProp.java -演示了使用內置方法獲取系統屬性,這里是對java.lang.System的getProperty方法進行trace.
SubtypeTracer.java -演示了如何對指定超類的所有子類的指定方法進行trace.
ThreadCounter.java -演示了在腳本中如何使用jvmstat計數器. (jstat -J-Djstat.showUnsupported=true -name btrace.com.sun.btrace.samples.ThreadCounter.count需要這樣來從外部通過jstat來訪問)
ThreadCounterBean.java -同上,只不過使用了JMX.
ThreadBean.java -演示了對預編譯器的使用(并結合了JMX).
ThreadStart.java -演示了腳本中DTrace的用法.
Timers.java -演示了在一個腳本中同時使用多個@OnTimer
URLTracker.java -演示了在每次URL.openConnection成功返回時打印出url.這里也使用了D語言腳本.
WebServiceTracker.java -演示了如何根據注解進行trace.
總結
以上是生活随笔為你收集整理的BTrace简介及使用的全部內容，希望文章能夠幫你解決所遇到的問題。
- 上一篇： G1 GC 日志格式
- 下一篇： 快速搞懂ThreadLocal实现原理