У меня следующая странная проблема, надеюсь, вы, ребята, сможете мне помочь. Если есть какие-либо вопросы, я постараюсь ответить на них как можно лучше.
Эта проблема
У меня есть веб-сервер с 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) = ?