찾다
운영 및 유지보수리눅스 운영 및 유지 관리Linux 명령 수집을 위한 동적 추적 도구(자세한 예)

이 기사에서는 작업에서 일반적으로 사용되는 동적 추적 도구인 strace, arthas, bpftrace 등 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만 사용하면 됩니다. 모든 시스템 호출을 추적한 다음 SQL을 보내는 시스템 호출을 다음과 같이 grep out합니다.

$ strace -T -tt -f -s 10000 -p 87 |& tee strace.log

Linux 명령 수집을 위한 동적 추적 도구(자세한 예)

mysql의 jdbc 드라이버가 sendto 시스템 호출과 recvfrom을 통해 SQL을 보내는 것을 그림에서 명확하게 볼 수 있습니다. 반환 결과를 얻으면 SQL이 문자열이기 때문에 strace가 자동으로 이를 식별하는 데 도움이 된다는 것을 알 수 있습니다. 그러나 반환 결과가 바이너리이므로 식별하기가 쉽지 않습니다. mysql 프로토콜.

그리고 실제로 SQL 실행 시간이 얼마나 걸리는지 위에서 쉽게 알 수 있습니다. 동일한 스레드 번호로 sendto와 recvfrom 간의 시간 차이를 계산해 보세요.

ltrace

대부분의 프로세스는 기본적으로 Linux의 glibc, Windows의 msvc와 같은 시스템 호출 대신 기본 c 라이브러리를 사용하므로 라이브러리 호출을 추적하는 데 사용할 수 있는 도구 ltrace도 있습니다. :

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

기본적인 사용법은 strace와 동일합니다. 일반적으로 strace를 사용하면 충분합니다.

arthas

arthas는 Java 메서드의 호출 매개변수와 반환 값을 관찰할 수 있는 동적 추적 도구입니다. 또한 디컴파일 및 스레딩과 같은 많은 실용적인 기능도 제공합니다. , 힙 메모리 덤프, Flame 그래프 등이 있습니다.

다운로드 및 사용

# 下载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 and 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를 볼 수 있습니다. 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 디스크, 스레드 프로파일링, 힙 덤프, 디컴파일, Flame 그래프 및 기타 기능도 제공합니다.

# 显示耗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 기술을 캡슐화하고 스크립팅 언어를 구현하는 동적 추적 도구입니다. 위에서 소개한 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 운영 체제의 5 가지 핵심 구성 요소Linux 운영 체제의 5 가지 핵심 구성 요소May 08, 2025 am 12:08 AM

Linux 운영 체제의 5 가지 핵심 구성 요소는 다음과 같습니다. 1. 커널, 2. 시스템 라이브러리, 3. 시스템 도구, 4. 시스템 서비스, 5. 파일 시스템. 이러한 구성 요소는 함께 작동하여 시스템의 안정적이고 효율적인 운영을 보장하고 강력하고 유연한 운영 체제를 형성합니다.

Linux의 5 가지 필수 요소 : 설명Linux의 5 가지 필수 요소 : 설명May 07, 2025 am 12:14 AM

Linux의 5 가지 핵심 요소는 다음과 같습니다. 1. Kernel, 2. 명령 줄 인터페이스, 3. 파일 시스템, 4. 패키지 관리, 5. 커뮤니티 및 오픈 소스. 이러한 요소는 함께 Linux의 특성과 기능을 정의합니다.

Linux 운영 : 보안 및 사용자 관리Linux 운영 : 보안 및 사용자 관리May 06, 2025 am 12:04 AM

Linux 사용자 관리 및 보안은 다음 단계를 통해 달성 할 수 있습니다. 1. SudouserAdd-m-gdevelopers-s/bin/bashjohn과 같은 명령을 사용하여 사용자 및 그룹을 만듭니다. 2. for loop 및 chpasswd 명령을 사용하여 대량 사용자를 생성하고 비밀번호 정책을 설정합니다. 3. 일반적인 오류, 홈 디렉토리 및 쉘 설정을 확인하고 수정하십시오. 4. 강력한 암호화 정책, 정기 감사 및 최소 기관의 원칙과 같은 모범 사례를 구현하십시오. 5. 성능을 최적화하고 Sudo를 사용하고 PAM 모듈 구성을 조정하십시오. 이러한 방법을 통해 사용자를 효과적으로 관리하고 시스템 보안을 개선 할 수 있습니다.

Linux 작업 : 파일 시스템, 프로세스 등Linux 작업 : 파일 시스템, 프로세스 등May 05, 2025 am 12:16 AM

Linux 파일 시스템 및 프로세스 관리의 핵심 작업에는 파일 시스템 관리 및 프로세스 제어가 포함됩니다. 1) 파일 시스템 작업에는 MKDIR, RMDIR, CP 및 MV와 같은 명령을 사용하여 파일 또는 디렉토리 작성, 삭제, 복사 및 이동이 포함됩니다. 2) 프로세스 관리에는 ./my_script.sh&, top and kill과 같은 명령을 사용하여 프로세스를 시작, 모니터링 및 킬링하는 것이 포함됩니다.

Linux 작업 : 쉘 스크립팅 및 자동화Linux 작업 : 쉘 스크립팅 및 자동화May 04, 2025 am 12:15 AM

Shell Scripts는 Linux 시스템에서 명령을 자동화하기위한 강력한 도구입니다. 1) 쉘 스크립트는 통역사를 통해 라인별로 명령을 실행하여 변수 대체 및 조건부 판단을 처리합니다. 2) 기본 사용법에는 TAR 명령을 사용하여 디렉토리를 백업하는 것과 같은 백업 작업이 포함됩니다. 3) 고급 사용에는 서비스를 관리하기 위해 기능 및 사례 명세서를 사용하는 것이 포함됩니다. 4) 디버깅 기술에는 SET-X를 사용하여 명령이 실패 할 때 디버깅 모드 및 SET-E가 종료 할 수 있습니다. 5) 서브 쉘, 배열 사용 및 최적화 루프를 피하기 위해 성능 최적화가 권장됩니다.

Linux 작업 : 핵심 기능 이해Linux 작업 : 핵심 기능 이해May 03, 2025 am 12:09 AM

Linux는 단순성, 모듈성 및 개방성을 강조하는 Unix 기반의 멀티 태스킹 운영 시스템입니다. 핵심 기능에는 다음이 포함됩니다. 파일 시스템 : 트리 구조로 구성되고 Ext4, XFS, BTRFS와 같은 여러 파일 시스템을 지원하고 DF-T를 사용하여 파일 시스템 유형을 봅니다. 프로세스 관리 : PS 명령을 통해 프로세스를보고 우선 순위 설정 및 신호 처리가 포함 된 PID를 사용하여 프로세스를 관리합니다. 네트워크 구성 : IP 주소의 유연한 설정 및 네트워크 서비스 관리 및 sudoipaddradd를 사용하여 IP를 구성합니다. 이러한 기능은 기본 명령 및 고급 스크립트 자동화를 통해 실제 작업에 적용되어 효율성을 향상시키고 오류를 줄입니다.

Linux : 유지 관리 모드 입력 및 종료Linux : 유지 관리 모드 입력 및 종료May 02, 2025 am 12:01 AM

Linux 유지 관리 모드를 입력하는 방법에는 다음이 포함됩니다. 1. Grub 구성 파일 편집, "단일"또는 "1"매개 변수를 추가하고 Grub 구성을 업데이트합니다. 2. 그루브 메뉴에서 시작 매개 변수를 편집하고 "단일"또는 "1"을 추가하십시오. 종료 유지 보수 모드는 시스템을 다시 시작하면됩니다. 이 단계를 사용하면 필요할 때 유지 보수 모드를 신속하게 입력하고 안전하게 종료하여 시스템 안정성과 보안을 보장 할 수 있습니다.

Linux 이해 : 정의 된 핵심 구성 요소Linux 이해 : 정의 된 핵심 구성 요소May 01, 2025 am 12:19 AM

Linux의 핵심 구성 요소에는 커널, 쉘, 파일 시스템, 프로세스 관리 및 메모리 관리가 포함됩니다. 1) 커널 관리 시스템 리소스, 2) Shell은 사용자 상호 작용 인터페이스를 제공합니다. 3) 파일 시스템은 여러 형식, 4) 프로세스 관리는 Fork 및 5) 메모리 관리를 통해 가상 메모리 기술을 사용하여 구현됩니다.

See all articles

핫 AI 도구

Undresser.AI Undress

Undresser.AI Undress

사실적인 누드 사진을 만들기 위한 AI 기반 앱

AI Clothes Remover

AI Clothes Remover

사진에서 옷을 제거하는 온라인 AI 도구입니다.

Undress AI Tool

Undress AI Tool

무료로 이미지를 벗다

Clothoff.io

Clothoff.io

AI 옷 제거제

Video Face Swap

Video Face Swap

완전히 무료인 AI 얼굴 교환 도구를 사용하여 모든 비디오의 얼굴을 쉽게 바꾸세요!

뜨거운 도구

안전한 시험 브라우저

안전한 시험 브라우저

안전한 시험 브라우저는 온라인 시험을 안전하게 치르기 위한 보안 브라우저 환경입니다. 이 소프트웨어는 모든 컴퓨터를 안전한 워크스테이션으로 바꿔줍니다. 이는 모든 유틸리티에 대한 액세스를 제어하고 학생들이 승인되지 않은 리소스를 사용하는 것을 방지합니다.

SublimeText3 Mac 버전

SublimeText3 Mac 버전

신 수준의 코드 편집 소프트웨어(SublimeText3)

mPDF

mPDF

mPDF는 UTF-8로 인코딩된 HTML에서 PDF 파일을 생성할 수 있는 PHP 라이브러리입니다. 원저자인 Ian Back은 자신의 웹 사이트에서 "즉시" PDF 파일을 출력하고 다양한 언어를 처리하기 위해 mPDF를 작성했습니다. HTML2FPDF와 같은 원본 스크립트보다 유니코드 글꼴을 사용할 때 속도가 느리고 더 큰 파일을 생성하지만 CSS 스타일 등을 지원하고 많은 개선 사항이 있습니다. RTL(아랍어, 히브리어), CJK(중국어, 일본어, 한국어)를 포함한 거의 모든 언어를 지원합니다. 중첩된 블록 수준 요소(예: P, DIV)를 지원합니다.

메모장++7.3.1

메모장++7.3.1

사용하기 쉬운 무료 코드 편집기

WebStorm Mac 버전

WebStorm Mac 버전

유용한 JavaScript 개발 도구