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 模块缓存

      

  • 相关阅读:
    Note/Solution 转置原理 & 多点求值
    Note/Solution 「洛谷 P5158」「模板」多项式快速插值
    Solution 「CTS 2019」「洛谷 P5404」氪金手游
    Solution 「CEOI 2017」「洛谷 P4654」Mousetrap
    Solution Set Border Theory
    Solution Set Stirling 数相关杂题
    Solution 「CEOI 2006」「洛谷 P5974」ANTENNA
    Solution 「ZJOI 2013」「洛谷 P3337」防守战线
    Solution 「CF 923E」Perpetual Subtraction
    KVM虚拟化
  • 原文地址:https://www.cnblogs.com/lulu/p/3872206.html
Copyright © 2011-2022 走看看