数据库内核月报

数据库内核月报 - 2024 / 04

如何使用 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。

[ 90s ] thds: 32 tps: 19488.04 qps: 301753.61
[ 91s ] thds: 32 tps: 4912.97  qps: 78695.49              # start ebpf uprobe
[ 92s ] thds: 32 tps: 12584.17 qps: 201264.72
[ 93s ] thds: 32 tps: 19611.97 qps: 303792.55

ebpf 输出了函数时延的直方图信息,平时时延是 3153 纳秒,其中在 2048 纳秒到 4095 纳秒的时延调用了 971975 次。

但我们也能看到因使能开销对精度的影响, 统计结果1 us 以下的时延都为 0。

     nsecs               : count     distribution
       256 -> 511        : 0        |                                        |
       512 -> 1023       : 0        |                                        |
      1024 -> 2047       : 268363   |***********                             |
      2048 -> 4095       : 971975   |****************************************|
      4096 -> 8191       : 101768   |****                                    |
      8192 -> 16383      : 8389     |                                        |
     16384 -> 32767      : 86       |                                        |
     32768 -> 65535      : 13666    |                                        |
     65536 -> 131071     : 56       |                                        |
avg = 3153 nsecs, total: 4223229085 nsecs, count: 1339391

基于 Intel CPU 硬件指令 trace 流的方式,我们实现了更精确,对程序性能影响更小的时延性能分析工具。

2 PT_PERF 安装

在 Linux 4.2+ 和 GCC 7+ 版本下,可以通过下面命令安装 PT_PERF

sudo yum install binutils binutils-devel elfutils-libelf-devel -y 
git clone https://github.com/mysqlperformance/pt_perf.git
cd pt_perf
make

在使用之前我们需要配置一些系统参数,

echo 131072 > /proc/sys/kernel/perf_event_mlock_kb
echo 0 > /proc/sys/kernel/kptr_restrict

3 时延分析

我们用 PT_PERF 对相同 read_only 负载进行分析

[ 90s ] thds: 32 tps: 19651.81 qps: 314423.96
[ 91s ] thds: 32 tps: 19418.84 qps: 310733.39       # start pt perf trace
[ 92s ] thds: 32 tps: 19221.36 qps: 307534.77
[ 93s ] thds: 32 tps: 19241.35 qps: 307857.54

在 91s 时对 ‘row_search_mvcc’ 函数进行 trace,可以看到 qps 从 31w 下降到 30.7w,对性能影响较小。

pt_perf 的输出主要包括:

sudo ./func_latency -b /disk2/bin/mysqld -f row_search_mvcc -d 1 -i -t -s -p `mysqlpid` -o

===========================================================================================================
Histogram - Latency of [row_search_mvcc]:
          ns             : cnt        distribution        sched      distribution
        32 -> 63         : 1003561  |****                | 0        |                    |
        64 -> 127        : 4231126  |********************| 0        |                    |
       128 -> 255        : 3443046  |****************    | 0        |                    |
       256 -> 511        : 879947   |****                | 0        |                    |
       512 -> 1023       : 41407    |                    | 0        |                    |
      1024 -> 2047       : 1472     |                    | 0        |                    |
      2048 -> 4095       : 148607   |                    | 3        |                    |
      4096 -> 8191       : 86048    |                    | 121      |********************|
      8192 -> 16383      : 9781     |                    | 88       |**************      |
     16384 -> 32767      : 54725    |                    | 105      |*****************   |
     32768 -> 65535      : 44435    |                    | 4        |                    |
     65536 -> 131071     : 619      |                    | 0        |                    |
    131072 -> 262143     : 3        |                    | 1        |                    |
trace count: 9944777, average latency: 564 ns
sched count:     322,   sched latency:   0 ns, cpu percent: 404 %
sched total: 268506, sched each time: 16 ns

-----------------------------------------------------------------------------------------------------------
Histogram - Child functions's Latency of [row_search_mvcc]:
                    name                 : avg        cnt        sched_time cpu_pct(%) distribution (total)
__irqentry_text_start                    : 14141      4167       159        4.20      |*                   |
asm_sysvec_reschedule_ipi                : 10580      24         8586       0.00      |                    |
asm_exc_nmi                              : 9363       76         0          0.05      |                    |
asm_sysvec_call_function_single          : 7702       35         5517       0.01      |                    |
asm_sysvec_apic_timer_interrupt          : 7488       1370       41         0.74      |                    |
btr_pcur_open_with_no_init_func          : 2014       337908     1          49.02     |*****************   |
asm_sysvec_call_function                 : 1515       98         0          0.01      |                    |
asm_sysvec_irq_work                      : 1447       72         0          0.01      |                    |
ut_new_get_key_by_file                   : 784        3910       2          0.22      |                    |
sel_restore_position_for_mysql           : 699        944        0          0.05      |                    |
btr_pcur_store_position                  : 227        243264     0          3.98      |*                   |
trx_assign_read_view                     : 226        337908     0          5.52      |*                   |
mtr_t::commit                            : 168        338855     0          4.11      |*                   |
ut_allocator<unsigned char>::allocate    : 156        3910       0          0.04      |                    |
row_sel_store_mysql_rec                  : 80         9947703    0          57.48     |********************|
free                                     : 74         3910       0          0.02      |                    |
que_thr_move_to_run_state_for_mysql      : 59         338852     0          1.46      |                    |
trx_start_if_not_started_low             : 58         338852     0          1.43      |                    |
row_sel_dequeue_cached_row_for_mysql     : 58         9510339    0          40.26     |**************      |
cmp_dtuple_rec                           : 57         482732     0          1.99      |                    |
rec_get_offsets_func                     : 47         10189058   0          34.63     |************        |
mtr_t::start                             : 47         338852     0          1.17      |                    |
ReadView_guard::bind_snapshot            : 45         338852     0          1.10      |                    |
row_search_end_range_check               : 40         9706318    0          28.31     |*********           |
pfs_memory_free_v1                       : 37         3910       0          0.01      |                    |
row_prebuilt_t::can_prefetch_records     : 29         241376     0          0.52      |                    |
lock_clust_rec_cons_read_sees            : 25         9943793    0          18.01     |******              |
que_thr_stop_for_mysql_no_error          : 22         338855     0          0.55      |                    |
btr_pcur_move_to_next                    : 18         10120567   0          13.52     |****                |
mtr_t::Impl::~Impl                       : 9          9944782    0          6.66      |**                  |
ReadView_guard::~ReadView_guard          : 8          9944782    0          6.16      |**                  |
trx_is_interrupted                       : 7          10457511   0          5.31      |*                   |
ReadView_guard::ReadView_guard           : 6          9944777    0          4.32      |*                   |
row_sel_fetch_last_buf                   : 6          9605884    0          4.76      |*                   |
lob::undo_vers_t::reset                  : 4          20402293   0          6.46      |**                  |
row_sel_enqueue_cache_row_for_mysql      : 3          9510294    0          2.64      |                    |
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 缓存中取数据,时间很短。

===========================================================================================================
Histogram - Latency of [row_search_mvcc]
           called from [ha_innobase::index_read]:
          ns             : cnt        distribution        sched      distribution
      2048 -> 4095       : 148424   |********************| 0        |                    |
      4096 -> 8191       : 84834    |***********         | 73       |*****************   |
      8192 -> 16383      : 6273     |                    | 69       |****************    |
     16384 -> 32767      : 53379    |*******             | 82       |********************|
     32768 -> 65535      : 44376    |*****               | 4        |                    |
     65536 -> 131071     : 619      |                    | 0        |                    |
    131072 -> 262143     : 3        |                    | 1        |                    |
trace count: 337908, average latency: 12222 ns
sched count:    229,   sched latency:     9 ns, cpu percent: 297 %

...

===========================================================================================================
Histogram - Latency of [row_search_mvcc]
           called from [ha_innobase::general_fetch]:
          ns             : cnt        distribution        sched      distribution
        32 -> 63         : 1003561  |****                | 0        |                    |
        64 -> 127        : 4231126  |********************| 0        |                    |
       128 -> 255        : 3443046  |****************    | 0        |                    |
       256 -> 511        : 879947   |****                | 0        |                    |
       512 -> 1023       : 41407    |                    | 0        |                    |
      1024 -> 2047       : 1472     |                    | 0        |                    |
      2048 -> 4095       : 183      |                    | 3        |*                   |
      4096 -> 8191       : 1214     |                    | 48       |********************|
      8192 -> 16383      : 3508     |                    | 19       |*******             |
     16384 -> 32767      : 1346     |                    | 23       |*********           |
     32768 -> 65535      : 59       |                    | 0        |                    |
trace count: 9606869, average latency: 154 ns
sched count:      93,   sched latency:   0 ns, cpu percent: 106 %

...

通过指定 -l,也能看到随采样时间的时延散点图,用于排查异常的时延点,找到异常时间点的时间范围,横坐标是从 trace 开始到 trace 结束的时间,纵坐标是时延。

通过 –srcline,也可以看到每个函数的地址,源文件位置以及行号,存在多个相同子函数时,方便快速定位。

Histogram - Child functions's Latency of [row_search_mvcc(row0sel.cc:4292)]:
                    name                 : avg        cnt        src_line           distribution (total)
btr_pcur_open_with_no_init_func(34b90d0) : 1777       583484     btr0pcur.ic:417   |*****************   |
ut_new_get_key_by_file(3058340)          : 664        6809       ut0new.h:458      |                    |
sel_restore_position_for_mysql(34b958b)  : 597        1728       row0sel.cc:3403   |                    |
btr_pcur_store_position(303ace0)         : 206        420243     btr0pcur.cc:95    |*                   |
trx_assign_read_view(357f910)            : 205        583484     trx0trx.cc:2549   |**                  |
mtr_t::commit(33d3910)                   : 146        585216     mtr0mtr.cc:900    |*                   |
ut_allocator<unsigned char>::allocate(2f : 129        6809       ut0new.h:617      |                    |
row_sel_store_mysql_rec(34bea10)         : 68         17171737   row0sel.cc:2958   |********************|

有了 off-cpu 时间的指标,我们也能够直观地看到因资源等待的一些瓶颈,如我们分别在同一台机器和不同机器来压测 MySQL 实例,可以看到 get_command 获取 SQL 指令的开销是不同的。远端发压的 get_command 时间高出本机发压 30us,主要都是调度出去等待网络包的时间,因此实际执行 SQL 的 dispatch_command CPU 开销占比也有所差别。

# 本机发压
-----------------------------------------------------------------------------------------------------------
Histogram - Child functions's Latency of [do_command]:
                    name                 : avg        cnt        sched_time cpu_pct(%) distribution (total)
dispatch_command                         : 82752      333059     2          2743.12   |********************|
Protocol_classic::get_command            : 13106      333054     7682       179.79    |***                 |

# 远端发压
-----------------------------------------------------------------------------------------------------------
Histogram - Child functions's Latency of [do_command]:
                    name                 : avg        cnt        sched_time cpu_pct(%) distribution (total)
dispatch_command                         : 78660      263266     100        2058.90   |********************|
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 数据的丢失程度。

sudo ./func_latency -b /disk2/bin/mysqld -f do_command -d 1 -s -p `mysqlpid` -o -w 10 -l -t
[ trace process 121576 for 1.00 seconds ]
[ perf record: Woken up 0 times to write data ]
[ perf record: Captured and wrote 3047.905 MB perf.data ]
[ perf record has consumed 11.75 seconds ]
[ start 10 parallel workers ]
[ perf script has consumed 110.87 seconds ]
[ parse actions has consumed 4.18 seconds ]
[ parsed 1554137 actions, trace errors: 459 ]
[ analyze functions has consumed 0.19 seconds ]
[ real trace time: 1.75 seconds ]
[ miss trace time: 1.25 seconds ]

实际上 trace 量和数据丢失的程度也和程序的压力息息相关,压力不大,trace 数据量和数据丢失都不会很严重。

但为了减少 trace 数据量带来的解析过慢,以及数据丢失带来的影响,我们可以:

当然,也可以同时考虑这些方式来减少 trace 数据量。我们分别来看每种方式的 trace 时间,以及数据丢失程度。

从解析时间和 trace errors 可以看到,使用 Ip_filtering 和 trace 单个线程都能很好减少 trace 的数据量,数据基本没有丢失。减少 trace 时间也能够降低部分解析时间,压力较大时,但要考虑 trace 的线程数目,虽然只 trace 0.01s,但实际 trace 了 0.82s。从散点图我们也能看到每种方式的数据丢失程度。

# Ip_filtering
sudo ./func_latency -b /disk2/bin/mysqld -f do_command -d 1 -s -p `mysqlpid` -t -i -o -l
[ trace process 121576 for 1.00 seconds ]
[ perf record: Woken up 0 times to write data ]
[ perf record: Captured and wrote 603.105 MB perf.data ]
[ perf record has consumed 10.64 seconds ]
[ start 10 parallel workers ]
[ perf script has consumed 6.94 seconds ]
[ parse actions has consumed 2.82 seconds ]
[ parsed 7737348 actions, trace errors: 0 ]
[ analyze functions has consumed 1.16 seconds ]
[ real trace time: 1.00 seconds ]
[ miss trace time: 0.00 seconds ]

# trace 单个线程
sudo ./func_latency -b /disk2/bin/mysqld -f do_command -d 1 -s -T 123205 -t -o -l
[ trace thread 123205 for 1.00 seconds ]
[ perf record: Woken up 63 times to write data ]
[ perf record: Captured and wrote 503.424 MB perf.data ]
[ perf record has consumed 3.21 seconds ]
[ start 10 parallel workers ]
[ perf script has consumed 13.94 seconds ]
[ parse actions has consumed 0.08 seconds ]
[ parsed 184278 actions, trace errors: 0 ]
[ analyze functions has consumed 0.12 seconds ]
[ real trace time: 1.00 seconds ]
[ miss trace time: 0.00 seconds ]

# trace 0.1s
sudo ./func_latency -b /disk2/bin/mysqld -f do_command -d 0.01 -s -p `mysqlpid` -t -o -l
[ trace process 121576 for 0.01 seconds ]
[ perf record: Woken up 0 times to write data ]
[ perf record: Captured and wrote 1946.374 MB perf.data ]
[ perf record has consumed 10.65 seconds ]
[ start 10 parallel workers ]
[ perf script has consumed 74.54 seconds ]
[ parse actions has consumed 3.72 seconds ]
[ parsed 913309 actions, trace errors: 357 ]
[ analyze functions has consumed 0.11 seconds ]
[ real trace time: 0.82 seconds ]
[ miss trace time: 0.31 seconds ]