粤公网安备 44030502006476号
【背景】
最近在优化一个监控模块里面的dns解析功能，原来的做法是用旁路线程调用getaddrinfo去同步解析，解析实时性非常差，所以决定将解析改成异步执行。网上搜索了一些dns异步解析的库/接口, 大致有：getaddrinfo_a 、adns、c-ares、udns等等。这些库虽然功能相对比较全，但是在我的场景各种别扭或者低效，不能很好地满足我的需求：其实需求很简单，我就需要解析ipv4的协议编解码接口就行了，然后结合epoll完成异步解析。在纠结了很久之后，决定按照dns协议自己实现解析ipv4的协议编解码接口，然后结合epoll完成异步解析。
【问题表现】
优化后的程序dns解析功能一切正常，之前扫描一遍hash表（共享内存里面）并解析完需要几分钟甚至几个小时，优化后解析完整个hash表只需要几秒钟。可另外一个跟优化“完全无关”的功能却受了影响，调用tcp.py(tcp端口探测的python脚本)总是报错：
2014-09-03 17:19:53,645 ERROR cmp_tcp.py:26 connect(10.190.164.92, 8001) ret: 114, cost: 0ms, err: EALREADY
显示为连接已经在建立中
【问题分析】
一． 分析c++代码
因为之前就遇到过因为SIGCHLD信号导致程序不能正常工作的情况，毕竟在优化前后没有对tcp.py做过任何改动，第一感觉又是因为某个信号问题导致的。仔细diff了几遍修改前后的c++代码，没有任何跟信号打交道的地方。除了之前调用getaddrinfo,而现在不调用这个接口以外，没有其他特别之处。难道是getaddrinfo里面会打开或者屏蔽某个信号？为了验证是不是getaddrinfo导致的，在main函数创建工作线程以前显式地调用了一次getaddrinfo，发现问题依旧，确定跟c++里面是否调用getaddrinfo无关。
回到python源码本身，核心代码就下面几行：
sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
sock.settimeout(10) # 10 seconds
ecode = sock.connect_ex((ip, port))
sock.close()
ecode总是为EALREADY，英文注解为：Operation already in progress，意思是当前这个socket已经在异步连接中，如果在这个socket上面调用第二次connect会导致返回EALREADY。可是python代码里面明明只调用了一次connect_ex(返回错误码的版本，connect为抛异常的版本)，而且socket也是临时创建的，没有复用任何之前创建的socket，感觉非常的匪夷所思。
二．找到出问题的环节
为了验证问题出现在哪个环节，试着将上面的几行代码拷贝到脚本的不同地方，因为脚本可以支持直接探测域名，所以python脚本里面会调用getaddrinfo先进行域名解析，如果将以上几行python代码拷贝到调用getaddrinfo之前的地方，需要将域名对应的ip直接写死。结果发现在调用getaddrinfo之前的connect_ex调用都是正常的，在getaddrinfo之后的调用都返回EALREADY错误。于是怀疑是python里面的getaddrinfo里面做了什么事情，回到一开始对信号的怀疑，感觉可能是getaddrinfo里面处理了跟信号有关的东西。猜测终归只是猜测，于是决定用神器strace一看究竟：
strace片段1. 第一处connect:
18:35:20.759017 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 1043 <0.000007>
18:35:20.759056 connect(1043, {sa_family=AF_INET, sin_port=htons(443), sin_addr=inet_addr("203.195.128.189")}, 16) = 0 <0.032906>
connect完全正常，第二处connect表现跟上面一样，不单独列出。
strace片段2. 第三处connect:
18:35:20.854934 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 1045 <0.000007>
18:35:20.854959 fcntl(1045, F_GETFL) = 0x2 (flags O_RDWR) <0.000004>
18:35:20.854980 fcntl(1045, F_SETFL, O_RDWR|O_NONBLOCK) = 0 <0.000005>
18:35:20.855045 connect(1045, {sa_family=AF_INET, sin_port=htons(443), sin_addr=inet_addr("203.195.128.189")}, 16) = -1 EINPROGRESS (Operation no
w in progress) <0.000012>
18:35:20.855079 select(1046, NULL, [1024 1026 1045], NULL, {2097157, 0}) = 2 (out [1026 1045], left {2097156, 999997}) <0.000007>
18:35:20.855131 connect(1045, {sa_family=AF_INET, sin_port=htons(443), sin_addr=inet_addr("203.195.128.189")}, 16) = -1 EALREADY (Operation alrea
dy in progress) <0.000005>
connect开始报错。可以看到python(内核)这里的实现，先将socket设置为非阻塞，然后调用一次connect，发现不能立马连上，所以将fd放入select进行监听，select返回fd可写(可写表示连接建立成功)后，python调用了第二次connect以确保连接真的成功，但是第二次connect返回了EALREADY，表示连接其实还在建立当中，并没有成功。至于getaddrino的调用，对应的系统调用只有创建socket跟114.114.114.114：53通信而已，没有特别之处，可以排除getaddrinfo的影响。
问题是为啥第一处connect是阻塞的，而第二处是非阻塞呢？对比代码发现是socket.setdefaulttimeout(5)引起的，只要给socket设置超时，python就会自动将socket设置为非阻塞。为啥select返回连接建立成功，而select后的connect却没有返回0，而是返回EALREADY错误呢？
Strace片段3. 为了对比优化前后的具体差异，决定strace一下优化前的c++程序调用tcp.py的执行过程，结果(第三处connect)显示为：
10:21:27.542192 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 20 <0.000008>
10:21:27.542217 fcntl(20, F_GETFL) = 0x2 (flags O_RDWR) <0.000004>
10:21:27.542239 fcntl(20, F_SETFL, O_RDWR|O_NONBLOCK) = 0 <0.000004>
10:21:27.542305 connect(20, {sa_family=AF_INET, sin_port=htons(443), sin_addr=inet_addr("203.195.128.189")}, 16) = -1 EINPROGRESS (Operation now
in progress) <0.000012>
10:21:27.542341 select(21, NULL, [20], NULL, {5, 0}) = 1 (out [20], left {4, 965442}) <0.034567>
10:21:27.576992 connect(20, {sa_family=AF_INET, sin_port=htons(443), sin_addr=inet_addr("203.195.128.189")}, 16) = 0 <0.000008>
Strace片段2对应出问题的版本，strace片段3对应正常的版本，对比看系统调用的结构完全一样。仔细看会发现，select的返回时延差别很大，问题版本的select只花了7个微秒就返回了，正常版本的select却等了30多个毫秒才返回。203.195.128.189这个ip 正常ping一次要30几个毫秒，所以正常版本的select耗时是符合预期的。问题版本的select其实并没有等到连接真正成功就返回了，可是select并没有报错，而是显示为连接已经成功，从而python调用第二次connect以确认链接是否真的成功，connect理所当然的返回了EALREADY。
定位到这里，我也没有什么头绪了，既然阻塞版本的socket不会有问题，直接用阻塞版本的socket规避掉这个问题得了。但是不搞定这个问题又会睡不好觉，而且这里的阻塞版没法控制超时，在现网环境是不可取的，tcp自然超时可能得花几十秒，分分钟导致进程被阻死。想到这里还是决定硬着头皮继续定位，既然是select调用出了问题，如果在python代码里面显示调用select看看会怎么样呢?
三．Python显式调用select确认
修改后的tcp.py代码：
sock = socket.socket(socket.AF_INET,socket.SOCK_STREAM)
sock.setblocking(0);
ecode= sock.connect_ex(("203.195.128.189", 443));
log.debug("1 errno = %d, sockfd = %d" % (ecode, sock.fileno()));
inputs = [sock]
rlist, wlist, xlist = select.select(inputs, inputs, inputs, 5);
log.debug("select %d %d %d" % (len(rlist), len(wlist), len(xlist)));
python脚本抛出异常（为了快速调试，没有捕获异常）：
$ Traceback (most recent call last):
File "./cmp_tcp.py", line 92, in ?
rlist, wlist, xlist = select.select(inputs, inputs, inputs, 5);
ValueError: filedescriptor out of range in select()
对应的debug log为：
2014-09-05 11:03:01,767 DEBUG cmp_tcp.py:89 1 errno = 115, sockfd = 1043
因为select直接抛出了异常，所以第二个debug log没有机会执行。
四．问题根源分析
什么情况？python脚本明明只创建了一个socket，加上打日志的几个fd，冲上天最多有几十个fd吧？！可是异常信息明确显示select中的fd超出了范围，python不至于乱报。这是一个很重要的线索，根据这个线索，对比c++代码的diff，发现了问题的根源：是父进程的大量fd被python子进程继承导致的！具体见下面的分析：
Dns解析一般是基于udp协议，c++代码里面为了提高性能，避免反复创建、销毁socket带来的开销，创建了一个udp socket pool，而且预先将这些fd的EPOLLIN事件注册到epoll里面（这里的实现不用监听EPOLLOUT事件）。这样有dns请求的时候，直接从udp socket pool取一个fd进行send，然后等待epoll的input事件，recv完成后将这个fd归还到udp socket pool。这个pool的capacity计算规则是：capacity = min(1024, getrlimit(RLIMIT_NOFILE) / 4)，一般机器的getrlimit(RLIMIT_NOFILE)值都上万，所以capacity一般为1024。
问题非常清晰了，父进程的dns_resolver子线程创建了一个1024大小的udp sock pool，python子进程继承了这一批fd，然后python子进程新创建的fd必然是>=1024的。加之坑爹的python使用了古董级的select调用，两者“完美”的合作导致了select问题的发生。
回顾一下之前的strace片段2，当时没有注意fd的范围，其实当时的sockfd为1045，已经超出了select的处理范围，其实从这里已经可以看出问题。另外，我只创建了一个socket，为啥select里面额外监听了1024和1026，设置的5秒超时也显示为2097157？这里分析应该是fd越了select数组的界，导致内存被写坏引起的。
五．解决方法
既然找到问题原因了，解决思路自然很清晰了，大概有如下几种解决方法：
1. 阻塞方式不会调用select，可以规避select的问题，但是容易造成进程阻塞，在现网环境不宜采用。
2. 将capacity = min(1024, getrlimit(RLIMIT_NOFILE) / 4)改为capacity = min(512, getrlimit(RLIMIT_NOFILE) / 4)，这样不至于继承1024个那么多fd到python子进程，可以解决select的问题。但是除了这个udp socket pool以外，还有一些其他的fd也会被继承，所以这种方式也不是100%安全。
3. 既然是继承了大量的fd，而这些fd实际上对于python子进程来说没有实际用处，那我选择close一个1024以下的fd让socket复用就行了。
Python代码：
os.close(1023);
sock = socket.socket(socket.AF_INET,socket.SOCK_STREAM)
ecode = sock.connect_ex(("203.195.128.189", 443));
strace跟踪：
12:35:36.752416 close(1023) = 0 <0.000006>
12:35:36.752448 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 1023 <0.000008>
12:35:36.752478 fcntl(1023, F_GETFL) = 0x2 (flags O_RDWR) <0.000005>
12:35:36.752504 fcntl(1023, F_SETFL, O_RDWR|O_NONBLOCK) = 0 <0.000006>
12:35:36.752581 connect(1023, {sa_family=AF_INET, sin_port=htons(443), sin_addr=inet_addr("203.195.128.189")}, 16) = -1 EINPROGRESS (Operation no
w in progress) <0.000016>
12:35:36.752628 select(1024, NULL, [1023], NULL, {5, 0}) = 1 (out [1023], left {4, 967988}) <0.032021>
12:35:36.784727 connect(1023, {sa_family=AF_INET, sin_port=htons(443), sin_addr=inet_addr("203.195.128.189")}, 16) = 0 <0.000005>
从strace的信息来看确实是管用的。Close的1023这个fd被socket复用了，没有超出select的范围，一切正常。
4. 手工改为poll轮询。
Python代码：
sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
sock.setblocking(0);
ecode = sock.connect_ex(("203.195.128.189", 443));
log.debug("1 errno = %d, sockfd = %d" % (ecode, sock.fileno()));
poller = select.poll()
poller.register(sock, select.POLLOUT);
events = poller.poll(5000) # 5000ms
poller.unregister(sock)
sock.close()
log.debug("events=%r" % events)
if not events or events[0][1] != select.POLLOUT:
log.error("connect err")
else:
log.debug("connect succ")
strace跟踪：
13:30:42.834133 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 1043 <0.000009>
13:30:42.834216 fcntl(1043, F_GETFL) = 0x2 (flags O_RDWR) <0.000006>
13:30:42.834243 fcntl(1043, F_SETFL, O_RDWR|O_NONBLOCK) = 0 <0.000006>
13:30:42.834283 connect(1043, {sa_family=AF_INET, sin_port=htons(443), sin_addr=inet_addr("203.195.128.189")}, 16) = -1 EINPROGRESS (Operation now in progress) <0.000022>
13:30:42.834695 poll([{fd=1043, events=POLLOUT, revents=POLLOUT}], 1, 5000) = 1 <0.032136>
对应的日志：
2014-09-05 13:30:42,834 DEBUG cmp_tcp.py:90 1 errno = 115, sockfd = 1043
2014-09-05 13:30:42,866 DEBUG cmp_tcp.py:97 events=[(1043, 4)]
2014-09-05 13:30:42,867 DEBUG cmp_tcp.py:102 connect succ
改为poll后完全正常
【总结】
1. 看似无关的2件事情，可能具有某种深层次的关联，而这种关联可能需要仔细分析才能发现
2. 具体到这件事情，其实本质上c++代码没有bug，但是c++的大量socket fd被python子进程无形地继承了，加之python内核坑爹地调用了古董级的select，而select玩不了1024以上的fd，所以导致fd在select的数组中溢出。更为坑爹的是，内核对select调用还成功返回了。
3. 以上给出的四种解决方法中，后两种方法都可以被最终采用，但是第三种方式怪怪的，第四种才是釜底抽薪的方式。