Author: bayan
在我们线上的客户有一个实例，在每天固定的时间都会出现慢SQL的问题；该用户线上业务对于SQL执行的时间较为严格，执行时间超过150ms就认为是慢SQL。 在以往的排查经验中，认为这类慢SQL的问题一般都是锁等待的问题，或者是底层文件系统的IO抖动造成的；但是这次我们都排查过一番，出现慢SQL语句的锁等待很低；而且在底层的文件系统虽然偶尔会有一些长尾的慢IO的情况，但是和慢SQL出现的时间对不上。 后面我们尝试使用线上版本复现用户的这个场景，后来终于在模拟了线上用户执行SQL的模式和压力后，复现了线上出现慢SQL的场景。我们尝试对这个实例进行打栈后发现一些蛛丝马迹，怀疑可能和IO有关系；因为用户请求的栈最后落到了IO上面；但是这并不能说明和IO一定有关系，因为我们打栈时的情况并不一定是出现慢SQL时的情况。 此时，我们需要一个工具来精确的分析出慢SQL到底是怎么执行的，这样我们才能具体的分析出问题的根本原因；所以我们借助PT_PERF工具来分析一下这次慢SQL具体的执行过程。
通过PT_PERF 使用介绍这篇文章我们可以非常精确的知道每一个函数的执行时间；那么我们知道MySQL处理用户请求的入口函数是do_command，那么我们在获取到进程号，和执行do_command的线程号后就可以通过下面这个命令就可以查看到这个函数在处理用户请求时执行的一些具体情况：
//首先通过 --history=1 这个参数来采集一批perf数据，后面只需要使用参数 --history=2 参数来对这批perf数据进行处理，不然就需要每次从进程5147 线程53218 上抓取数据
/usr/share/pt_func_perf/func_latency -b "/u01/polardb57_current/bin/mysqld" -P "/usr/share/pt_func_perf/perf" -f "do_command" -d 15 -p 5147 -t -s -T 53218 --history=1
// 打出do_command函数执行的具体情况
/usr/share/pt_func_perf/func_latency -b "/u01/polardb57_current/bin/mysqld" -P "/usr/share/pt_func_perf/perf" -f "do_command" -d 15 -p 5147 -t -s -T 53218 --history=2
[ start 10 parallel workers ]
[ perf script has consumed 3.61 seconds ]
[ parse actions has consumed 0.01 seconds ]
[ parsed 44524 actions, trace errors: 0 ]
[ analyze functions has consumed 0.01 seconds ]
[ real trace time: 14.85 seconds ]
[ miss trace time: 0.00 seconds ]
===========================================================================================================
Histogram - Latency of [do_command]:
ns : cnt distribution
16384 -> 32767 : 1 | |
32768 -> 65535 : 0 | |
65536 -> 131071 : 0 | |
131072 -> 262143 : 0 | |
262144 -> 524287 : 268 |*** |
524288 -> 1048575 : 1734 |********************|
1048576 -> 2097151 : 200 |** |
2097152 -> 4194303 : 15 | |
4194304 -> 8388607 : 6 | |
8388608 -> 16777215 : 0 | |
16777216 -> 33554431 : 0 | |
33554432 -> 67108863 : 1 | |
67108864 -> 134217727 : 1 | |
trace count: 2226, average latency: 854514 ns
...
//如果需要函数do_command执行的更加详细的时间线以及耗时，可以执行如下命令
#/usr/share/pt_func_perf/func_latency -b "/u01/polardb57_current/bin/mysqld" -P "/usr/share/pt_func_perf/perf" -f "do_command" -d 15 -p 5147 -t -s -T 53218 -l --history=2
[ start 10 parallel workers ]
[ perf script has consumed 3.54 seconds ]
[ parse actions has consumed 0.01 seconds ]
[ parsed 44524 actions, trace errors: 0 ]
[ analyze functions has consumed 0.01 seconds ]
[ real trace time: 14.85 seconds ]
[ miss trace time: 0.00 seconds ]
Thread 53218:
start_timestamp: 2772258869939489
┐y(us)⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀
├118322⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀
│⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀
│⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠐⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀
│⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀
├94657.4⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀
│⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀
│⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀
│⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀
├70993⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀
│⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀
│⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀
│⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠁⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀
├47328.7⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀
│⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀
│⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀
│⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀
├23664.3⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀
│⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀
│⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⡀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀
│⣀⣀⡁⠀⡀⢀⢈⣀⡀⣀⣀⣀⣠⡠⣀⢄⡠⠀⡀⣈⣀⢀⠀⠀⠀⠀⠀⠀⡨⣀⣀⠄⣐⢀⣀⡀⣀⠀⡀⣀⣀⣀⢀⡀⢀⠀⣀⡀⢀⣀⣀⡀⢀⢀⡠⣀⠀⣀⠀⡀⠀⣀⣀⣀⡀⣀⣀⣀⠄⢀⡀⠀⠀⠀⠀⠀⠀⢀⡀
┼───────────┬───────────┬───────────┬───────────┬───────────┬───────────┬──────┐
│0⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀2.22715e+06⠀4.45429e+06⠀6.68144e+06⠀8.90859e+06⠀1.11357e+07⠀⠀⠀⠀⠀⠀⠀⠀x(us)
│⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀
┘⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀
[ print stat has consumed 0.00 seconds ]
...
从上面的结果我们可以很清晰的看到虽然do_command的平均执行时间在0.85ms左右，而且绝大部分执行时间都在0.5ms~1ms之间；但是偶尔会出现超过67ms的慢请求；同时这个工具也可以打出do_command执行的时间线及耗时，从这个时间线上我们可以看到，有一次超过94ms的长尾请求，这个超过94ms的长尾请求就是我们需要关注的。 那么通过-a参数可以指定父函数并且指定父函数的耗时范围，然后查看这个父函数的子函数执行情况，这样我们就可以知道这次超过67ms的执行，最终是那个子函数耗时占比最大。 然后我们一直顺着耗时最大的子函数一直向下定位就能发现最终的具体情况；具体的调用链路为： do_command -> dispatch_command->mysql_parse->mysql_execute_command->Sql_cmd_update::execute->Sql_cmd_update::try_single_table_update->mysql_update->handler::ha_update_row->ha_innobase::update_row->row_update_for_mysql->row_update_for_mysql_using_upd_graph->row_upd_step->row_upd->row_upd_clust_step->btr_pcur_restore_position_func->btr_cur_search_to_nth_level->buf_page_get_gen 最终我们一直定位到如下情况：
//指定父函数为do_command，耗时区间在67ms~134ms；子函数buf_page_get_gen的执行情况
/usr/share/pt_func_perf/func_latency -b "/u01/polardb57_current/bin/mysqld" -P "/usr/share/pt_func_perf/perf" -f "buf_page_get_gen" -d 15 -p 5147 -t -s -T 53218 --history=2 -a do_command#67108864,134217727
[ start 10 parallel workers ]
[ perf script has consumed 3.74 seconds ]
[ parse actions has consumed 0.12 seconds ]
[ parsed 389356 actions, trace errors: 0 ]
[ analyze functions has consumed 0.07 seconds ]
[ real trace time: 14.85 seconds ]
[ miss trace time: 0.00 seconds ]
[ ancestor: do_command, call: 2226, return: 2226 ]
====================================================================================================
Histogram - Latency of [buf_page_get_gen]:
ns : cnt distribution
64 -> 127 : 2 |************* |
128 -> 255 : 2 |************* |
256 -> 511 : 3 |********************|
512 -> 1023 : 3 |********************|
1024 -> 2047 : 1 |****** |
2048 -> 4095 : 0 | |
4096 -> 8191 : 0 | |
8192 -> 16383 : 0 | |
16384 -> 32767 : 0 | |
32768 -> 65535 : 0 | |
65536 -> 131071 : 0 | |
131072 -> 262143 : 0 | |
262144 -> 524287 : 0 | |
524288 -> 1048575 : 0 | |
1048576 -> 2097151 : 0 | |
2097152 -> 4194303 : 0 | |
4194304 -> 8388607 : 0 | |
8388608 -> 16777215 : 0 | |
16777216 -> 33554431 : 0 | |
33554432 -> 67108863 : 0 | |
67108864 -> 134217727 : 1 |****** |
trace count: 12, average latency: 8761090 ns
----------------------------------------------------------------------------------------------------
Histogram - Child functions's Latency of [buf_page_get_gen]:
name : avg cnt call_line distribution (total)
pfs_rw_lock_x_lock_func : 26281791 4 buf0buf.cc:5111 |********************|
buf_page_make_young_if_needed : 174 12 buf0buf.cc:5049 | |
thd_add_io_stats : 89 12 buf0buf.cc:4533 | |
buf_page_hash_get_low : 88 12 buf0buf.cc:4562 | |
mtr_t::memo_push : 62 12 buf0buf.cc:5120 | |
*self : 58 12 - | |
pfs_rw_lock_s_unlock_func : 12 12 buf0buf.cc:4694 | |
pfs_rw_lock_s_lock_func : 6 8 buf0buf.cc:5097 | |
fsp_is_system_temporary : 1 12 buf0buf.cc:4679 | |
srv_polar_is_master : 0 12 buf0buf.cc:5064 | |
fsp_is_system_temporary : 0 12 buf0buf.cc:4722 | |
----------------------------------------------------------------------------------------------------
...
====================================================================================================
Histogram - Latency of [buf_page_get_gen]
called from [btr_cur_search_to_nth_level(buf0buf.cc:5139)]:
ns : cnt distribution
64 -> 127 : 2 |************* |
128 -> 255 : 1 |****** |
256 -> 511 : 3 |********************|
512 -> 1023 : 0 | |
1024 -> 2047 : 1 |****** |
2048 -> 4095 : 0 | |
4096 -> 8191 : 0 | |
8192 -> 16383 : 0 | |
16384 -> 32767 : 0 | |
32768 -> 65535 : 0 | |
65536 -> 131071 : 0 | |
131072 -> 262143 : 0 | |
262144 -> 524287 : 0 | |
524288 -> 1048575 : 0 | |
1048576 -> 2097151 : 0 | |
2097152 -> 4194303 : 0 | |
4194304 -> 8388607 : 0 | |
8388608 -> 16777215 : 0 | |
16777216 -> 33554431 : 0 | |
33554432 -> 67108863 : 0 | |
67108864 -> 134217727 : 1 |****** |
trace count: 8, average latency: 13141336 ns
----------------------------------------------------------------------------------------------------
Histogram - Child functions's Latency of [buf_page_get_gen]
called from [btr_cur_search_to_nth_level(buf0buf.cc:5139)]:
name : avg cnt call_line distribution (total)
pfs_rw_lock_x_lock_func : 105126958 1 buf0buf.cc:5111 |********************|
buf_page_make_young_if_needed : 156 8 buf0buf.cc:5049 | |
buf_page_hash_get_low : 85 8 buf0buf.cc:4562 | |
mtr_t::memo_push : 85 8 buf0buf.cc:5120 | |
thd_add_io_stats : 64 8 buf0buf.cc:4533 | |
*self : 55 8 - | |
pfs_rw_lock_s_unlock_func : 10 8 buf0buf.cc:4694 | |
pfs_rw_lock_s_lock_func : 5 7 buf0buf.cc:5097 | |
srv_polar_is_master : 1 8 buf0buf.cc:5064 | |
fsp_is_system_temporary : 1 8 buf0buf.cc:4722 | |
fsp_is_system_temporary : 1 8 buf0buf.cc:4679 | |
====================================================================================================
...
从上面的信息我们就可以看出，这次长尾的慢SQL主要是由于在更新主键索引时获取主键所在的数据页等锁导致的；而page锁的等锁时间不会反映在慢SQL的信息中。 一般主键的page锁等待有下面这几种情况：
那么我们下面就分别详细的分析这上面三个问题，来看下到底是什么情况。
首先我们从上面的信息知道，这里的锁等待时间超过100ms；那么有两种可能：
那么如果是上面这两种情况，我们只需要监控一下整个进程do_command函数的耗时分布就可以查明具体的情况。
//对进程5147进行全采样
#/usr/share/pt_func_perf/func_latency -b "/u01/polardb57_current/bin/mysqld" -P "/usr/share/pt_func_perf/perf" -f "do_command" -d 2 -p 5147 -t -s --history=2
[ start 10 parallel workers ]
[ perf script has consumed 28.63 seconds ]
[ parse actions has consumed 0.09 seconds ]
[ parsed 422494 actions, trace errors: 0 ]
[ analyze functions has consumed 0.02 seconds ]
[ real trace time: 2.10 seconds ]
[ miss trace time: 0.00 seconds ]
===========================================================================================================
Histogram - Latency of [do_command]:
ns : cnt distribution
1024 -> 2047 : 2 | |
2048 -> 4095 : 0 | |
4096 -> 8191 : 1 | |
8192 -> 16383 : 7 | |
16384 -> 32767 : 7 | |
32768 -> 65535 : 5 | |
65536 -> 131071 : 2 | |
131072 -> 262143 : 8 | |
262144 -> 524287 : 1214 |* |
524288 -> 1048575 : 16244 |********************|
1048576 -> 2097151 : 3535 |**** |
2097152 -> 4194303 : 81 | |
4194304 -> 8388607 : 9 | |
8388608 -> 16777215 : 0 | |
16777216 -> 33554431 : 0 | |
33554432 -> 67108863 : 0 | |
67108864 -> 134217727 : 0 | |
134217728 -> 268435455 : 0 | |
268435456 -> 536870911 : 0 | |
536870912 -> 1073741823 : 1 | |
trace count: 21116, average latency: 901122 ns
-----------------------------------------------------------------------------------------------------------
Histogram - Child functions's Latency of [do_command]:
name : avg cnt call_line distribution (total)
dispatch_command : 842302 21116 sql_parse.cc:1126 |********************|
Protocol_classic::get_command : 58478 21116 sql_parse.cc:1065 |* |
my_realloc : 6117 6 sql_string.h:372 | |
*self : 140 21116 - | |
my_net_set_read_timeout : 120 21116 sql_parse.cc:1033 | |
my_net_set_read_timeout : 35 21116 sql_parse.cc:1124 | |
Protocol_classic::get_packet : 19 21116 sql_parse.cc:1127 | |
Protocol_text::type : 14 21116 sql_parse.cc:1001 | |
Protocol_classic::get_net : 8 21116 sql_parse.cc:1032 | |
Diagnostics_area::reset_diagnostics_area : 0 21116 sql_parse.cc:1022 | |
Protocol_classic::get_packet : 0 21116 sql_parse.cc:1120 | |
===========================================================================================================
...
通过这个工具的采样我们可以发现，超过50ms的长尾请求只有一个，并没有多个，所以排除了第一种另外一个线程也持有这个page锁很长时间的情况。 而且进一步观察，长尾请求超过几十ms的只有一个，说明这个page锁只有这一个请求在等待；所以也排除了第二种情况。
这种情况我们只需要对purge线程的逻辑采样，就可以知道purge线程的各个子函数的耗时；如果有purge的长尾，那么就有可能和导致这个长尾的慢SQL。
#/usr/share/pt_func_perf/func_latency -b "/u01/polardb57_current/bin/mysqld" -P "/usr/share/pt_func_perf/perf" -f "row_purge_step" -d 30 -p 5147 -t -s -T 5290,5291,5292,5293 --history=2
[ start 10 parallel workers ]
[ perf script has consumed 24.12 seconds ]
[ parse actions has consumed 1.13 seconds ]
[ parsed 2676658 actions, trace errors: 0 ]
[ analyze functions has consumed 0.31 seconds ]
[ real trace time: 30.00 seconds ]
[ miss trace time: 0.00 seconds ]
====================================================================================================
Histogram - Latency of [row_purge_step]:
ns : cnt distribution
0 -> 1 : 153560 |**** |
2 -> 3 : 737319 |********************|
4 -> 7 : 113474 |*** |
8 -> 15 : 18556 | |
16 -> 31 : 14378 | |
32 -> 63 : 25776 | |
64 -> 127 : 38635 |* |
128 -> 255 : 28274 | |
256 -> 511 : 41669 |* |
512 -> 1023 : 1786 | |
1024 -> 2047 : 242 | |
2048 -> 4095 : 9443 | |
4096 -> 8191 : 1518 | |
8192 -> 16383 : 375 | |
16384 -> 32767 : 7 | |
32768 -> 65535 : 4 | |
65536 -> 131071 : 1 | |
131072 -> 262143 : 1 | |
262144 -> 524287 : 1 | |
trace count: 1185019, average latency: 59 ns
----------------------------------------------------------------------------------------------------
row_purge_step是purge的入口函数，从这里我们可以观察到，row_purge_step最长的耗时也就0.2ms~0.5ms左右；而且purge的平均耗时是59ns，而且history list一直保持在2.5K左右，说明purge再整个处理过程中不是瓶颈；所以应该也不是purge导致的这次慢请求。
//发现的慢IO日志
[Warning] InnoDB: [RDS Diagnose] Write len:16384, latency: 5676us.
[Warning] InnoDB: [RDS Diagnose] Write len:16384, latency: 5171us.
[Warning] InnoDB: [RDS Diagnose] Write len:16384, latency: 8820us.
[Warning] InnoDB: [RDS Diagnose] Write len:16384, latency: 7188us.
[Warning] InnoDB: [RDS Diagnose] Write len:16384, latency: 6346us.
...
为了进一步验证上面这种情况，我们修改了IO队列长度；发现改短IO队列长度后，慢SQL马上减少了很多，进一步调整以后，慢SQL完全消失；这充分说明了，就是这里导致的问题。
在以往我们定位性能问题的时候，尤其是长尾问题；如果想要知道某一个函数具体的调用时间的分布，只能在函数中进行埋点；但是这一方面依赖于我们对代码的熟悉程度，另一方面埋点可能导致程序的行为发生改变。所以在定位性能问题，尤其是定位一些长尾的问题时是很困难的。这类问题发生在线上时，因为发布的代码不能更改，不能打栈，之前我们只能使用perf查看程序运行的一些大致情况。 但是，通过PT_PERF工具，我们不仅仅可以知道任一函数执行的情况，还可以指定父函数，指定耗时来查看其子函数的行为；这大大加快了我们定位问题的速度。而且这个工具的采样对于程序影响很小，对于线上问题的定位非常友好。 最后，需要注意的一点是，使用PT_PERF工具对程序进行采样是，需要注意采样时间；因为对整个进程进行采样，可能采样的数据量会特别大；在这种情况下，如果可以确定要采样的内容的线程号，可以指定线程进行采样，这样数据量会少很多。