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

问题描述:

前两天老大跟我讲了一个他们原来遇到的问题,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