LINUX.ORG.RU
ФорумAdmin

Aapache перестает обрабатывать запросы.

 


0

1

Добрый день. Есть проблема с Apache.

Apache в какой-то момент перестает обрабатывать запросы. HTTP запрос ему отправлен,а ответа нет.

Server version: Apache/2.2.19 (Unix)
Architecture:   64-bit
Server MPM:     Prefork
  threaded:     no
    forked:     yes (variable process count)

При старте apache создается родительский процесс и несколько дочерних. Когда поступает новый запрос,то он перенаправляетя одному из дочерних процессов на обработку.

Я наблюдаю с помощью strace за родтельским процессом и дочерним. Обычно это выглядит так.

Родительский процесс
strace -vp <master_pid>

wait4(-1, 0x7fff23b7b84c, WNOHANG|WSTOPPED, NULL) = 0
select(0, NULL, NULL, NULL, {1, 0})     = 0 (Timeout)
wait4(-1, 0x7fff23b7b84c, WNOHANG|WSTOPPED, NULL) = 0
select(0, NULL, NULL, NULL, {1, 0})     = 0 (Timeout)
...
и т.д.


Дочерний процесс
strace -vp <child_pid>

#Ожидание запроса
futex(0x7f32d3ae3000, FUTEX_WAIT, 0, NULL

#Поступление запроса,обработка

epoll_wait(7, {{EPOLLIN, {u32=12209800, u64=12209800}}}, 2, 10000) = 1
accept(4, {sa_family=AF_INET, sin_port=htons(35696), sin_addr=inet_addr("127.0.0.1")}, [16]) = 11
futex(0x7faf46972000, FUTEX_WAKE, 1)    = 1
fcntl(11, F_GETFL)                      = 0x2 (flags O_RDWR)
fcntl(11, F_SETFL, O_RDWR|O_NONBLOCK)   = 0
read(11, "GET /phpinfo.php?=PHPE9568F34-D42"..., 8000) = 566
stat("/var/www/site.com/public_html/phpinfo.php", {st_dev=makedev(147, 0), st_ino=5816332, st_mode=S_IFREG|0600, st_nlink=1, st_uid=1000, st_gid=600, st_blksize=4096, st_blocks=8, st_size=18, st_atime=2013/03/06-18:53:58, st_mtime=2009/09/22-17:57:22, st_ctime=2010/12/20-16:30:00}) = 0
open("/var/www/site.com/public_html/.htaccess", O_RDONLY) = 12
fstat(12, {st_dev=makedev(147, 0), st_ino=5823385, st_mode=S_IFREG|0600, st_nlink=1, st_uid=1000, st_gid=600, st_blksize=4096, st_blocks=8, st_size=153, st_atime=2013/03/06-18:53:58, st_mtime=2010/12/23-18:20:37, st_ctime=2010/12/23-18:26:05}) = 0
read(12, "php_value mbstring.func_overload "..., 4096) = 153
read(12, ""..., 4096)                   = 0
close(12)                               = 0
open("/var/www/site.com/public_html/phpinfo.php/.htaccess", O_RDONLY) = -1 ENOTDIR (Not a directory)
rt_sigaction(SIGCHLD, {0x7faf44833820, [CHLD], SA_RESTORER|SA_RESTART, 0x7faf451ff1e0}, {0x7faf44833820, [CHLD], SA_RESTORER|SA_RESTART, 0x7faf451ff1e0}, 8) = 0
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={900, 0}}, NULL) = 0
rt_sigaction(SIGPROF, {0x7faf44879130, [PROF], SA_RESTORER|SA_RESTART, 0x7faf451ff1e0}, {0x7faf44879130, [PROF], SA_RESTORER|SA_RESTART, 0x7faf451ff1e0}, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [PROF], NULL, 8) = 0
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
writev(11, [{"HTTP/1.1 200 OK\r\nDate: Thu, 07 Ma"..., 171}, {"GIF89ax\0C\0\346j\0\177\202\27097G(%*\314\315\342\241\244\313\323\325\347\262\264"..., 2524}], 2) = 2695
write(8, "site.com 98.34.52.44"..., 257) = 257
shutdown(11, 1 /* send */)              = 0
poll([{fd=11, events=POLLIN}], 1, 2000) = 1 ([{fd=11, revents=POLLIN|POLLHUP}])
read(11, ""..., 512)                    = 0
close(11)                               = 0
read(5, 0x7fffb6fdbbab, 1)              = -1 EAGAIN (Resource temporarily unavailable)

#Ожидание нового запроса
futex(0x7faf46972000, FUTEX_WAIT, 0, NULL

В один момент родительский процесс убивает дочерние процессы (по timout вроде) и создает новые.

select(0, NULL, NULL, NULL, {1, 0})     = ? ERESTARTNOHAND (To be restarted)
--- SIGCHLD (Child exited) @ 0 (0) ---
select(0, NULL, NULL, NULL, {0, 742953}) = 0 (Timeout)
wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG|WSTOPPED, NULL) = 14481
wait4(-1, 0x7fffbe8854bc, WNOHANG|WSTOPPED, NULL) = 0
select(0, NULL, NULL, NULL, {1, 0})     = 0 (Timeout)
clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7fb1afeeda30) = 29584

С этого момента дочерние процессы все время висият в ожидании запроса.
futex(0x7f32d3ae3000, FUTEX_WAIT, 0, NULL

В родительском процессе я так понимаю постоянное ожидание завершения работы от дочерних процессов (wait4)
wait4(-1, 0x7fff23b7b84c, WNOHANG|WSTOPPED, NULL) = 0
select(0, NULL, NULL, NULL, {1, 0})     = 0 (Timeout)
wait4(-1, 0x7fff23b7b84c, WNOHANG|WSTOPPED, NULL) = 0
select(0, NULL, NULL, NULL, {1, 0})     = 0 (Timeout)

Для распределения запросов между дочерними процессами в Apache 2 используются мьютексы. Multi Processing Modules (MPM).


Подскажите пожалуйста куда копнуть,чтобы отследить что происходит с запросами и как узнать причну почему дочернему процессу не передается запрос?

Спасибо.

Ответ на: комментарий от true_admin

Запусил
strace -ttfvp <master_pid>
До момента когда запросы перестают обрабатываться все идет как и раньше.
4720 - это pid родительского процесса.

4720  16:53:24.870881 wait4(-1, 0x7fff466b545c, WNOHANG|WSTOPPED, NULL) = 0
4720  16:53:24.870957 select(0, NULL, NULL, NULL, {1, 0}
Переодически проскаривают обрабатываемые запросы дочерними процессами

Когда запросы перестают обрабатываться дочерними процессами, то идет такой вывод. В цикле. Одно и тоже.

4720  16:55:23.901122 write(6, "!"..., 1) = 1
4720  16:55:23.901203 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 11
4720  16:55:23.901247 fcntl(11, F_GETFL) = 0x2 (flags O_RDWR)
4720  16:55:23.901286 fcntl(11, F_SETFL, O_RDWR|O_NONBLOCK) = 0
4720  16:55:23.901322 connect(11, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("127.0.0.1")}, 16) = -1 EINPROGRESS (Operation now in progress)
4720  16:55:23.901404 poll([{fd=11, events=POLLOUT}], 1, 3000) = 1 ([{fd=11, revents=POLLOUT}])
4720  16:55:23.901449 getsockopt(11, SOL_SOCKET, SO_ERROR, [3048961540712562688], [4]) = 0
4720  16:55:23.901504 write(11, "OPTIONS * HTTP/1.0\r\nUser-Agent: A"..., 77) = 77
4720  16:55:23.901561 close(11)         = 0
4720  16:55:23.901606 wait4(-1, 0x7fff2d75fedc, WNOHANG|WSTOPPED, NULL) = 0
4720  16:55:23.901645 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
[\code]
Вызовы socket,getsockopt я так понимаю это попытки создания сокетов. Пока не разобрался с синтаксисом. Удачные это вызовы или нет.

atomlab
() автор топика
Ответ на: комментарий от atomlab

У тебя скрипты, похоже, пытаются подключиться к 127.0.0.1:80 . Причём у них это получается. Короче, проблема в (php?) скриптах. Возможно, в одном скрипте. Если дать ключ -s 256 то будет видно что он посылает. А так из «OPTIONS * HTTP/1.0\r\nUser-Agent: A» сложно понять что происходит.

true_admin ★★★★★
()
Ответ на: комментарий от atomlab

После рестарта апача повторяю процедуру.
Опять все работает нормально,потом апач прибивает очередной процесс и дальше идут вызовы

17373 17:14:36.549939 wait4(-1, 0x7fff0754f38c, WNOHANG|WSTOPPED, NULL) = 0
17373 17:14:36.550003 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
Вот так это выглядит
17373 17:14:32.923940 --- SIGCHLD (Child exited) @ 0 (0) ---
17373 17:14:32.923965 select(0, NULL, NULL, NULL, {0, 610053}) = 0 (Timeout)
17373 17:14:33.537935 write(6, "!"..., 1) = 1
17373 17:14:33.538063 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 11
17373 17:14:33.538135 fcntl(11, F_GETFL) = 0x2 (flags O_RDWR)
17373 17:14:33.538204 fcntl(11, F_SETFL, O_RDWR|O_NONBLOCK) = 0
17373 17:14:33.538271 connect(11, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("127.0.0.1")}, 16) = -1 EINPROGRESS (Operation now in progress)
17373 17:14:33.538407 poll([{fd=11, events=POLLOUT}], 1, 3000) = 1 ([{fd=11, revents=POLLOUT}])
17373 17:14:33.538457 getsockopt(11, SOL_SOCKET, SO_ERROR, [5247228332264652800], [4]) = 0
17373 17:14:33.538507 write(11, "OPTIONS * HTTP/1.0\r\nUser-Agent: A"..., 77) = 77
17373 17:14:33.538578 close(11)         = 0
17373 17:14:33.538628 wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG|WSTOPPED, NULL) = 18334
17373 17:14:33.538700 wait4(-1, 0x7fff0754f38c, WNOHANG|WSTOPPED, NULL) = 0
17373 17:14:33.538738 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
17373 17:14:34.541897 wait4(-1, 0x7fff0754f38c, WNOHANG|WSTOPPED, NULL) = 0
17373 17:14:34.541958 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
17373 17:14:35.545929 wait4(-1, 0x7fff0754f38c, WNOHANG|WSTOPPED, NULL) = 0
17373 17:14:35.545994 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
17373 17:14:36.549939 wait4(-1, 0x7fff0754f38c, WNOHANG|WSTOPPED, NULL) = 0
17373 17:14:36.550003 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)

atomlab
() автор топика
Ответ на: комментарий от true_admin

Спасибо за ответ
Странно что в php скриптах. Потоу что на сайте лежит безобидный phpinfo.php,я на нем и тестирую. А так до дочернего процесса я так понимаю даже не доходит запрос,чтобы php скрипт обработать.

atomlab
() автор топика
Ответ на: комментарий от atomlab

А другие сайты есть? Ну и покажи уж strace целиком :). Можно даже запустить весь апач под стрейсом (-s1024 -f ....) чтобы уж наверняка.

true_admin ★★★★★
()
Ответ на: комментарий от true_admin

Это не php-скрипты. Это внутреннее соединение apache (internal dummy connection). Apache так сбрасывает детей из accept/poll(). А вот почему он решил это сделать - вопрос.

Chumka ★★★
()
Ответ на: комментарий от Chumka

Apache использует accept mutex для распределения поступающих клиентских запросов между дочерними процессами. Этот мьютекс делает активным в текущий момент на прослушке коннектов только один дочерний процесс с помощью системного вызова accept() и представляет собой контроль доступа к TCP/IP. Для его инициализации сначала вызывается процедура accept_mutex_on() / accept_mutex_off(). После того, как дочерний процесс получает коннект, он начинает обрабатывать клиентский запрос, а на прослушуку становится другой дочерний процесс — в теории это называется Leader-Follower pattern. Кроссплатформенная обработка, зависящая от специфики конкретной операционной системы, реализована на основе MPM.

Источник
В апаче выбирается метод AcceptMutex с помощью которого будет происходить реализация мьютекса.
В моем конфиге апача выбран метод AcceptMutex=posixsem
Я пока не эсперементировал с их сменой.

Я так понял, что модуль апача MPM передает клиентские запросы любому дочернему процессу (на основе статуса процесса. Свободен\несвободен). Но при этом родительский запрос так же может принять клиентский запрос и обработать на равне с дочерними. Т.е. родительский процесс не участвует в распределении запросов по child'ам. Он следит за дочерними процессами. Прибивает их и создает. Но child'ы получают запросы с помощью MPM. И тут мне strace родительского процесса мало чего скажет.

Дочерние процесссы созданы и ждут запросов,но не получают их. Может косяк в работе MPM. Ищу возможно ли отследить работу MPM.

atomlab
() автор топика
Ответ на: комментарий от atomlab

По теории ты все правильно написал. За исключением того, что родительский процесс может принять и обработать соединение. Не может. Он потому и не удерживает блокировку. И он никому не передает соединение. Соединение передается ядром процессу, который вызвал accept().

Если еще углубиться в теорию, то в Linux accept_mutex_on() / accept_mutex_off() не нужен, если слушается один интерфейс и порт (например указана директива Listen 127.0.0.1:80). Поскольку вызов accept() является последовательным. Все дети просто сидят на accept(), а не на блокировках (futex, в твоем случае).

Что происходит у тебя я не понял. Самый первый трейс вообще очень странный: сначала лочится один мьютеркс

futex(0x7f32d3ae3000, FUTEX_WAIT, 0, NULL

а потом разлочивается ДРУГОЙ:

futex(0x7faf46972000, FUTEX_WAKE, 1) = 1

Такое ощущение, что этот трейс ошибочно руками сформирован.

Я бы посоветовал в момент зависания посмотреть трейс ВСЕХ детей. Думаю, все дети, кроме одного, будут висеть на futex(), а один-единственный что-то делать.

Chumka ★★★
()
Ответ на: комментарий от Chumka

Linux accept_mutex_on() / accept_mutex_off() не нужен, если слушается один интерфейс и порт (например указана директива Listen 127.0.0.1:80)

У меня для каждого пользователя свой апачевский конфиг и слушает каждый на отдельном локальном ip.Nginx проксирует на них в зависимости на какой сайт пришел запрос.
Понаблюдал еще strace.В момент завиcания в родительском процессе и в дочерних все выглядит так.
Родительский

# strace -vp 4257
Process 4257 attached - interrupt to quit
select(0, NULL, NULL, NULL, {0, 978894}) = 0 (Timeout)
wait4(-1, 0x7fff0cf7db4c, WNOHANG|WSTOPPED, NULL) = 0
select(0, NULL, NULL, NULL, {1, 0})     = 0 (Timeout)
wait4(-1, 0x7fff0cf7db4c, WNOHANG|WSTOPPED, NULL) = 0
select(0, NULL, NULL, NULL, {1, 0})     = 0 (Timeout)
wait4(-1, 0x7fff0cf7db4c, WNOHANG|WSTOPPED, NULL) = 0
select(0, NULL, NULL, NULL, {1, 0})     = 0 (Timeout)
wait4(-1, 0x7fff0cf7db4c, WNOHANG|WSTOPPED, NULL) = 0
select(0, NULL, NULL, NULL, {1, 0})     = 0 (Timeout)
И два дочерних. Просто ждут.
# strace -vp 4282
Process 4282 attached - interrupt to quit
futex(0x7faafc74f000, FUTEX_WAIT, 0, NULL
# strace -vp 4290
Process 4290 attached - interrupt to quit
futex(0x7faafc74f000, FUTEX_WAIT, 0, NULL

В нормальном рабочем режиме родительский процесс выглядит точно так же, а в дочерние процессы попадают запросы и выглядит это так:
# strace -vp 18002
Process 18002 attached - interrupt to quit
futex(0x7fd65d5b5000, FUTEX_LOCK_PI, 1) = 0
epoll_wait(7, {{EPOLLIN, {u32=12201576, u64=12201576}}}, 2, 10000) = 1
accept(4, {sa_family=AF_INET, sin_port=htons(50918), sin_addr=inet_addr("127.0.0.1")}, [16]) = 11
futex(0x7fd65d5b5000, FUTEX_UNLOCK_PI, 128) = 0
fcntl(11, F_GETFL)                      = 0x2 (flags O_RDWR)
fcntl(11, F_SETFL, O_RDWR|O_NONBLOCK)   = 0
read(11, "GET /phpinfo.php HTTP/1.0\r\nHost: "..., 8000) = 506
stat("/var/www/site.com/phpinfo.php", {st_dev=makedev(147, 0), st_ino=5816332, st_mode=S_IFREG|0600, st_nlink=1, st_uid=1000, st_gid=600, st_blksize=4096, st_blocks=8, st_size=18, st_atime=2013/03/08-18:54:58, st_mtime=2009/09/22-17:57:22, st_ctime=2010/12/20-16:30:00}) = 0
open("/var/www/site.com/.htaccess", O_RDONLY) = 12
fstat(12, {st_dev=makedev(147, 0), st_ino=5823385, st_mode=S_IFREG|0600, st_nlink=1, st_uid=1000, st_gid=600, st_blksize=4096, st_blocks=8, st_size=187, st_atime=2013/03/08-17:26:58, st_mtime=2013/03/07-17:26:14, st_ctime=2013/03/07-17:26:14}) = 0
read(12, "php_value mbstring.func_overload "..., 4096) = 187
read(12, ""..., 4096)                   = 0
close(12)                               = 0
open("/var/www/site.com/phpinfo.php/.htaccess", O_RDONLY) = -1 ENOTDIR (Not a directory)
rt_sigaction(SIGCHLD, {0x7fd65b476820, [CHLD], SA_RESTORER|SA_RESTART, 0x7fd65be421e0}, {0x7fd65b476820, [CHLD], SA_RESTORER|SA_RESTART, 0x7fd65be421e0}, 8) = 0
brk(0xeab000)                           = 0xeab000
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={900, 0}}, NULL) = 0
rt_sigaction(SIGPROF, {0x7fd65b4bc130, [PROF], SA_RESTORER|SA_RESTART, 0x7fd65be421e0}, {0x7fd65b4bc130, [PROF], SA_RESTORER|SA_RESTART, 0x7fd65be421e0}, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [PROF], NULL, 8) = 0
getcwd("/"..., 4095)                    = 2
chdir("/var/www/site.com/")      = 0
...
И дальше большая простыня обработки странички.
Строчка в самом начале
futex(0x7fd65d5b5000, FUTEX_LOCK_PI, 1) = 0
Видимо говорит,что выполнена блокировка мьютекса, процесс получает доступ к прослушке 80 порта, пошла передача запроса.
А при зависании все дочение процессы просто ждут.
futex(0x7faafc74f000, FUTEX_WAIT, 0, NULL

Вчера в конфиге апача сменил метод блокировки AcceptMutex.
AcceptMutex posixsem
на
AcceptMutex pthread

Наблюдаю. Уже почти сутки зависаний нет.

atomlab
() автор топика
Вы не можете добавлять комментарии в эту тему. Тема перемещена в архив.