如何使用Intel Processor Trace工具查看任意函數(shù)執(zhí)行時間

在上一篇文章 PT_PERF: 基于 Intel PT 的時延性能分析工具 中，我們介紹了 Intel Processor Trace 時延分析工具的背景，功能和實現(xiàn)。

本篇文章我們主要介紹一下如何使用 PT_PERF 工具查看任意函數(shù)的執(zhí)行時間，包括 on-cpu 和 off-cpu 的時間。

1 背景

時延是我們最直接判斷一個函數(shù)執(zhí)行效率的方式。我們最為習慣的是在編譯前對程序埋點，但這費時費力，并且修改代碼可能影響了程序的執(zhí)行行為，造成統(tǒng)計誤差。借助 eBPF 的 func_latency 工具和 dynamic instrumentation 技術(shù)，我們能夠在不修改程序的情況下，統(tǒng)計函數(shù)時延，但通常工具的使能開銷就是 2000 cpu cycles，并且在高頻函數(shù)調(diào)用下，工具對程序性能的影響達到 50% 以上。

舉個例子，我們對 MySQL 啟動一個 32 線程的 sysbench oltp_read_only 只讀負載，在 91 秒使用 eBPF 統(tǒng)計 1s 時間 MySQL innodb 中 'row_search_mvcc' 的函數(shù)時延。此時 MySQL 的 QPS 從 30 w 下降到了 7.8 w。

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

ebpf 輸出了函數(shù)時延的直方圖信息，平時時延是 3153 納秒，其中在 2048 納秒到 4095 納秒的時延調(diào)用了 971975 次。

但我們也能看到因使能開銷對精度的影響, 統(tǒng)計結(jié)果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 流的方式，我們實現(xiàn)了更精確，對程序性能影響更小的時延性能分析工具。

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

在使用之前我們需要配置一些系統(tǒng)參數(shù)，

修改 perf_event_mlock_kb 支持更大的 trace buffer，減少 trace 數(shù)據(jù)丟失。

修改 kptr_restrict 支持追蹤內(nèi)核函數(shù)，如追蹤 off-cpu 分析需要的 schedule 內(nèi)核函數(shù)。

echo131072>/proc/sys/kernel/perf_event_mlock_kb
echo0>/proc/sys/kernel/kptr_restrict

3 時延分析

我們用 PT_PERF 對相同 read_only 負載進行分

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

在 91s 時對 'row_search_mvcc' 函數(shù)進行 trace，可以看到 qps 從 31w 下降到 30.7w，對性能影響較小。

pt_perf 的輸出主要包括：

和 eBPF 類似的時延直方圖，可以看到 ‘row_search_mvcc’ 的平均時延為 564 ns，以及在每個時延區(qū)間的調(diào)用次數(shù)，精度能精確到 10 ns。

off-cpu (被內(nèi)核調(diào)度出去的時間) 的時延直方圖，因為當前負載主要是 cpu 密集型，所以調(diào)度很少，只有 322 次 row_search_mvcc 被調(diào)度，off-cpu 時延在 564ns 的平均時延中占比為 0 ns，可以忽略不計。

row_search_mvcc 這個函數(shù)占用的 on-cpu 時間為 404%，約占用 4 個 cpu 核。

接下來是 row_search_mvcc 每個子函數(shù)調(diào)用次數(shù)，平均時延，以及 off-cpu，on-cpu 時間?？梢钥吹絻蓚€占比較高的函數(shù)，一個是遍歷 btree 的函數(shù) btr_pcur_open_with_no_init_func ，以及存儲查詢到的數(shù)據(jù)行的函數(shù) row_sel_store_mysql_rec。

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::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                       : 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::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 還分別輸出了從不同函數(shù)調(diào)用 row_search_mvcc 函數(shù)的時延，其中從 index_read 中調(diào)用的 row_search_mvcc 時延達到了 12us，這是 mysql 從 root 節(jié)點遍歷 btree 的函數(shù)。從 general_fetch 中調(diào)用的 row_search_mvcc 時延為 154 ns，因為這大部分是從 record 緩存中取數(shù)據(jù)，時間很短。

===========================================================================================================
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 結(jié)束的時間，縱坐標是時延。

通過 --srcline，也可以看到每個函數(shù)的地址，源文件位置以及行號，存在多個相同子函數(shù)時，方便快速定位。

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::allocate(2f : 129        6809       ut0new.h:617      |                    |
row_sel_store_mysql_rec(34bea10)         : 68         17171737   row0sel.cc:2958   |********************|

有了 off-cpu 時間的指標，我們也能夠直觀地看到因資源等待的一些瓶頸，如我們分別在同一臺機器和不同機器來壓測 MySQL 實例，可以看到 get_command 獲取 SQL 指令的開銷是不同的。遠端發(fā)壓的 get_command 時間高出本機發(fā)壓 30us，主要都是調(diào)度出去等待網(wǎng)絡包的時間，因此實際執(zhí)行 SQL 的 dispatch_command CPU 開銷占比也有所差別。

# 本機發(fā)壓
-----------------------------------------------------------------------------------------------------------
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    |***                 |


# 遠端發(fā)壓
-----------------------------------------------------------------------------------------------------------
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 數(shù)據(jù)量大和數(shù)據(jù)丟失問題

CPU 的指令執(zhí)行是很快的，trace 得到的指令流也是巨大的。使用硬件 trace 來分析性能的最關(guān)鍵問題是：如何快速處理龐大的指令流，以及應對 trace 丟失問題。

在 Linux 5.10 之前的 Perf tool 版本不支持 Ip_filtering，PT_PERF 在 trace 階段，需要采樣全量指令，再解析時來統(tǒng)計目標函數(shù)的時延。

舉個例子來說明 trace 的數(shù)據(jù)量和丟失現(xiàn)象。

在 Intel(R) Xeon(R) Platinum 8163 包含 96 核 CPU 的機器上，使用 sysbench oltp_read_only 32 并發(fā)的壓力，輸出 PT_PERF 的中間結(jié)果，可以看到，指定采集 mysql 進程一秒，得到了 3G 的原始的指令流（perf.data），如果將全量指令跳轉(zhuǎn)解析將得到 122 GB 的解析文件，啟動 10 個并發(fā) worker 來解析，需要 500 秒的解析時間。即使只解析目標函數(shù)跳轉(zhuǎn)得到較小的解析文件，也需要花費 110 秒的時間，目前因為 intel-pt 的格式原因，遍歷指令流的開銷是無法避免的。

并且在 trace 過程中遇到了 45 次數(shù)據(jù)丟失，雖然指定了 1s 的 trace 時間，但實際的 trace 時間跨度為 1.75s，其中丟失了 1.25s 的 trace 時間。通過數(shù)據(jù)丟失的日志我們可以丟棄不完整的函數(shù)調(diào)用，但難以對異常點的排查，從生成的散點圖我們也能看到的 trace 數(shù)據(jù)的丟失程度。

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 量和數(shù)據(jù)丟失的程度也和程序的壓力息息相關(guān)，壓力不大，trace 數(shù)據(jù)量和數(shù)據(jù)丟失都不會很嚴重。

但為了減少 trace 數(shù)據(jù)量帶來的解析過慢，以及數(shù)據(jù)丟失帶來的影響，我們可以：

5.10 版本以上可以使用 ip_filtering (-i)，只 trace 目標函數(shù)跳轉(zhuǎn)的指令流。

只 trace 單個，或部分線程的指令流。

減少 trace 的時間，但無法避免 trace 數(shù)據(jù)的丟失，實際上 trace 時間需要考慮 PT 使能的時間（考慮到所有線程 event open 和 buffer 映射的時間）。

當然，也可以同時考慮這些方式來減少 trace 數(shù)據(jù)量。我們分別來看每種方式的 trace 時間，以及數(shù)據(jù)丟失程度。

從解析時間和 trace errors 可以看到，使用 Ip_filtering 和 trace 單個線程都能很好減少 trace 的數(shù)據(jù)量，數(shù)據(jù)基本沒有丟失。減少 trace 時間也能夠降低部分解析時間，壓力較大時，但要考慮 trace 的線程數(shù)目，雖然只 trace 0.01s，但實際 trace 了 0.82s。從散點圖我們也能看到每種方式的數(shù)據(jù)丟失程度。

# 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 ]