Linux命令拾遺之動態追蹤工具（範例詳解）
2022-01-10 22:00:43
執行緒與記憶體剖析，只能觀測到程序的整體情況，有些時候我們需要觀測到某一方法級別，比如呼叫方法test()時，傳入的引數是什麼，返回值是多少，花費了多少時間？這種情況下，我們就需要使用一些動態追蹤工具了，如strace、arthas、bpftrace、systemtap等。
strace與ltrace
strace是Linux中用來觀測系統呼叫的工具，學過作業系統原理都知道，作業系統嚮應用程式暴露了一批系統呼叫介面，應用程式只能通過這些系統呼叫介面來存取作業系統，比如申請記憶體、檔案或網路io操作等。
用法如下：
# -T 列印系統呼叫花費的時間 # -tt 列印系統呼叫的時間點 # -s 輸出的最大長度，預設32，對於呼叫引數較長的場景，建議加大 # -f 是否追蹤fork出來子程序的系統呼叫，由於伺服器端服務普通使用執行緒池，建議加上 # -p 指定追蹤的程序pid # -o 指定追蹤紀錄檔輸出到哪個檔案，不指定則直接輸出到終端 $ strace -T -tt -f -s 10000 -p 87 -o strace.log
範例：抓取實際傳送的SQL
有些時候，我們會發現程式碼中完全沒問題的SQL，卻查不到資料，這極有可能是由於專案中一些底層框架改寫了SQL，導致真實傳送的SQL與程式碼中的SQL不一樣。
遇到這種情況，先別急著扒底層框架程式碼，那樣會比較花時間，畢竟程式設計師的時間很寶貴，不然要加更多班的，怎麼快速確認是不是這個原因呢？
有兩種方法，第一種是使用wireshark抓包，第二種就是本篇介紹的strace了，由於程式必然要通過網路io相關的系統呼叫，將SQL命令傳送到資料庫，因此我們只需要用strace追蹤所有系統呼叫，然後grep出傳送SQL的系統呼叫即可，如下：
$ strace -T -tt -f -s 10000 -p 87 |& tee strace.log
從圖中可以清晰看到，mysql的jdbc驅動是通過sendto系統呼叫來傳送SQL，通過recvfrom來獲取返回結果，可以發現，由於SQL是字串，strace自動幫我們識別出來了，而返回結果因為是二進位制的，就不容易識別了，需要非常熟悉mysql協定才行。
另外，從上面其實也很容易看出SQL執行耗時，計算相同執行緒號的sendto與recvfrom之間的時間差即可。
ltrace
由於大多數程序基本都會使用基礎c庫，而不是系統呼叫，如Linux上的glibc，Windows上的msvc，所以還有一個工具ltrace，可以用來追蹤庫呼叫，如下：
$ ltrace -T -tt -f -s 10000 -p 87 -o ltrace.log
基本用法和strace一樣，一般來說，使用strace就夠了。
arthas
arthas是java下的一款動態追蹤工具，可以觀測到java方法的呼叫引數、返回值等，除此之外，還提供了很多實用功能，如反編譯、執行緒剖析、堆記憶體轉儲、火焰圖等。
下載與使用
# 下載arthas $ wget https://arthas.aliyun.com/download/3.4.6?mirror=aliyun -O arthas-packaging-3.4.6-bin.zip # 解壓 $ unzip arthas-packaging-3.4.6-bin.zip -d arthas && cd arthas/ # 進入arthas命令互動介面 $ java -jar arthas-boot.jar `pgrep -n java` [INFO] arthas-boot version: 3.4.6 [INFO] arthas home: /home/work/arthas [INFO] Try to attach process 3368243 [INFO] Attach process 3368243 success. [INFO] arthas-client connect 127.0.0.1 3658 ,---. ,------. ,--------.,--. ,--. ,---. ,---. / O \ | .--. ''--. .--'| '--' | / O \ ' .-' | .-. || '--'.' | | | .--. || .-. |`. `-. | | | || |\ \ | | | | | || | | |.-' | `--' `--'`--' '--' `--' `--' `--'`--' `--'`-----' wiki https://arthas.aliyun.com/doc tutorials https://arthas.aliyun.com/doc/arthas-tutorials.html version 3.4.6 pid 3368243 time 2021-11-13 13:35:49 # help可檢視arthas提供了哪些命令 [arthas@3368243]$ help # help watch可檢視watch命令具體用法 [arthas@3368243]$ help watch
watch、trace與stack
在arthas中，使用watch、trace、stack命令可以觀測方法呼叫情況，如下：
# watch觀測執行的查詢SQL，-x 3指定物件展開層級
[arthas@3368243]$ watch org.apache.ibatis.executor.statement.PreparedStatementHandler parameterize '{target.boundSql.sql,target.boundSql.parameterObject}' -x 3
method=org.apache.ibatis.executor.statement.PreparedStatementHandler.parameterize location=AtExit
ts=2021-11-13 14:50:34; [cost=0.071342ms] result=@ArrayList[
@String[select id,log_info,create_time,update_time,add_time from app_log where id=?],
@ParamMap[
@String[id]:@Long[41115],
@String[param1]:@Long[41115],
],
]
# watch觀測耗時超過200ms的SQL
[arthas@3368243]$ watch com.mysql.jdbc.PreparedStatement execute '{target.toString()}' 'target.originalSql.contains("select") && #cost > 200' -x 2
Press Q or Ctrl+C to abort.
Affect(class count: 3 , method count: 1) cost in 123 ms, listenerId: 25
method=com.mysql.jdbc.PreparedStatement.execute location=AtExit
ts=2021-11-13 14:58:42; [cost=1001.558851ms] result=@ArrayList[
@String[com.mysql.jdbc.PreparedStatement@6283cfe6: select count(*) from app_log],
]
# trace追蹤方法耗時，層層追蹤，就可找到耗時根因，--skipJDKMethod false顯示jdk方法耗時，預設不顯示
[arthas@3368243]$ trace com.mysql.jdbc.PreparedStatement execute 'target.originalSql.contains("select") && #cost > 200' --skipJDKMethod false
Press Q or Ctrl+C to abort.
Affect(class count: 3 , method count: 1) cost in 191 ms, listenerId: 26
---ts=2021-11-13 15:00:40;thread_name=http-nio-8080-exec-47;id=76;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@5a2d131d
---[1001.465544ms] com.mysql.jdbc.PreparedStatement:execute()
+---[0.022119ms] com.mysql.jdbc.PreparedStatement:checkClosed() #1274
+---[0.016294ms] com.mysql.jdbc.MySQLConnection:getConnectionMutex() #57
+---[0.017862ms] com.mysql.jdbc.PreparedStatement:checkReadOnlySafeStatement() #1278
+---[0.008996ms] com.mysql.jdbc.PreparedStatement:createStreamingResultSet() #1294
+---[0.010783ms] com.mysql.jdbc.PreparedStatement:clearWarnings() #1296
+---[0.017843ms] com.mysql.jdbc.PreparedStatement:fillSendPacket() #1316
+---[0.008543ms] com.mysql.jdbc.MySQLConnection:getCatalog() #1320
+---[0.009293ms] java.lang.String:equals() #57
+---[0.008824ms] com.mysql.jdbc.MySQLConnection:getCacheResultSetMetadata() #1328
+---[0.009892ms] com.mysql.jdbc.MySQLConnection:useMaxRows() #1354
+---[1001.055229ms] com.mysql.jdbc.PreparedStatement:executeInternal() #1379
+---[0.02076ms] com.mysql.jdbc.ResultSetInternalMethods:reallyResult() #1388
+---[0.011517ms] com.mysql.jdbc.MySQLConnection:getCacheResultSetMetadata() #57
+---[0.00842ms] com.mysql.jdbc.ResultSetInternalMethods:getUpdateID() #1404
---[0.008112ms] com.mysql.jdbc.ResultSetInternalMethods:reallyResult() #1409
# stack追蹤方法呼叫棧，找到耗時SQL來源
[arthas@3368243]$ stack com.mysql.jdbc.PreparedStatement execute 'target.originalSql.contains("select") && #cost > 200'
Press Q or Ctrl+C to abort.
Affect(class count: 3 , method count: 1) cost in 138 ms, listenerId: 27
ts=2021-11-13 15:01:55;thread_name=http-nio-8080-exec-5;id=2d;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@5a2d131d
@com.mysql.jdbc.PreparedStatement.execute()
at com.alibaba.druid.pool.DruidPooledPreparedStatement.execute(DruidPooledPreparedStatement.java:493)
at org.apache.ibatis.executor.statement.PreparedStatementHandler.query(PreparedStatementHandler.java:63)
at org.apache.ibatis.executor.statement.RoutingStatementHandler.query(RoutingStatementHandler.java:79)
at org.apache.ibatis.executor.SimpleExecutor.doQuery(SimpleExecutor.java:63)
at org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(BaseExecutor.java:326)
at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:156)
at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:136)
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:148)
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:141)
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectOne(DefaultSqlSession.java:77)
at sun.reflect.GeneratedMethodAccessor75.invoke(null:-1)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:433)
at com.sun.proxy.$Proxy113.selectOne(null:-1)
at org.mybatis.spring.SqlSessionTemplate.selectOne(SqlSessionTemplate.java:166)
at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:83)
at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:59)
at com.sun.proxy.$Proxy119.selectCost(null:-1)
at com.demo.example.web.controller.TestController.select(TestController.java:57)可以看到watch、trace、stack命令中都可以指定條件表示式，只要滿足ognl表示式語法即可，ognl完整語法很複雜，如下是一些經常使用的：
ognl
通過ognl命令，可直接檢視靜態變數的值，如下：
# 呼叫System.getProperty靜態函數，檢視jvm預設字元編碼
[arthas@3368243]$ ognl '@System@getProperty("file.encoding")'
@String[UTF-8]
# 找到springboot類載入器
[arthas@3368243]$ classloader -t
+-BootstrapClassLoader
+-sun.misc.Launcher$ExtClassLoader@492691d7
+-sun.misc.Launcher$AppClassLoader@764c12b6
+-org.springframework.boot.loader.LaunchedURLClassLoader@4361bd48
# 獲取springboot中所有的beanName，-c指定springboot的classloader的hash值
# 一般Spring專案，都會定義一個SpringUtil的，用於獲取bean容器ApplicationContext
[arthas@3368243]$ ognl -c 4361bd48 '#[email protected]@applicationContext, #context.beanFactory.beanDefinitionNames'
@String[][
@String[org.springframework.context.annotation.internalConfigurationAnnotationProcessor],
@String[org.springframework.context.annotation.internalAutowiredAnnotationProcessor],
@String[org.springframework.context.annotation.internalCommonAnnotationProcessor],
@String[testController],
@String[apiController],
@String[loginService],
...
]
# 獲取springboot設定，如server.port是設定http伺服器埠的
[arthas@3368243]$ ognl -c 4361bd48 '#[email protected]@applicationContext, #context.getEnvironment().getProperty("server.port")'
@String[8080]
# 檢視server.port定義在哪個組態檔中
# 可以很容易看到，server.port定義在application-web.yml
[arthas@3368243]$ ognl -c 4361bd48 '#[email protected]@applicationContext, #context.environment.propertySources.propertySourceList.{? containsProperty("server.port")}'
@ArrayList[
@ConfigurationPropertySourcesPropertySource[ConfigurationPropertySourcesPropertySource {name='configurationProperties'}],
@OriginTrackedMapPropertySource[OriginTrackedMapPropertySource {name='applicationConfig: [classpath:/application-web.yml]'}],
]
# 呼叫springboot中bean的方法，獲取返回值
[arthas@3368243]$ ognl -c 4361bd48 '#[email protected]@applicationContext, #context.getBean("demoMapper").queryOne(12)' -x 2
@ArrayList[
@HashMap[
@String[update_time]:@Timestamp[2021-11-09 18:38:13,000],
@String[create_time]:@Timestamp[2021-04-17 15:52:55,000],
@String[log_info]:@String[TbTRNsh2SixuFrkYLTeb25a6zklEZj0uWANKRMe],
@String[id]:@Long[12],
@String[add_time]:@Integer[61],
],
]
# 檢視springboot自帶tomcat的執行緒池的情況
[arthas@3368243]$ ognl -c 4361bd48 '#[email protected]@applicationContext, #context.webServer.tomcat.server.services[0].connectors[0].protocolHandler.endpoint.executor'
@ThreadPoolExecutor[
sm=@StringManager[org.apache.tomcat.util.res.StringManager@16886f49],
submittedCount=@AtomicInteger[1],
threadRenewalDelay=@Long[1000],
workQueue=@TaskQueue[isEmpty=true;size=0],
mainLock=@ReentrantLock[java.util.concurrent.locks.ReentrantLock@69e9cf90[Unlocked]],
workers=@HashSet[isEmpty=false;size=10],
largestPoolSize=@Integer[49],
completedTaskCount=@Long[10176],
threadFactory=@TaskThreadFactory[org.apache.tomcat.util.threads.TaskThreadFactory@63c03c4f],
handler=@RejectHandler[org.apache.tomcat.util.threads.ThreadPoolExecutor$RejectHandler@3667e559],
keepAliveTime=@Long[60000000000],
allowCoreThreadTimeOut=@Boolean[false],
corePoolSize=@Integer[10],
maximumPoolSize=@Integer[8000],
]其它命令
arthas還提供了jvm大盤、執行緒剖析、堆轉儲、反編譯、火焰圖等功能，如下：
# 顯示耗cpu較多的前4個執行緒
[arthas@3368243]$ thread -n 4
"C2 CompilerThread0" [Internal] cpuUsage=8.13% deltaTime=16ms time=46159ms
"C2 CompilerThread1" [Internal] cpuUsage=4.2% deltaTime=8ms time=47311ms
"C1 CompilerThread2" [Internal] cpuUsage=3.06% deltaTime=6ms time=17402ms
"http-nio-8080-exec-40" Id=111 cpuUsage=1.29% deltaTime=2ms time=624ms RUNNABLE (in native)
at java.net.SocketInputStream.socketRead0(Native Method)
...
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4113)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2570)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2731)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2818)
...
at com.demo.example.web.controller.TestController.select(TestController.java:57)
# 堆轉儲
[arthas@3368243]$ heapdump
Dumping heap to /tmp/heapdump2021-11-13-15-117226383240040009563.hprof ...
Heap dump file created
# cpu火焰圖，容器環境下profiler start可能用不了，可用profiler start -e itimer替代
[arthas@3368243]$ profiler start
Started [cpu] profiling
[arthas@3368243]$ profiler stop
OK
profiler output file: /home/work/app/arthas-output/20211113-151208.svg
# dashboard就類似Linux下的top一樣，可看jvm執行緒、堆記憶體的整體情況
[arthas@3368243]$ dashboard
# jvm就類似Linux下的ps一樣，可以看jvm程序的一些基本資訊，如：jvm引數、類載入、執行緒數、開啟檔案描述符數等
[arthas@3368243]$ jvm
# 反編譯
[arthas@3368243]$ jad com.demo.example.web.controller.TestController可見，arthas已經不是一個單純的動態追蹤工具了，它把jvm下常用的診斷功能幾乎全囊括了。
bpftrace
arthas只能追蹤java程式，對於原生程式(如MySQL)就無能為力了，好在Linux生態提供了大量的機制以及配套工具，可用於追蹤原生程式的呼叫，如perf、bpftrace、systemtap等，由於bpftrace使用難度較小，本篇主要介紹它的用法。
bpftrace是基於ebpf技術實現的動態追蹤工具，它對ebpf技術進行封裝，實現了一種指令碼語言，就像上面介紹的arthas基於ognl一樣，它實現的指令碼語言類似於awk，封裝了常見語句塊，並提供內建變數與內建函數，如下：
$ sudo bpftrace -e 'BEGIN { printf("Hello, World!\n"); } '
Attaching 1 probe...
Hello, World!範例：在呼叫端追蹤慢SQL
前面我們用strace追蹤過mysql的jdbc驅動，它使用sendto與recvfrom系統呼叫來與mysql伺服器通訊，因此，我們在sendto呼叫時，計下時間點，然後在recvfrom結束時，計算時間之差，就可以得到相應SQL的耗時了，如下：
先找到sendto與recvfrom系統呼叫在bpftrace中的追蹤點，如下：
# 查詢sendto|recvfrom系統呼叫的追蹤點，可以看到sys_enter_開頭的追蹤點應該是進入時觸發，sys_exit_開頭的退出時觸發
$ sudo bpftrace -l '*tracepoint:syscalls*' |grep -E 'sendto|recvfrom'
tracepoint:syscalls:sys_enter_sendto
tracepoint:syscalls:sys_exit_sendto
tracepoint:syscalls:sys_enter_recvfrom
tracepoint:syscalls:sys_exit_recvfrom
# 檢視系統呼叫引數，方便我們編寫指令碼
$ sudo bpftrace -lv tracepoint:syscalls:sys_enter_sendto
tracepoint:syscalls:sys_enter_sendto
int __syscall_nr;
int fd;
void * buff;
size_t len;
unsigned int flags;
struct sockaddr * addr;
int addr_len;編寫追蹤指令碼trace_slowsql_from_syscall.bt，指令碼程式碼如下：
#!/usr/local/bin/bpftrace
BEGIN {
printf("Tracing jdbc SQL slower than %d ms by sendto/recvfrom syscall\n", $1);
printf("%-10s %-6s %6s %s\n", "TIME(ms)", "PID", "MS", "QUERY");
}
tracepoint:syscalls:sys_enter_sendto /comm == "java"/ {
// mysql協定中，包開始的第5位元組指示命令型別，3代表SQL查詢
$com = *(((uint8 *) args->buff)+4);
if($com == (uint8)3){
@query[tid]=str(((uint8 *) args->buff)+5, (args->len)-5);
@start[tid]=nsecs;
}
}
tracepoint:syscalls:sys_exit_recvfrom /comm == "java" && @start[tid]/ {
$dur = (nsecs - @start[tid]) / 1000000;
if ($dur > $1) {
printf("%-10u %-6d %6d %s\n", elapsed / 1000000, pid, $dur, @query[tid]);
}
delete(@query[tid]);
delete(@start[tid]);
}其中，comm表示程序名稱，tid表示執行緒號，@query[tid]與@start[tid]類似map，以tid為key的話，這個變數就像一個執行緒本地變數了。
呼叫上面的指令碼，可以看到各SQL執行耗時，如下：
$ sudo BPFTRACE_STRLEN=80 bpftrace trace_slowsql_from_syscall.bt Attaching 3 probes... Tracing jdbc SQL slower than 0 ms by sendto/recvfrom syscall TIME(ms) PID MS QUERY 6398 3368243 125 select sleep(0.1) 16427 3368243 22 select id from app_log al order by id desc limit 1 16431 3368243 20 select id,log_info,create_time,update_time,add_time from app_log where id=11692 17492 3368243 21 select id,log_info,create_time,update_time,add_time from app_log where id=29214
範例：在伺服器端追蹤慢SQL
從呼叫端來追蹤SQL耗時，會包含網路往返時間，為了得到更精確的SQL耗時，我們可以寫一個追蹤伺服器端mysql的指令碼，來觀測SQL耗時，如下：
確定mysqld服務程序的可執行檔案與入口函數
$ which mysqld /usr/local/mysql/bin/mysqld # objdump可匯出可執行檔案的動態符號表，做幾張mysqld的火焰圖就可發現，dispatch_command是SQL處理的入口函數 # 另外，由於mysql是c++寫的，方法名是編譯器改寫過的，這也是為啥下面指令碼中要用*dispatch_command*模糊匹配 $ objdump -tT /usr/local/mysql/bin/mysqld | grep dispatch_command 00000000014efdf3 g F .text 000000000000252e _Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command 00000000014efdf3 g DF .text 000000000000252e Base _Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command
使用uprobe追蹤dispatch_command的呼叫，如下：
#!/usr/bin/bpftrace
BEGIN{
printf("Tracing mysqld SQL slower than %d ms. Ctrl-C to end.\n", $1);
printf("%-10s %-6s %6s %s\n", "TIME(ms)", "PID", "MS", "QUERY");
}
uprobe:/usr/local/mysql/bin/mysqld:*dispatch_command*{
if (arg2 == (uint8)3) {
@query[tid] = str(*arg1);
@start[tid] = nsecs;
}
}
uretprobe:/usr/local/mysql/bin/mysqld:*dispatch_command* /@start[tid]/{
$dur = (nsecs - @start[tid]) / 1000000;
if ($dur > $1) {
printf("%-10u %-6d %6d %s\n", elapsed / 1000000, pid, $dur, @query[tid]);
}
delete(@query[tid]);
delete(@start[tid]);
}追蹤指令碼整體上與之前系統呼叫版本的類似，不過追蹤點不一樣而已。
範例：找出掃描大量行的SQL
眾所周知，SQL執行時需要掃描資料，並且掃描的資料越多，SQL效能就會越差。
但對於一些中間情況，SQL掃描行數不多也不少，如2w條。且這2w條資料都在快取中的話，SQL執行時間不會很長，導致沒有記錄在慢查詢紀錄檔中，但如果這樣的SQL並行量大起來的話，會非常耗費CPU。
對於mysql的話，掃描行的函數是row_search_mvcc（如果你經常抓取mysql棧的話，很容易發現這個函數），每掃一行呼叫一次，如果在追蹤指令碼中追蹤此函數，記錄下呼叫次數，就可以觀測SQL的掃描行數了，如下：
#!/usr/bin/bpftrace
BEGIN{
printf("Tracing mysqld SQL scan row than %d. Ctrl-C to end.\n", $1);
printf("%-10s %-6s %6s %10s %s\n", "TIME(ms)", "PID", "MS", "SCAN_NUM", "QUERY");
}
uprobe:/usr/local/mysql/bin/mysqld:*dispatch_command*{
$COM_QUERY = (uint8)3;
if (arg2 == $COM_QUERY) {
@query[tid] = str(*arg1);
@start[tid] = nsecs;
}
}
uprobe:/usr/local/mysql/bin/mysqld:*row_search_mvcc*{
@scan_num[tid]++;
}
uretprobe:/usr/local/mysql/bin/mysqld:*dispatch_command* /@start[tid]/{
$dur = (nsecs - @start[tid]) / 1000000;
if (@scan_num[tid] > $1) {
printf("%-10u %-6d %6d %10d %s\n", elapsed / 1000000, pid, $dur, @scan_num[tid], @query[tid]);
}
delete(@query[tid]);
delete(@start[tid]);
delete(@scan_num[tid]);
}指令碼執行效果如下：
$ sudo BPFTRACE_STRLEN=80 bpftrace trace_mysql_scan.bt 200
Attaching 4 probes...
Tracing mysqld SQL scan row than 200. Ctrl-C to end.
TIME(ms) PID MS SCAN_NUM QUERY
150614 1892 4 300 select * from app_log limit 300
# 全表掃描，慢！
17489 1892 424 43717 select count(*) from app_log
# 大範圍索引掃描，慢！
193013 1892 253 20000 select count(*) from app_log where id < 20000
# 深分頁，會查詢前20300條，取最後300條，慢！
213395 1892 209 20300 select * from app_log limit 20000,300
# 索引效果不佳，雖然只會查到一條資料，但掃描資料量不會少，慢！
430374 1892 186 15000 select * from app_log where id < 20000 and seq = 15000 limit 1如上所示，app_log是我建的一張測試表，共43716條資料，其中id欄位是自增主鍵，seq值與id值一樣，但沒有索引。
可以看到上面的幾個場景，不管什麼場景，只要掃描行數變大，耗時就會變長，但也都沒有超過500毫秒的，原因是這個表很小，資料可以全部快取在記憶體中。
可見，像bpftrace這樣的動態追蹤工具是非常強大的，而且比arthas更加靈活，arthas只能追蹤單個函數，而bpftrace可以跨函數追蹤。
總結
已經介紹了不少診斷工具了，這裡簡單概括一下它們的應用場景：
軟體資源觀測，如ps、lsof、netstat，用來檢查程序基本情況，如記憶體佔用、開啟哪些檔案、建立了哪些連線等。
硬體資源觀測，如top、iostat、sar等，類似Windows上工作管理員一樣，讓你對硬體資源佔用以及在程序上情況有個大概瞭解，最多觀測到執行緒級別，這些工具一般只能指示進一步調查的方向，很少能直接確認原因。
執行緒與記憶體剖析，如jstack、jmap等，比較容易分析執行緒卡住或記憶體oom問題，而oncpu火焰圖容易找出熱程式碼路徑，分析高cpu瓶頸，offcpu火焰圖則容易找出經常阻塞的程式碼路徑，分析高耗時問題。
動態追蹤工具，如arthas、bpftrace等，能追蹤到方法呼叫級，常用於問題需要深入調查的場景，如問題不在程式碼實現上，而在呼叫資料上，就像上面row_search_mvcc函數一樣，抓火焰圖會發現它出現頻繁，但由於它是核心函數，這個頻繁可能是正常的，也可能是不正常的，需要將呼叫次數分散到SQL上才能確認。
相關推薦：《Linux視訊教學》
以上就是Linux命令拾遺之動態追蹤工具（範例詳解）的詳細內容，更多請關注TW511.COM其它相關文章！