用 perf 和 SystemTap 跟踪 MongoDB 访问超时

用 perf 和 SystemTap 跟踪 MongoDB 访问超时

王滨王滨

事情的起因是我们为 LeanCloud 结构化存储后端搭建了一个实验性质的小集群,使用了 MongoDB 3.0 和 WiredTiger 引擎。该集群在平稳运行了几个月后的某一天突然开始出现大量不明原因的超时。

按常规套路,我首先怀疑到 io,但是检查 iostatdstat iotop 之后便排除了这一可能。况且我们给 MongoDB 用的是 Intel 企业级 SSD,也不太可能在这里出问题。

再 top 看了一下,CPU 占用 200% 上下,机器本身是 12 cores / 24 threads,处理这个 load 应该非常轻松。内存 64G,mongod 用掉了近一半,剩下一半被 page cache 占用着,也符合 MongoDB 官方推荐的标准。

然后从 MongoDB 的日志中发现与慢查询相关的数字非常奇怪,读写锁的占用都很小(几十个us),也正常使用了索引(IXSCANIDHACK),可是最后查询的完成时间都是几千 ms 甚至一万 ms 以上。

CPU、IO、内存都不缺,但是性能就是上不去,那很可能就是单线程瓶颈和锁的问题了。再次打开 top 按下 H 切换到线程模式,果然看到有一个线程占用了 100% 的 CPU。

于是下意识地 strace 上去,发现这个线程只调用了一个 syscall:futex。所以,有什么东西是单线程处理并且还拿着锁……pstack 一下,只给了一个函数名 __evict_server。再没有更多的信息了。


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 打上补丁,目的主要是优化缓存,修改很小:

  1. 将遍历链表能用到的东西都放在一个 cache line 里。
  2. 因为字符串的那个解引用仅仅判断了一个类型(通过与 "file:" 比较),所以将 name 的前 4 个字节作为一个 uint32 嵌在链表中,可以减少一次 cache miss。实际上观察了一下所有的 item 都是 file 类型。

具体补丁可以看这里


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)

这里插播一个脑洞(来源忘掉了):
如果希望看到 SSL 连接里的数据,通常的方法会比较烦,配证书做中间人什么的,遇到线上问题也不太可能停机搞,这时可以用 SystemTap hook 住 OpenSSL 的 SSL_READ 和 SSL_WRITE,直接得到 SSL 连接内收发的数据。

4. perf 火焰图 & SystemTap 跟踪锁争抢

经过了刚才的修改,MongoDB 的性能有一些改善,但是还是会定期出现超时的情况。这一次我们用 perf 画一下超时的火焰图:


$ sudo perf record -a -g -F 997 -- sleep 30
$ git clone https://github.com/brendangregg/FlameGraph
$ sudo perf script | \
       FlameGraph/stackcollapse-perf.pl | \
       FlameGraph/flamegraph.pl \
       > flame.svg

➤ SVG版(可交互)

在火焰图上可以看到,__evict_server 占用了很大一部分 CPU(要包含 __evict_clear_walk,因为编译优化,以及截图的时候没有调试符号),除此之外,右边的是处理查询请求占用的 CPU,那么左边的 __ckpt_server 是什么鬼?

看了源码,发现跟 WiredTiger 的 checkpointing 过程有关,总之就是一个数据落盘的过程。听起来好复杂的一个过程,那么有理由猜测它跟 __evict_server 一样也会拿着一些锁,跟处理请求的线程争抢。

那么,用 SystemTap 来确认一下(脚本取自这里,做了些很小的修改):


global FUTEX_WAIT = 0 /*, FUTEX_WAKE = 1 */
global FUTEX_PRIVATE_FLAG = 128 /* linux 2.6.22+ */
global FUTEX_CLOCK_REALTIME = 256 /* linux 2.6.29+ */

global lock_waits # long-lived stats on (tid,lock) blockage elapsed time
global process_names # long-lived pid-to-execname mapping

probe syscall.futex.return {
  if (($op & ~(FUTEX_PRIVATE_FLAG|FUTEX_CLOCK_REALTIME)) != FUTEX_WAIT) next
  process_names[pid()] = execname()
  elapsed = gettimeofday_us() - @entry(gettimeofday_us())
  lock_waits[pid(), $uaddr] <<< elapsed
}

probe end {
  foreach ([pid+, lock] in lock_waits)
    printf ("%s[%d] lock %p contended %d times, avg %d max %d min %d us\n",
            process_names[pid], pid, lock, @count(lock_waits[pid,lock]),
            @avg(lock_waits[pid,lock]),
            @max(lock_waits[pid,lock]),
            @min(lock_waits[pid,lock]))
}

经整理的结果:


0x3964500 contended 640 times, avg 4652783 max 20910627 min 1 us
0x3964400 contended 7833 times, avg 172389 max 20631809 min 1 us
0x1c38b60 contended 264 times, avg 400212 max 4135264 min 2 us
0x7f65a88ac8ec contended 3194 times, avg 100692 max 102941 min 33363 us
0x396a800 contended 54 times, avg 21390 max 44599 min 8 us
0x1c38484 contended 112 times, avg 15309 max 34762 min 155 us
0x3543100 contended 3 times, avg 2964 max 5175 min 1694 us
0x1c2ee40 contended 455 times, avg 14 max 4379 min 0 us
0x1c4b660 contended 213 times, avg 113 max 4176 min 1 us
0x7fb6cc14bee0 contended 45 times, avg 50 max 1536 min 1 us
0x363dec0 contended 86 times, avg 48 max 1116 min 1 us
0x1c3ff00 contended 12 times, avg 196 max 961 min 18 us
0x3846c48 contended 6 times, avg 157 max 843 min 9 us
0x7f65a88aca24 contended 20 times, avg 580 max 810 min 406 us
0x1c4b1a0 contended 17 times, avg 36 max 497 min 1 us
0x7fb6cd1cc990 contended 786 times, avg 22 max 459 min 0 us
......

然后找可疑的锁,用这个脚本可以找到相应的 stacktrace:


probe syscall.futex {
    if($uaddr == $1) {
        print_ubacktrace()
        exit()
    }
}

这里同样是结果丢掉了…… 拿一个演示数据参考一下吧。

这里实际上是 mmap 引擎的 MongoDB 在争抢某一个锁。


root@[redacted]:/home/ubuntu/bwang# stap \
    -d /lib/x86_64-linux-gnu/libpthread-2.19.so \
    -d /usr/bin/mongod \
    futex-bt.stp 0x3964188 | \
    c++filt

0x7f7d711e9f1c : __lll_lock_wait+0x1c/0x30 [/lib/x86_64-linux-gnu/libpthread-2.19.so]
0x7f7d711e5649 : _L_lock_909+0xf/0x1b [/lib/x86_64-linux-gnu/libpthread-2.19.so] 
0x7f7d711e5470 : __pthread_mutex_lock+0x70/0x23a [/lib/x86_64-linux-gnu/libpthread-2.19.so] 
0xa22c90 : mongo::LockManager::unlock(mongo::LockRequest*)+0x70/0x4f0 [/usr/bin/mongod]
0xa311a1 : mongo::LockerImpl<true>::_unlockImpl(mongo::FastMapNoAlloc<mongo::ResourceId, mongo::LockRequest, 16>::IteratorImpl<mongo::FastMapNoAlloc<mongo::ResourceId, mongo::LockRequest, 16>, mongo::LockRequest>&)+0x111/0x4b0 [/usr/bin/mongod]
0xa31b41 : mongo::LockerImpl<true>::unlock(mongo::ResourceId)+0x191/0x260 [/usr/bin/mongod] 
0xa22029 : mongo::Lock::DBLock::~DBLock()+0x19/0x40 [/usr/bin/mongod]
0x93a7c8 : mongo::AutoGetCollectionForRead::~AutoGetCollectionForRead()+0x58/0xa0 [/usr/bin/mongod]
0x91cd25 : mongo::GlobalCursorIdCache::timeoutCursors(mongo::OperationContext*, int)+0x175/0x340 [/usr/bin/mongod]
0x946850 : mongo::ClientCursorMonitor::run()+0xb0/0x120 [/usr/bin/mongod]
0x10ca1e4 : mongo::BackgroundJob::jobBody()+0x144/0x450[/usr/bin/mongod]
0x11a44ff : thread_proxy+0x6f/0x290 [/usr/bin/mongod] 
0x7f7d711e3184 : start_thread+0xc4/0x330 [/lib/x86_64-linux-gnu/libpthread-2.19.so] 
0x7f7d702d537d : 0x7f7d702d537d [/lib/x86_64-linux-gnu/libc-2.19.so+0xfa37d/0x3c0000]

可以看到争抢特定锁的线程的完整调用栈被打印了出来。

在当时的分析中,能发现 __ckpt_server 同样争抢了 __evict_server 的锁,不过这里看不到了。

然后到这里分析就结束了…… 因为线上的影响还在,我们就回滚成 mmap 引擎了(哭

我们仍然在调研这个问题,有进展再更新。


5. BONUS:perf & SystemTap 与 Node.js

这里与 MongoDB 就没关系了。因为我们的云引擎大部分用户都在用 Node.js,所以就 Node.js 特别的写一点。

node 有参数 --perf-basic-prof 可以生成 perf 可以读的 map 文件,有了这个 JIT 的代码也能画出火焰图,还能标注到源自哪个 js 文件!性能分析、调查实例为什么卡死,用这个非常合适!

➤ SVG版(可交互)

node 还提供了几个 USDT,可以在 这里 看到。
我们可以用 SystemTap 来 hook 住这几个地方,然后可以做任意你想做的分析。
下面是个最简单的例子,会打印出 node 进程处理的所有请求:


probe node_http_server_request = process("node").mark("http__server__request")
{
  remote = user_string($arg3);
  port = $arg4;
  method = user_string($arg5);
  url = user_string($arg6);
  fd = $arg7;

  probestr = sprintf("%s(remote=%s, port=%d, method=%s, url=%s, fd=%d)",
    $$name,
    remote,
    port,
    method,
    url,
    fd);
}

# 上面这些是从 nodejs 里拿的,实际上把 `node.stp` 文件放在 tapset 文件夹中,就不用复制过来了

probe node_http_server_request {
    println(probestr);
}

效果:


$ sudo stap -v ./test.stp
......
http__server__request(remote=127.0.0.1, port=37164, method=GET, url=/1.1, fd=14)
http__server__request(remote=127.0.0.1, port=37172, method=GET, url=/, fd=14)
http__server__request(remote=127.0.0.1, port=37174, method=GET, url=/, fd=14)
http__server__request(remote=127.0.0.1, port=37176, method=GET, url=/, fd=14)
http__server__request(remote=127.0.0.1, port=37178, method=GET, url=/, fd=14)
http__server__request(remote=127.0.0.1, port=37180, method=GET, url=/, fd=14)
http__server__request(remote=127.0.0.1, port=37182, method=GET, url=/, fd=14)
^CPass 5: run completed in 0usr/30sys/24800real ms.

6. 相关的资料

  • SystemTap 的资料可以去 OpenResty 的 repo 里找,里面有很多针对 nginx 的脚本,可以在学习 SystemTap 的时候同时深入理解一下 nginx。
  • 可以关注一下 余峰的博客,里面也有一些 SystemTap 的内容。
  • perf 和其他的 Linux tracer (eBPF、ftrace 等等)可以看 Brendan Gregg 的博客(强烈推荐)。
文章被以下专栏收录
17 条评论
推荐阅读