Linux コマンド収集用動的追跡ツール (詳細な例)
- WBOY転載
- 2022-01-10 19:19:272617ブラウズ
この記事では、strace、arthas、bpftrace など、仕事でよく使用される動的トレース ツールを含む Linux コマンド動的トレース ツールに関する知識を提供します。みんなが助けてくれることを願っています。
スレッドとメモリの分析では、プロセス全体の状況を観察することしかできません。メソッド test()、pass を呼び出すときなど、特定のメソッド レベルを観察する必要がある場合があります。 in パラメータは何ですか、戻り値は何ですか、そしてそれにかかる時間はどれくらいですか?この場合、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 と異なることが原因であると考えられます。
この状況に遭遇した場合は、基礎となるフレームワーク コードを急いで掘り出さないでください。さらに時間がかかります。結局のところ、プログラマの時間は貴重です。そうしないと、残業しなければなりません。どうすればすぐに見つけられますか?これが原因かどうかを確認してください?毛糸ですか?
方法は 2 つあります。1 つ目は Wireshark を使用してパケットをキャプチャする方法で、2 つ目はこの記事で紹介した strace です。プログラムはネットワーク IO 関連のシステム コールを通じて SQL コマンドをデータベースに送信する必要があるため、必要な作業は、strace を使用してすべてのシステム コールを追跡し、次のように SQL を送信するシステム コールを grep するだけです。画像、mysql jdbc ドライバーは、sendto システム コールを介して SQL を送信し、recvfrom を介して戻り結果を取得します。SQL は文字列であるため、strace が自動的にそれを識別するのに役立ちますが、戻り結果を識別するのは簡単ではないことがわかります。これはバイナリであり、mysql プロトコルに精通している場合にのみ必要です。
また、SQLの実行に時間がかかることは、同じスレッド番号でsendtoとrecvfromの時間差を計算するだけで簡単にわかります。 
ほとんどのプロセスは基本的に、Linux の glibc、Windows の glibc、msvc などのシステム コールの代わりに基本的な C ライブラリを使用するためです。 $ strace -T -tt -f -s 10000 -p 87 |& tee strace.log
基本的な使用法は strace と同じです。一般的には、strace を使用するだけで十分です。
arthas は Java の動的追跡ツールで、Java メソッドの呼び出しパラメータや戻り値などを監視できます。さらに、逆コンパイル、スレッドプロファイリング、ヒープメモリダンプ、フレームグラフなど、多くの実用的な機能も提供します。 ダウンロードして使用してください
$ ltrace -T -tt -f -s 10000 -p 87 -o ltrace.log
監視、トレース、スタック
arthas では、 watch、trace、および stack コマンドは、次のようにメソッド呼び出しを監視できます。 # 下载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
ognl 式の構文が次のとおりである限り、watch、trace、および stack コマンドで条件式を指定できることがわかります。 met、ognl の完全な構文 これは非常に複雑です。一般的に使用されるものをいくつか示します:
Through ognl コマンドを使用すると、次のように静的変数の値を直接表示できます。 # 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)その他のコマンド
arthas は jvm ディスクも提供します、スレッド分析、ヒープ ダンプ、逆コンパイル、フレーム グラフ、その他の機能は次のとおりです: # 调用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。
bpftrace
arthas は Java プログラムのみを追跡でき、ネイティブ プログラム (MySQL など) については何もできません。幸いなことに、Linux エコシステムは次のことを提供します。 perf、bpftrace、systemtap などのネイティブ プログラムの呼び出しを追跡するための仕組みとサポート ツールが多数あります。 bpftrace は使い方が比較的難しいため、この記事では主に使い方を紹介します。 bpftrace は、ebpf テクノロジーに基づく動的追跡ツールです。ebpf テクノロジーをカプセル化し、スクリプト言語を実装します。上で紹介した arthas が ognl に基づいているのと同じように、実装するスクリプト言語は awk に似ています。共通のステートメントをカプセル化します。次のようにブロックし、組み込み変数と組み込み関数を提供します。 # 显示耗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
例: 呼び出し側で遅い 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 中国語 Web サイトの他の関連記事を参照してください。