记一次小小的问题排查

最近在用Go写一个小型的项目,其中使用了MCQ来收集同步信息,奇怪的是,发送了大约1000W条消息,最后记录下来的只有一半!于是,开始详细记录日志信息,发现每隔一段时间,就会重复出现dial tcp 127.0.0.1:22201: can't assign requested address,恩,22201是我本地起的消息队列服务的端口。

首先,直觉上认为是多开了协程并发处理文本导致分配的端口不够用了,据说OSX默认端口就开放了100个。。于是,就把程序改成了不使用协程的方式,再次测试依然如此。

既然无法分配地址,那就用netstat命令看看网络连接的情况,使用netstat -n | grep 22201查看:

tcp4       0      8  127.0.0.1.22201        127.0.0.1.49332        ESTABLISHED
tcp4       0      0  127.0.0.1.49332        127.0.0.1.22201        ESTABLISHED
tcp4       0      0  127.0.0.1.22201        127.0.0.1.49331        ESTABLISHED
tcp4       0      0  127.0.0.1.49331        127.0.0.1.22201        FIN_WAIT_1
tcp4       0      0  127.0.0.1.22201        127.0.0.1.49330        ESTABLISHED
tcp4       0      0  127.0.0.1.49330        127.0.0.1.22201        FIN_WAIT_1
tcp4       0      0  127.0.0.1.22201        127.0.0.1.49329        ESTABLISHED
tcp4       0      0  127.0.0.1.49329        127.0.0.1.22201        FIN_WAIT_1
udp4       0      0  *.22201                *.*

看起来,应该是这个FIN_WAIT_1导致的。在TCP连接的状态与关闭方式,及其对Server与Client的影响中讲的很是详细:

主动关闭连接的一方等待对方返回ACK包。若Socket在ESTABLISHED状态下主动关闭连接并向对方发送FIN包(表示己方不再有数据需要发送),则进入FIN_WAIT_1状态,等待对方返回ACK包,此后还能读取数据,但不能发送数据。在正常情况下,无论对方处于何种状态,都应该马上返回ACK包,所以FIN_WAIT_1状态一般很难见到。

client端的关闭过程是CLOSED -> SYN_SENT -> ESTABLISHED -> FIN_WAIT_1 -> FIN_WAIT_2 -> TIME_WAIT -> CLOSED,而在发送出最后一个ACK包后,无论对方是否收到,client都会进入TIME_WAIT状态,等待2MSL的时间,然后才能释放网络资源。那问题就很明确了,使用sysctl net.inet.tcp.msl看下MSL的值:

15000

默认是15s,修改成1s好了~

sudo sysctl -w net.inet.tcp.msl=1000
Password:
net.inet.tcp.msl: 15000 -> 1000

再次运行程序,终于正常了,不在有卡顿无法分配地址的情况。


updated

今天在测试这个小项目时,又出现了这个问题,使用netstat -n | awk '/^tcp/ {++S[$NF]} END {for(a in S) print a, S[a]}'得到:

FIN_WAIT_2 128
SYN_SENT 3
CLOSE_WAIT 128
ESTABLISHED 5091

最后问了老大,原来是因为我使用了其他项目中的一个queue包,而这个包只是从MCQ中Get消息,而不是用来Set的,所以tcp连接较长。。。于是,直接修改使用Go Memcached client library #golang来连接,问题解决了。。

FIN_WAIT_1 1
ESTABLISHED 62