erlang 虚机CPU 占用高排查

提示：扫一扫查出行
【扫一扫了解最新限行尾号】
复制提示

-问题起因

近期线上一组服务中，个别节点服务器CPU使用率很低，只有其他1/4。排除业务不均，曾怀疑是系统top统计错误，从Erlang调度器的利用率调查找到通过erlang:statistics(scheduler_wall_time) 查看服务器CPU低的机器调度器实际的CPU利用率很高接近100%，而其他机器都不到30%。

分析不同业务服务，发现只有在node 中进程数采用调度器CPU利用低这个问题。

- 高利用率

Cpu0 : 68.2%us, 11.4%sy, 0.0%ni, 3.7%id, 0.0%wa, 0.0%hi, 16.7%si, 0.0%st
Cpu1 : 81.6%us, 13.4%sy, 0.0%ni, 4.3%id, 0.0%wa, 0.0%hi, 0.7%si, 0.0%st
Cpu2 : 1.3%us, 0.3%sy, 0.0%ni, 98.0%id, 0.3%wa, 0.0%hi, 0.0%si, 0.0%st
Cpu3 : 1.3%us, 0.3%sy, 0.0%ni, 98.0%id, 0.3%wa, 0.0%hi, 0.0%si, 0.0%st
Cpu4 : 0.7%us, 1.0%sy, 0.0%ni, 98.0%id, 0.0%wa, 0.0%hi, 0.3%si, 0.0%st
[{total,0.06939920430400189},
{,0.8268947112724254},
{,0.8384896040437823},
{,8.867169683843468e-6},
{,1.0365168328954172e-5},
{,1.0024957622820418e-5},
{,8.853059601737486e-6},
{,8.402152852410522e-6},
{,7.63072324998243e-6},
{,8.474728373485058e-6},
{,1.1576532481056016e-5},
{,1.6194115883237974e-5},
{,1.44167774196793e-5},
{,9.819386220386243e-6},
{,7.892097518034394e-6},
{,7.163693583884608e-6},
{,7.1916733850567694e-6},
{,7.148667780983167e-6},
{,6.134044075369504e-6},
{,8.508809953551505e-6},
{,8.418451926460262e-6},
{,7.99327959145592e-6},
{,1.0466001303723225e-5},
{,1.165690052491439e-5},
{,1.110477551389582e-5}]

- 低利用率

Cpu0 : 50.9%us, 13.7%sy, 0.0%ni, 21.4%id, 0.0%wa, 0.0%hi, 14.0%si, 0.0%st
Cpu1 : 70.5%us, 14.1%sy, 0.0%ni, 15.1%id, 0.0%wa, 0.0%hi, 0.3%si, 0.0%st
Cpu2 : 68.2%us, 16.1%sy, 0.0%ni, 15.4%id, 0.0%wa, 0.0%hi, 0.3%si, 0.0%st
Cpu3 : 68.4%us, 15.1%sy, 0.0%ni, 16.1%id, 0.0%wa, 0.0%hi, 0.3%si, 0.0%st
Cpu4 : 69.9%us, 15.4%sy, 0.0%ni, 14.7%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Cpu5 : 67.9%us, 14.1%sy, 0.0%ni, 17.6%id, 0.0%wa, 0.0%hi, 0.3%si, 0.0%st
Cpu6 : 50.6%us, 13.4%sy, 0.0%ni, 35.9%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Cpu7 : 41.5%us, 10.8%sy, 0.0%ni, 47.7%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Cpu8 : 32.1%us, 9.6%sy, 0.0%ni, 58.3%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Cpu9 : 0.7%us, 1.0%sy, 0.0%ni, 98.0%id, 0.0%wa, 0.0%hi, 0.3%si, 0.0%st[{total,0.09717691269949602},
{,0.18233794842702225},
{,0.29948956042597197},
{,0.29957276129564725},
{,0.3039782882961829},
{,0.29122320708472654},
{,0.31739635715470543},
{,0.2454373354022171},
{,0.26177474519403443},
{,0.13033757084128628},
{,8.274133360405898e-5},
{,4.181167100346997e-5},
{,4.0870150064878635e-5},
{,4.012856385623552e-5},
{,4.402024019534071e-5},
{,4.464950668964882e-5},
{,4.662729312473385e-5},
{,4.765041344339578e-5},
{,4.442241285611087e-5},
{,4.494246472994659e-5},
{,4.1057127449095396e-5},
{,4.487741704964992e-5},
{,3.939601150277982e-5},
{,4.02231871509171e-5},
{,3.866736564497342e-5}]

-Whatsapp 案例

erlang方面能找到案例不多，幸运的发现whatsapp 给出了类似案例详细的分析：

http://highscalability.com/blog/2014/2/26/the-whatsapp-architecture-facebook-bought-for-19-billion.html

First bottleneck showed up at 425K. System ran into a lot of contention. Work stopped.
Instrumented the scheduler to measure how much useful work is being done, or sleeping, or spinning.
Under load it started to hit sleeping locks so 35-45% CPU was being used across the system but the schedulers are at 95% utilization.

whatsapp 在单机425K连接时遇到瓶颈，虚机实际只35~45%cpu却给系统造成了95%的cpu。

文中没有提到具体细节，关于scheduler：

1. +swt low Set the scheduler wake up threshold to low because schedulers would go to sleep and would never wake up

2. 设置进程优先级为实时 Run BEAM at real-time priority so that other things like cron jobs don’t interrupt schedule. Prevents glitches that would cause backlogs of important user traffic

3. 禁用spin（ patch beam）Patch to dial down spin counts so the scheduler wouldn’t spin，+ssct 1 (via patch; scheduler spin count)

-工具分析

通过微博私信，请教了下郑思瑶，推荐VTune分析，推测是大量进程时调度器消耗过大。

通过Intel 官方网站，填写注册信息，会立即回复邮件下载地址，并给30天试用期。

速度很慢，建议挂着VPN下载；VTune 的linux版本命令行模式使用很简单：

tar -zxf vtune_amplifier_xe_2015.tar.gz

cd vtune_amplifier_xe_2015

./install.sh

cd /opt/intel/vtune_amplifier_xe_2015.1.0.367959/

source amplxe-vars.sh

amplxe-cl -collect lightweight-hotspots -run-pass-thru=--no-altstack -target-pid=1575

amplxe-cl -report hotspots

可直接线上执行，不影响服务正常运行，得到如下结果：

Summary
-------
Elapsed Time: 19.345
CPU Time: 182.023
Average CPU Usage: 9.155
CPI Rate: 1.501Function Module CPU Time:Self
------------------------------------------- ------------------ -------------
sched_spin_wait beam.smp 72.754
raw_local_irq_enable vmlinux 19.282
process_main beam.smp 10.476
ethr_native_atomic32_read beam.smp 8.337
func@0xffffffff8100af60 vmlinux 3.007
__pthread_mutex_lock libpthread-2.12.so 2.342
raw_local_irq_restore vmlinux 1.973
__sched_yield libc-2.12.so 1.913
pthread_mutex_unlock libpthread-2.12.so 1.553
__audit_syscall_exit vmlinux 1.192
system_call vmlinux 1.156
erts_thr_yield beam.smp 1.114
handle_delayed_dealloc beam.smp 0.977
update beam.smp 0.828
raw_local_irq_enable vmlinux 0.780

可以看到sched_spin_wait占用了 40% 的CPU时间

#define ERTS_SCHED_SPIN_UNTIL_YIELD 100
static erts_aint32_t
sched_spin_wait(ErtsSchedulerSleepInfo *ssi, int spincount)
{
int until_yield = ERTS_SCHED_SPIN_UNTIL_YIELD;
int sc = spincount;
erts_aint32_t flgs; do {
flgs = erts_smp_atomic32_read_acqb(&ssi->flags);
if ((flgs & (ERTS_SSI_FLG_SLEEPING|ERTS_SSI_FLG_WAITING))
!= (ERTS_SSI_FLG_SLEEPING|ERTS_SSI_FLG_WAITING)) {
break;
}
ERTS_SPIN_BODY;
if (--until_yield == ) {
until_yield = ERTS_SCHED_SPIN_UNTIL_YIELD;
erts_thr_yield();
}
} while (--sc > );
return flgs;
}

默认spincount = 10000，但每次都有atom 读操作，原子操作一般几十到几百CPU周期，导致这个忙等待实际执行完的话会很长。

同时也找到对应的配置：

启动参数：+sbwt none 即可见spin彻底关掉，而不必像whatsapp patch beam解决。

同时strace 系统调用比较：

利用率高机器：

% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
34.07 0.022954 0 49747 writev
33.15 0.022336 0 58925 11806 recvfrom
21.04 0.014176 1 14558 2394 futex
8.37 0.005636 0 24722 4 epoll_ctl
2.71 0.001828 0 6947 epoll_wait
0.30 0.000199 10 19 munmap
0.24 0.000164 0 612 sched_yield
0.12 0.000078 16 5 mmap
0.00 0.000000 0 4 close

利用率低机器：

% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
86.38 13.138511 futex
6.91 1.050431 writev
5.70 0.866909 recvfrom
0.54 0.082772 sched_yield
0.43 0.065219 epoll_ctl
0.01 0.002220 munmap
0.01 0.001092 epoll_wait
0.00 0.000675 mmap
0.00 0.000612 connect
0.00 0.000564 fcntl
0.00 0.000529 getsockname
0.00 0.000457 getsockopt
0.00 0.000341 socket
0.00 0.000127 read
0.00 0.000109 bind

两次strace 时间不同，可通过writev比例看出，第二次futex量要快高一倍，调度器线程切换较为严重。