一、简述

我们的产品中使用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官方的建议做了调整。观察了一会，还是收到了相同的报警邮件。

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

net.ipv4.tcp_max_syn_backlog是512 —— 没问题。
net.core.somaxconn是默认的128 —— 低了。

动手改吧：

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部署在同一云服务内网。用ping和dmsg了解了下网络状态：前者不到2ms，后者的net io不足200kps。确实没什么问题。

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

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

四、报文分析

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

先看看成功的报文序列：

大概的流程是：

双方三次握手建立起TCP连接 —— 报文118~120。
monitor发起HTTP GET请求，目的是申请与swoole建立WebSocket连接 —— 报文121。
swoole返回HTTP响应，同意建立WebSocket连接 —— 报文122、123。
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

Swoole连接超时分析