溫馨提示×
您好，登錄后才能下訂單哦！
點擊 登錄注冊 即表示同意《億速云用戶服務條款》
您好，登錄后才能下訂單哦！
在生產上我們經常會碰到一些不好排查的問題，例如線程安全問題，用最簡單的threaddump或者heapdump不好查到問題原因。為了排查這些問題，有時我們會臨時加一些日志，比如在一些關鍵的函數里打印出入參，然后重新打包發布，如果打了日志還是沒找到問題，繼續加日志，重新打包發布。對于上線流程復雜而且審核比較嚴的公司，從改代碼到上線需要層層的流轉，會大大影響問題排查的進度。
這個時候我們可以使用能夠在線調試的工具幫助我們查找問題，例如btrace，可以動態的插入代碼，極大提高我們查找問題的效率。本文通過生產案例介紹如何用這一類工具快速定位傳統方法不好定位的問題。
服務器在高并發的情況下cpu消耗很高，響應速度變慢，打threaddump，發現創建了大量的Timer-xxx線程，狀態都是runnable，但是沒有函數堆棧，也就是剛創建了還沒執行。打heapdump看，還是不好發現問題，也只能看到一堆沒有堆棧的線程。
查了代碼，發現近期改的地方沒有主動創建Timer的地方，所以大概率是第三方jar包創建的，怎么才能找到是誰創建的線程。用這種靜態的分析方法已經不太好用了，因為不管是ThreadDump還是HeapDump，抓住的都是一個快照，ThreadDump主要用來看線程的狀態，HeapDump主要是看內存里的東西，還可以看線程里調用鏈上的棧的內容（僅限于對象，基本類型看不到）。
我們要知道誰創建的線程，只要知道誰調用了Thread類的start方法即可。假如我們在ThreadDump里看到如下的stacktrace:
java.lang.Thread.start()
com.xxx.SomeClass.startNewThread();
…
那我們就知道是誰創建了新線程，但是遺憾的是start方法太快，而ThreadDump很難抓到，start調用結束后就有一個新的stacktrace了。大部分情況下ThreadDump只會抓到比較慢的函數，最常見的是socket.read()這樣的，還有一些需要多次循環的。
必須借助功能更強大的工具進行分析，比如Btrace，可以動態的插入字節碼，可以使我們動態的在線查找問題。Btrace是比較基礎的工具，需要自己寫代碼插入，原理就是字節碼增強，或者叫Instrumentation，類似于AOP，通過插入一些代碼進行調試分析，包括很多性能監控工具，也是通過這個原理進行無侵入的埋點。
BTrace是Java的安全可靠的動態跟蹤工具。 它的工作原理是通過 instrument + asm 來對正在運行的java程序中的class類進行動態增強。使用Btrace時需要寫btrace腳本，也就是Java代碼，這些代碼會被植入運行的JVM中，如果寫的不好，可能會把JVM搞崩潰。
Arthas是阿里開源的一款工具，跟Btrace的原理一樣，它用起來更簡單，把最常用的功能都做了封裝，不需要自己寫代碼了，使用起來比較簡單，但是靈活性不如BTrace。
用Btrace舉兩個例子，沒法用threaddump和heapdump快速定位問題的情況。
假如我們有以下代碼，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)
通過調用堆棧，就能找到是誰創建的線程了。
下面的代碼，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，可以看到函數堆棧以及入參，查看一下慢線程的入參：
在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寫代碼比較好。
上述兩個問題都可以用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方便，但是兩個都不安全，能不用盡量不用，用了的話最好重啟應用。
找到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)
......
看代碼是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包。創建線程的代碼如下：
網上搜索這個參數，這個選項配成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驗證結果如下：
Weblogic上部署了多個應用，但是只有一個應用有這個問題，通過分析數據源的配置，發現在mybatis的參數里有一個
這個配置的單位是秒，也不知道開發人員怎么想的，設置了25000秒，如果sql變慢了，就會導致大量的Timer線程出現。
這個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里加入下面的參數就可以了。
這個參數到底要不要用，怎么用，還得根據場景不同來區分，mysql也有這方面的坑，
https://blog.csdn.net/aa283818932/article/details/40379211
這一篇文章講了jdbc的各種超時，講的比較好。
https://www.cubrid.org/blog/understanding-jdbc-internals-and-timeout-configuration
免責聲明：本站發布的內容（圖片、視頻和文字）以原創、轉載和分享為主，文章觀點不代表本網站立場，如果涉及侵權請聯系站長郵箱：is@yisu.com進行舉報，并提供相關證據，一經查實，將立刻刪除涉嫌侵權內容。
