介绍 perf 和 SystemTap 跟踪 MongoDB 访问超时


  • Lv 1

     

    1. perf

     

    先让 perf 来打头阵。perf top 一下,看看系统内实时的 CPU 消耗(原图丢了,拿个凑数):

     

    再选择 Annotate,找出热点(可以精确到 CPU 指令):

     

    对应着源码

     

    如果你关注的程序有调试符号并且能根据调试符号找到源码,那么 perf 会在相关的指令旁边显示源码。

     

    此时能看出大部分的 CPU 都消耗在链表遍历上了。

     

    追链表是个非常缓存不友好的行为,另外还能看到有个字符串的解引用也会占用大量的 CPU,这里只可能是 cache-miss 了。

     

    perf stat -e cache-references,cache-misses -p <TID> 一下那个线程,发现绝大部分都是 cache-miss。(没法上图,忘记保存了)。

     

    关于 CPU cache,有一个非常有意思的页面,可以感性地认识一下内存相对于缓存有多慢。

     

    通过 perf list 可以看到 perf 具体能统计哪些指标

     

     

    # 硬件(CPU 中的 Performance Monitor Unit)指标

    branch-instructions      # 执行的跳转指令数

    branch-misses            # 分支预测失败数

    bus-cycles               # 不知道……(以下用 - 代替)

    cache-misses             # 缓存未命中

    cache-references         # 缓存访问数

    cpu-cycles or cycles     # CPU 时钟周期数

    instructions             # 执行的指令数

    ref-cycles               # - (跟 bus-cycles 有些乱糟的关系)

    stalled-cycles-frontend  # CPU 前端等待(前端是指取指/译码、分支预测、访存等等东西,后端是指执行指令的过程)

     

    # 软件指针

    alignment-faults        # 对齐错误,x86/x64 会自动处理访存不对齐,所以不用关注

    bpf-output              # 跟 eBPF 有关,不知道是干啥的

    context-switches or cs  # 上下文切换数(程序被调度走了)

    cpu-clock               # CPU 时钟(这里是软件统计的,不如上面的准)

    cpu-migrations          # CPU 迁移(程序从 CPU1 执行,但是被调度到 CPU2 上去了)

    dummy                   # -

    emulation-faults        # -

    major-faults            # 主要缺页错误(需要的页不在内存中,要去磁盘上取出再填进去)

    minor-faults            # 次要缺页错误(需要的页在内存中,只是缺页表项,填上页表项就好了)

    page-faults OR faults   # == major-faults + minor-faults

    task-clock              # -

     

    # 硬件指针(Hardware cache event)

    L1-dcache-load-misses      # L1 资料缓存未命中

    L1-dcache-loads            # L1 资料缓存访问数

    L1-dcache-prefetch-misses  # L1 资料缓存预取未命中

    L1-dcache-store-misses     # L1 资料缓存RFO未命中(RFO: read-for-ownership,读取并且失效这个缓存)

    L1-dcache-stores           # L1 数据缓存RFO

    L1-icache-load-misses      # L1 指令缓存未命中

    LLC-load-misses            # LLC: Last Level Cache,即 L2/L3 缓存。

    LLC-loads                  # 这些根据上面的说明看名子应该能知道是什么

    LLC-prefetch-misses        # 就不再一个个解释了

    LLC-prefetches             #

    LLC-store-misses           #

    LLC-stores                 #

    branch-load-misses         # BPU 缓存未命中(BPU:Branch Processing Unit)

    branch-loads               # 与分支预测有关的缓存

    dTLB-load-misses           # 资料 TLB 缓存未命中(TLB: Translation Lookaside Buffer)

    dTLB-loads                 # TLB 是页表的缓存,用来加速虚拟地址->物理地址(VA->PA)转换的

    dTLB-store-misses          # 同不一个个解释了……

    dTLB-stores                #

    iTLB-load-misses           # 指令 TLB 缓存未命中

    iTLB-loads                 #

    node-load-misses           # 本地访存未命中,需要跨 NUMA node(其实就是 CPU)访存

    node-loads                 # 访存数(这里访存数跟 LLC miss 对不上号,因为 LLC miss 后可能会跨 core 取到缓存)

    node-prefetch-misses       #

    node-prefetches            #

    node-store-misses          #

    node-stores                #

     

    找到了热点,下一步就是给 MongoDB 打上补丁,目的主要是优化缓存

    http://link.zhihu.com/?target=...

     

     

     

     

    2. SystemTap

     

    想知道每次 __evict_clear_all_walks (__evict_server 调用了这个函数)具体耗费了多上时间?貌似 perf 不太擅长做这个

     

    那么这时候就可以用 SystemTap 了:

     

     

    global times

     

    probe process("/usr/bin/mongod").function("__evict_clear_all_walks").return {

        times <<< gettimeofday_us() - @entry(gettimeofday_us())

    }

     

    probe timer.s(1) {

        print(@hist_linear(times, 16000, 36000, 500))

    }

    直方图左边的数字是函数执行的时间,单位是 us,右边是落在这个区间内的次数。

     

    【打补丁前】

     

     

    value |-------------------------------------------------- count

    16400 |@                                                    4

    16600 |@@@@                                                14

    16800 |@@@@                                                13

    17000 |                                                     1

    17200 |@                                                    5

    17400 |@@@                                                 10

    17600 |@                                                    3

    17800 |@@@@@@@@                                            24

    18000 |@@@@@@@@@@@@@@@@@@@@@                               63

    18200 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@                      92

    18400 |@@@@@@@@@@@@@@@@@                                   53

    18600 |@@@@@@@@@@@@@@@@@@@@@@@@@@                          80

    18800 |@@@@@@@@                                            26

    19000 |@@@@@@@@@@@@@                                       39

    19200 |@@@@@@@@                                            24

    19400 |@@@@                                                12

    19600 |@                                                    3

    19800 |@                                                    5

    20000 |                                                     2

    20200 |@@                                                   7

    20400 |@@@                                                 11

    20600 |@@@                                                  9

    20800 |@@                                                   8

    21000 |@@@                                                 11

    21200 |@@@@@@@                                             21

    21400 |@@@@@@@                                             22

    21600 |@@@@@@@@@@@@@@@@@@@@                                60

    21800 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@           121

    22000 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@        131

    22200 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@                     95

    22400 |@@@@@@@@@@@@@@@@@@@@                                61

    22600 |@@@@@@@@@@@@@@@@@@@@@@@@@@@                         81

    22800 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@                       87

    23000 |@@@@@@@@@@@@@@@@@@@@@@                              67

    23200 |@@@@@@@@@@@@@@@@                                    50

    23400 |@@@@@                                               15

    23600 |@                                                    4

    23800 |@                                                    4

    24000 |                                                     2

    【打补丁后】

     

     

     4900 |                                                      6

     5000 |@@@@@@@                                             295

     5100 |@@@@@@@@@@@                                         430

     5200 |@                                                    55

     5300 |                                                     17

     5400 |                                                     25

     5500 |                                                     30

     5600 |                                                     13

     5700 |                                                     16

     5800 |                                                     19

     5900 |                                                      8

     6000 |                                                      9

     6100 |                                                     16

     6200 |                                                     14

     6300 |@                                                    67

     6400 |@@@@                                                175

     6500 |@@@@@@@                                             293

     6600 |@@                                                  109

     6700 |@@                                                   78

     6800 |@@                                                   89

     6900 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@  1864

     7000 |@@@@                                                171

     7100 |                                                     29

     7200 |                                                     22

     7300 |                                                      8

    SystemTap 是目前 Linux 最强大的 tracer/profiler,可以跟踪内核以及用户态程序中的任意函数、syscall、语句甚至指令,还可以跟踪 DTrace 的 USDT(写在代码中的预定义的 trace point,比如刚才提到的 MongoDB 补丁代码中的那句 DTRACE_PROBE(proton, dhandle_not_file)。

     


登录后回复
 

与 萌阔论坛 的连接断开,我们正在尝试重连,请耐心等待