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