☰

一段时间后，某些东西“杀死”了我的 Apache-PHP 进程

tag-icon • tag-icon linux networking debian apache-http-server php
一段时间后，某些东西“杀死”了我的 Apache-PHP 进程

我遇到了以下非常奇怪的问题，希望你们能帮助我。如果有任何问题，我会尽力回答。

问题

我有一个装有 Debian 6.0、Apache 2.2.16 和 PHP 5.3.9 的 Web 服务器。不幸的是，没有办法升级这些组件。
有时，在页面加载过程中，对服务器的 HTTP 请求会被中断。它总是持续大约 3 分钟（在 180 到 195 秒之间变化）。脚本会停止，没有任何提示，不会将任何输出发送回客户端，也不会执行服务器端操作。

测试用例

为了弄清问题，请查看以下测试脚本，我可以用它来重现问题。请注意，该服务器上的许多脚本都存在此问题，这些脚本的运行时间超过 3 分钟。

<?php
    echo "Start: ".date('Y-m-d H:i:s')."<br>\n";
    flush(); ob_flush();

    $count = 0;
    while ($count++ < 300) {
        sleep(1);
        echo ".";
        flush(); ob_flush();
    }

    echo "<br>\nFinished: ".date('Y-m-d H:i:s');

它运行 5 分钟，每秒输出一个点。为了重现该问题，我在 3 个不同的浏览器（Chrome、Firefox、IE）中使用 2 个不同的域打开它，这样脚本运行了 6 次。我在每个窗口中启动脚本，每次间隔约 1 秒。

会发生什么

如果出现问题，我只能看到大约 180 个点，但相对于某个绝对时间点。因此，如果第一个脚本在 10:00:00 开始，第二个脚本在 10:00:02 开始，第三个脚本在 10:00:03 开始​​，那么第一个脚本输出 186 个点，第二个脚本输出 184 个点，第三个脚本输出 183 个点。这意味着，所有脚本都在不同的时间开始，但恰好在 10:03:06 结束。

我也尝试过这个脚本file_put_contents()，所以我可以看到，如果脚本不再向客户端发送输出。但即使这样也停止了，所以整个 php 脚本必须在服务器端被终止并且不再执行。

我还注意到，问题并不总是发生。有时我必须花半天时间才能看到效果，有时第一次尝试就会发生。此外，当它发生时，它大多会发生在所有 6 个窗口中，但并非总是如此。有时，前两个窗口在 5 分钟后正常完成，而其他 4 个窗口在 3 分钟左右停止。

我查看了服务器和客户端之间的流量的 tcpdump。当没有更多输出发送时，服务器立即发送“FIN，ACK”。apache
access.log 只显示脚本的开始，在 error.log 中不存在与问题或问题发生时间相关的任何内容。

结论

首先，看起来对服务器的请求或负载是相关的，因为我可以更频繁地看到问题，当许多人 (70) 使用服务器并且许多 cronjobs 正在运行时。
也许是某种网络过载，因此网络崩溃并终止所有连接。但为什么会发生这种情况，有时 4 个窗口中有 2 个完成加载脚本，而其他窗口没有？
我还认为这是由某个 cronjob（服务器上有太多 cronjob）引起的，它每隔 x 分钟就会终止太旧的 apache 脚本。但我找不到一个，这也不能解释，为什么它每次都会发生（当它发生时）大约 3 分钟。此外，其他用户的更多旧 apache 进程仍在运行并且没有被终止。
我排除了客户端的问题，因为我可以在具有不同操作系统和不同浏览器的不同客户端上观察问题。

谢谢

我希望我能够很好地描述我的问题，以便您能给我一些建议，告诉我如何更好地分析问题，问题出在哪里以及如何修复它（无需升级服务器的重要部分）。也许这只是某个地方的神秘设置？
感谢大家读到最后！

有趣的事实：如果脚本没有输出，运行时间超过 3 分钟（因为计算了一些 fe），并且问题发生了，Firefox 大多会认为“嘿，没有输出但完成了？让我们重新加载脚本！”，很少会认为“嘿，没有输出但完成了？我会向用户显示一条空的响应消息”。很好，如果这个脚本背后有一些重要的操作，并且这个操作一次又一次地被执行G

通过你的评论知道事实

仅当请求完成时才会写入 access.log。如果在加载过程中取消，则不存在 access.log 条目。

失败的流程正在得到SIGKILL。

失败的脚本 每 10 秒启动一次测试脚本。时间从 3 分钟到无限长不等（大部分在 3 到 4 分钟之间）。有趣的是：大部分启动的脚本中有 12 个被终止。

通过您的评论进行测试

相隔几秒开始：

chrome_backoffice: Start: 2015-06-11 09:41:46 (cancled at 09:44:56)
..............................................................................................................................................................................................
NO ACCESS LOG ENTRY

chrome_server: Start: 2015-06-11 09:41:49 (cancled at 09:44:56)
...........................................................................................................................................................................................
NO ACCESS LOG ENTRY

firefox_server: Start: 2015-06-11 09:41:51 (cancled at 09:44:56)
.........................................................................................................................................................................................
NO ACCESS LOG ENTRY

firefox_backoffice: Start: 2015-06-11 09:41:52 (cancled at 09:44:56)
........................................................................................................................................................................................
NO ACCESS LOG ENTRY

ie_backoffice: Start: 2015-06-11 09:41:53 (cancled at 09:44:56)
.......................................................................................................................................................................................
NO ACCESS LOG ENTRY

ie_server: Start: 2015-06-11 09:41:56 (cancled at 09:44:56)
....................................................................................................................................................................................
NO ACCESS LOG ENTRY

相隔一分钟开始：

chrome_backoffice: Start: 2015-06-11 09:46:17
............................................................................................................................................................................................................................................................................................................
Finished: 2015-06-11 09:51:17
###DOMAIN###:443 192.168.###IP### - - [11/Jun/2015:09:46:17 +0200] "GET /###PATH###/sleepTest.php HTTP/1.1" 200 2174 "-" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/41.0.2272.89 Safari/537.36"

chrome_server: Start: 2015-06-11 09:47:17
............................................................................................................................................................................................................................................................................................................
Finished: 2015-06-11 09:52:17
###DOMAIN###:80 192.168.###IP### - - [11/Jun/2015:09:47:17 +0200] "GET /###PATH###/sleepTest.php HTTP/1.1" 200 2174 "-" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/41.0.2272.89 Safari/537.36"

firefox_backoffice: Start: 2015-06-11 09:48:17 (cancled at 09:52:23)
......................................................................................................................................................................................................................................................
NO ACCESSLOG ENTRY

firefox_server: Start: 2015-06-11 09:50:55
............................................................................................................................................................................................................................................................................................................
Finished: 2015-06-11 09:55:55
###DOMAIN###:80 192.168.###IP### - - [11/Jun/2015:09:50:55 +0200] "GET /###PATH###/sleepTest.php HTTP/1.1" 200 2172 "-" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:38.0) Gecko/20100101 Firefox/38.0"

ie_backoffice: Start: 2015-06-11 09:50:57
............................................................................................................................................................................................................................................................................................................
Finished: 2015-06-11 09:55:57
###DOMAIN###:443 192.168.###IP### - - [11/Jun/2015:09:50:57 +0200] "GET /###PATH###/sleepTest.php HTTP/1.1" 200 2173 "-" "Mozilla/5.0 (Windows NT 6.1; WOW64; Trident/7.0; rv:11.0) like Gecko"

ie_server: Start: 2015-06-11 09:50:56
............................................................................................................................................................................................................................................................................................................
Finished: 2015-06-11 09:55:56
###DOMAIN###:80 192.168.###IP### - - [11/Jun/2015:09:50:56 +0200] "GET /###PATH###/sleepTest.php HTTP/1.1" 200 2173 "-" "Mozilla/5.0 (Windows NT 6.1; WOW64; Trident/7.0; rv:11.0) like Gecko"

相隔 30 秒开始：

chrome_backoffice: Start: 2015-06-11 09:56:36 (cancled at 10:00:00)
............................................................................................................................................................................................................
NO ACCESSLOG ENTRY

chrome_server: Start: 2015-06-11 09:57:06
............................................................................................................................................................................................................................................................................................................
Finished: 2015-06-11 10:02:06
###DOMAIN###:80 192.168.###IP### - - [11/Jun/2015:09:57:06 +0200] "GET /###PATH###/sleepTest.php HTTP/1.1" 200 2177 "-" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/41.0.2272.89 Safari/537.36"

firefox_backoffice: Start: 2015-06-11 09:57:36
............................................................................................................................................................................................................................................................................................................
Finished: 2015-06-11 10:02:36
###DOMAIN###:443 192.168.###IP### - - [11/Jun/2015:09:57:36 +0200] "GET /###PATH###/sleepTest.php HTTP/1.1" 200 2177 "-" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:38.0) Gecko/20100101 Firefox/38.0"

firefox_server: Start: 2015-06-11 09:58:06
............................................................................................................................................................................................................................................................................................................
Finished: 2015-06-11 10:03:06
###DOMAIN###:80 192.168.###IP### - - [11/Jun/2015:09:58:06 +0200] "GET /###PATH###/sleepTest.php HTTP/1.1" 200 2177 "-" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:38.0) Gecko/20100101 Firefox/38.0"

ie_backoffice: Start: 2015-06-11 09:58:39
............................................................................................................................................................................................................................................................................................................
Finished: 2015-06-11 10:03:39
###DOMAIN###:443 192.168.###IP### - - [11/Jun/2015:09:58:39 +0200] "GET /###PATH###/sleepTest.php HTTP/1.1" 200 2177 "-" "Mozilla/5.0 (Windows NT 6.1; WOW64; Trident/7.0; rv:11.0) like Gecko"

ie_server: Start: 2015-06-11 09:59:08
............................................................................................................................................................................................................................................................................................................
Finished: 2015-06-11 10:04:08
###DOMAIN###:80 192.168.###IP### - - [11/Jun/2015:09:59:08 +0200] "GET /###PATH###/sleepTest.php HTTP/1.1" 200 2177 "-" "Mozilla/5.0 (Windows NT 6.1; WOW64; Trident/7.0; rv:11.0) like Gecko"

另一个测试案例：
服务器上的自动脚本，每 10 秒启动一次上述测试脚本。测试脚本在 MySQL 表中更新其状态。如果完成，则填充“结束”列。否则，“进度”列包含脚本仍在运行的最后一秒的日期。 https://jsfiddle.net/v8boufn8/

strace进程失败时：

[...]
--- SIGCHLD (Child exited) @ 0 (0) ---
write(22, "\0", 1)                      = -1 EAGAIN (Resource temporarily unavailable)
rt_sigreturn(0x16)                      = 0
close(42)                               = 0
wait4(22231, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 22231
poll([{fd=41, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
write(41, "\1\0\0\0\16", 5)             = 5
read(41, "\7\0\0\1\0\0\0\2\0\0\0", 16384) = 11
poll([{fd=41, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
write(41, "\v\0\0\0\2*********", 15)   = 15
read(41, "\7\0\0\1\0\0\0\2\0\0\0", 16384) = 11
poll([{fd=41, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
write(41, "D\3\0\0\3UPDATE `*******`.`*********"..., 840) = 840
read(41, "0\0\0\1\0\1\0\2\0\0\0(Rows matched: 1  Cha"..., 16384) = 52
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
rt_sigaction(SIGCHLD, NULL, {0x7f423be749d0, [], SA_RESTORER|SA_NOCLDSTOP, 0x7f42509a7f60}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
nanosleep({1, 0}, 0x7fff37f40790)       = 0
writev(40, [{"\27\3\1\0 A0\245\3059\204\365\311\356\334\261tu&\273\236\201e\321\243_\346h\324\226\335\217"..., 111}], 1) = 111
pipe2([42, 43], O_CLOEXEC)              = 0
clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f425144ea10) = 22439
close(43)                               = 0
fcntl(42, F_SETFD, 0)                   = 0
fstat(42, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
read(42, "0.99\n", 8192)                = 5
read(42, "", 8192)                      = 0
--- SIGCHLD (Child exited) @ 0 (0) ---
write(22, "\0", 1)                      = -1 EAGAIN (Resource temporarily unavailable)
rt_sigreturn(0x16)                      = 0
close(42)                               = 0
wait4(22439, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 22439
poll([{fd=41, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
write(41, "\1\0\0\0\16", 5)             = 5
read(41, "\7\0\0\1\0\0\0\2\0\0\0", 16384) = 11
poll([{fd=41, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
write(41, "\v\0\0\0\2**********", 15)   = 15
read(41, "\7\0\0\1\0\0\0\2\0\0\0", 16384) = 11
poll([{fd=41, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
write(41, "D\3\0\0\3UPDATE `*******`.`*********"..., 840) = 840
read(41, "0\0\0\1\0\1\0\2\0\0\0(Rows matched: 1  Cha"..., 16384) = 52
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
rt_sigaction(SIGCHLD, NULL, {0x7f423be749d0, [], SA_RESTORER|SA_NOCLDSTOP, 0x7f42509a7f60}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
nanosleep({1, 0},  <unfinished ...>
+++ killed by SIGKILL +++

strace成功流程：

[...]
munmap(0x7f424a7e7000, 1078264)         = 0
munmap(0x7f424a8ef000, 1128872)         = 0
munmap(0x7f4251346000, 1080672)         = 0
close(14)                               = 0
munmap(0x7f423759c000, 67108864)        = 0
close(28)                               = 0
close(38)                               = 0
munmap(0x7f423e2cf000, 2570696)         = 0
munmap(0x7f423c074000, 2463760)         = 0
write(22, "@", 1)                       = -1 EAGAIN (Resource temporarily unavailable)
close(22)                               = 0
close(21)                               = 0
rt_sigaction(SIGCHLD, {SIG_DFL, [], SA_RESTORER|SA_NOCLDSTOP, 0x7f42509a7f60}, {0x7f423be749d0, [], SA_RESTORER|SA_NOCLDSTOP, 0x7f42509a7f60}, 8) = 0
munmap(0x7f423bc61000, 4270440)         = 0
munmap(0x7f423b95f000, 3152520)         = 0
munmap(0x7f423b6f8000, 2517800)         = 0
munmap(0x7f423b59c000, 1425296)         = 0
munmap(0x7f4237203000, 3770008)         = 0
munmap(0x7f4236e74000, 3731272)         = 0
munmap(0x7f423683a000, 1280128)         = 0
munmap(0x7f4235cc6000, 6166888)         = 0
munmap(0x7f424af2d000, 2645224)         = 0
munmap(0x7f424ac19000, 3223576)         = 0
munmap(0x7f424aa03000, 2186232)         = 0
close(9)                                = 0
close(8)                                = 0
exit_group(0)                           = ?

答案1

有时问题可能是在调用 opcache_reset() 函数时其他脚本执行完毕，时间正好是180秒，在php-fpm日志中有如下信息：

警告：[pool www] 子进程 X 在启动后 Y 秒因信号 9 (SIGKILL) 而退出

原因是php-fpm 使用 SIGKILL 终止其子进程3分钟后https://bugs.php.net/bug.php?id=75107&thanks=6

opcache_reset() 触发 opcache 重启。如果在启动重启后，进程持有 SHM 锁的时间超过 opcache.force_restart_timeout 秒，它将被终止。另请参阅http://php.net/manual/en/opcache.configuration.php#ini.opcache.force-restart-timeout。

因此，有两个解决方案：

  1. 增加 opcache.force_restart_timeout
  2. 停止在 auto/crontab 脚本中使用 opcache_reset。也许可以使用http://php.net/manual/en/function.opcache-invalidate.php足够的？

相关内容