|
|
php.net | support | documentation | report a bug | advanced search | search howto | statistics | random bug | login |
[2018-07-10 02:28 UTC] mnikulin at plesk dot com
Description:
------------
I caught php-fpm in a weird state while I was trying to look closer at another issue (#74083 "master PHP-fpm is stopped on multiple reloads"). The aim is to check stability when several requests for reload (kill -USR2) arrive in parallel. In my case PHP-FPM process failed into partially working state.
Likely it is hard to reproduce the same state. In my opinion even completely died process is not so terrible due to killed service is easier to notice.
php-fpm: Installed: 1:7.0+35ubuntu6.1
configuration:
ubuntu default "www" dynamic pool with pm.start_servers = 2
~30 other on-demand pools
Test script:
---------------
for i in {1..10} ; do ( systemctl reload php7.0-fpm ; echo "$i status $?" ; ) & done
Expected result:
----------------
Signals (SIGUSR1, SIGUSR2, SIGQUIT, SIGTERM) are properly masked while critical operations at initialization and shutdown stages are performed. So daemon is running after reload request (SIGUSR2), it reloads configuration and is responsive to requests on all configured sockets.
Actual result:
--------------
- PHP-FPM daemon is running.
- Requests handled by most of the pools fail with 502 code.
- Previously configured sockets are open.
- "www" pool is working, however no new children are spawn in response to increased load.
- The only result of more attempts to reload are additional "[06-Jul-2018 12:06:34] NOTICE: Reloading in progress ..." log entries.
- Changes in configuration files are ignored (e.g. no new sockets become open).
ps xauwf
root 15007 0.0 3.2 368532 32976 ? Ss Jul05 0:05 php-fpm: master process (/etc/php/7.0/fpm/php-fpm.conf)
www-data 7535 0.0 0.6 368292 6668 ? S 11:17 0:00 \_ php-fpm: pool www
www-data 7539 0.0 0.6 368292 6668 ? S 11:17 0:00 \_ php-fpm: pool www
systemd is regularly notified
strace:
epoll_wait(39, [], 301, 553) = 0
clock_gettime(CLOCK_MONOTONIC, {89876, 465329966}) = 0
socket(PF_LOCAL, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 40
getsockopt(40, SOL_SOCKET, SO_SNDBUF, [212992], [4]) = 0
setsockopt(40, SOL_SOCKET, SO_SNDBUFFORCE, [8388608], 4) = 0
sendmsg(40, {msg_name(21)={sa_family=AF_LOCAL, sun_path="/run/systemd/notify"}, msg_iov(1)=[{"READY=1\nSTATUS=Processes active:"..., 84}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 84
close(40) = 0
clock_gettime(CLOCK_MONOTONIC, {89876, 467799731}) = 0
Attempt to reload once more:
strace
12:01:53.155389 clock_gettime(CLOCK_MONOTONIC, {90970, 718593604}) = 0
12:01:53.155618 epoll_wait(39, 0x562314725f70, 301, 338) = -1 EINTR (Interrupted system call)
12:01:53.290441 --- SIGUSR2 {si_signo=SIGUSR2, si_code=SI_USER, si_pid=8841, si_uid=0} ---
12:01:53.290519 write(7, "2", 1) = 1
12:01:53.290626 rt_sigreturn({mask=[]}) = -1 EINTR (Interrupted system call)
12:01:53.290762 clock_gettime(CLOCK_MONOTONIC, {90970, 853986574}) = 0
12:01:53.291297 clock_gettime(CLOCK_MONOTONIC, {90970, 854429547}) = 0
12:01:53.291401 clock_gettime(CLOCK_MONOTONIC, {90970, 854526970}) = 0
12:01:53.291499 epoll_wait(39, [{EPOLLIN, {u32=331364736, u64=94708655208832}}], 301, 203) = 1
12:01:53.291600 read(6, "2", 1) = 1
12:01:53.291712 gettimeofday({1530856913, 291798}, NULL) = 0
12:01:53.291867 write(5, "[06-Jul-2018 12:01:53] NOTICE: R"..., 57) = 57
12:01:53.292071 read(6, 0x7ffee5c6fd77, 1) = -1 EAGAIN (Resource temporarily unavailable)
12:01:53.292511 clock_gettime(CLOCK_MONOTONIC, {90970, 855637928}) = 0
12:01:53.292618 clock_gettime(CLOCK_MONOTONIC, {90970, 855745156}) = 0
12:01:53.291297 clock_gettime(CLOCK_MONOTONIC, {90970, 854429547}) = 0
12:01:53.291401 clock_gettime(CLOCK_MONOTONIC, {90970, 854526970}) = 0
12:01:53.291499 epoll_wait(39, [{EPOLLIN, {u32=331364736, u64=94708655208832}}], 301, 203) = 1
12:01:53.291600 read(6, "2", 1) = 1
12:01:53.291712 gettimeofday({1530856913, 291798}, NULL) = 0
12:01:53.291867 write(5, "[06-Jul-2018 12:01:53] NOTICE: R"..., 57) = 57
12:01:53.292071 read(6, 0x7ffee5c6fd77, 1) = -1 EAGAIN (Resource temporarily unavailable)
12:01:53.292511 clock_gettime(CLOCK_MONOTONIC, {90970, 855637928}) = 0
Internally it is in the reload state
(gdb) p fpm_state
$1 = 2
# FPM_PCTL_STATE_RELOADING
There was an attempt to send SIGTERM to all children, but SIGKILL was not sent for some reason:
(gdb) p fpm_signal_sent
$2 = 15
# 15) SIGTERM
www pool is in the list, child count and their PIDs are correct
(gdb) p fpm_globals.running_children
$3 = 2
(gdb) p *$pwww
$37 = {next = 0x0, config = 0x562314721a40, user = 0x5623147247b0 "www-data", home = 0x5623147247d0 "/var/www", listen_address_domain = FPM_AF_UNIX, listening_socket = 38, set_uid = 33, set_gid = 33, socket_uid = 33, socket_gid = 33,
socket_mode = 432, children = 0x562314727bc0, running_children = 2, idle_spawn_rate = 1, warn_max_children = 0, scoreboard = 0x7f8587748000, log_fd = -1, limit_extensions = 0x562314721ec0, ondemand_event = 0x0, socket_event_set = 0}
(gdb) p *$pwww->children
$38 = {prev = 0x0, next = 0x562314727ac0, started = {tv_sec = 88316, tv_usec = 284870}, wp = 0x5623147219b0, ev_stdout = {fd = 0, timeout = {tv_sec = 0, tv_usec = 0}, frequency = {tv_sec = 0, tv_usec = 0}, callback = 0x0, arg = 0x0,
flags = 0, index = 0, which = 0}, ev_stderr = {fd = 0, timeout = {tv_sec = 0, tv_usec = 0}, frequency = {tv_sec = 0, tv_usec = 0}, callback = 0x0, arg = 0x0, flags = 0, index = 0, which = 0}, shm_slot_i = 0, fd_stdout = -1,
fd_stderr = -1, tracer = 0x0, slow_logged = {tv_sec = 0, tv_usec = 0}, idle_kill = 0, pid = 7539, scoreboard_i = 1}
(gdb) p *$pwww->children->next
$39 = {prev = 0x562314727bc0, next = 0x0, started = {tv_sec = 88316, tv_usec = 284478}, wp = 0x5623147219b0, ev_stdout = {fd = 0, timeout = {tv_sec = 0, tv_usec = 0}, frequency = {tv_sec = 0, tv_usec = 0}, callback = 0x0, arg = 0x0,
flags = 0, index = 0, which = 0}, ev_stderr = {fd = 0, timeout = {tv_sec = 0, tv_usec = 0}, frequency = {tv_sec = 0, tv_usec = 0}, callback = 0x0, arg = 0x0, flags = 0, index = 0, which = 0}, shm_slot_i = 0, fd_stdout = -1,
fd_stderr = -1, tracer = 0x0, slow_logged = {tv_sec = 0, tv_usec = 0}, idle_kill = 0, pid = 7535, scoreboard_i = 0}
pctl_event has some reasonable values of its fields, not trash
$40 = {fd = -1, timeout = {tv_sec = 88317, tv_usec = 284972}, frequency = {tv_sec = 1, tv_usec = 0}, callback = 0x5623138b8580 <fpm_pctl_action>, arg = 0x0, flags = 0, index = -1, which = 1}
However this handler is not in the timer queue
(gdb) p *fpm_event_queue_timer
$43 = {prev = 0x0, next = 0x562314727ce0, ev = 0x562313c03d00 <heartbeat>}
(gdb) p *fpm_event_queue_timer->next
$44 = {prev = 0x562314727d50, next = 0x0, ev = 0x562313c03a80 <heartbeat>}
(gdb) p *fpm_event_queue_timer->ev
$45 = {fd = -1, timeout = {tv_sec = 347438, tv_usec = 829245}, frequency = {tv_sec = 10, tv_usec = 0}, callback = 0x5623138bea40 <fpm_systemd_heartbeat>, arg = 0x0, flags = 4, index = -1, which = 1}
(gdb) p *fpm_event_queue_timer->next->ev
$46 = {fd = -1, timeout = {tv_sec = 347430, tv_usec = 49454}, frequency = {tv_sec = 1, tv_usec = 0}, callback = 0x5623138b85a0 <fpm_pctl_perform_idle_server_maintenance_heartbeat>, arg = 0x0, flags = 4, index = -1, which = 1}
I have not found any obvious place where a system call can be interrupted in such way that next timer is not arranged. I do not see a way to remove an event from the queue without firing the scheduled handler at first as well. It is quite strange that SIGKILL was not send to the running children.
It is really terrible that systemd believes that fpm service is a healthy state and it is even worser that some pools serve incoming request. It is hard to detect such case, looks like all pools have to be checked otherwise some sites may stop working. Reload does not cure the problem, restart is required and it has to be diagnosed somehow.
Patchesphp-76601_kill-not-rescheduled_7.2.11_2018-09-28.patch (last revision 2018-10-16 04:34 UTC by mnikulin at plesk dot com)php-fpm-76601-avoid-child-ignorance_7.2.11_2018-09-28.patch (last revision 2018-10-16 04:32 UTC by mnikulin at plesk dot com) php-76601_kill-not-rescheduled_2018-07-11.patch (last revision 2018-07-11 08:09 UTC by mnikulin at plesk dot com) Pull Requests
Pull requests:
HistoryAllCommentsChangesGit/SVN commits
|
|||||||||||||||||||||||||||||||||||||
Copyright © 2001-2024 The PHP GroupAll rights reserved. |
Last updated: Thu Nov 21 08:01:29 2024 UTC |
I have traced down a part of the problem. SIGKILL is not sent to FPM workers at all. The open question is why SIGQUIT and SIGTERM are not enough sometimes. Maybe kill() of a child is interrupted by SIGUSR2 received by the master process and check for EINTR is required after the kill() call. Missed SIGQUIT and SIGTERM are hardly can be desirable, but ensuring SIGKILL delivery allows to avoid process stuck in some intermediate semi-functional state. The problem is that SIGTERM and SIGKILL share the same fpm_event_s structure and scheduled through the same event queue. The handler is invoked synchronously and it is unable to reschedule itself fpm_process_ctl.c:202 static void fpm_pctl_action_next() fpm_pctl_timeout_set(timeout); due to fpm_events.c:156 static int fpm_event_queue_add() if (fpm_event_queue_isset(*queue, ev)) { return 0; } The timer is removed from the queue *after* completion of the handler fpm_events.c:440 void fpm_event_loop() } else { /* delete the event */ Possible solution is to mark the event as persistent (see the patch). It helps even in the case when some signals from previous iteration are not delivered, the cost is another second before reexec. With the patch from https://bugs.php.net/bug.php?id=74083 PHP-FPM becomes immune to SIGUSR2 flood.SIGQUIT and SIGTERM may be missed by children just after reload due to fpm_signals.c:169 static void sig_handler() if (fpm_globals.parent_pid != getpid()) { /* prevent a signal race condition when child process have not set up it's own signal handler yet */ return; } Looks like this measure is not a solution for all cases. sigprocmask() SIG_BLOCK/SIG_UNBLOCK may be added around the fork() call to fpm_children.c:400 int fpm_children_make() pid = fork();