Re[2]: Умирают воркеры

Wed Mar 4 15:19:47 MSK 2009

Изучаю error_log nginx-a с опцией debug. Прошу пояснить мне некоторые моменты:

2009/03/04 14:02:44 [debug] 61601#0: bind() 93.84.113.218:80 #5 
2009/03/04 14:02:44 [debug] 61601#0: counter: 00000008005BA080, 1
2009/03/04 14:02:44 [debug] 61602#0: bind() 93.84.113.218:80 #5 
2009/03/04 14:02:44 [notice] 61602#0: using the "kqueue" event method
2009/03/04 14:02:44 [debug] 61602#0: counter: 00000008005BA080, 1
2009/03/04 14:02:44 [notice] 61602#0: nginx/0.6.35
2009/03/04 14:02:44 [notice] 61602#0: OS: FreeBSD 7.0-RELEASE
2009/03/04 14:02:44 [notice] 61602#0: kern.osreldate: 700055, built on 700055
2009/03/04 14:02:44 [notice] 61602#0: hw.ncpu: 2
2009/03/04 14:02:44 [notice] 61602#0: net.inet.tcp.sendspace: 65535
2009/03/04 14:02:44 [notice] 61602#0: kern.ipc.somaxconn: 4096
2009/03/04 14:02:44 [notice] 61602#0: getrlimit(RLIMIT_NOFILE): 230400:230400
2009/03/04 14:02:44 [debug] 61603#0: write: 6, 00007FFFFFFFE900, 6, 0
2009/03/04 14:02:44 [notice] 61603#0: start worker processes
2009/03/04 14:02:44 [debug] 61603#0: channel 6:7
2009/03/04 14:02:44 [notice] 61603#0: start worker process 61604
2009/03/04 14:02:44 [debug] 61603#0: channel 8:9
2009/03/04 14:02:44 [notice] 61603#0: start worker process 61605
2009/03/04 14:02:44 [debug] 61603#0: pass channel s:1 pid:61605 fd:8 to s:0 pid:61604 fd:6
2009/03/04 14:02:44 [debug] 61603#0: channel 10:11
2009/03/04 14:02:44 [notice] 61603#0: start worker process 61606
2009/03/04 14:02:44 [debug] 61603#0: pass channel s:2 pid:61606 fd:10 to s:0 pid:61604 fd:6
2009/03/04 14:02:44 [debug] 61603#0: pass channel s:2 pid:61606 fd:10 to s:1 pid:61605 fd:8
2009/03/04 14:02:44 [debug] 61603#0: sigsuspend

Здесь, как я понимаю мастер создает три воркера с pid 61603, 61604 и 61605.

Далее идет 
2009/03/04 14:02:44 [debug] 61604#0: malloc: 0000000800D0F000:16384
2009/03/04 14:02:44 [debug] 61604#0: malloc: 0000000800D37000:16384
2009/03/04 14:02:44 [debug] 61604#0: malloc: 0000000800D4F000:16384
2009/03/04 14:02:44 [debug] 61605#0: malloc: 0000000800D0F000:16384
2009/03/04 14:02:44 [debug] 61605#0: malloc: 0000000800D37000:16384
2009/03/04 14:02:44 [debug] 61605#0: malloc: 0000000800D4F000:16384
2009/03/04 14:02:44 [debug] 61606#0: malloc: 0000000800D0F000:16384
2009/03/04 14:02:44 [debug] 61606#0: malloc: 0000000800D37000:16384
2009/03/04 14:02:44 [debug] 61606#0: malloc: 0000000800D4F000:16384
2009/03/04 14:02:44 [debug] 61604#0: malloc: 0000000800E00000:1556480
2009/03/04 14:02:44 [debug] 61606#0: malloc: 0000000800E00000:1556480
2009/03/04 14:02:44 [debug] 61605#0: malloc: 0000000800E00000:1556480
2009/03/04 14:02:44 [debug] 61604#0: malloc: 0000000801000000:1146880
2009/03/04 14:02:44 [debug] 61605#0: malloc: 0000000801000000:1146880
2009/03/04 14:02:44 [debug] 61606#0: malloc: 0000000801000000:1146880
2009/03/04 14:02:44 [debug] 61605#0: malloc: 0000000801200000:1146880
2009/03/04 14:02:44 [debug] 61606#0: malloc: 0000000801200000:1146880

Здесь каждый воркер отъедает себе кусок памяти.

Потом идет:

2009/03/04 14:02:44 [debug] 61605#0: kevent set event: 9: ft:-1 fl:0005
2009/03/04 14:02:44 [debug] 61605#0: worker cycle
2009/03/04 14:02:44 [debug] 61605#0: accept mutex locked
2009/03/04 14:02:44 [debug] 61605#0: kevent set event: 5: ft:-1 fl:0005
2009/03/04 14:02:44 [debug] 61605#0: kevent timer: -1, changes: 2
2009/03/04 14:02:44 [debug] 61605#0: kevent events: 1
2009/03/04 14:02:44 [debug] 61605#0: kevent: 9: ft:-1 fl:0000 ff:00000000 d:32 ud:0000000801000070
2009/03/04 14:02:44 [debug] 61605#0: post event 0000000801000070
2009/03/04 14:02:44 [debug] 61605#0: timer delta: 22
2009/03/04 14:02:44 [debug] 61605#0: posted events 0000000801000070
2009/03/04 14:02:44 [debug] 61605#0: posted event 0000000801000070
2009/03/04 14:02:44 [debug] 61605#0: delete posted event 0000000801000070
2009/03/04 14:02:44 [debug] 61605#0: channel handler
2009/03/04 14:02:44 [notice] 61603#0: signal 23 (SIGIO) received
2009/03/04 14:02:44 [debug] 61603#0: wake up
2009/03/04 14:02:44 [debug] 61603#0: sigsuspend

Прошу объяснить, что здесь происходит и нормально ли это. здесь мастеру приходит сигнал SIGIO откуда-то.

Потом идет:

2009/03/04 14:02:44 [debug] 61606#0: kevent set event: 11: ft:-1 fl:0005
2009/03/04 14:02:44 [debug] 61606#0: worker cycle
2009/03/04 14:02:44 [debug] 61606#0: accept mutex locked
2009/03/04 14:02:44 [debug] 61606#0: kevent set event: 5: ft:-1 fl:0005
2009/03/04 14:02:44 [debug] 61606#0: kevent timer: -1, changes: 2
2009/03/04 14:02:44 [debug] 61605#0: channel: 32
2009/03/04 14:02:44 [debug] 61605#0: channel command: 1
2009/03/04 14:02:44 [debug] 61605#0: get channel s:2 pid:61606 fd:7
2009/03/04 14:02:44 [debug] 61605#0: channel: -2
2009/03/04 14:02:44 [debug] 61605#0: posted event 0000000000000000
2009/03/04 14:02:44 [debug] 61605#0: worker cycle
2009/03/04 14:02:44 [debug] 61605#0: accept mutex lock failed: 1
2009/03/04 14:02:44 [debug] 61605#0: kevent set event: 5: ft:-1 fl:0008
2009/03/04 14:02:44 [debug] 61605#0: kevent timer: 500, changes: 1
2009/03/04 14:02:44 [debug] 61604#0: malloc: 0000000801200000:1146880
2009/03/04 14:02:44 [debug] 61604#0: kevent set event: 7: ft:-1 fl:0005
2009/03/04 14:02:44 [debug] 61604#0: worker cycle
2009/03/04 14:02:44 [debug] 61604#0: accept mutex lock failed: 0
2009/03/04 14:02:44 [debug] 61604#0: kevent timer: 500, changes: 1
2009/03/04 14:02:44 [debug] 61604#0: kevent events: 1
2009/03/04 14:02:44 [debug] 61604#0: kevent: 7: ft:-1 fl:0000 ff:00000000 d:64 ud:0000000801000070
2009/03/04 14:02:44 [debug] 61604#0: channel handler
2009/03/04 14:02:44 [debug] 61604#0: channel: 32
2009/03/04 14:02:44 [debug] 61604#0: channel command: 1
2009/03/04 14:02:44 [debug] 61604#0: get channel s:1 pid:61605 fd:6
2009/03/04 14:02:44 [debug] 61604#0: channel: 32
2009/03/04 14:02:44 [debug] 61604#0: channel command: 1
2009/03/04 14:02:44 [debug] 61604#0: get channel s:2 pid:61606 fd:9
2009/03/04 14:02:44 [notice] 61603#0: signal 23 (SIGIO) received
2009/03/04 14:02:44 [debug] 61604#0: channel: -2
2009/03/04 14:02:44 [debug] 61603#0: wake up
2009/03/04 14:02:44 [debug] 61604#0: timer delta: 26
2009/03/04 14:02:44 [debug] 61603#0: sigsuspend
2009/03/04 14:02:44 [debug] 61604#0: posted events 0000000000000000
2009/03/04 14:02:44 [debug] 61604#0: worker cycle
2009/03/04 14:02:44 [notice] 61603#0: signal 23 (SIGIO) received
2009/03/04 14:02:44 [debug] 61604#0: accept mutex lock failed: 0
2009/03/04 14:02:44 [debug] 61603#0: wake up
2009/03/04 14:02:44 [debug] 61604#0: kevent timer: 500, changes: 0
2009/03/04 14:02:44 [debug] 61603#0: sigsuspend

опять мастер получает откуда-то сигнал SIGIO.
и что значит строка: 61604#0: accept mutex lock failed: 0? это нормально?

потом идут строки практически от одного воркера 61606. куда девались все остальные?

В статистике nginx-a количество соединений растет скачкообразно и никак не желает уменьшаться. При достижении 1500-2000 соединений (это по статистике так) скорость резко падает.

Пробовал вешать nginx на отдельный порт, куда пользователи подключаются, ошибок вроде нет, все работает нормально. статистика показывает правильное число соединений (1-3 моих соединений) и никаких скачков. Скорость отдачи файла тоже очень даже приличная. Правда наблюдал интересный эффект: скорость начинается с маленькой (1-2 Кб/с) и постепенно растет до нужной (250-300 Кб/с). Если закачку оборвать, а потом возобновить, скорость сразу устанавливается в 250-300 Кб/с.

А как только возвращаю на порт, где повиснет 100-150 онлайн-пользователей, сразу начинаются смерти воркеров, скачки коннектов и падение скорости.

Я уже не знаю, что делать(( Где смотреть и что ковырять?