Swoole连接超时分析


2017-04-24

一、简述

我们的产品中使用Swoole来构建长连接服务,用于C/S之间的实时数据交互。同时也编写了一个监控程序monitor来定时检查长连接服务的可用性。结构是这样的:

不知从什么时候起,每天都会收到几封报警邮件,关键信息是这样的:

check_websocket: failed... err_code(11)...err_info: Resource temporarily unavailable

因为最近团队忙的很,这个错误也没有影响业务的可用性,所以一直没管。等到前两天我有闲了,就尝试着分析、处理。

二、无脑排查

先瞅了一眼monitor的代码,这个错误是在swoole的WebSocketClient:connect()失败时输出的,该方法的实现是这样的:

public function connect($timeout = 1)
{
    $this->socket = new \swoole_client(SWOOLE_SOCK_TCP);
    if (!$this->socket->connect($this->host, $this->port, $timeout))
    {
        return false;
    }
    $this->socket->send($this->createHeader());
    return $this->recv();
}

根据报警邮件里的信息,判断失败应该出现在其中的socket.connect()调用。

第一反应是服务器或者swoole进程的配置或者资源不够。登入服务器简单查看了下资源占用和内核参数,资源占用正常,内核参数设低了,于是根据Swoole官方的建议做了调整。观察了一会,还是收到了相同的报警邮件。

难道是连接数不够?看了一下内核参数设定:

动手改吧:

sudo sysctl -w net.core.somaxconn=8192

顺便也调整了monitor中设定swoole配置的代码,显式把backlog设为8192,通过ss -ltn确认生效后继续观察,过了一阵还是收到了报警邮件。看样子没这么简单,无脑调优失败。

那就摆正态度、认真分析吧~

三、数据采集

首先收集系统和Swoole进程的TCP连接情况。通过简单的netstat脚本(附在文末)持续观察了一段时间,发现系统总TCP连接不足10,000,swoole的TCP入连接不足3,000。这连接负载挺低的。难道是网络延时导致超时?

理论上不应该是网络问题,因为server和monitor部署在同一云服务内网。用pingdmsg了解了下网络状态:前者不到2ms,后者的net io不足200kps。确实没什么问题。

再看了看Swoole的进程数量、状态,也都正常。到这里,我的好奇心被勾起来了~

难不成是丢包或者类似的奇葩问题?

四、报文分析

tcpdump分别在monitor所在服务器和swoole所在服务器上抓包。发现monitor和swoole之间的『超时』很严重,经常两三次重试才能成功一次,但只有5次重试都失败才会发送报警邮件。所以每天才『只』收到不足十封的报警邮件,要是没有这个重试机制,我们早就被报警邮件淹没了……

先看看成功的报文序列:

大概的流程是:

  1. 双方三次握手建立起TCP连接 —— 报文118~120。
  2. monitor发起HTTP GET请求,目的是申请与swoole建立WebSocket连接 —— 报文121。
  3. swoole返回HTTP响应,同意建立WebSocket连接 —— 报文122、123。
  4. monitor主动结束WebSocket连接 —— 报文124。

这就是monitor正常的存活检测方法 —— 只要建立WebSocket连接成功,就认为swoole存活、可用,然后断开连接。

再来看看超时的报文序列:

可以看出和正常报文序列的区别:swoole没有返回「同意建立WebSocket连接」的HTTP响应报文。于是monitor在5秒钟之后超时发送了一段内容后结束了TCP连接。

monitor发送的那段内容,也就是报文6中的Continuation,的值是88:02:03:e8。查阅RFC 6455,得知其含义是「正常关闭」:

The Close frame MAY contain a body (the “Application data” portion of
the frame) that indicates a reason for closing, such as an endpoint
shutting down, an endpoint having received a frame too large, or an
endpoint having received a frame that does not conform to the format
expected by the endpoint. If there is a body, the first two bytes of
the body MUST be a 2-byte unsigned integer (in network byte order)
representing a status code with value /code/ defined in Section 7.4.
Following the 2-byte integer, the body MAY contain UTF-8-encoded data
with value /reason/, the interpretation of which is not defined by
this specification.

1000 indicates a normal closure, meaning that the purpose for which
the connection was established has been fulfilled.

也就是说,这个报文和正常报文序列中的报文124是相同的含义,都是关闭连接。只不过超时情况下,连接没有从HTTP(TCP)升级到WebSocket,所以Wireshark就当做普通的TCP报文显示了。

到这里,我的结论是:超时问题出在应用层协议,也就是协商HTTP升级为WebSocket的过程中。和内核协议栈没关系,所以之前的无脑调优自然没有效果。

那么接下来应该怎么继续分析呢?

五、strace分析

先找到swoole的master进程ID,然后sudo strace -p 25289 -f -F,对输出进行定位、裁剪后,得到以下的调用序列:

 1 accept4(4, {sa_family=AF_INET, sin_port=htons(46407), sin_addr=inet_addr("X.X.X.X")}, [16], SOCK_CLOEXEC|SOCK_NONBLOCK) = 2032
 2 epoll_ctl(204, EPOLL_CTL_ADD, 2032, {EPOLLOUT, {u32=2032, u64=2032}} <unfinished ...>
 3 <... epoll_wait resumed> {{EPOLLOUT, {u32=2032, u64=2032}}}, 4096, -1) = 1
 4 epoll_ctl(204, EPOLL_CTL_MOD, 2032, {EPOLLIN, {u32=2032, u64=2032}} <unfinished ...>
 5 <... epoll_wait resumed> {{EPOLLIN, {u32=2032, u64=2032}}}, 4096, -1) = 1
 6 recvfrom(2032,  <unfinished ...>
 7 <... epoll_wait resumed> {{EPOLLIN, {u32=2032, u64=2032}}}, 4096, -1) = 1
 8 recvfrom(2032, "\210\2\3\350", 8192, 0, NULL, NULL) = 4
 9 epoll_wait(204, {{EPOLLIN, {u32=2032, u64=2032}}}, 4096, -1) = 1
10 recvfrom(2032, "", 8188, 0, NULL, NULL) = 0
11 epoll_ctl(204, EPOLL_CTL_DEL, 2032, NULL) = 0
12 close(2032)

其中行6是recvfrom了HTTP GET请求。但是不知什么原因,swoole并没有返回响应报文,而是继续等待接收更多的数据。于是在行8时收到了monitor因为5秒超时而发来的WebSocket FIN报文,结束了整个连接。这进一步说明问题出在应用层协议沟通过程中。

那么究竟是swoole的问题,还是monitor问题呢?我翻了翻monitor的代码,发现内容非常简单,就是直接调用swoole项目封装的WebSocketClient.php库来建立连接,然后断开。monitor自身没有做任何业务上的处理。再翻了翻WebSocketClient.php不到300行的代码,没有发现端倪。那么可以重点怀疑是swoole的问题了。

把这个分析报告分享给大伙之后,请同事升级swoole到最新的版本。再抓包,超时现象消失。终于不用被报警邮件困扰了 :-)

六、资料

七、附录

# 使用netstat查看系统的TCP连接情况
OUTPUT=/tmp/nst.log
echo -n $( date "+%Y-%m-%d_%H:%M:%S" ) >> $OUTPUT
echo -n " " >> $OUTPUT
netstat -n | awk 'BEGIN { OFS = " "; ORS = " " } /^tcp/ {++y[$NF]} END {for(w in y) print w, y[w]}' >> $OUTPUT
echo "" >> $OUTPUT
# 使用netstat查看指定进程的TCP连接情况(记得要把第四行中的{keyword}换成进程的关键字)
OUTPUT=/tmp/swcc.log
echo -n $( date "+%Y-%m-%d_%H:%M:%S" ) >> $OUTPUT
echo -n " " >> $OUTPUT
echo -n $( netstat -nutp | grep '{keyword} | wc -l ) >> $OUTPUT
echo "" >> $OUTPUT