首页 > 代码库 > 记一次erlang 节点CPU严重波动排查过程
记一次erlang 节点CPU严重波动排查过程
新服务上线后观察到，CPU在10 ~ 70%间波动严重，但从每秒业务计数器看业务处理速度很平均。
接下来是排查步骤：
1. dstat -tam
大概每10s一个周期，网络流量开始变得很小，随后突然增大，CPU也激增。
网络流量变化和从性能计数器结果上并不符合，服务相关业务较为复杂，先找出那个业务占用网络流量。
2. iftop
找出流量最大的几个目标IP，并且周期的流量变为0随后激增。
通过IP 知道是外部http接口地址，因为接口调用是异步进行的，性能计算是执行开始记录的，而不是结束记录，因此可以理解。
也就是每过一段时间所有异步执行的接口调用都会被block一段时间。
3. tcpdump
既然被block，首先想到的就是依赖服务不稳定，不定期超时造成。
抓取tcp 包确认
但是从网络包中，没有找到任何tcp连接失败，重传等，IO统计流量为0 时，客户端就没有发起任何http 请求。
也就说明问题出在调用方，httpclient。
4.lhttpc
仔细看了一遍lhttpc源码，能找到唯一可能影响的地方就是 lhttpc 限制并发连接数为50.
线上查lhttpc配置时，却发现部署版本不是最新的，汗。。。找到对应版本发现老版本没有并发连接数限制，比较简单也找不到其他问题。
5. 找出block 代码路径
找出调用入口，手动执行，发现确实，存在block情况
通过抓取进程栈：
io:format("~s~n", [element(2, process_info(Pid, backtrace))]).
定位到是 lhttpc 老实在调用其他一个接口时block 数秒
6. fprof 工具
fprof:start().
fprof:apply(M, F, A).
fprof:profile().
fprof:analyze().
得到如下结果（摘要）
{[{{lhttpc_client,request,9}, 1, 4993.730, 0.018}], { {lhttpc_client,execute,9}, 1, 4993.730, 0.018}, % [{{lhttpc_client,send_request,1}, 1, 4993.486, 0.004}, {{lhttpc_lib,format_request,7}, 1, 0.130, 0.008}, {{gen_server,call,3}, 1, 0.046, 0.003}, {{lhttpc_lib,normalize_method,1}, 1, 0.038, 0.017}, {{proplists,get_value,3}, 6, 0.006, 0.006}, {{proplists,is_defined,2}, 2, 0.003, 0.003}, {{proplists,get_value,2}, 1, 0.003, 0.002}]}.{[{{lhttpc_client,execute,9}, 1, 4993.486, 0.004}, {{lhttpc_client,send_request,1}, 1, 0.000, 0.003}], { {lhttpc_client,send_request,1}, 2, 4993.486, 0.007}, % [{{lhttpc_sock,connect,5}, 1, 4932.214, 0.006}, {{lhttpc_client,read_response,1}, 1, 61.202, 0.004}, {{lhttpc_sock,send,3}, 1, 0.061, 0.001}, {{erlang,setelement,3}, 1, 0.002, 0.002}, {{lhttpc_client,send_request,1}, 1, 0.000, 0.003}]}.{[{{inet_gethost_native,getit,2}, 1, 4929.280, 0.000}, {{prim_inet,recv0,3}, 1, 59.932, 0.000}, {{prim_inet,connect0,4}, 1, 2.082, 0.000}, {{lhttpc_client,request,9}, 1, 0.017, 0.000}, {{gen,do_call,4}, 1, 0.017, 0.000}], { suspend, 5, 4991.328, 0.000}, % [ ]}.{[{{gen_tcp,connect,4}, 1, 4932.188, 0.007}], { {gen_tcp,connect1,4}, 1, 4932.188, 0.007}, % [{{inet_tcp,getaddrs,2}, 1, 4929.488, 0.013}, {{gen_tcp,try_connect,6}, 1, 2.672, 0.020}, {{gen_tcp,mod,2}, 1, 0.019, 0.002}, {{inet_tcp,getserv,1}, 1, 0.002, 0.002}]}.{[{{gen_tcp,connect1,4}, 1, 4929.488, 0.013}], { {inet_tcp,getaddrs,2}, 1, 4929.488, 0.013}, % [{{inet,getaddrs_tm,3}, 1, 4929.475, 0.008}]}.{[{{inet_tcp,getaddrs,2}, 1, 4929.475, 0.008}], { {inet,getaddrs_tm,3}, 1, 4929.475, 0.008}, % [{{inet,gethostbyname_tm,3}, 1, 4929.445, 0.005}, {{inet_parse,visible_string,1}, 1, 0.022, 0.001}]}.{[{{inet,getaddrs_tm,3}, 1, 4929.445, 0.005}], { {inet,gethostbyname_tm,3}, 1, 4929.445, 0.005}, % [{{inet,gethostbyname_tm,4}, 1, 4929.430, 0.002}, {{inet_db,res_option,1}, 1, 0.009, 0.002}, {{lists,member,2}, 1, 0.001, 0.001}]}.{[{{inet,gethostbyname_tm,3}, 1, 4929.430, 0.002}], { {inet,gethostbyname_tm,4}, 1, 4929.430, 0.002}, % [{{inet,gethostbyname_tm_native,4}, 1, 4929.428, 0.004}]}.{[{{inet,gethostbyname_tm,4}, 1, 4929.428, 0.004}], { {inet,gethostbyname_tm_native,4}, 1, 4929.428, 0.004}, % [{{inet_gethost_native,gethostbyname,2}, 1, 4929.423, 0.002}, {{inet,gethostbyname_tm,5}, 1, 0.001, 0.001}]}.从上面看，block在于 inet_tcp:getaddrs, 阅读源码发现是调用native 解析dns 的问题。
7. erlang dns
dig 域名，dnsserver 是内网服务器，响应都在1ms内，长时间测试，不存在任何延时。
因为怀疑是erlang dns 实现的问题
http://erlang.org/doc/apps/erts/inet_cfg.html
> inet_db:get_rc().
[{nameservers,{10,13,8,25}},
{nameservers,{172,16,105,248}},
{resolv_conf,"/etc/resolv.conf"},
{hosts_file,"/etc/hosts"},
{lookup,[native]}]
> ets:lookup(inet_db, cache_size).
[{cache_size,100}]
{lookup, Methods}.
Methods = [atom()]
Specify lookup methods and in which order to try them. The valid methods are: native (use system calls), file (use host data retrieved from system configuration files and/or the user configuration file) or dns (use the Erlang DNS client inet_res for nameserver queries).
上面说明，默认情况erlang 每次dns查询都是查询直接走系统调用，只有但 lookup [dns] 时才会启用erlang 内部的 dns cache。
8. 系统dns
既然erlang 没有dnscache 抓包分析一下，系统
tcpdump -i any udp port 53
21:34:58.739732 IP 10.77.128.49.49003 > 10.13.8.25.domain: 26954+ A? i.api.xxx.cn. (32)
21:34:58.739941 IP 10.13.8.25.domain > 10.77.128.49.49003: 26954 1/4/4 A 172.16.105.232 (193)
21:34:58.740546 IP 10.77.128.49.40072 > 10.13.8.25.domain: 39440+ A? i.api.xxx.cn. (32)
21:35:02.205299 IP 10.77.128.49.6060 > 10.13.8.25.domain: 48139+ A? bx49. (22)
21:35:02.207506 IP 10.13.8.25.domain > 10.77.128.49.6060: 48139 NXDomain 0/1/0 (97)
21:35:03.479277 IP 10.77.128.49.51277 > 10.13.8.25.domain: 11779+ A? bx49. (22)
21:35:03.479501 IP 10.13.8.25.domain > 10.77.128.49.51277: 11779 NXDomain 0/1/0 (97)
21:35:03.745591 IP 10.77.128.49.24134 > 172.16.105.248.domain: 39440+ A? i.api.xxx.cn. (32)
21:35:03.747254 IP 172.16.105.248.domain > 10.77.128.49.24134: 39440 1/4/4 A 172.16.105.232 (193)
从包中，存在大量频繁的请求对i.api.xxx.cn 域名的查询，而且被我标黄的那条记录没有应答，5s后重发请求才收到结果。
总结：
i.api.xxx.cn 接口不支持keepalive，每次都需要新建连接，erlang 每次都需要进行系统调用查询DNS
服务器没有启动 nscd 服务，没有缓存
DNS 使用UDP 协议，即使时内网，偶尔也会丢失
erlang 对于并发查询同一个DNS 会做合并，同时只会有一个DNS 请求
erlang 的系统调用超时时间太长（5s），没有及时的重发查询，造成期间请求堆积，等DNS返回，堆积的业务同时开始处理，造成CPU波动。
解决方案：
1. 启动nscd 2. 配置inet 使用内存dns 模块缓存