搜索
首页运维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

45.png

从图中可以清晰看到,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完整语法很复杂,如下是一些经常使用的:

46.png

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编辑器

螳螂BT

螳螂BT

Mantis是一个易于部署的基于Web的缺陷跟踪工具,用于帮助产品缺陷跟踪。它需要PHP、MySQL和一个Web服务器。请查看我们的演示和托管服务。

ZendStudio 13.5.1 Mac

ZendStudio 13.5.1 Mac

功能强大的PHP集成开发环境

Dreamweaver Mac版

Dreamweaver Mac版

视觉化网页开发工具

MinGW - 适用于 Windows 的极简 GNU

MinGW - 适用于 Windows 的极简 GNU

这个项目正在迁移到osdn.net/projects/mingw的过程中,你可以继续在那里关注我们。MinGW:GNU编译器集合(GCC)的本地Windows移植版本,可自由分发的导入库和用于构建本地Windows应用程序的头文件;包括对MSVC运行时的扩展,以支持C99功能。MinGW的所有软件都可以在64位Windows平台上运行。