nginx -s reload header image

Nginx debug 日志分析:reload 过程发生了什么

最近在研究 Nginx 源码。我把 Nginx 的 debug 日志给开了,看一看 reload 流程产生的日志都有哪些,并对源码进行简单阅读,以期对 Nginx 的 reload 流程产生一个感性认知。

两点说明:

(一) 为了叙述方便,部分日志做了删减、顺序调整;

(二) 为了便于记忆与理解,日志中的进程号都被我做了修改,约定如下:

  • 4000:触发信号的 nginx -s reload 进程
  • 4100:master 进程
  • 5000:旧 worker 进程
  • 5001:新 worker 进程

日志结构

一条典型的日志长这样:

2022/11/20 02:31:09 [notice] 4000#0: signal process started

从左到右依次是本地时间、日志等级、当前 PID、当前线程号、日志正文。如果是与某一条连接有关联的,还会在线程号后边打印连接号(ngx_connection 在连接池中的下标),如下边的 *3

2022/11/20 02:31:39 [debug] 5000#0: *3 open index "/usr/local/nginx/html/index.html"

日志流程分析

信号处理进程

2022/11/20 02:31:09 [notice] 4000#0: signal process started

这一日志发生在 ngx_signal_process 函数中。这个函数的调用发生在主函数完成参数解析、配置解析、模块初始化、ngx_cycle 结构初始化等步骤之后(源码见 /src/core/nginx.c#L334)。除了提到的这些步骤,最终完成的事情就只是从 nginx.pid 中读取 master 进程的 PID,然后向其发送相应的信号,仅此而已。所以可以看到后边就再也没有出现 4000 这个进程。

新旧 worker 的切换

2022/11/20 02:31:10 [notice] 4100#0: start worker processes
2022/11/20 02:31:10 [debug] 4100#0: channel 4:5
2022/11/20 02:31:10 [notice] 4100#0: start worker process 5001
2022/11/20 02:31:10 [debug] 4100#0: pass channel s:1 pid:5001 fd:4 to s:0 pid:5000 fd:3
2022/11/20 02:31:10 [debug] 4100#0: child: 0 5000 e:0 t:0 d:0 r:1 j:0
2022/11/20 02:31:10 [debug] 4100#0: child: 1 5001 e:0 t:0 d:0 r:1 j:1
2022/11/20 02:31:10 [debug] 4100#0: sigsuspend
2022/11/20 02:31:10 [notice] 4100#0: signal 17 (SIGCHLD) received from 5000
2022/11/20 02:31:10 [notice] 4100#0: worker process 5000 exited with code 0
2022/11/20 02:31:10 [debug] 4100#0: shmtx forced unlock
2022/11/20 02:31:10 [debug] 4100#0: wake up, sigio 0
2022/11/20 02:31:10 [debug] 4100#0: reap children
2022/11/20 02:31:10 [debug] 4100#0: child: 0 5000 e:1 t:1 d:0 r:1 j:0
2022/11/20 02:31:10 [debug] 4100#0: pass close channel s:0 pid:5000 to:5001
2022/11/20 02:31:10 [debug] 4100#0: child: 1 5001 e:0 t:0 d:0 r:1 j:0
2022/11/20 02:31:10 [debug] 4100#0: sigsuspend

这段逻辑主要在 ngx_start_worker_processes 函数开始:

static void
ngx_start_worker_processes(ngx_cycle_t *cycle, ngx_int_t n, ngx_int_t type)
{
    ngx_int_t  i;

    ngx_log_error(NGX_LOG_NOTICE, cycle->log, 0, "start worker processes");

    for (i = 0; i < n; i++) {

        ngx_spawn_process(cycle, ngx_worker_process_cycle,
                          (void *) (intptr_t) i, "worker process", type);

        ngx_pass_open_channel(cycle);
    }
}

参数 n 就是需要启动的 worker 进程数,这里循环 n 次调用 ngx_spawn_processngx_pass_open_channel

channel 4:5 这一行日志发生在 ngx_spawn_process 中,为 socketpair 得到的 socket fd 对(可双向通信)。随后此函数调用 fork 创建子进程并打印出日志:

ngx_process_slot = s;

pid = fork();

switch (pid) {

case -1:
    ngx_log_error(NGX_LOG_ALERT, cycle->log, ngx_errno,
                  "fork() failed while spawning \"%s\"", name);
    ngx_close_channel(ngx_processes[s].channel, cycle->log);
    return NGX_INVALID_PID;

case 0:
    ngx_parent = ngx_pid;
    ngx_pid = ngx_getpid();
    proc(cycle, data);
    break;

default:
    break;
}

ngx_log_error(NGX_LOG_NOTICE, cycle->log, 0, "start %s %P", name, pid);

ngx_processes[s].pid = pid;
ngx_processes[s].exited = 0;

完成子进程的创建后,继续往下走,来到 ngx_pass_open_channel 函数。这个函数从 ngx_process_slot 这个下标中读取出新进程的相关信息,并遍历所有已有的子进程,调用 ngx_write_channel 向其发送下边这段数据:

ngx_channel_t  ch;

ngx_memzero(&ch, sizeof(ngx_channel_t));

ch.command = NGX_CMD_OPEN_CHANNEL;
ch.pid = ngx_processes[ngx_process_slot].pid;
ch.slot = ngx_process_slot;
ch.fd = ngx_processes[ngx_process_slot].channel[0];

对于这段数据的接收方,数据处理的流程发生在 ngx_channel_handler 函数中。此函数收到 NGX_CMD_OPEN_CHANNEL 命令之后,会将对应的 pidfd 等信息放置到自身内存中,这样就完成了将新进程的 socketpair fd 传递到各个旧进程的过程。

随后的 child: 0 5000 e:0 t:0 d:0 r:1 j:0child: 1 5001 e:0 t:0 d:0 r:1 j:1 均发生在 ngx_signal_worker_processes 函数中。各个字段含义如下:

ngx_log_debug7(NGX_LOG_DEBUG_EVENT, cycle->log, 0,
                "child: %i %P e:%d t:%d d:%d r:%d j:%d",
                i,
                ngx_processes[i].pid,
                ngx_processes[i].exiting,
                ngx_processes[i].exited,
                ngx_processes[i].detached,
                ngx_processes[i].respawn,
                ngx_processes[i].just_spawn);

注意到 5001,也就是新 workerjust_spawn 字段为 1,这能让其在后续发送信号时被跳过,进而避免被误杀:

for (i = 0; i < ngx_last_process; i++) {
    // ... 省略中间的代码 ...

    if (ngx_processes[i].just_spawn) {
        ngx_processes[i].just_spawn = 0;
        continue;
    }

    // ... 省略中间的代码 ...

    ngx_log_debug2(NGX_LOG_DEBUG_CORE, cycle->log, 0,
                    "kill (%P, %d)", ngx_processes[i].pid, signo);

    if (kill(ngx_processes[i].pid, signo) == -1) {
        err = ngx_errno;
        ngx_log_error(NGX_LOG_ALERT, cycle->log, err,
                        "kill(%P, %d) failed", ngx_processes[i].pid, signo);

        if (err == NGX_ESRCH) {
            ngx_processes[i].exited = 1;
            ngx_processes[i].exiting = 0;
            ngx_reap = 1;
        }

        continue;
    }
}

各个旧 worker 收到信号之后,将不再处理新请求,并在所有已有请求处理完成之后退出(我记得有个退出超时强制杀死的设定,但一时半会找不到代码了)。

现在,master 重新进入 sigsuspend 状态,等待信号的唤醒。可以看到,因为我本地的 Nginx 非常空闲,master 进程很快就收到 SIGCHLD 信号:

2022/11/20 02:31:10 [debug] 4100#0: sigsuspend
2022/11/20 02:31:10 [notice] 4100#0: signal 17 (SIGCHLD) received from 5000
2022/11/20 02:31:10 [notice] 4100#0: worker process 5000 exited with code 0

收到该信号后,master 进程会进入 ngx_reap_children 完成对旧 worker 的清理工作。清理完成后再次进入 sigsuspend 状态等待新信号的来临:

2022/11/20 02:31:10 [debug] 4100#0: shmtx forced unlock
2022/11/20 02:31:10 [debug] 4100#0: wake up, sigio 0
2022/11/20 02:31:10 [debug] 4100#0: reap children
2022/11/20 02:31:10 [debug] 4100#0: child: 0 5000 e:1 t:1 d:0 r:1 j:0
2022/11/20 02:31:10 [debug] 4100#0: pass close channel s:0 pid:5000 to:5001
2022/11/20 02:31:10 [debug] 4100#0: child: 1 5001 e:0 t:0 d:0 r:1 j:0
2022/11/20 02:31:10 [debug] 4100#0: sigsuspend

workerepoll 事件注册

2022/11/20 02:31:10 [debug] 5001#0: notify eventfd: 11
2022/11/20 02:31:10 [debug] 5001#0: testing the EPOLLRDHUP flag: success
2022/11/20 02:31:10 [debug] 5001#0: epoll add event: fd:6 op:1 ev:00002001
2022/11/20 02:31:10 [debug] 5001#0: epoll add event: fd:5 op:1 ev:00002001
2022/11/20 02:31:10 [debug] 5001#0: setproctitle: "nginx: worker process"
2022/11/20 02:31:10 [debug] 5001#0: worker cycle

一些内存池相关的日志被我隐去。

首先遇到的 notify eventfd: 11 来自 ngx_epoll_notify_init 函数,这一机制往 epoll 中注册了 notify_fd 的读事件,并由 ngx_epoll_notify_handler 进行可读事件的处理。被用于 event 模块的 notify 钩子中:

static ngx_event_module_t  ngx_epoll_module_ctx = {
    &epoll_name,
    ngx_epoll_create_conf,               /* create configuration */
    ngx_epoll_init_conf,                 /* init configuration */

    {
        ngx_epoll_add_event,             /* add an event */
        ngx_epoll_del_event,             /* delete an event */
        ngx_epoll_add_event,             /* enable an event */
        ngx_epoll_del_event,             /* disable an event */
        ngx_epoll_add_connection,        /* add an connection */
        ngx_epoll_del_connection,        /* delete an connection */
#if (NGX_HAVE_EVENTFD)
        ngx_epoll_notify,                /* trigger a notify */
#else
        NULL,                            /* trigger a notify */
#endif
        ngx_epoll_process_events,        /* process the events */
        ngx_epoll_init,                  /* init the events */
        ngx_epoll_done,                  /* done the events */
    }
};

目前全局搜索仅搜到 ngx_thread_pool_handler 这一处用法,暂且按下不表。

随后的日志显示,某段逻辑添加了两个 epoll 事件,关联的 fd 通过 /proc/5001/fd 可以观察得到是两个 socket。至于是什么的 socket,从日志中暂时分析不出来,大概率就是 Nginx 监听的端口。

随后,setproctitle 设置进程名称之后就进入了 worker 进程的主循环 worker cycle

static void
ngx_worker_process_cycle(ngx_cycle_t *cycle, void *data)
{
    ngx_int_t worker = (intptr_t) data;

    ngx_process = NGX_PROCESS_WORKER;
    ngx_worker = worker;

    ngx_worker_process_init(cycle, worker);

    ngx_setproctitle("worker process");

    for ( ;; ) {

        if (ngx_exiting) {
            if (ngx_event_no_timers_left() == NGX_OK) {
                ngx_log_error(NGX_LOG_NOTICE, cycle->log, 0, "exiting");
                ngx_worker_process_exit(cycle);
            }
        }

        ngx_log_debug0(NGX_LOG_DEBUG_EVENT, cycle->log, 0, "worker cycle");

        ngx_process_events_and_timers(cycle);

        if (ngx_terminate) {
            ngx_log_error(NGX_LOG_NOTICE, cycle->log, 0, "exiting");
            ngx_worker_process_exit(cycle);
        }

        if (ngx_quit) {
            ngx_quit = 0;
            ngx_log_error(NGX_LOG_NOTICE, cycle->log, 0,
                          "gracefully shutting down");
            ngx_setproctitle("worker process is shutting down");

            if (!ngx_exiting) {
                ngx_exiting = 1;
                ngx_set_shutdown_timer(cycle);
                ngx_close_listening_sockets(cycle);
                ngx_close_idle_connections(cycle);
            }
        }

        if (ngx_reopen) {
            ngx_reopen = 0;
            ngx_log_error(NGX_LOG_NOTICE, cycle->log, 0, "reopening logs");
            ngx_reopen_files(cycle, -1);
        }
    }
}

其中最核心的是对 ngx_process_events_and_timers 的调用,这个函数完成了事件驱动与定时器机制,正是这两个机制推动着 Nginx 的运行。除此之外,主循环中就只剩下对几个全局标志位的处理:ngx_exitingngx_terminatengx_quitngx_reopen 等。他们一般由 master 发送过来的相应信号所触发。

worker 删除旧 workerchannel 信息

2022/11/20 02:31:10 [debug] 5001#0: epoll: fd:5 ev:0001 d:00007FDCE72480F0
2022/11/20 02:31:10 [debug] 5001#0: channel handler
2022/11/20 02:31:10 [debug] 5001#0: channel: 32
2022/11/20 02:31:10 [debug] 5001#0: channel command: 2
2022/11/20 02:31:10 [debug] 5001#0: close channel s:0 pid:5000 our:5000 fd:3
2022/11/20 02:31:10 [debug] 5001#0: channel: -2
2022/11/20 02:31:10 [debug] 5001#0: timer delta: 764
2022/11/20 02:31:10 [debug] 5001#0: worker cycle

虽然出于行文逻辑的关系我将其放置到了最后,但其实这段逻辑发生的时刻应该是在 masterngx_reap_children 函数完成调用之后。因为旧 worker 已经退出了,这里需要通知各个进程将旧 workerchannel 信息删除。其中 channel command: 2 这段日志,2 的含义即为 NGX_CMD_CLOSE_CHANNEL

题图来自 Photo by Markus Spiske on Unsplash

发表回复

您的电子邮箱地址不会被公开。 必填项已用*标注

此站点使用Akismet来减少垃圾评论。了解我们如何处理您的评论数据