3

У меня следующая странная проблема, надеюсь, вы, ребята, сможете мне помочь. Если есть какие-либо вопросы, я постараюсь ответить на них как можно лучше.

Эта проблема

У меня есть веб-сервер с Debian 6.0, Apache 2.2.16 и PHP 5.3.9. К сожалению, нет возможности обновить эти компоненты.
Время от времени 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.
Возможно, это своего рода перегрузка сети, так что сеть разрушает все соединения. Но почему так получается, что иногда 2 из 4 окон заканчивают загрузку скрипта, а остальные нет?
Я также думал, что это вызвано каким-то cronjob (их слишком много на сервере), который убивает слишком старые скрипты apache каждые x минут. Но я не смог найти ни одного, и это не объяснило бы, почему это происходит (когда это происходит) каждый раз в раунде около 3 минут. Кроме того, более старые процессы Apache от других пользователей по-прежнему работают и не уничтожаются.
Я исключаю проблему на стороне клиента, потому что я могу наблюдать проблему на разных клиентах с разными ОС и разными браузерами.

Спасибо

Я надеюсь, что смог описать мою проблему достаточно хорошо для вас, чтобы вы могли дать мне советы, как я могу лучше проанализировать, где проблема и как я могу ее исправить (без необходимости обновления основных частей сервера). Возможно, это просто какая-то загадочная обстановка где-то?
Спасибо всем за прочтение до конца!

Интересный факт: если в скрипте не выполняется вывод, который выполняется дольше 3 минут (потому что вычисляется что-то, например), и возникает проблема, Firefox в основном думает: «Привет, нет вывода, но закончен? Давайте перезагрузим скрипт!", и редко думает" эй, нет выхода, но закончил? Я покажу пользователю пустое ответное сообщение ". Отлично, если какое - то важное действие за этим сценарием , и это действие становится снова выполняется снова и снова г

Факты через ваши комментарии

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 ответ1

0

Иногда проблема может быть вызвана функцией opcache_reset(), когда выполняется другой скрипт. Время составляет ровно 180 секунд, и в журнале php-fpm есть сообщение вроде:

ВНИМАНИЕ: [пул www] дочерний элемент X вышел по сигналу 9 (SIGKILL) через Y секунд после запуска

Причина в том, что 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.

Итак, есть 2 решения:

  1. увеличить opcache.force_restart_timeout
  2. прекратить использование opcache_reset в сценариях auto/crontab. Может быть, достаточно использовать http://php.net/manual/en/function.opcache-invalidate.php ?
|источник

Всё ещё ищете ответ? Посмотрите другие вопросы с метками .