搜尋
首頁運維linux運維Linux指令拾遺之動態追蹤工具(實例詳解)

這篇文章為大家帶來了linux指令動態追蹤工具的相關知識,其中主要介紹工作中常用的動態追蹤工具strace、arthas、bpftrace等。希望對大家有幫助。

Linux指令拾遺之動態追蹤工具(實例詳解)

線程與記憶體剖析,只能觀測到進程的整體情況,有些時候我們需要觀測到某一方法級別,例如調用方法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

Linux指令拾遺之動態追蹤工具(實例詳解)

從圖中可以清楚看到,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完整語法很複雜,如下是一些常用的:

Linux指令拾遺之動態追蹤工具(實例詳解)

#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 '#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服务端口的
[arthas@3368243]$ ognl -c 4361bd48 '#context=@com.demo.example.web.SpringUtil@applicationContext, #context.getEnvironment().getProperty("server.port")'
@String[8080]
# 查看server.port定义在哪个配置文件中
# 可以很容易看到,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]'}],
]
# 调用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大碟、執行緒剖析、堆轉儲、反編譯、火焰圖等功能,如下:

# 显示耗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指令拾遺之動態追蹤工具(實例詳解)的詳細內容。更多資訊請關注PHP中文網其他相關文章!

陳述
本文轉載於:掘金。如有侵權,請聯絡admin@php.cn刪除
Linux:如何進入恢復模式(和維護)Linux:如何進入恢復模式(和維護)Apr 18, 2025 am 12:05 AM

進入Linux恢復模式的步驟是:1.重啟系統並按特定鍵進入GRUB菜單;2.選擇帶有(recoverymode)的選項;3.在恢復模式菜單中選擇操作,如fsck或root。恢復模式允許你以單用戶模式啟動系統,進行文件系統檢查和修復、編輯配置文件等操作,幫助解決系統問題。

Linux的基本要素:為初學者解釋Linux的基本要素:為初學者解釋Apr 17, 2025 am 12:08 AM

Linux的核心組件包括內核、文件系統、Shell和常用工具。 1.內核管理硬件資源並提供基本服務。 2.文件系統組織和存儲數據。 3.Shell是用戶與系統交互的接口。 4.常用工具幫助完成日常任務。

Linux:看看其基本結構Linux:看看其基本結構Apr 16, 2025 am 12:01 AM

Linux的基本結構包括內核、文件系統和Shell。 1)內核管理硬件資源,使用uname-r查看版本。 2)EXT4文件系統支持大文件和日誌,使用mkfs.ext4創建。 3)Shell如Bash提供命令行交互,使用ls-l列出文件。

Linux操作:系統管理和維護Linux操作:系統管理和維護Apr 15, 2025 am 12:10 AM

Linux系統管理和維護的關鍵步驟包括:1)掌握基礎知識,如文件系統結構和用戶管理;2)進行系統監控與資源管理,使用top、htop等工具;3)利用系統日誌進行故障排查,借助journalctl等工具;4)編寫自動化腳本和任務調度,使用cron工具;5)實施安全管理與防護,通過iptables配置防火牆;6)進行性能優化與最佳實踐,調整內核參數和養成良好習慣。

了解Linux的維護模式:必需品了解Linux的維護模式:必需品Apr 14, 2025 am 12:04 AM

Linux維護模式通過在啟動時添加init=/bin/bash或single參數進入。 1.進入維護模式:編輯GRUB菜單,添加啟動參數。 2.重新掛載文件系統為讀寫模式:mount-oremount,rw/。 3.修復文件系統:使用fsck命令,如fsck/dev/sda1。4.備份數據並謹慎操作,避免數據丟失。

Debian如何提升Hadoop數據處理速度Debian如何提升Hadoop數據處理速度Apr 13, 2025 am 11:54 AM

本文探討如何在Debian系統上提升Hadoop數據處理效率。優化策略涵蓋硬件升級、操作系統參數調整、Hadoop配置修改以及高效算法和工具的運用。一、硬件資源強化確保所有節點硬件配置一致,尤其關注CPU、內存和網絡設備性能。選擇高性能硬件組件對於提升整體處理速度至關重要。二、操作系統調優文件描述符和網絡連接數:修改/etc/security/limits.conf文件,增加系統允許同時打開的文件描述符和網絡連接數上限。 JVM參數調整:在hadoop-env.sh文件中調整

Debian syslog如何學習Debian syslog如何學習Apr 13, 2025 am 11:51 AM

本指南將指導您學習如何在Debian系統中使用Syslog。 Syslog是Linux系統中用於記錄系統和應用程序日誌消息的關鍵服務,它幫助管理員監控和分析系統活動,從而快速識別並解決問題。一、Syslog基礎知識Syslog的核心功能包括:集中收集和管理日誌消息;支持多種日誌輸出格式和目標位置(例如文件或網絡);提供實時日誌查看和過濾功能。二、安裝和配置Syslog(使用Rsyslog)Debian系統默認使用Rsyslog。您可以通過以下命令安裝:sudoaptupdatesud

Debian中Hadoop版本怎麼選Debian中Hadoop版本怎麼選Apr 13, 2025 am 11:48 AM

選擇適合Debian系統的Hadoop版本,需要綜合考慮以下幾個關鍵因素:一、穩定性與長期支持:對於追求穩定性和安全性的用戶,建議選擇Debian穩定版,例如Debian11(Bullseye)。該版本經過充分測試,擁有長達五年的支持週期,能夠確保系統穩定運行。二、軟件包更新速度:如果您需要使用最新的Hadoop功能和特性,則可以考慮Debian的不穩定版(Sid)。但需注意,不穩定版可能存在兼容性問題和穩定性風險。三、社區支持與資源:Debian擁有龐大的社區支持,可以提供豐富的文檔和

See all articles

熱AI工具

Undresser.AI Undress

Undresser.AI Undress

人工智慧驅動的應用程序,用於創建逼真的裸體照片

AI Clothes Remover

AI Clothes Remover

用於從照片中去除衣服的線上人工智慧工具。

Undress AI Tool

Undress AI Tool

免費脫衣圖片

Clothoff.io

Clothoff.io

AI脫衣器

AI Hentai Generator

AI Hentai Generator

免費產生 AI 無盡。

熱門文章

R.E.P.O.能量晶體解釋及其做什麼(黃色晶體)
1 個月前By尊渡假赌尊渡假赌尊渡假赌
R.E.P.O.最佳圖形設置
1 個月前By尊渡假赌尊渡假赌尊渡假赌
威爾R.E.P.O.有交叉遊戲嗎?
1 個月前By尊渡假赌尊渡假赌尊渡假赌

熱工具

VSCode Windows 64位元 下載

VSCode Windows 64位元 下載

微軟推出的免費、功能強大的一款IDE編輯器

MantisBT

MantisBT

Mantis是一個易於部署的基於Web的缺陷追蹤工具,用於幫助產品缺陷追蹤。它需要PHP、MySQL和一個Web伺服器。請查看我們的演示和託管服務。

ZendStudio 13.5.1 Mac

ZendStudio 13.5.1 Mac

強大的PHP整合開發環境

Dreamweaver Mac版

Dreamweaver Mac版

視覺化網頁開發工具

MinGW - Minimalist GNU for Windows

MinGW - Minimalist GNU for Windows

這個專案正在遷移到osdn.net/projects/mingw的過程中,你可以繼續在那裡關注我們。 MinGW:GNU編譯器集合(GCC)的本機Windows移植版本,可自由分發的導入函式庫和用於建置本機Windows應用程式的頭檔;包括對MSVC執行時間的擴展,以支援C99功能。 MinGW的所有軟體都可以在64位元Windows平台上運作。