zoukankan      html  css  js  c++  java
  • 一次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 模块缓存

      

  • 相关阅读:
    去除UINavigationBar的下边框
    struts2配置log
    GET和POST方式的乱码问题
    Eclipse中导入MyEclipse生成的war包
    TOMCAT管理页面部署WAR包 大小超出上限
    Java死锁 Thread Dump分析
    自定义标签之IterationTag
    Chart.js学习
    计数排序
    练手系列之旋转字符串
  • 原文地址:https://www.cnblogs.com/lulu/p/3872206.html
Copyright © 2011-2022 走看看