fpm开启slowlog Fsockopen出现Operation now in progress的
问题描述： 前两天老大跟我讲了一个他们原来遇到的问题，php采用fastcgi的方式启动，并且打开slow log日志，当调用fsockopen读取一个连接，这个连接超过了slowlog设置的时间，fpm进程就会抛出一个warning，用来记录关于这个满请求的一些基本信息。 详细描述
问题描述：
前两天老大跟我讲了一个他们原来遇到的问题，php采用fastcgi的方式启动，并且打开slow log日志，当调用fsockopen读取一个连接，这个连接超过了slowlog设置的时间，fpm进程就会抛出一个warning，用来记录关于这个满请求的一些基本信息。
详细描述如下：
假如我们设置的slowlog 的时间为5s，而通过fsockopen去访问一个不存在的ip和端口，连接超时时间设为10s，代码如下：
图1
我们去访问一个不存在的IP和端口，通过浏览器访问，在错误日志里面我们会收到两个warning，一个是fpm抛出来的slowlog，另外一个是PHP Warning:? fsockopen(): unable to connect to 2.3.2.1:9999 (Operation now in progress)。
正常情况来讲，fsockopen连接出错应该出现Connection timed out，但事实并非如此，似乎fpm抛出脚本超时之后就结束了，为什么？
后来在命令行下运行该脚本，却没有出现Operation now in progress,是fsockopen Connection timed out的错误，这就说明并非是fsockopen的问题，发生在fpm上。
本次问题追踪分为两个部分，本文主要介绍fpm的运行机制，关于答案请看
fpm开启slowlog Fsockopen出现Operation now in progress的问题追踪二
问题追踪
因为是在线上出现的问题，线上php的版本是5.2.8，我本地装的是php 5.3，经过测试，php 5.3也有同样的问题。
Operation now in progress 这个异常，本身是没有任何问题的，它是非阻塞connect的一个返回值，该值表明connect正在进行中，等等，非阻塞？可能问题就出现在这里，
如果使用非阻塞connect,后面应该通过调用select，检查select的写事件，一旦返回，则说明有可用数据接收。
要定位这个问题，似乎没有别的办法，只能去看fpm的源码了，在翻看源码时也确实定位到了问题根源。
不过要弄清这个问题，我们先要明白fpm的工作流程。
FPM工作流程
简述
Fpm是多进程的程序，fpm启动时它通过一个master，fork出 max_children为工作进程，并把子进程的进程id及其他相关信息保存到 struct fpm_worker_pool_s指向的children指针中。
工作进程用来接收网络请求，当有链接通过nginx问时，nginx发现我们访问的是php文件，它就会把该文件的绝对目录通过fastcgi_pass指定的网络端口传递到fpm的9000端口，
fpm接收到该请求，并从children中查找空闲进程,通过该空闲进程去处理请求。
详细介绍
图2
在翻看fpm源码过程当中，发现主进程监听的不是网络事件，而是时间事件，现在的时间超过事件所设定的时间后，则会触发fpm_got_signal函数，该函数通过管道sp[2]来进行主进程和子进程的通信，它主要用来处理SIGCHLD、SIGINT、SIGTERM、SIGQUIT、SIGUSR1、SIGUSR2这几个信号，不同的信号有不同的处理逻辑：
代码段1：
static void fpm_got_signal(struct fpm_event_s *ev, short which, void *arg) /* {{{ */
{
char c;
int res, ret;
//fd是sp[2]管道
int fd = ev->fd;
........
switch (c) {
case 'C' : /* SIGCHLD */
zlog(ZLOG_DEBUG, "received SIGCHLD");
//调用waitpid，等待子进程产生SIGCHLD
fpm_children_bury();
break;
case 'I' : /* SIGINT */
zlog(ZLOG_DEBUG, "received SIGINT");
zlog(ZLOG_NOTICE, "Terminating ...");
fpm_pctl(FPM_PCTL_STATE_TERMINATING, FPM_PCTL_ACTION_SET);
break;
case 'T' : /* SIGTERM */
zlog(ZLOG_DEBUG, "received SIGTERM");
zlog(ZLOG_NOTICE, "Terminating ...");
fpm_pctl(FPM_PCTL_STATE_TERMINATING, FPM_PCTL_ACTION_SET);
break;
case 'Q' : /* SIGQUIT */
zlog(ZLOG_DEBUG, "received SIGQUIT");
zlog(ZLOG_NOTICE, "Finishing ...");
fpm_pctl(FPM_PCTL_STATE_FINISHING, FPM_PCTL_ACTION_SET);
break;
........
}
下面来看一个无比复杂的图：
图3
为了搞清楚细节，阅读了大部分fpm源码，画出了上面的图，很复杂，
看不懂没关系，我根据源码来慢慢讲
Fpm的main函数在sapi/fpm/fpm/fpm_main.c 1548行，
上面一部分都可以忽略，用来处理fpm启动参数和php环境的初始化，来看1824行，
代码段2：
int main(int argc,char **argv){
.........
//fpm初始化
if (0 > fpm_init(argc, argv, fpm_config ? fpm_config : CGIG(fpm_config), fpm_prefix, fpm_pid, test_conf, php_allow_to_run_as_root, force_daemon)) {
//出错-----
if (fpm_globals.send_config_pipe[1]) {
int writeval = 0;
zlog(ZLOG_DEBUG, "Sending \"0\" (error) to parent via fd=%d", fpm_globals.send_config_pipe[1]);
write(fpm_globals.send_config_pipe[1], &writeval, sizeof(writeval));
close(fpm_globals.send_config_pipe[1]);
}
return FPM_EXIT_CONFIG;
}
.........
}
Fpm_init进行了初始化，也就是图中A的位置，它的主要工作正如图3所标示，下面是主要代码
代码段3：
int fpm_init(int argc, char **argv, char *config, char *prefix, char *pid, int test_conf, int run_as_root, int force_daemon) /* {{{ */
{
..........
if (0 > fpm_php_init_main() ||
0 > fpm_stdio_init_main() ||//初始化io
0 > fpm_conf_init_main(test_conf, force_daemon) ||//加载fpm 配置文件
0 > fpm_unix_init_main() ||
0 > fpm_scoreboard_init_main() ||
0 > fpm_pctl_init_main() ||
0 > fpm_env_init_main() ||
0 > fpm_signals_init_main() ||//注册进程信号的callback，很关键
0 > fpm_children_init_main() ||
0 > fpm_sockets_init_main() ||//socket 初始化
0 > fpm_worker_pool_init_main() ||//工作池初始化
0 > fpm_event_init_main()) {//事件IO初始化
if (fpm_globals.test_successful) {
exit(FPM_EXIT_OK);
} else {
zlog(ZLOG_ERROR, "FPM initialization failed");
return -1;
}
}
if (0 > fpm_conf_write_pid()) {//写入fpm 的进程id
zlog(ZLOG_ERROR, "FPM initialization failed");
return -1;
}
..........
}
主要工作已经注释到源码里，这里不细谈，
紧接着在 main函数中 有一个fpm_run函数
代码段4：
.......
//fcgi_fd 是socket句柄
fcgi_fd = fpm_run(&max_requests);
parent = 0;
//子进程继续往下执行，父进程会在fpm_run中while
/* onced forked tell zlog to also send messages through sapi_cgi_log_fastcgi() */
zlog_set_external_logger(sapi_cgi_log_fastcgi);
........
图3里下面部分操作都的封装到这个函数里了
代码段5：
int fpm_run(int *max_requests) /* {{{ */
{
struct fpm_worker_pool_s *wp;
/* create initial children in all pools */
for (wp = fpm_worker_all_pools; wp; wp = wp->next) {
int is_parent;
is_parent = fpm_children_create_initial(wp);
//子进程
if (!is_parent) {
goto run_child;
}
/* handle error */
if (is_parent == 2) {//子进程创建失败
fpm_pctl(FPM_PCTL_STATE_TERMINATING, FPM_PCTL_ACTION_SET);
fpm_event_loop(1);
}
}
/* run event loop forever */
//主进程监听事件
fpm_event_loop(0);
run_child: /* only workers reach this point */
fpm_cleanups_run(FPM_CLEANUP_CHILD);
*max_requests = fpm_globals.max_requests;
///返回socket句柄
return fpm_globals.listening_socket;
}
该函数先创建子进程，把进程相关信息放在struct fpm_worker_pool_s *wp这个指针里，
父进程调用fpm_event_loop（0），子进程直接返回sock句柄，然后继续运行 fpm_main.c 1848之后的代码，进行accept操作；
fpm_event_loop是时间事件监听操作，
代码段6：
void fpm_event_loop(int err) /* {{{ */
{
static struct fpm_event_s signal_fd_event;
/* sanity check */
if (fpm_globals.parent_pid != getpid()) {
return;
}
//注册callback = fpm_got_signal
/**
设置signal_fd_event参数，ev->fd=sp[0]
fpm_signals_get_fd()是管道句柄sp[0]：读;
**/
fpm_event_set(&signal_fd_event, fpm_signals_get_fd(), FPM_EV_READ, &fpm_got_signal, NULL);
fpm_event_add(&signal_fd_event, 0);
/* add timers */
if (fpm_globals.heartbeat > 0) {
//fpm超时检测处理
fpm_pctl_heartbeat(NULL, 0, NULL);
}
.......
while(1){
...............
//wait事件
ret = module->wait(fpm_event_queue_fd, timeout);
.............
while (q) {
fpm_clock_get(&now);
if (q->ev) {
if (timercmp(&now, &q->ev->timeout, >) || timercmp(&now, &q->ev->timeout, ==)) {
//处理信号SIGCHILD fpm_got_signal
fpm_event_fire(q->ev);
.............
}
}
}
}
注册fpm_got_signal回调函数，该函数会在下面的监听时间事件时执行。
注意看fpm_pctl_heartbeat函数，这里就是执行慢脚本记录的地方，跟进去看看，
fpm_process_ctl.c 442行
代码段7：
void fpm_pctl_heartbeat(struct fpm_event_s *ev, short which, void *arg) /* {{{ */
{
static struct fpm_event_s heartbeat;
struct timeval now;
if (fpm_globals.parent_pid != getpid()) {
return; /* sanity check */
}
if (which == FPM_EV_TIMEOUT) {
fpm_clock_get(&now);//获取时间
//检测slowlog，
fpm_pctl_check_request_timeout(&now);
return;
}
/* ensure heartbeat is not lower than FPM_PCTL_MIN_HEARTBEAT */
fpm_globals.heartbeat = MAX(fpm_globals.heartbeat, FPM_PCTL_MIN_HEARTBEAT);
/* first call without setting to initialize the timer */
zlog(ZLOG_DEBUG, "heartbeat have been set up with a timeout of %dms", fpm_globals.heartbeat);
fpm_event_set_timer(&heartbeat, FPM_EV_PERSIST, &fpm_pctl_heartbeat, NULL);
fpm_event_add(&heartbeat, fpm_globals.heartbeat);
}
调用了fpm_ptcl_check_request_timeout函数，可能会发现只有witch== FPM_EV_TIMEOUT的时候，才会调用的，上面的函数传的witch是0 ，它应该是执行不了的，是的，第一次是不会执行的，首次执行会调用463和464行，用来注册时间事件，把fpm_ptcl_hearbeat作为一个回调函数来使用的，所以这里并不影响我们，继续查看fpm_pctl_check_request_timeout函数
代码段8：
static void fpm_pctl_check_request_timeout(struct timeval *now) /* {{{ */
{
........
//检测slow log
fpm_request_check_timed_out(child, now, terminate_timeout, slowlog_timeout);
..........
}
又是一个调用，fpm_request_check_timed_out，继续跟
fpm_request.c 230行，终于到了，
代码段9：
void fpm_request_check_timed_out(struct fpm_child_s *child, struct timeval *now, int terminate_timeout, int slowlog_timeout) /* {{{ */
{
.........
#if HAVE_FPM_TRACE
/**
检测子进程运行状态和时间
**/
if (child->slow_logged.tv_sec == 0 && slowlog_timeout &&
proc.request_stage == FPM_REQUEST_EXECUTING && tv.tv_sec >= slowlog_timeout) {
str_purify_filename(purified_script_filename, proc.script_filename, sizeof(proc.script_filename));
child->slow_logged = proc.accepted;
child->tracer = fpm_php_trace;//注册输出trace信息的callback函数
//暂停子进程
fpm_trace_signal(child->pid);
//记录slow log的日志
zlog(ZLOG_WARNING, "[pool %s] child %d, script '%s' (request: \"%s %s\") executing too slow (%d.%06d sec), logging",
child->wp->config->name, (int) child->pid, purified_script_filename, proc.request_method, proc.request_uri,
(int) tv.tv_sec, (int) tv.tv_usec);
}
else
#endif
if (terminate_timeout && tv.tv_sec >= terminate_timeout) {
str_purify_filename(purified_script_filename, proc.script_filename, sizeof(proc.script_filename));
fpm_pctl_kill(child->pid, FPM_PCTL_TERM);
zlog(ZLOG_WARNING, "[pool %s] child %d, script '%s' (request: \"%s %s\") execution timed out (%d.%06d sec), terminating",
child->wp->config->name, (int) child->pid, purified_script_filename, proc.request_method, proc.request_uri,
(int) tv.tv_sec, (int) tv.tv_usec);
}
}
.........
}
这里是关键代码，上面的那个判断是，如果开启了慢日志 && slowlog_timeout&& 当前进程的状态为Running && 进程执行的时间大于我们配置的时间，
slowlog_timeout是php-fpm.conf中配置的request_slowlog_timeout参数，
然后会注册一个callback函数fpm_php_trace，用来在主进程中执行，暂停子进程，最后记录slowlog的日志。
if (terminate_timeout && tv.tv_sec >= terminate_timeout) { 这里开始是中断请求的代码，如果设置了request_terminate_timeout，这里就会被执行。
那上面那个暂停进程是什么意思？为什么要暂停子进程？
暂停子进程的目的，是希望能让父进程获取子进程当前运行时的详细信息，用来打印trace，
现在回到fpm_event_loop函数，来看看这个过程，回到 fpm_event_loop函数
图4
410行是epoll_wait事件，它支持select、poll、epoll
看428行，fpm_event_fire函数，将要执行fpm_got_signal函数，还记得上面说过的一个用来回调的信号处理函数吗？
图5
对就是这里，它将会在产生时间事件的时候被执行：
fpm_events.c 52行图6
fpm_children_bury函数里调用waitpid，
图7
WNOHANG|WUNTRACED的意思是有任何进程被暂停则立即返回，
如果检测到进程被暂停，则会执行fpm_php_trace抛出trace信息到日志中，（fpm_php_trace是上面代码段9注册的callback），最后发送继续运行的信号给子进程。
图8
子进程收到继续运行的信号会，会继续运行fpm_main.c 1848之后的代码，接收用户请求，处理php脚本。
Fpm的执行流程就是这样，很复杂，涉及的代码量很多，需要慢慢看。
Fpm的工作流程大概是明白了，但是上面的问题还没有找到答案，为什么抛出慢脚本的日志后进程就挂了？
这个问题的答案请参看：fpm开启slowlog Fsockopen出现Operation now in progress的问题追踪二
原文出处:http://www.imsiren.com/archives/1088上一篇： php5中的应验合法性的扩展
下一篇： php生成shtml类用法实例_PHP