我的书签
添加书签
移除书签如何使用 Intel Processor Trace 工具查看任意函数执行时间
Author: 谢榕彪(归墨)
在上一篇文章 PT_PERF: 基于 Intel PT 的时延性能分析工具 中，我们介绍了 Intel Processor Trace 时延分析工具的背景，功能和实现。
本篇文章我们主要介绍一下如何使用 PT_PERF 工具查看任意函数的执行时间，包括 on-cpu 和 off-cpu 的时间。
1 背景
时延是我们最直接判断一个函数执行效率的方式。我们最为习惯的是在编译前对程序埋点，但这费时费力，并且修改代码可能影响了程序的执行行为，造成统计误差。借助 eBPF 的 func_latency 工具和 dynamic instrumentation 技术，我们能够在不修改程序的情况下，统计函数时延，但通常工具的使能开销就是 2000 cpu cycles，并且在高频函数调用下，工具对程序性能的影响达到 50% 以上。
举个例子，我们对 MySQL 启动一个 32 线程的 sysbench oltp_read_only 只读负载，在 91 秒使用 eBPF 统计 1s 时间 MySQL innodb 中 ‘row_search_mvcc’ 的函数时延。此时 MySQL 的 QPS 从 30 w 下降到了 7.8 w。
1. [ 90s ] thds: 32 tps: 19488.04 qps: 301753.61
2. [ 91s ] thds: 32 tps: 4912.97 qps: 78695.49 # start ebpf uprobe
3. [ 92s ] thds: 32 tps: 12584.17 qps: 201264.72
4. [ 93s ] thds: 32 tps: 19611.97 qps: 303792.55
ebpf 输出了函数时延的直方图信息，平时时延是 3153 纳秒，其中在 2048 纳秒到 4095 纳秒的时延调用了 971975 次。
但我们也能看到因使能开销对精度的影响, 统计结果1 us 以下的时延都为 0。
1. nsecs : count distribution
2. 256 -> 511 : 0 | |
3. 512 -> 1023 : 0 | |
4. 1024 -> 2047 : 268363 |*********** |
5. 2048 -> 4095 : 971975 |****************************************|
6. 4096 -> 8191 : 101768 |**** |
7. 8192 -> 16383 : 8389 | |
8. 16384 -> 32767 : 86 | |
9. 32768 -> 65535 : 13666 | |
10. 65536 -> 131071 : 56 | |
11. avg = 3153 nsecs, total: 4223229085 nsecs, count: 1339391
基于 Intel CPU 硬件指令 trace 流的方式，我们实现了更精确，对程序性能影响更小的时延性能分析工具。
2 PT_PERF 安装
在 Linux 4.2+ 和 GCC 7+ 版本下，可以通过下面命令安装 PT_PERF。
1. sudo yum install binutils binutils-devel elfutils-libelf-devel -y
2. git clone https://github.com/mysqlperformance/pt_perf.git
3. cd pt_perf
4. make
在使用之前我们需要配置一些系统参数，
- 修改 perf_event_mlock_kb 支持更大的 trace buffer，减少 trace 数据丢失。
- 修改 kptr_restrict 支持追踪内核函数，如追踪 off-cpu 分析需要的 schedule 内核函数。
1. echo 131072 > /proc/sys/kernel/perf_event_mlock_kb
2. echo 0 > /proc/sys/kernel/kptr_restrict
3 时延分析
我们用 PT_PERF 对相同 read_only 负载进行分析
1. [ 90s ] thds: 32 tps: 19651.81 qps: 314423.96
2. [ 91s ] thds: 32 tps: 19418.84 qps: 310733.39 # start pt perf trace
3. [ 92s ] thds: 32 tps: 19221.36 qps: 307534.77
4. [ 93s ] thds: 32 tps: 19241.35 qps: 307857.54
在 91s 时对 ‘row_search_mvcc’ 函数进行 trace，可以看到 qps 从 31w 下降到 30.7w，对性能影响较小。
pt_perf 的输出主要包括：
- 和 eBPF 类似的时延直方图，可以看到 ‘row_search_mvcc’ 的平均时延为 564 ns，以及在每个时延区间的调用次数，精度能精确到 10 ns。
- off-cpu (被内核调度出去的时间) 的时延直方图，因为当前负载主要是 cpu 密集型，所以调度很少，只有 322 次 row_search_mvcc 被调度，off-cpu 时延在 564ns 的平均时延中占比为 0 ns，可以忽略不计。
- row_search_mvcc 这个函数占用的 on-cpu 时间为 404%，约占用 4 个 cpu 核。
- 接下来是 row_search_mvcc 每个子函数调用次数，平均时延，以及 off-cpu，on-cpu 时间。可以看到两个占比较高的函数，一个是遍历 btree 的函数 btr_pcur_open_with_no_init_func ，以及存储查询到的数据行的函数 row_sel_store_mysql_rec。
1. sudo ./func_latency -b /disk2/bin/mysqld -f row_search_mvcc -d 1 -i -t -s -p `mysqlpid` -o
3. ===========================================================================================================
4. Histogram - Latency of [row_search_mvcc]:
5. ns : cnt distribution sched distribution
6. 32 -> 63 : 1003561 |**** | 0 | |
7. 64 -> 127 : 4231126 |********************| 0 | |
8. 128 -> 255 : 3443046 |**************** | 0 | |
9. 256 -> 511 : 879947 |**** | 0 | |
10. 512 -> 1023 : 41407 | | 0 | |
11. 1024 -> 2047 : 1472 | | 0 | |
12. 2048 -> 4095 : 148607 | | 3 | |
13. 4096 -> 8191 : 86048 | | 121 |********************|
14. 8192 -> 16383 : 9781 | | 88 |************** |
15. 16384 -> 32767 : 54725 | | 105 |***************** |
16. 32768 -> 65535 : 44435 | | 4 | |
17. 65536 -> 131071 : 619 | | 0 | |
18. 131072 -> 262143 : 3 | | 1 | |
19. trace count: 9944777, average latency: 564 ns
20. sched count: 322, sched latency: 0 ns, cpu percent: 404 %
21. sched total: 268506, sched each time: 16 ns
23. -----------------------------------------------------------------------------------------------------------
24. Histogram - Child functions's Latency of [row_search_mvcc]:
25. name : avg cnt sched_time cpu_pct(%) distribution (total)
26. __irqentry_text_start : 14141 4167 159 4.20 |* |
27. asm_sysvec_reschedule_ipi : 10580 24 8586 0.00 | |
28. asm_exc_nmi : 9363 76 0 0.05 | |
29. asm_sysvec_call_function_single : 7702 35 5517 0.01 | |
30. asm_sysvec_apic_timer_interrupt : 7488 1370 41 0.74 | |
31. btr_pcur_open_with_no_init_func : 2014 337908 1 49.02 |***************** |
32. asm_sysvec_call_function : 1515 98 0 0.01 | |
33. asm_sysvec_irq_work : 1447 72 0 0.01 | |
34. ut_new_get_key_by_file : 784 3910 2 0.22 | |
35. sel_restore_position_for_mysql : 699 944 0 0.05 | |
36. btr_pcur_store_position : 227 243264 0 3.98 |* |
37. trx_assign_read_view : 226 337908 0 5.52 |* |
38. mtr_t::commit : 168 338855 0 4.11 |* |
39. ut_allocator<unsigned char>::allocate : 156 3910 0 0.04 | |
40. row_sel_store_mysql_rec : 80 9947703 0 57.48 |********************|
41. free : 74 3910 0 0.02 | |
42. que_thr_move_to_run_state_for_mysql : 59 338852 0 1.46 | |
43. trx_start_if_not_started_low : 58 338852 0 1.43 | |
44. row_sel_dequeue_cached_row_for_mysql : 58 9510339 0 40.26 |************** |
45. cmp_dtuple_rec : 57 482732 0 1.99 | |
46. rec_get_offsets_func : 47 10189058 0 34.63 |************ |
47. mtr_t::start : 47 338852 0 1.17 | |
48. ReadView_guard::bind_snapshot : 45 338852 0 1.10 | |
49. row_search_end_range_check : 40 9706318 0 28.31 |********* |
50. pfs_memory_free_v1 : 37 3910 0 0.01 | |
51. row_prebuilt_t::can_prefetch_records : 29 241376 0 0.52 | |
52. lock_clust_rec_cons_read_sees : 25 9943793 0 18.01 |****** |
53. que_thr_stop_for_mysql_no_error : 22 338855 0 0.55 | |
54. btr_pcur_move_to_next : 18 10120567 0 13.52 |**** |
55. mtr_t::Impl::~Impl : 9 9944782 0 6.66 |** |
56. ReadView_guard::~ReadView_guard : 8 9944782 0 6.16 |** |
57. trx_is_interrupted : 7 10457511 0 5.31 |* |
58. ReadView_guard::ReadView_guard : 6 9944777 0 4.32 |* |
59. row_sel_fetch_last_buf : 6 9605884 0 4.76 |* |
60. lob::undo_vers_t::reset : 4 20402293 0 6.46 |** |
61. row_sel_enqueue_cache_row_for_mysql : 3 9510294 0 2.64 | |
62. row_sel_get_record_buffer : 2 9944777 0 2.06 | |
除此之外，PT_PERF 还分别输出了从不同函数调用 row_search_mvcc 函数的时延，其中从 index_read 中调用的 row_search_mvcc 时延达到了 12us，这是 mysql 从 root 节点遍历 btree 的函数。从 general_fetch 中调用的 row_search_mvcc 时延为 154 ns，因为这大部分是从 record 缓存中取数据，时间很短。
1. ===========================================================================================================
2. Histogram - Latency of [row_search_mvcc]
3. called from [ha_innobase::index_read]:
4. ns : cnt distribution sched distribution
5. 2048 -> 4095 : 148424 |********************| 0 | |
6. 4096 -> 8191 : 84834 |*********** | 73 |***************** |
7. 8192 -> 16383 : 6273 | | 69 |**************** |
8. 16384 -> 32767 : 53379 |******* | 82 |********************|
9. 32768 -> 65535 : 44376 |***** | 4 | |
10. 65536 -> 131071 : 619 | | 0 | |
11. 131072 -> 262143 : 3 | | 1 | |
12. trace count: 337908, average latency: 12222 ns
13. sched count: 229, sched latency: 9 ns, cpu percent: 297 %
15. ...
17. ===========================================================================================================
18. Histogram - Latency of [row_search_mvcc]
19. called from [ha_innobase::general_fetch]:
20. ns : cnt distribution sched distribution
21. 32 -> 63 : 1003561 |**** | 0 | |
22. 64 -> 127 : 4231126 |********************| 0 | |
23. 128 -> 255 : 3443046 |**************** | 0 | |
24. 256 -> 511 : 879947 |**** | 0 | |
25. 512 -> 1023 : 41407 | | 0 | |
26. 1024 -> 2047 : 1472 | | 0 | |
27. 2048 -> 4095 : 183 | | 3 |* |
28. 4096 -> 8191 : 1214 | | 48 |********************|
29. 8192 -> 16383 : 3508 | | 19 |******* |
30. 16384 -> 32767 : 1346 | | 23 |********* |
31. 32768 -> 65535 : 59 | | 0 | |
32. trace count: 9606869, average latency: 154 ns
33. sched count: 93, sched latency: 0 ns, cpu percent: 106 %
35. ...
通过指定 -l，也能看到随采样时间的时延散点图，用于排查异常的时延点，找到异常时间点的时间范围，横坐标是从 trace 开始到 trace 结束的时间，纵坐标是时延。
通过 –srcline，也可以看到每个函数的地址，源文件位置以及行号，存在多个相同子函数时，方便快速定位。
1. Histogram - Child functions's Latency of [row_search_mvcc(row0sel.cc:4292)]:
2. name : avg cnt src_line distribution (total)
3. btr_pcur_open_with_no_init_func(34b90d0) : 1777 583484 btr0pcur.ic:417 |***************** |
4. ut_new_get_key_by_file(3058340) : 664 6809 ut0new.h:458 | |
5. sel_restore_position_for_mysql(34b958b) : 597 1728 row0sel.cc:3403 | |
6. btr_pcur_store_position(303ace0) : 206 420243 btr0pcur.cc:95 |* |
7. trx_assign_read_view(357f910) : 205 583484 trx0trx.cc:2549 |** |
8. mtr_t::commit(33d3910) : 146 585216 mtr0mtr.cc:900 |* |
9. ut_allocator<unsigned char>::allocate(2f : 129 6809 ut0new.h:617 | |
10. row_sel_store_mysql_rec(34bea10) : 68 17171737 row0sel.cc:2958 |********************|
有了 off-cpu 时间的指标，我们也能够直观地看到因资源等待的一些瓶颈，如我们分别在同一台机器和不同机器来压测 MySQL 实例，可以看到 get_command 获取 SQL 指令的开销是不同的。远端发压的 get_command 时间高出本机发压 30us，主要都是调度出去等待网络包的时间，因此实际执行 SQL 的 dispatch_command CPU 开销占比也有所差别。
1. # 本机发压
2. -----------------------------------------------------------------------------------------------------------
3. Histogram - Child functions's Latency of [do_command]:
4. name : avg cnt sched_time cpu_pct(%) distribution (total)
5. dispatch_command : 82752 333059 2 2743.12 |********************|
6. Protocol_classic::get_command : 13106 333054 7682 179.79 |*** |
8. # 远端发压
9. -----------------------------------------------------------------------------------------------------------
10. Histogram - Child functions's Latency of [do_command]:
11. name : avg cnt sched_time cpu_pct(%) distribution (total)
12. dispatch_command : 78660 263266 100 2058.90 |********************|
13. Protocol_classic::get_command : 42541 263256 36322 162.97 |********** |
4 Trace 数据量大和数据丢失问题
CPU 的指令执行是很快的，trace 得到的指令流也是巨大的。使用硬件 trace 来分析性能的最关键问题是：如何快速处理庞大的指令流，以及应对 trace 丢失问题。
在 Linux 5.10 之前的 Perf tool 版本不支持 Ip_filtering，PT_PERF 在 trace 阶段，需要采样全量指令，再解析时来统计目标函数的时延。
举个例子来说明 trace 的数据量和丢失现象。
在 Intel(R) Xeon(R) Platinum 8163 包含 96 核 CPU 的机器上，使用 sysbench oltp_read_only 32 并发的压力，输出 PT_PERF 的中间结果，可以看到，指定采集 mysql 进程一秒，得到了 3G 的原始的指令流（perf.data），如果将全量指令跳转解析将得到 122 GB 的解析文件，启动 10 个并发 worker 来解析，需要 500 秒的解析时间。即使只解析目标函数跳转得到较小的解析文件，也需要花费 110 秒的时间，目前因为 intel-pt 的格式原因，遍历指令流的开销是无法避免的。
并且在 trace 过程中遇到了 45 次数据丢失，虽然指定了 1s 的 trace 时间，但实际的 trace 时间跨度为 1.75s，其中丢失了 1.25s 的 trace 时间。通过数据丢失的日志我们可以丢弃不完整的函数调用，但难以对异常点的排查，从生成的散点图我们也能看到的 trace 数据的丢失程度。
1. sudo ./func_latency -b /disk2/bin/mysqld -f do_command -d 1 -s -p `mysqlpid` -o -w 10 -l -t
2. [ trace process 121576 for 1.00 seconds ]
3. [ perf record: Woken up 0 times to write data ]
4. [ perf record: Captured and wrote 3047.905 MB perf.data ]
5. [ perf record has consumed 11.75 seconds ]
6. [ start 10 parallel workers ]
7. [ perf script has consumed 110.87 seconds ]
8. [ parse actions has consumed 4.18 seconds ]
9. [ parsed 1554137 actions, trace errors: 459 ]
10. [ analyze functions has consumed 0.19 seconds ]
11. [ real trace time: 1.75 seconds ]
12. [ miss trace time: 1.25 seconds ]
实际上 trace 量和数据丢失的程度也和程序的压力息息相关，压力不大，trace 数据量和数据丢失都不会很严重。
但为了减少 trace 数据量带来的解析过慢，以及数据丢失带来的影响，我们可以：
- 5.10 版本以上可以使用 ip_filtering (-i)，只 trace 目标函数跳转的指令流。
- 只 trace 单个，或部分线程的指令流。
- 减少 trace 的时间，但无法避免 trace 数据的丢失，实际上 trace 时间需要考虑 PT 使能的时间（考虑到所有线程 event open 和 buffer 映射的时间）。
当然，也可以同时考虑这些方式来减少 trace 数据量。我们分别来看每种方式的 trace 时间，以及数据丢失程度。
从解析时间和 trace errors 可以看到，使用 Ip_filtering 和 trace 单个线程都能很好减少 trace 的数据量，数据基本没有丢失。减少 trace 时间也能够降低部分解析时间，压力较大时，但要考虑 trace 的线程数目，虽然只 trace 0.01s，但实际 trace 了 0.82s。从散点图我们也能看到每种方式的数据丢失程度。
1. # Ip_filtering
2. sudo ./func_latency -b /disk2/bin/mysqld -f do_command -d 1 -s -p `mysqlpid` -t -i -o -l
3. [ trace process 121576 for 1.00 seconds ]
4. [ perf record: Woken up 0 times to write data ]
5. [ perf record: Captured and wrote 603.105 MB perf.data ]
6. [ perf record has consumed 10.64 seconds ]
7. [ start 10 parallel workers ]
8. [ perf script has consumed 6.94 seconds ]
9. [ parse actions has consumed 2.82 seconds ]
10. [ parsed 7737348 actions, trace errors: 0 ]
11. [ analyze functions has consumed 1.16 seconds ]
12. [ real trace time: 1.00 seconds ]
13. [ miss trace time: 0.00 seconds ]
15. # trace 单个线程
16. sudo ./func_latency -b /disk2/bin/mysqld -f do_command -d 1 -s -T 123205 -t -o -l
17. [ trace thread 123205 for 1.00 seconds ]
18. [ perf record: Woken up 63 times to write data ]
19. [ perf record: Captured and wrote 503.424 MB perf.data ]
20. [ perf record has consumed 3.21 seconds ]
21. [ start 10 parallel workers ]
22. [ perf script has consumed 13.94 seconds ]
23. [ parse actions has consumed 0.08 seconds ]
24. [ parsed 184278 actions, trace errors: 0 ]
25. [ analyze functions has consumed 0.12 seconds ]
26. [ real trace time: 1.00 seconds ]
27. [ miss trace time: 0.00 seconds ]
29. # trace 0.1s
30. sudo ./func_latency -b /disk2/bin/mysqld -f do_command -d 0.01 -s -p `mysqlpid` -t -o -l
31. [ trace process 121576 for 0.01 seconds ]
32. [ perf record: Woken up 0 times to write data ]
33. [ perf record: Captured and wrote 1946.374 MB perf.data ]
34. [ perf record has consumed 10.65 seconds ]
35. [ start 10 parallel workers ]
36. [ perf script has consumed 74.54 seconds ]
37. [ parse actions has consumed 3.72 seconds ]
38. [ parsed 913309 actions, trace errors: 357 ]
39. [ analyze functions has consumed 0.11 seconds ]
40. [ real trace time: 0.82 seconds ]
41. [ miss trace time: 0.31 seconds ]
