日本综合一区二区|亚洲中文天堂综合|日韩欧美自拍一区|男女精品天堂一区|欧美自拍第6页亚洲成人精品一区|亚洲黄色天堂一区二区成人|超碰91偷拍第一页|日韩av夜夜嗨中文字幕|久久蜜综合视频官网|精美人妻一区二区三区

RELATEED CONSULTING
相關(guān)咨詢
選擇下列產(chǎn)品馬上在線溝通
服務(wù)時(shí)間：8:30-17:00
你可能遇到了下面的問題
關(guān)閉右側(cè)工具欄

新聞中心

這里有您想知道的互聯(lián)網(wǎng)營(yíng)銷解決方案
Linux動(dòng)態(tài)追蹤工具strace、arthas、bpftrace

這是Linux命令拾遺系列的第六篇，本篇主要介紹工作中常用的動(dòng)態(tài)追蹤工具strace、arthas、bpftrace等。

之前介紹了一些線程與內(nèi)存剖析工具，如jstack、pstack能很容易觀測(cè)到線程被卡在了什么位置，而jmap、gcore則容易排查內(nèi)存泄露、oom等問題。

但線程與內(nèi)存剖析，只能觀測(cè)到進(jìn)程的整體情況，有些時(shí)候我們需要觀測(cè)到某一方法級(jí)別，比如調(diào)用方法test()時(shí)，傳入的參數(shù)是什么，返回值是多少，花費(fèi)了多少時(shí)間？這種情況下，我們就需要使用一些動(dòng)態(tài)追蹤工具了，如strace、arthas、bpftrace、systemtap等。

strace與ltrace

strace是Linux中用來(lái)觀測(cè)系統(tǒng)調(diào)用的工具，學(xué)過(guò)操作系統(tǒng)原理都知道，操作系統(tǒng)向應(yīng)用程序暴露了一批系統(tǒng)調(diào)用接口，應(yīng)用程序只能通過(guò)這些系統(tǒng)調(diào)用接口來(lái)訪問操作系統(tǒng)，比如申請(qǐng)內(nèi)存、文件或網(wǎng)絡(luò)io操作等。
用法如下：

# -T 打印系統(tǒng)調(diào)用花費(fèi)的時(shí)間
# -tt 打印系統(tǒng)調(diào)用的時(shí)間點(diǎn)
# -s 輸出的最大長(zhǎng)度，默認(rèn)32，對(duì)于調(diào)用參數(shù)較長(zhǎng)的場(chǎng)景，建議加大
# -f 是否追蹤fork出來(lái)子進(jìn)程的系統(tǒng)調(diào)用，由于服務(wù)端服務(wù)普通使用線程池，建議加上
# -p 指定追蹤的進(jìn)程pid
# -o 指定追蹤日志輸出到哪個(gè)文件，不指定則直接輸出到終端
$ strace -T -tt -f -s 10000 -p 87 -o strace.log

實(shí)例：抓取實(shí)際發(fā)送的SQL

有些時(shí)候，我們會(huì)發(fā)現(xiàn)代碼中完全沒問題的SQL，卻查不到數(shù)據(jù)，這極有可能是由于項(xiàng)目中一些底層框架改寫了SQL，導(dǎo)致真實(shí)發(fā)送的SQL與代碼中的SQL不一樣。

遇到這種情況，先別急著扒底層框架代碼，那樣會(huì)比較花時(shí)間，畢竟程序員的時(shí)間很寶貴，不然要加更多班的，怎么快速確認(rèn)是不是這個(gè)原因呢？

有兩種方法，第一種是使用wireshark抓包，第二種就是本篇介紹的strace了，由于程序必然要通過(guò)網(wǎng)絡(luò)io相關(guān)的系統(tǒng)調(diào)用，將SQL命令發(fā)送到數(shù)據(jù)庫(kù)，因此我們只需要用strace追蹤所有系統(tǒng)調(diào)用，然后grep出發(fā)送SQL的系統(tǒng)調(diào)用即可，如下：

$ strace -T -tt -f -s 10000 -p 87 |& tee strace.log


從圖中可以清晰看到，mysql的jdbc驅(qū)動(dòng)是通過(guò)sendto系統(tǒng)調(diào)用來(lái)發(fā)送SQL，通過(guò)recvfrom來(lái)獲取返回結(jié)果，可以發(fā)現(xiàn)，由于SQL是字符串，strace自動(dòng)幫我們識(shí)別出來(lái)了，而返回結(jié)果因?yàn)槭嵌M(jìn)制的，就不容易識(shí)別了，需要非常熟悉mysql協(xié)議才行。

另外，從上面其實(shí)也很容易看出SQL執(zhí)行耗時(shí)，計(jì)算相同線程號(hào)的sendto與recvfrom之間的時(shí)間差即可。

ltrace
由于大多數(shù)進(jìn)程基本都會(huì)使用基礎(chǔ)c庫(kù)，而不是系統(tǒng)調(diào)用，如Linux上的glibc，Windows上的msvc，所以還有一個(gè)工具ltrace，可以用來(lái)追蹤庫(kù)調(diào)用，如下：

$ ltrace -T -tt -f -s 10000 -p 87 -o ltrace.log

基本用法和strace一樣，一般來(lái)說(shuō)，使用strace就夠了。

arthas

arthas是java下的一款動(dòng)態(tài)追蹤工具，可以觀測(cè)到j(luò)ava方法的調(diào)用參數(shù)、返回值等，除此之外，還提供了很多實(shí)用功能，如反編譯、線程剖析、堆內(nèi)存轉(zhuǎn)儲(chǔ)、火焰圖等。
下載與使用

# 下載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/

# 進(jìn)入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命令可以觀測(cè)方法調(diào)用情況，如下：

# watch觀測(cè)執(zhí)行的查詢SQL，-x 3指定對(duì)象展開層級(jí)
[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觀測(cè)耗時(shí)超過(guò)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追蹤方法耗時(shí)，層層追蹤，就可找到耗時(shí)根因，--skipJDKMethod false顯示jdk方法耗時(shí)，默認(rèn)不顯示
[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追蹤方法調(diào)用棧，找到耗時(shí)SQL來(lái)源
[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命令中都可以指定條件表達(dá)式，只要滿足ognl表達(dá)式語(yǔ)法即可，ognl完整語(yǔ)法很復(fù)雜，如下是一些經(jīng)常使用的：

分類 示例
內(nèi)置變量 watch/trace/stack命令中內(nèi)置了params,target,returnObj,throwExp,#cost，分別表示參數(shù),調(diào)用對(duì)象自身，返回值，異常，執(zhí)行耗時(shí)。
屬性獲取 通過(guò).user獲取對(duì)象user屬性值，.user.userId獲取對(duì)象中user屬性中的userId屬性。
數(shù)組、集合或Map元素獲取 通過(guò).orders[0]獲取數(shù)組或集合中第一個(gè)元素，通過(guò).userMap["lisi"]獲取Map中對(duì)應(yīng)key值
對(duì)象方法調(diào)用 通過(guò).getUser()可直接調(diào)用對(duì)象的方法
靜態(tài)變量與方法訪問 靜態(tài)變量訪問@class@member，
靜態(tài)方法調(diào)用@class@method(args)
條件判斷 數(shù)值可使用> >= ==等比較，字符串可直接通過(guò)== !=比較，如.name=="zhangsan"
邏輯運(yùn)算 通過(guò)&& || !實(shí)現(xiàn)條件與或非功能
數(shù)組包含 對(duì)于數(shù)組/List/Set，可以使用in,not in判斷元素是否存在，如"zhangsan" in .names
變量賦值 當(dāng)前時(shí)間賦值到變量obj，#obj=new java.util.Date(), #obj.toString()
List、Map構(gòu)造 List構(gòu)造{"green", "red", "blue"}，
Map構(gòu)造#{"id" : 1, "name" : "lisi", "birthday" : new java.util.Date()}
字段提取 提取userList中的birthday，.userList.{birthday.getYear()}
列表過(guò)濾 過(guò)濾出userList中的id<2的元素，.userList.{? id<2 }

ognl
通過(guò)ognl命令，可直接查看靜態(tài)變量的值，如下：

# 調(diào)用System.getProperty靜態(tài)函數(shù)，查看jvm默認(rèn)字符編碼
[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項(xiàng)目，都會(huì)定義一個(gè)SpringUtil的，用于獲取bean容器ApplicationContext
[arthas@3368243]$ ognl -c 4361bd48 '#context=@com.demo.example.web.SpringUtil@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服務(wù)端口的
[arthas@3368243]$ ognl -c 4361bd48 '#context=@com.demo.example.web.SpringUtil@applicationContext, #context.getEnvironment().getProperty("server.port")'
@String[8080]

# 查看server.port定義在哪個(gè)配置文件中
# 可以很容易看到，server.port定義在application-web.yml
[arthas@3368243]$ ognl -c 4361bd48 '#context=@com.demo.example.web.SpringUtil@applicationContext, #context.environment.propertySources.propertySourceList.{? containsProperty("server.port")}'
@ArrayList[
    @ConfigurationPropertySourcesPropertySource[ConfigurationPropertySourcesPropertySource {name='configurationProperties'}],
    @OriginTrackedMapPropertySource[OriginTrackedMapPropertySource {name='applicationConfig: [classpath:/application-web.yml]'}],
]

# 調(diào)用springboot中bean的方法，獲取返回值
[arthas@3368243]$ ognl -c 4361bd48 '#context=@com.demo.example.web.SpringUtil@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 '#context=@com.demo.example.web.SpringUtil@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大盤、線程剖析、堆轉(zhuǎn)儲(chǔ)、反編譯、火焰圖等功能，如下：

# 顯示耗cpu較多的前4個(gè)線程
[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)

# 堆轉(zhuǎn)儲(chǔ)
[arthas@3368243]$ heapdump
Dumping heap to /tmp/heapdump2021-11-13-15-117226383240040009563.hprof ...
Heap dump file created

# cpu火焰圖，容器環(huán)境下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線程、堆內(nèi)存的整體情況
[arthas@3368243]$ dashboard

# jvm就類似Linux下的ps一樣，可以看jvm進(jìn)程的一些基本信息，如：jvm參數(shù)、類加載、線程數(shù)、打開文件描述符數(shù)等
[arthas@3368243]$ jvm

# 反編譯
[arthas@3368243]$ jad com.demo.example.web.controller.TestController

可見，arthas已經(jīng)不是一個(gè)單純的動(dòng)態(tài)追蹤工具了，它把jvm下常用的診斷功能幾乎全囊括了。

bpftrace

arthas只能追蹤java程序，對(duì)于原生程序(如MySQL)就無(wú)能為力了，好在Linux生態(tài)提供了大量的機(jī)制以及配套工具，可用于追蹤原生程序的調(diào)用，如perf、bpftrace、systemtap等，由于bpftrace使用難度較小，本篇主要介紹它的用法。

bpftrace是基于ebpf技術(shù)實(shí)現(xiàn)的動(dòng)態(tài)追蹤工具，它對(duì)ebpf技術(shù)進(jìn)行封裝，實(shí)現(xiàn)了一種腳本語(yǔ)言，就像上面介紹的arthas基于ognl一樣，它實(shí)現(xiàn)的腳本語(yǔ)言類似于awk，封裝了常見語(yǔ)句塊，并提供內(nèi)置變量與內(nèi)置函數(shù)，如下：

$ sudo bpftrace -e 'BEGIN { printf("Hello, World!\n"); } '
Attaching 1 probe...
Hello, World!

實(shí)例：在調(diào)用端追蹤慢SQL

前面我們用strace追蹤過(guò)mysql的jdbc驅(qū)動(dòng)，它使用sendto與recvfrom系統(tǒng)調(diào)用來(lái)與mysql服務(wù)器通信，因此，我們?cè)趕endto調(diào)用時(shí)，計(jì)下時(shí)間點(diǎn)，然后在recvfrom結(jié)束時(shí)，計(jì)算時(shí)間之差，就可以得到相應(yīng)SQL的耗時(shí)了，如下：

  1. 先找到sendto與recvfrom系統(tǒng)調(diào)用在bpftrace中的追蹤點(diǎn)，如下：
# 查找sendto|recvfrom系統(tǒng)調(diào)用的追蹤點(diǎn)，可以看到sys_enter_開頭的追蹤點(diǎn)應(yīng)該是進(jìn)入時(shí)觸發(fā)，sys_exit_開頭的退出時(shí)觸發(fā)
$ 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 

# 查看系統(tǒng)調(diào)用參數(shù)，方便我們編寫腳本
$ 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;
  1. 編寫追蹤腳本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協(xié)議中，包開始的第5字節(jié)指示命令類型，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表示進(jìn)程名稱，tid表示線程號(hào)，@query[tid]與@start[tid]類似map，以tid為key的話，這個(gè)變量就像一個(gè)線程本地變量了。
3. 調(diào)用上面的腳本，可以看到各SQL執(zhí)行耗時(shí)，如下：

$ 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

實(shí)例：在服務(wù)端追蹤慢SQL

從調(diào)用端來(lái)追蹤SQL耗時(shí)，會(huì)包含網(wǎng)絡(luò)往返時(shí)間，為了得到更精確的SQL耗時(shí)，我們可以寫一個(gè)追蹤服務(wù)端mysql的腳本，來(lái)觀測(cè)SQL耗時(shí)，如下：

  1. 確定mysqld服務(wù)進(jìn)程的可執(zhí)行文件與入口函數(shù)
$ which mysqld
/usr/local/mysql/bin/mysqld

# objdump可導(dǎo)出可執(zhí)行文件的動(dòng)態(tài)符號(hào)表，做幾張mysqld的火焰圖就可發(fā)現(xiàn)，dispatch_command是SQL處理的入口函數(shù)
# 另外，由于mysql是c++寫的，方法名是編譯器改寫過(guò)的，這也是為啥下面腳本中要用*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
  1. 使用uprobe追蹤dispatch_command的調(diào)用，如下：
#!/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]);
}

追蹤腳本整體上與之前系統(tǒng)調(diào)用版本的類似，不過(guò)追蹤點(diǎn)不一樣而已。

實(shí)例：找出掃描大量行的SQL

眾所周知，SQL執(zhí)行時(shí)需要掃描數(shù)據(jù)，并且掃描的數(shù)據(jù)越多，SQL性能就會(huì)越差。
但對(duì)于一些中間情況，SQL掃描行數(shù)不多也不少，如2w條。且這2w條數(shù)據(jù)都在緩存中的話，SQL執(zhí)行時(shí)間不會(huì)很長(zhǎng)，導(dǎo)致沒有記錄在慢查詢?nèi)罩局校绻@樣的SQL并發(fā)量大起來(lái)的話，會(huì)非常耗費(fèi)CPU。

對(duì)于mysql的話，掃描行的函數(shù)是row_search_mvcc（如果你經(jīng)常抓取mysql棧的話，很容易發(fā)現(xiàn)這個(gè)函數(shù)），每掃一行調(diào)用一次，如果在追蹤腳本中追蹤此函數(shù)，記錄下調(diào)用次數(shù)，就可以觀測(cè)SQL的掃描行數(shù)了，如下：

#!/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]);
}

腳本運(yùn)行效果如下：

$ 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                    
                                    # 深分頁(yè)，會(huì)查詢前20300條，取最后300條，慢！
213395     1892      209      20300 select * from app_log limit 20000,300                            
                                    # 索引效果不佳，雖然只會(huì)查到一條數(shù)據(jù)，但掃描數(shù)據(jù)量不會(huì)少，慢！
430374     1892      186      15000 select * from app_log where id < 20000 and seq = 15000 limit 1

如上所示，app_log是我建的一張測(cè)試表，共43716條數(shù)據(jù)，其中id字段是自增主鍵，seq值與id值一樣，但沒有索引。
可以看到上面的幾個(gè)場(chǎng)景，不管什么場(chǎng)景，只要掃描行數(shù)變大，耗時(shí)就會(huì)變長(zhǎng)，但也都沒有超過(guò)500毫秒的，原因是這個(gè)表很小，數(shù)據(jù)可以全部緩存在內(nèi)存中。

可見，像bpftrace這樣的動(dòng)態(tài)追蹤工具是非常強(qiáng)大的，而且比arthas更加靈活，arthas只能追蹤單個(gè)函數(shù)，而bpftrace可以跨函數(shù)追蹤。

bpftrace使用手冊(cè)：https://github.com/iovisor/bpftrace/blob/master/docs/reference_guide.md

總結(jié)

已經(jīng)介紹了不少診斷工具了，這里簡(jiǎn)單概括一下它們的應(yīng)用場(chǎng)景：

  1. 軟件資源觀測(cè)，如ps、lsof、netstat，用來(lái)檢查進(jìn)程基本情況，如內(nèi)存占用、打開哪些文件、創(chuàng)建了哪些連接等。
  2. 硬件資源觀測(cè)，如top、iostat、sar等，類似Windows上任務(wù)管理器一樣，讓你對(duì)硬件資源占用以及在進(jìn)程上情況有個(gè)大概了解，最多觀測(cè)到線程級(jí)別，這些工具一般只能指示進(jìn)一步調(diào)查的方向，很少能直接確認(rèn)原因。
  3. 線程與內(nèi)存剖析，如jstack、jmap等，比較容易分析線程卡住或內(nèi)存oom問題，而oncpu火焰圖容易找出熱代碼路徑，分析高cpu瓶頸，offcpu火焰圖則容易找出經(jīng)常阻塞的代碼路徑，分析高耗時(shí)問題。
  4. 動(dòng)態(tài)追蹤工具，如arthas、bpftrace等，能追蹤到方法調(diào)用級(jí)，常用于問題需要深入調(diào)查的場(chǎng)景，如問題不在代碼實(shí)現(xiàn)上，而在調(diào)用數(shù)據(jù)上，就像上面row_search_mvcc函數(shù)一樣，抓火焰圖會(huì)發(fā)現(xiàn)它出現(xiàn)頻繁，但由于它是核心函數(shù)，這個(gè)頻繁可能是正常的，也可能是不正常的，需要將調(diào)用次數(shù)分散到SQL上才能確認(rèn)。

網(wǎng)站名稱：Linux動(dòng)態(tài)追蹤工具strace、arthas、bpftrace
網(wǎng)站鏈接：http://www.dlmjj.cn/article/djdhshp.html