• 技术文章 >运维 >linux运维

    Linux命令拾遗之动态追踪工具(实例详解)

    长期闲置长期闲置2022-01-10 19:19:27转载141
    本篇文章给大家带来了linux命令动态追踪工具的相关知识,其中主要介绍工作中常用的动态追踪工具strace、arthas、bpftrace等。希望对大家有帮助。

    线程与内存剖析,只能观测到进程的整体情况,有些时候我们需要观测到某一方法级别,比如调用方法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可以跨函数追踪。

    总结

    已经介绍了不少诊断工具了,这里简单概括一下它们的应用场景:

    相关推荐:《Linux视频教程

    以上就是Linux命令拾遗之动态追踪工具(实例详解)的详细内容,更多请关注php中文网其它相关文章!

    声明:本文转载于:掘金,如有侵犯,请联系admin@php.cn删除
    专题推荐:linux
    上一篇:Linux命令拾遗之理解系统负载(整理分享) 下一篇:linux中多进程和多线程的区别是什么

    相关文章推荐

    • linux安装vim的命令是什么• linux怎样增加路由• linux怎样关闭终端• linux怎样删除路由• Linux环境下GRE的部署(整理分享)

    全部评论我要评论

  • 取消发布评论发送
  • 1/1

    PHP中文网