欢迎您访问程序员文章站本站旨在为大家提供分享程序员计算机编程知识！
您现在的位置是： 首页  >  php教程

fpm开启slowlog Fsockopen出现Operation now in progress的

程序员文章站 2024-04-04 16:27:59
...

问题描述： 前两天老大跟我讲了一个他们原来遇到的问题，php采用fastcgi的方式启动，并且打开slow log日志，当调用fsockopen读取一个连接，这个连接超过了slowlog设置的时间，fpm进程就会抛出一个warning，用来记录关于这个满请求的一些基本信息。 详细描述

问题描述：

前两天老大跟我讲了一个他们原来遇到的问题，php采用fastcgi的方式启动，并且打开slow log日志，当调用fsockopen读取一个连接，这个连接超过了slowlog设置的时间，fpm进程就会抛出一个warning，用来记录关于这个满请求的一些基本信息。

详细描述如下：

假如我们设置的slowlog 的时间为5s，而通过fsockopen去访问一个不存在的ip和端口，连接超时时间设为10s，代码如下：

fpm开启slowlog Fsockopen出现Operation now in progress的

图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中查找空闲进程,通过该空闲进程去处理请求。

详细介绍

fpm开启slowlog Fsockopen出现Operation now in progress的

图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;
    ........
}

下面来看一个无比复杂的图：

fpm开启slowlog Fsockopen出现Operation now in progress的

图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函数

fpm开启slowlog Fsockopen出现Operation now in progress的

图4

410行是epoll_wait事件，它支持select、poll、epoll
看428行，fpm_event_fire函数，将要执行fpm_got_signal函数，还记得上面说过的一个用来回调的信号处理函数吗？
fpm开启slowlog Fsockopen出现Operation now in progress的

图5

对就是这里，它将会在产生时间事件的时候被执行：
fpm_events.c 52行
fpm开启slowlog Fsockopen出现Operation now in progress的图6

fpm_children_bury函数里调用waitpid，
fpm开启slowlog Fsockopen出现Operation now in progress的

图7

WNOHANG|WUNTRACED的意思是有任何进程被暂停则立即返回，
如果检测到进程被暂停，则会执行fpm_php_trace抛出trace信息到日志中，（fpm_php_trace是上面代码段9注册的callback），最后发送继续运行的信号给子进程。

fpm开启slowlog Fsockopen出现Operation now in progress的

图8

子进程收到继续运行的信号会，会继续运行fpm_main.c 1848之后的代码，接收用户请求，处理php脚本。

Fpm的执行流程就是这样，很复杂，涉及的代码量很多，需要慢慢看。

Fpm的工作流程大概是明白了，但是上面的问题还没有找到答案，为什么抛出慢脚本的日志后进程就挂了？

这个问题的答案请参看：fpm开启slowlog Fsockopen出现Operation now in progress的问题追踪二

原文出处:http://www.imsiren.com/archives/1088
相关标签： fpm 开启 slowlog Fsockopen 出现 Op

上一篇： SQL语句中SUM与COUNT的区别深入分析_MySQL

下一篇： php中经典方法实现判断多维数组是否为空_PHP

推荐阅读