Linux命令拾遺之動(dòng)態(tài)追蹤工具（實(shí)例詳解）

247

本篇文章給大家?guī)砹?a >linux命令動(dòng)態(tài)追蹤工具的相關(guān)知識(shí)，其中主要介紹工作中常用的動(dòng)態(tài)追蹤工具strace、arthas、bpftrace等。希望對(duì)大家有幫助。

Linux命令拾遺之動(dòng)態(tài)追蹤工具（實(shí)例詳解）

線程與內(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中用來觀測(cè)系統(tǒng)調(diào)用的工具，學(xué)過操作系統(tǒng)原理都知道，操作系統(tǒng)向應(yīng)用程序暴露了一批系統(tǒng)調(diào)用接口，應(yīng)用程序只能通過這些系統(tǒng)調(diào)用接口來訪問操作系統(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出來子進(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了，由于程序必然要通過網(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

Linux命令拾遺之動(dòng)態(tài)追蹤工具（實(shí)例詳解）

從圖中可以清晰看到，mysql的jdbc驅(qū)動(dòng)是通過sendto系統(tǒng)調(diào)用來發(fā)送SQL，通過recvfrom來獲取返回結(jié)果，可以發(fā)現(xiàn)，由于SQL是字符串，strace自動(dòng)幫我們識(shí)別出來了，而返回結(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，可以用來追蹤庫(kù)調(diào)用，如下：

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

基本用法和strace一樣，一般來說，使用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í)超過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來源 [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)常使用的：

Linux命令拾遺之動(dòng)態(tài)追蹤工具（實(shí)例詳解）

ognl

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

先找到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;

編寫追蹤腳本trace_slowsql_from_syscall.bt，腳本代碼如下：

#!/usr/local/bin/bpftrace BEGIN?{ ????printf("Tracing?jdbc?SQL?slower?than?%d?ms?by?sendto/recvfrom?syscalln",?$1); ????printf("%-10s?%-6s?%6s?%sn",?"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?%sn",?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è)線程本地變量了。

調(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)用端來追蹤SQL耗時(shí)，會(huì)包含網(wǎng)絡(luò)往返時(shí)間，為了得到更精確的SQL耗時(shí)，我們可以寫一個(gè)追蹤服務(wù)端mysql的腳本，來觀測(cè)SQL耗時(shí)，如下：

確定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++寫的，方法名是編譯器改寫過的，這也是為啥下面腳本中要用*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的調(diào)用，如下：

#!/usr/bin/bpftrace BEGIN{ ????printf("Tracing?mysqld?SQL?slower?than?%d?ms.?Ctrl-C?to?end.n",?$1); ????printf("%-10s?%-6s?%6s?%sn",?"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?%sn",?elapsed?/?1000000,?pid,?$dur,?@query[tid]); ????} ????delete(@query[tid]); ????delete(@start[tid]); }

追蹤腳本整體上與之前系統(tǒng)調(diào)用版本的類似，不過追蹤點(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ā)量大起來的話，會(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?%sn",?"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?%sn",?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?<p>如上所示，app_log是我建的一張測(cè)試表，共43716條數(shù)據(jù)，其中id字段是自增主鍵，seq值與id值一樣，但沒有索引。</p><p>可以看到上面的幾個(gè)場(chǎng)景，不管什么場(chǎng)景，只要掃描行數(shù)變大，耗時(shí)就會(huì)變長(zhǎng)，但也都沒有超過500毫秒的，原因是這個(gè)表很小，數(shù)據(jù)可以全部緩存在內(nèi)存中。</p><p>可見，像bpftrace這樣的動(dòng)態(tài)追蹤工具是非常強(qiáng)大的，而且比arthas更加靈活，arthas只能追蹤單個(gè)函數(shù)，而bpftrace可以跨函數(shù)追蹤。</p><p><strong><span style="font-size: 20px;">總結(jié)</span></strong></p><p>已經(jīng)介紹了不少診斷工具了，這里簡(jiǎn)單概括一下它們的應(yīng)用場(chǎng)景：</p>

  • 軟件資源觀測(cè)，如ps、lsof、netstat，用來檢查進(jìn)程基本情況，如內(nèi)存占用、打開哪些文件、創(chuàng)建了哪些連接等。

  • 硬件資源觀測(cè)，如top、iostat、sar等，類似Windows上任務(wù)管理器一樣，讓你對(duì)硬件資源占用以及在進(jìn)程上情況有個(gè)大概了解，最多觀測(cè)到線程級(jí)別，這些工具一般只能指示進(jìn)一步調(diào)查的方向，很少能直接確認(rèn)原因。

  • 線程與內(nèi)存剖析，如jstack、jmap等，比較容易分析線程卡住或內(nèi)存oom問題，而oncpu火焰圖容易找出熱代碼路徑，分析高cpu瓶頸，offcpu火焰圖則容易找出經(jīng)常阻塞的代碼路徑，分析高耗時(shí)問題。

  • 動(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)。

相關(guān)推薦：《Linux視頻教程》

? 版權(quán)聲明
THE END
互聯(lián)網(wǎng)運(yùn)維
# linux
喜歡就支持一下吧
點(diǎn)贊7 分享