Linux动态追踪用具是什么

今天小编给大家分享一下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

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 '#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[TbTRNsh3SixuFrkYLTeb25a6zklEZj0uWANKRMe],

       @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可以跨函数追踪。

（编辑：银川站长网）

【声明】本站内容均来自网络，其相关言论仅代表作者个人观点，不代表本站立场。若无意侵犯到您的权利，请及时与联系站长删除相关内容!