fpm开启slowlog Fsockopen出现Operation now in progress的问题追踪二
作者 斯人 | 发布于 2014 年 6 月 4 日
fsockopen PHP php-fpm PHP内核

关于具体问题,请参见上一篇 fpm开启slowlog Fsockopen出现Operation now in progress的问题追踪一

本文主要是定位问题。

接上一篇。

引起该问题的原因有两个:
1)connect的socket连接操作是非阻塞的(是起因但并非结果):
如果connect要用非阻塞,那就需要select/poll来监听我们的socket句柄。
Fsockopen调用 main/network.c 中php_network_connect_socket函数来建立connect连接,
首先它会将sock句柄设为非阻塞

然后调用connect调用链接,因为是非阻塞的,所以它会立即返回,正常情况返回值为EINPROGRESS,告诉你TCP链接正在进行中

调用poll来等待POLLIN|POLLERR|POLLHUP三个事件产生,注意:
不管发生下面哪个事件,poll都会返回当前事件的数量。
当有可读数据时,产生POLLIN
当有可写时间时,产生POLLOUT
当出错时(不管是什么错误),会产生POLLERR
Poll返回值大于0时,调用getsockopt来检测是否有socket错误产生,而不是像select一样验证是否是某个具体的事件。

上面说了非阻塞connect调用会立即返回,而不管connect是否调用成功,所以这意味着此时TCP的三次握手正在进行中,有可能阻塞在某一步,来回顾下三次握手吧:

1、主机A通过向主机B发送一个数据段给主机B,向主机B发送建立连接的请求

2、主机B收到A的数据段,然后返回应答数据单给A

3、主机A收到B的回复后,再次发送应答数据给B,告诉B我已经ok了

因为代码访问的是不存在或不可用的IP,所以三次握手一直停留在第一步,A向B发送请求目的地不可达的过程,是建立连接的过程,此时socket的状态一直都是EINPROGRESS,因为poll检测到句柄产生了POLLERR事件,调用getsockopt来检测socket的错误状态,返回的错误就是Operation now in progress,将IP换成可达而端口不存在的,则返回的错误为Connection refused,此时三次握手停在第二步,而错误码已被更新,所以调用getsockopt返回的错误即为 链接被拒绝,拿到错误后把错误指针error_string设置为php_socket_strerror(error)的返回值,立即返回-1错误,子进程发现函数返回的是-1 则说明链接失败了,则直接抛出error_string的错误内容。此时子进程进行回收操作,将错误内容及错误码通过socket返回给nginx,关闭此次连接。

为什么用curl的方式没有产生问题?php的curl扩展采用的是libcurl库实现的,libcurl在进行连接时虽然也是非阻塞,但是 io模型采用的是while(select(..)) ,如果select没有返回则一直循环等待事件的产生,直到达到fpm的超时设置,用strace查看,会发现这个现象:

一直重复调用select,所以对于fpm的子进程来讲,该操作一直阻塞,直到php脚本超时返回502错误。

2)父子进程切换

父子进程切换发生在有慢日志产生的时候,父进程需要拿到子进程的内存、堆栈信息等,把这些数据抛出到慢日志文件中,然后子进程继续运行,进行socket操作,检测到socket错误后直接返回,做一些回收操作后该进程结束,此时发送给父进程一个子进程退出的信号,父进程检测子进程是否异常退出,如果异常退出则重新建立一个新的子进程,父进程结束重新监听事件。

哈,似乎还是没说到根源。

上面只是切换流程,真正的问题在于 父进程给子进程发送的那个信号,SIGCONT

没错,就是它,为了找它,我可真是煞费苦心,不知道牺牲多少脑细胞!

         Poll/select这种事件模型,是阻塞的,对于进程来讲,阻塞过程中,进程处于“中断”状态(sleeping),父进程给子进程发送SIGSTOP,此时子进程状态为暂停(STOP),父进程给子进程发送SIGCONT状态,进程则处于运行(Running

我写了一个简单的程序来验证。

1、2、3是程序的执行中,子进程的状态,如果不发送SIGSTOP和SIGCONT,则子进程的状态为S中断状态,并且会阻塞在select,20秒的时间,当发送了SIGCONT状态后,进程的状态变为Running状态,select就会停止阻塞,直接返回,换句话说,当子进程收到SIGCONT信号后,将进程的状态更改为Running,意味着指定的阻塞 timeout时间失效,将会立即返回,返回的时候connect还处于第一次握手EINPROGRESS的状态,所以此时获取到的错误就是Operation now in progress ,而命令行下不存在进程切换发送SIGSTOP和SIGCONT信号的情况,所以它会阻塞直到超时,超时时connect的错误状态已经改为110(连接超时),所以抛出来的错误就是 Connection Refused!

不知道这算不算一个Bug。

本打算从linux源码来证明这个问题,但是时间有限,所以暂时不能提供这个证明,后续我会在我博客再次跟踪从linux系统层来证明,想了解的可以关注下。

解决方案

1、修改php源码将poll操作改为while(poll(..)),直到脚本执行超时,这个办法跟libcurl的select方案相似,但比较有风险,因为php的代码量大,调用此函数的地方很多,也不知道作者用意何在,如果修改代码可能会产生不知道的错误。

2、直接采用curl的方式进行连接

3、关闭slowlog慢日志,这个也是推荐的一种方式,不存在父子进程切换,所以也就不会出现这个问题,阅读fpm源码时发现,进行 慢日志检测、进程切换、抛出trace信息、OP等都是是比较消耗性能的,所以从这个角度,也应该关闭sloglog。

已经将这个提交到php的bug系统中,等待回复:

https://bugs.php.net/bug.php?id=67471

原文出处:http://www.imsiren.com/archives/1104