排查API的connection reset by peer和Timeout exceeded问题

头像
c_rain
    阅读 11 分钟
    1

    前言

    这是一次实际生产中遇到的问题，根据问题模拟反复试验。看完这部分代码，您可以直接了解backlog的工作原理，以及系统调优时该怎么调，不至于胡乱设置。

    排查API的connection reset by peer问题：

    • 晚上22点～早上6点会偶尔出现，16:00出现过一次；
    • Client.Timeout exceeded大量出现；

    分析问题原因：

    connection reset by peer 会有几种情况出现：

    • 处于ESTABLISHED 、 CLOSE_WAIT 、FIN_WAIT1 、FIN_WAIT2 、SYN_RECV或下一个发送序号并不是最后一个队列数据段序号

    并且是被动关闭的结束状态的rst状态；

    • 处于TCP_SYN_SENT的rst状态；

      Client.Timeout exceeded 会有几种情况出现：

    • 由于rst之后客户端重试时间过短导致的超时；
    • 代码本身业务逻辑超时；- （该项不在本次验证范围）

    怀疑对象

    • nginx 中 keepalive requests 配置 - 排除
    • 内核参数net.core.somaxconn和net.ipv4.tcp_max_syn_backlog; - 排除
    • 内核参数net.core.netdev_max_backlog - 影响不大只会导致丢包，消耗性能
    • 网关nginx本身backlog和应用nginx本身backlog

    网络内核参数用途介绍

    #当网卡接收数据包的速度大于内核处理的速度时，会有一个队列保存这些数据包。这个参数表示该队列的最大值。
net.core.netdev_max_backlog = 262144

#用来限制监听(LISTEN)队列最大数据包的数量，超过这个数量就会导致链接超时或者触发重传机制。
net.core.somaxconn = 262144

#表示那些尚未收到客户端确认信息的连接（SYN消息）队列的长度，可以容纳更多等待连接的网络连接数。
net.ipv4.tcp_max_syn_backlog = 262144

    net.core.somaxconn 和 net.ipv4.tcp_max_syn_backlog用途
    1.png
    根据上图所示net.core.somaxconn 和 net.ipv4.tcp_max_syn_backlog用于全连接队列和半连接队列。

    • 半连接队列（Incomplete connection queue），又称 SYN 队列
    • 全连接队列（Completed connection queue），又称 Accept 队列

    net.core.netdev_max_backlog用途
    linux内核代码

    int netif_rx(struct sk_buff *skb)
{
    struct softnet_data *queue;
    unsigned long flags;

    /* if netpoll wants it, pretend we never saw it */
    if (netpoll_rx(skb))
        return NET_RX_DROP;

    if (!skb->tstamp.tv64)
        net_timestamp(skb);

    /*
     * The code is rearranged so that the path is the most
     * short when CPU is congested, but is still operating.
     */
    local_irq_save(flags);
    queue = &__get_cpu_var(softnet_data);

    __get_cpu_var(netdev_rx_stat).total++;
    if (queue->input_pkt_queue.qlen <= netdev_max_backlog) { //网卡队列长度限制
        if (queue->input_pkt_queue.qlen) {
enqueue:
            dev_hold(skb->dev);
            __skb_queue_tail(&queue->input_pkt_queue, skb);
            local_irq_restore(flags);
            return NET_RX_SUCCESS;  //成功
        }

        napi_schedule(&queue->backlog);
        goto enqueue;
    }

    __get_cpu_var(netdev_rx_stat).dropped++;
    local_irq_restore(flags);

    kfree_skb(skb);
    return NET_RX_DROP;  //删除包
}

    根据代码所示每个网络接口接收数据包的速率比内核处理这些包的速率快时，允许送到队列的最大数目，一旦超过将被丢弃。
    网卡阶段包容易导致dropped packet，容易造成丢包现象。

    实验内容

    • 模拟网关本身nginx配置
    • 模拟线上sysctl内核参数
    • ab压测试验
    • golang编写http.NewRequest长连接请求压测试验

    复现步骤

    查看内核参数

    #systcl -a |grep -e netdev_max_backlog -e somaxconn -e tcp_max_syn_backlog

    2.png
    发现net.core.somaxconn 和net.ipv4.tcp_max_syn_backlog 都不太可能造成backlog。
    不过netdev_max_backlog很容易造成丢包现象。

    查看应用本身backlog

    #ss -l

    3.jpeg
    发现nginx本身的backlog是511，然后好奇为什么是这样，就翻阅nginx源码查看。
    查看nginx源码：

    #define NGX_LISTEN_BACKLOG        511

    4.jpeg5.jpeg
    除了Darwin系列系统和freebsd系列系统是由系统本身决定，其余的系统的backlog都是默认511。
    明显nginx的backlog比较低了。

    rst导致的Timeout exceeded问题复现

    可以先把nginx backlog调整成10，然后golang的client timeout设置成1
    golang代码

    package main

import (
   "fmt"
   "io/ioutil"
   "net/http"
   "runtime"
   "time"
)

var httpclient *http.Client

func init(){
   httpclient = &http.Client{Timeout:1 * time.Second}
}

func PostForm(url string) (body []byte, err error) {
   req, err := http.NewRequest("POST", url,nil)
   if err != nil {
      fmt.Println("NewRequest: ",err)
      return nil,err
   }

   req.Header.Set("Content-Type","application/x-www-form-urlencoded")
   resp, err := httpclient.Do(req)
   if err != nil {
      fmt.Println("httpclient: ",err)
      return nil,err
   }

   if resp.StatusCode != http.StatusOK {
      return nil, fmt.Errorf("Bad HTTP Response: %v", resp.Status)
   }

   defer resp.Body.Close()
   return ioutil.ReadAll(resp.Body)
}

func runHttp(dd chan int,i int) {


   _, err := PostForm("http://192.168.1.107/index.php")
   if err != nil {
      fmt.Println("err: ",err)
      fmt.Println("执行中" ,i)
   }
   
   dd <- i
}

func main()  {
   runtime.GOMAXPROCS(runtime.NumCPU())
   var dd chan int = make(chan int,2000)

   for i := 0;i <= 200;i++  {
      go runHttp(dd,i)
   }
   for i := 0;i <= 200;i++  {
      <-dd
   }
}

    然后进行压测

    6.png
    通过netstat -s命令查看rst
    7.png
    netstat的参数解释：

    root@nginx:/# netstat -s
Ip:
   Forwarding: 1          //开启转发
   31 total packets received    //总收包数
   0 forwarded            //转发包数
   0 incoming packets discarded  //接收丢包数
   25 incoming packets delivered  //接收的数据包数
   15 requests sent out      //发出的数据包数
Icmp:
   0 ICMP messages received    //收到的ICMP包数
   0 input ICMP message failed    //收到ICMP失败数
   ICMP input histogram:
   0 ICMP messages sent      //ICMP发送数
   0 ICMP messages failed      //ICMP失败数
   ICMP output histogram:
Tcp:
   0 active connection openings  //主动连接数
   0 passive connection openings  //被动连接数
   11 failed connection attempts  //失败连接尝试数
   0 connection resets received  //接收的连接重置数
   0 connections established    //建立连接数
   25 segments received      //已接收报文数
   21 segments sent out      //已发送报文数
   4 segments retransmitted    //重传报文数
   0 bad segments received      //错误报文数
   0 resets sent          //发出的连接重置数
Udp:
   0 packets received
   ...
TcpExt:
   11 resets received for embryonic SYN_RECV sockets  //半连接重置数
   0 packet headers predicted
   TCPTimeouts: 7    //超时数
   TCPSynRetrans: 4  //SYN重传数
 ...

    rst导致的connection reset by peer问题复现

    可以先把nginx backlog调整成10，然后golang的client timeout设置成10秒，然后继续进行压测
    8.png
    发现直接没有Client.Timeout exceeded while awaiting headers错误，全是服务端rst重试失败后的报错connection reset by peer。
    wireshark工具：
    9.png

    下图为多次rst试验
    10.jpeg
    11.jpeg

    经过多次比较发现一个特别有意思的问题，就是connection reset by peer的出现不规律。
    后来经过排查原因是因为重试次数和时间导致的。

    Client.Timeout exceeded while awaiting headers源码分析

    net/http/client.go

    func (c *Client) do(req *Request) (retres *Response, reterr error) {
  //...省略
  for {
     //...省略 
     var didTimeout func() bool
     if resp, didTimeout, err = c.send(req, deadline); err != nil {
        // c.send() always closes req.Body
        reqBodyClosed = true
        if !deadline.IsZero() && didTimeout() {  //超时报错
           err = &httpError{
              // TODO: early in cycle: s/Client.Timeout exceeded/timeout or context cancellation/
              err:     err.Error() + " (Client.Timeout exceeded while awaiting headers)", 
              timeout: true,
           }
        }
        return nil, uerr(err)
     }
    //...省略
 
  }
}

    golang中的http请求部分会调用do函数，do函数本身处理http请求是调用 for 不断的去取http数据，此时client timeout超时，则报Client.Timeout exceeded while awaiting headers 错误。

    半队列的大小计算

    注入 tcp_v4_conn_request 方法:

    probe kernel.function("tcp_v4_conn_request") {
    tcphdr = __get_skb_tcphdr($skb);
    dport = __tcp_skb_dport(tcphdr);
    if (dport == 80)
    {
        // 当前 syn 排队队列的大小
        syn_qlen = @cast($sk, "struct inet_connection_sock")->icsk_accept_queue->listen_opt->qlen;
        // syn 队列总长度 log 值
        max_syn_qlen_log = @cast($sk, "struct inet_connection_sock")->icsk_accept_queue->listen_opt->max_qlen_log;
        // syn 队列总长度，2^n
        max_syn_qlen = (1 << max_syn_qlen_log);
        printf("syn queue: syn_qlen=%d, max_syn_qlen_log=%d, max_syn_qlen=%d\n",
        syn_qlen, max_syn_qlen_log, max_syn_qlen);
        // 程序本身的backlog大小
        max_acc_qlen = $sk->sk_max_ack_backlog;
        printf("accept queue length limit: %d\n", max_acc_qlen)  
        print_backtrace();
    }
}

    使用stap 执行上面的代码

    # stap -g syn_backlog.c

    调试内核代码，捕获80端口的数据包。
    12.png
    13.png
    14.png
    3425835EE1834051B234D391B78F4B8A.png

    经过多次验证得出结论半连接大小不会受到somaxconn和max_syn_backlog影响

    somaxconn max_syn_backlog listen backlog 半连接队列大小
    65535 65535 10 16
    65535 65535 512 1025
    65535 65535 65535 65536
    65536 65536 65536 131072
    181920 181920 181920 262144
    • 在系统参数不修改的情形，盲目调大 listen 的 backlog 对最终半连接队列的大小不会影响。
    • 在 listen 的 backlog 不变的情况下，不要盲目的调大 somaxconn 和 max_syn_backlog 对最终半连接队列的大小不会有影响

    三次压测试验

    #ab -r -c 200 -t300 http://192.168.1.107/index.php

    16.png
    17.png
    18.png

    经过n次压测可以看到设置nginx默认511时，半连接开关为512。会偶尔出现错误情况，其实压测就200并发。
    设置backlog 262144时特别稳定。backlog 30时表现的则没那么好。

    压测时特意抓了内核参数，发现其实和全队列有实际关系；
    xiugai.png

    加餐部分，net源码解析

    ## RESET发送流程

    图中会调用tcp_reset流程：
    19.png
    20.png

    tcp_reset函数 net/ipv4/tcp_input.c

    static void tcp_reset(struct sock *sk)
{
   /* We want the right error as BSD sees it (and indeed as we do). */
   switch (sk->sk_state) {
   case TCP_SYN_SENT:
       sk->sk_err = ECONNREFUSED; //报“Connection refused” 错
       break;
   case TCP_CLOSE_WAIT:
       sk->sk_err = EPIPE;       //报“Broken pipe” 错
        break;
   case TCP_CLOSE:
       return;
   default: // TCPF_ESTABLISHED | TCPF_FIN_WAIT1 | TCPF_FIN_WAIT2 | TCPF_SYN_RECV 
       sk->sk_err = ECONNRESET;  //报“Connection reset by peer” 错
   }

   if (!sock_flag(sk, SOCK_DEAD))
       sk->sk_error_report(sk);

   tcp_done(sk);
}
       1.TCP接收报文：在tcp_v4_rcv，如果校验和有问题，则发送RESET；
    2.TCP接收报文：在tcp_v4_rcv，如果 __inet_lookup_skb 函数找不到报文所请求的socket，则发送RESET；
    3.TCP收到SYN，发送SYN-ACK，并开始等待连接最后的ACK：在tcp_v4_do_rcv - tcp_v4_hnd_req - tcp_check_req，如果TCP报文头部包含RST，或者包含序列不合法的SYN，则发送RESET；
    4.TCP收到连接建立最后的ACK，并建立child套接字后：tcp_v4_do_rcv - tcp_child_process - tcp_rcv_state_process - tcp_ack 函数中，如果发现连接等待的最后ACK序列号有问题： before(ack, prior_snd_una)，则发送RESET；
    5.TCP在ESTABLISH状态收到报文，在tcp_v4_do_rcv - tcp_rcv_established - tcp_validate_incoming 函数中，如果发现有SYN报文出现在当前的接收窗口中： th->syn && !before(TCP_SKB_CB(skb)->seq, tp->rcv_nxt)，则发送RESET；
    6.TCP在进行状态迁移时：tcp_rcv_state_process -
如果此时socket处于LISTEN状态，且报文中含有ACK，则发送RESET;
如果此时socket处于FIN_WAIT_1或者FIN_WAIT_2；当接收已经shutdown，并且报文中有新的数据时，发送RESET；
如果测试socket处于FIN_WAIT_1；继续执行

    ## close时调用tcp_disconnect的Connection reset by peer报错

    int tcp_disconnect(struct sock *sk, int flags)
{
  struct inet_sock *inet = inet_sk(sk);
  struct inet_connection_sock *icsk = inet_csk(sk);
  struct tcp_sock *tp = tcp_sk(sk);
  int err = 0;
  int old_state = sk->sk_state;

  if (old_state != TCP_CLOSE)
      tcp_set_state(sk, TCP_CLOSE);

  /* ABORT function of RFC793 */
  if (old_state == TCP_LISTEN) {
      inet_csk_listen_stop(sk);
  } else if (tcp_need_reset(old_state) || // 处于ESTABLISHED 、 CLOSE_WAIT 、FIN_WAIT1 、FIN_WAIT2 、SYN_RECV或下一个发送序号并不是最后一个队列数据段序号
并且是被动关闭的结束状态的rst状态；
         (tp->snd_nxt != tp->write_seq &&
          (1 << old_state) & (TCPF_CLOSING | TCPF_LAST_ACK))) {
      /* The last check adjusts for discrepancy of Linux wrt. RFC
       * states
       */
      tcp_send_active_reset(sk, gfp_any());
      sk->sk_err = ECONNRESET;
  } else if (old_state == TCP_SYN_SENT) //处于TCP_SYN_SENT的rst状态
      sk->sk_err = ECONNRESET;

  //...省略
  return err;
}

    查看平常监控及报警

    22.jpeg
    查看监控发现大部分出现connection reset by peer时都处于压测阶段。
    23.png
    在根据日常监控可以得知，出现connection reset by peer最小一次并发时大概计算了一下200左右。

    总结

    1.syn不会受到内核参数影响，只会受到list backlog影响；
    2.内核参数和list backlog不是随便乱调整的。
    3.nginx 除了Darwin系列系统和freebsd系列系统是由系统本身决定，其余的系统的backlog都是默认511。
    明显nginx的backlog比较低了。
    4.可以通过stap调试内核。

    根据如上问题，其实可以看到一个情况。我们可以得知connection reset by peer罪魁祸手其实是
    内核(struct inet_connection_sock)->icsk_accept_queue->listen_opt->qlen
    参数导致的，其实是全队列。

    整改建议

    1.调整内核参数部分：

    net.core.somaxconn = 262144
net.ipv4.tcp_max_syn_backlog = 262144
net.core.netdev_max_backlog = 262144

    2.调整nginx配置
    添加

    server {
    listen       80 backlog=262144;
    }
    gocnginxlinuxtcpdump
    c_rain
    23 声望8 粉丝
    下一篇 »
    PHP常驻内存下phpredis扩展的一个BUG

    引用和评论

    推荐阅读
    头像
    【Golang源码分析】Golang如何实现自举 - 程序入口点（五）

    c_rain阅读 2.1k

    头像
    Go 语言-计算密集型服务 性能优化

    Jesse赞 4阅读 8.7k

    头像
    IO 密集型服务 耗时优化

    Jesse赞 4阅读 7.8k

    头像
    Go 语言 JSON 与 Cache 库 调研与选型

    Jesse赞 2阅读 7.4k

    头像
    一份简单i3wm配置

    notusednow赞 2阅读 31.1k

    头像
    Docker 万字入门教程

    Java陈序员赞 4阅读 3.9k

    头像
    告别ELK，APO提供基于ClickHouse开箱即用的高效日志方案——APO 0.6.0发布

    云观秋毫赞 1阅读 3.8k

    0 条评论
    得票最新