从 D-state 造成的 high load 到 Erlang 内存分配调优
在 Tubi，我们有个电影/电视剧的 metadata 服务，叫 Content，是一个 Elixir(Erlang) 写的服务。当请求 Tubi 的时候，这个服务会负责把需要的 metadata，比如标题、描述、图片等返回给客户端，是一个比较关键的服务。最近线上因为客户端发送了过多的请求，导致服务器的 (normalized) load 很快地从 0.5 升高到 1.3，同时 latency 升高，最终通过扩容来解决。请求量增加导致 load 升高很正常，但不正常的是请求量只增加了30%，但 load 却增加了 160%，所以想搞清楚为什么。
重现线上问题 #
能够在 staging 环境复现，问题就等于解决了一半。我先在 staging 把相关的两个服务升级到了和 production 一样的机型，然后用 Vegeta 来产生一定的 load，用 Vegeta 的原因是可以产生固定 QPS 的 load，因为 staging 机器比 production 数量少，所以我按比例发送了 400 QPS 的请求。另外，因为 Content 支持一个 gRPC 接口请求多个 content 的数据，所以我也尽量让每个请求和 production 环境的平均值相同。
我先来模拟出问题前的情况
cat targets.txt | ./vegeta attack -rate=400 -max-body=0 > results.bin # -max-body=0 is used to avoid large logs
通过监控可以看到 load 达到了 0.5，p99 latency 差不多是 75ms，Erlang 的 run queue 也在正常水平，和我们线上的正常情况比较接近。
然后我逐步增加了 load，到 520 QPS
cat targets.txt | ./vegeta attack -rate=520 -max-body=0 > results.bin
然后发现 load 很快到了 1.3，latency 也到了 2s，Erlang 的 run queue 非常高，基本上还原了线上的问题。然后就可以来 debug 了。
问题调查 #
通过 htop，可以看到有很多 D 状态的进程。
我们知道 Linux load 包括
- Running tasks
- Runnable tasks(waiting for CPU)
- Tasks in uninterruptible sleep state. See http://www.brendangregg.com/blog/2017-08-08/linux-load-averages.html for details.
所以 load 才会那么高，D 状态一般是因为磁盘 IO 或者锁导致，为了弄明白到底是什么原因，我们需要更深入研究。
我用 offcputime 来查看 Kernel Space 的调用栈（Kernel 需要 >= 4.9），并且只保留 state 2(TASK_UNINTERRUPTIBLE) ，然后再生成火焰图
sudo /usr/sbin/offcputime-bpfcc -K --state 2 -f 10 > out.stacks
awk '{ print $1, $2 / 1000 }' out.stacks | flamegraph.pl --color=io --countname=ms > out.offcpu.svg
我们可以看到有很多 rwsem_down_read_failed 的调用，而这就是 Linux Kernel 里加锁以及 TASK_UNINTERRUPTIBLE 被设置的地方，并且从火焰图可以看到加锁的之前发送了 page fault。
另外，从 vmstat 也可以验证，并没有很多 IO 操作
$ vmstat -w 1
procs -----------------------memory---------------------- ---swap-- -----io---- -system-- --------cpu--------
r b swpd free buff cache si so bi bo in cs us sy id wa st
2 0 0 9552352 217752 19212732 0 0 0 25 6 3 38 4 58 0 0
8 0 0 9881040 217752 19212860 0 0 0 1492 43269 60876 53 6 41 0 0
9 0 0 9799896 217752 19213052 0 0 0 0 46717 62012 57 7 36 0 0
16 0 0 9711712 217752 19213244 0 0 0 0 49103 63563 59 8 33 0 0
22 0 0 9772740 217752 19213372 0 0 0 0 48386 63826 56 8 36 0 0
6 0 0 9821224 217752 19213544 0 0 0 0 48229 64044 57 7 36 0 0
4 0 0 9932152 217752 19213688 0 0 0 1840 52131 66037 59 7 34 0 0
5 0 0 9750640 217752 19213880 0 0 0 0 55170 68330 61 9 31 0 0
于是我们可以确定，D 状态是由于 page fault 之后的锁造成的，并不是 IO 操作。但 page fault 正常情况下应该不会产生严重的问题，但这里是为什么造成了大量的 D 状态进程，已经 page fault 又是怎么产生的？
通过 sar 我们可以看到几乎所有的 page fault 都是 minor page faults ，并且数量非常多（20~30万/s）。minor page fault 通常不会有大问题，除非同时有大量的 page fault，就像我们现在这种情况。
sar -B 1
Linux 4.15.0-1044-aws (content-03) 08/11/19 _x86_64_ (16 CPU)
15:07:31 pgpgin/s pgpgout/s fault/s majflt/s pgfree/s pgscank/s pgscand/s pgsteal/s %vmeff
15:07:32 0.00 0.00 258816.00 0.00 316014.00 0.00 0.00 0.00 0.00
15:07:33 0.00 0.00 303459.00 0.00 294384.00 0.00 0.00 0.00 0.00
15:07:34 0.00 0.00 259817.00 0.00 330940.00 0.00 0.00 0.00 0.00
15:07:35 0.00 0.00 228191.00 0.00 272419.00 0.00 0.00 0.00 0.00
15:07:36 0.00 4276.00 303600.00 0.00 286122.00 0.00 0.00 0.00 0.00
15:07:37 0.00 32.00 248255.00 0.00 343716.00 0.00 0.00 0.00 0.00
15:07:38 0.00 20.00 236296.00 0.00 309811.00 0.00 0.00 0.00 0.00
15:07:39 0.00 0.00 295435.00 0.00 296189.00 0.00 0.00 0.00 0.00
15:07:40 0.00 0.00 279576.00 0.00 305584.00 0.00 0.00 0.00 0.00
15:07:41 0.00 0.00 220455.00 0.00 323671.00 0.00 0.00 0.00 0.00
15:07:42 0.00 0.00 356954.00 0.00 227642.00 0.00 0.00 0.00 0.00
15:07:43 0.00 0.00 237139.00 0.00 423679.00 0.00 0.00 0.00 0.00
15:07:44 0.00 0.00 274000.00 0.00 303181.00 0.00 0.00 0.00 0.00
15:07:45 0.00 0.00 271769.00 0.00 317360.00 0.00 0.00 0.00 0.00
15:07:46 0.00 0.00 282215.00 0.00 295938.00 0.00 0.00 0.00 0.00
15:07:47 0.00 0.00 252556.00 0.00 317603.00 0.00 0.00 0.00 0.00
15:07:48 0.00 0.00 249663.00 0.00 280742.00 0.00 0.00 0.00 0.00
15:07:49 0.00 0.00 295803.00 0.00 304895.00 0.00 0.00 0.00 0.00
为什么我们会有这么多 page fault？可以用 perf 来看一下原因：
sudo perf record -e page-faults -ag --call-graph dwarf # --call-graph dwarf is needed, otherwise we can't have symbols
sudo perf report -g graph --no-children
我们看到 page fault 都在 Erlang 进程中，尽管有些函数不能被很好地显示，我们还是可以看到一些有用的信息。比如 erts_garbage_collect_nobump 告诉我们 page fault 在 GC 执行的时候产生。我没有找到很直接的资料关于 Erlang GC 的时候产生 page fault 的问题，但我们可以从 page fault 产生原因和 Erlang 内存分配的工作原理来揣测。
Erlang 的 mseg_alloc 会通过 mmap 来分配内存，刚刚分配后，mmap 并不会使用的物理内存，而是等到这块内存需要被实际用到的时候再通过 page fault 来通知 Kernel 去进行实际分配，我写了个简单的 C 代码 来验证这点。也就是说只要程序需要像 OS 请求新的内存，就可能会产生 page fault。
Erlang 会对每个轻量级进程（actor）单独执行 GC，在 GC 运行的时候，Erlang 会创建一块新的内存，把老的数据拷过去，如果 Erlang 本身请求的内存不够了，就会像操作系统请求新的内存。所以就可以解释为什么 GC 的时候会产生 page fault 了。
Erlang 参数调优 #
那怎么来判断程序的内存分配是不是有问题，以及有没有需要调整的参数呢？
我用了 recon_alloc 来看内存分配的情况：
iex> :recon_alloc.sbcs_to_mbcs(:current)
[
{{:eheap_alloc, 0}, 1.7865168539325842}, # 1
{{:eheap_alloc, 11}, 0.04578313253012048},
{{:eheap_alloc, 6}, 0.04429530201342282},
{{:eheap_alloc, 3}, 0.02880658436213992},
{{:eheap_alloc, 16}, 0.02786377708978328},
{{:eheap_alloc, 2}, 0.026066350710900472},
...
iex> :recon_alloc.cache_hit_rates
[
{{:instance, 0},
[hit_rate: 0.6419778480913936, hits: 28810063, calls: 44877036]}, # 2
{{:instance, 16},
[hit_rate: 0.8994651408511145, hits: 5292434, calls: 5883979]},
{{:instance, 3},
[hit_rate: 0.8989566664247531, hits: 5239595, calls: 5828529]},
# I use this instead of average_block_sizes for getting block and carrier data for only {:eheap_alloc, 0}
> IO.inspect :recon_alloc.allocators, limit: :infinity
...
{{:eheap_alloc, 0},
[
...
mbcs: [
{:blocks, 89, 89, 127}, # 3
{:blocks_size, 704544, 704544, 846400}, # 4
{:carriers, 3, 3, 3},
{:mseg_alloc_carriers, 2},
{:sys_alloc_carriers, 1},
{:carriers_size, 1441792, 1441792, 1441792},
{:mseg_alloc_carriers_size, 1310720},
{:sys_alloc_carriers_size, 131072}
],
sbcs: [
{:blocks, 93, 278, 390}, # 6
{:blocks_size, 359408608, 1038591216, 1445304432}, # 7
{:carriers, 93, 278, 390},
{:mseg_alloc_carriers, 93},
{:sys_alloc_carriers, 0},
{:carriers_size, 369188864, 1069051904, 1508335616},
{:mseg_alloc_carriers_size, 369188864},
{:sys_alloc_carriers_size, 0}
]
]},
这些和 Erlang 的分配器非常相关，可以参考下列资料来了解：
http://erlang.org/doc/man/erts_alloc.html
http://www.erlang-factory.com/static/upload/media/139454517145429lukaslarsson.pdf ( video )
https://blog.heroku.com/logplex-down-the-rabbit-hole
简单来说一下 sbcs(single block carriers) 和 mbcs(multiblock carriers)，这是 Erlang 来分配内存的两种方式。当要分配的内存大于 sbct(single block carrier threshold) 时，会产生一个新的 sbcs，否则会通过 mbcs 来找到可以分配的空位。mbcs 更好，因为他们可以被重复使用，而不需要想操作系统要更多内存。但是对于 sbcs，Erlang 会调用 mmap/malloc 来分配内存。所以尽可能使用 mbcs 会使得性能更好，但如果我们有一些很大的数据，sbcs 会被使用，所以我们需要调整 sbct 和 lmbcs(Largest multiblock carrier size) 来更多地使用 mbcs。
现在让我们看一下上边的数据：
#1: sbcs/mbcs 应该保持在比较低的值，比如其他都是 <0.1，>=1 已经很大了，代表我们用了太多的 sbcs
#2: 0.8 以上是比较好的。我们的 cache_hit_rates 比较低，意味着经常需要分配内存
#3 + #4 + #6 + #7: sbcs 比 mbcs 多，并且 sbcs 平均大小是 is 359408608/93=3,864,608(3.6M)
#5: 我们现在的 sbct 是 524288 bytes（默认值），所以我们有很多 sbcs，我们需要增大到 3.6M，并调整 smbcs 和 lmbcs
我们对 Erlang 的参数做了调整：
$ cat vm.args
+MHsbct 4096 # Unit: KB. 4096*1024 is defualt value 524288 * 8
+MHsmbcs 2048 # Unit: KB. 2048*1024 is default value 262144 * 8
+MHlmbcs 40960 # Unit: KB. 40960*1024 is default value 5242880 * 8
然后再测一次，QPS可以达到 650，并且各种系统指标都在正常范围，也没有 D 状态的进程了，minor page fault 还是有，但只有 50000/s，相比之前已经少了很多。
也就是说在对 Erlang 内存分配的参数调优后，我们能处理的 QPS 增长了 40% 左右。
总结 #
通过对这个问题的抽丝剥茧，我们可以看到解决问题就像推理一样，需要环环相扣，最终当都扣上的时候，问题也就解决了。
另外，在查找资料的时候还看到 Linux team 在研究移除 page fault handler 中的锁，如果这个能够实现的话，可以预见，在很多场景下，性能都能够得到提升。
https://lwn.net/Articles/730531/
https://lwn.net/Articles/754739/