从 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 状态的进程。

Screen_Shot_2019-08-11_at_10_33_16_PM.png

我们知道 Linux load 包括

  1. Running tasks
  2. Runnable tasks(waiting for CPU)
  3. 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

Screen Shot 2019-08-09 at 9.58.18 AM.png

Screen Shot 2019-08-09 at 9.58.24 AM.png

我们可以看到有很多 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

Screen Shot 2019-08-10 at 2.50.07 PM.png

我们看到 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/

 
11
Kudos
 
11
Kudos

Now read this

我的 Elixir 2016

回顾自己 2016 年的技术方面,Elixir 应该最值得一说了。这一年,写了一些、参与了一些、看到了一些、想了一些,正好在这个时间点记录下来,算是对此的总结,也或许能从我的视角看到 Elixir 的一些发展。 开源项目 # 翻看今年的 GitHub,虽然也就 400 多个提交,不算多,但却是一直坚持在业余时间写代码的结果,主要就是 Elixir。除了代码量的收获,所有 Elixir 相关项目总共到达 200 多个 star,也算是对自己的一种鼓励。 ExChat #... Continue →