Re: nginx status: reading 100-200, writing 1-5. Как побороть?

Tue Sep 18 22:26:56 UTC 2012

VBart Wrote:
-------------------------------------------------------
> А если посмотреть по access-логу эти айпишники, шлют они только такие
> запросы, 
> или хорошие тоже?

При более детальном разборе стало ясно, что такую активность создают (в том
числе) и довольно давно зарегистрированные пользователи сайта. Но я вообще
не понимаю логику работы их клиентов (браузеров). Вот допустим на примере
77.223.64.124. Он начинается запрашивать страничку с сервера (причем не в
первом по порядку соединении, первые 2-3 устанавливаются и "молчат")

2012/09/19 01:32:58 [debug] 48557#0: *28 accept: 77.223.64.124 fd:30
2012/09/19 01:32:58 [debug] 48557#0: *28 event timer add: 30:
3000:1348003981827
2012/09/19 01:32:58 [debug] 48557#0: *28 epoll add event: fd:30 op:1
ev:80000001
2012/09/19 01:32:58 [debug] 48557#0: *28 post event 00007FA86915C218
2012/09/19 01:32:58 [debug] 48557#0: *28 delete posted event
00007FA86915C218
2012/09/19 01:32:58 [debug] 48557#0: *28 malloc: 00000000006FDB80:1296
2012/09/19 01:32:58 [debug] 48557#0: *28 posix_memalign:
00000000006FE0A0:256 @16
2012/09/19 01:32:58 [debug] 48557#0: *28 malloc: 00000000007F6550:16384
2012/09/19 01:32:58 [debug] 48557#0: *28 posix_memalign:
00000000007B75D0:4096 @16
2012/09/19 01:32:58 [debug] 48557#0: *28 http process request line
2012/09/19 01:32:58 [debug] 48557#0: *28 recv: fd:30 804 of 16384
2012/09/19 01:32:58 [debug] 48557#0: *28 http request line: "GET
/some_url.php HTTP/1.1"
2012/09/19 01:32:58 [debug] 48557#0: *28 http uri: "/some_url.php"
2012/09/19 01:32:58 [debug] 48557#0: *28 http args: ""
2012/09/19 01:32:58 [debug] 48557#0: *28 http exten: "php"
2012/09/19 01:32:58 [debug] 48557#0: *28 http process request header line
2012/09/19 01:32:58 [debug] 48557#0: *28 http header: "Host: coolsite.ru"
2012/09/19 01:32:58 [debug] 48557#0: *28 http header: "Connection:
keep-alive"
2012/09/19 01:32:58 [debug] 48557#0: *28 http header: "User-Agent:
Mozilla/5.0 (Windows NT 5.1) AppleWebKit/537.1 (KHTML, like Gecko)
Chrome/21.0.1180.89 Safari/537.1"
2012/09/19 01:32:58 [debug] 48557#0: *28 http header: "Accept:
text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8"
2012/09/19 01:32:58 [debug] 48557#0: *28 http header: "Accept-Encoding:
gzip,deflate,sdch"
2012/09/19 01:32:58 [debug] 48557#0: *28 http header: "Accept-Language:
ru-RU,ru;q=0.8,en-US;q=0.6,en;q=0.4"
2012/09/19 01:32:58 [debug] 48557#0: *28 http header: "Accept-Charset:
windows-1251,utf-8;q=0.7,*;q=0.3"

Ну и дальше идет нормальная обработка этого запроса, и клиенту вроде даже
что-то отправляется. Одновременно с нормальным запросом он открывает еще
тучу соединений и никак их не использует:

2012/09/19 01:32:58 [debug] 48557#0: *31 accept: 77.223.64.124 fd:32
2012/09/19 01:32:58 [debug] 48557#0: *31 event timer add: 32:
3000:1348003981827
2012/09/19 01:32:58 [debug] 48557#0: *31 epoll add event: fd:32 op:1
ev:80000001
2012/09/19 01:32:58 [debug] 48557#0: post event 00007FA86915C010
2012/09/19 01:32:58 [debug] 48557#0: delete posted event 00007FA86915C010
2012/09/19 01:32:58 [debug] 48557#0: accept on 0.0.0.0:80, ready: 0
2012/09/19 01:32:58 [debug] 48557#0: posix_memalign: 00000000006FE2C0:256
@16
2012/09/19 01:32:58 [debug] 48557#0: *32 accept: 77.223.64.124 fd:43
2012/09/19 01:32:58 [debug] 48557#0: *32 event timer add: 43:
3000:1348003981827
2012/09/19 01:32:58 [debug] 48557#0: *32 epoll add event: fd:43 op:1
ev:80000001
2012/09/19 01:32:58 [debug] 48557#0: post event 00007FA86915C010
2012/09/19 01:32:58 [debug] 48557#0: delete posted event 00007FA86915C010
2012/09/19 01:32:58 [debug] 48557#0: accept on 0.0.0.0:80, ready: 0
2012/09/19 01:32:58 [debug] 48557#0: posix_memalign: 00000000006FE3D0:256
@16
2012/09/19 01:32:58 [debug] 48557#0: *33 accept: 77.223.64.124 fd:44
2012/09/19 01:32:58 [debug] 48557#0: *33 event timer add: 44:
3000:1348003981827
2012/09/19 01:32:58 [debug] 48557#0: *33 epoll add event: fd:44 op:1
ev:80000001
2012/09/19 01:32:58 [debug] 48557#0: post event 00007FA86915C010
2012/09/19 01:32:58 [debug] 48557#0: delete posted event 00007FA86915C010
2012/09/19 01:32:58 [debug] 48557#0: accept on 0.0.0.0:80, ready: 0
2012/09/19 01:32:58 [debug] 48557#0: posix_memalign: 00000000006FE4E0:256
@16
2012/09/19 01:32:58 [debug] 48557#0: *34 accept: 77.223.64.124 fd:45
2012/09/19 01:32:58 [debug] 48557#0: *34 event timer add: 45:
3000:1348003981827
2012/09/19 01:32:58 [debug] 48557#0: *34 epoll add event: fd:45 op:1
ev:80000001
2012/09/19 01:32:58 [debug] 48557#0: post event 00007FA86915C010
2012/09/19 01:32:58 [debug] 48557#0: delete posted event 00007FA86915C010
2012/09/19 01:32:58 [debug] 48557#0: accept on 0.0.0.0:80, ready: 0
2012/09/19 01:32:58 [debug] 48557#0: posix_memalign: 00000000006FE5F0:256
@16
2012/09/19 01:32:58 [debug] 48557#0: *35 accept: 77.223.64.124 fd:46
2012/09/19 01:32:58 [debug] 48557#0: *35 event timer add: 46:
3000:1348003981827
2012/09/19 01:32:58 [debug] 48557#0: *35 epoll add event: fd:46 op:1
ev:80000001
2012/09/19 01:32:58 [debug] 48557#0: post event 00007FA86915C010
2012/09/19 01:32:58 [debug] 48557#0: delete posted event 00007FA86915C010
2012/09/19 01:32:58 [debug] 48557#0: accept on 0.0.0.0:80, ready: 0
2012/09/19 01:32:58 [debug] 48557#0: posix_memalign: 00000000006FE700:256
@16
2012/09/19 01:32:58 [debug] 48557#0: *36 accept: 77.223.64.124 fd:47
2012/09/19 01:32:58 [debug] 48557#0: *36 event timer add: 47:
3000:1348003981827
2012/09/19 01:32:58 [debug] 48557#0: *36 epoll add event: fd:47 op:1
ev:80000001
2012/09/19 01:32:58 [debug] 48557#0: post event 00007FA86915C010
2012/09/19 01:32:58 [debug] 48557#0: delete posted event 00007FA86915C010
2012/09/19 01:32:58 [debug] 48557#0: accept on 0.0.0.0:80, ready: 0
2012/09/19 01:32:58 [debug] 48557#0: posix_memalign: 00000000006FE810:256
@16

ну и так далее, еще штук 5-10. затем наступает тишина, и через
client_header_timeout (сейчас 3 секунды, раньше 10 секунд) все эти
соединения отваливаются по таймауту:

2012/09/19 01:33:01 [info] 48557#0: *24 client timed out (110: Connection
timed out) while reading client request line, client: 77.223.64.124, server:
0.0.0.0:80
2012/09/19 01:33:01 [debug] 48557#0: *24 close http connection: 36
2012/09/19 01:33:01 [debug] 48557#0: *24 reusable connection: 0
2012/09/19 01:33:01 [debug] 48557#0: *24 free: 00000000007BA250, unused: 48
2012/09/19 01:33:01 [debug] 48557#0: *25 event timer del: 37: 1348003981827
2012/09/19 01:33:01 [info] 48557#0: *25 client timed out (110: Connection
timed out) while reading client request line, client: 77.223.64.124, server:
0.0.0.0:80
2012/09/19 01:33:01 [debug] 48557#0: *25 close http connection: 37
2012/09/19 01:33:01 [debug] 48557#0: *25 reusable connection: 0
2012/09/19 01:33:01 [debug] 48557#0: *25 free: 00000000007BA360, unused: 48
2012/09/19 01:33:01 [debug] 48557#0: *30 event timer del: 42: 1348003981827
2012/09/19 01:33:01 [info] 48557#0: *30 client timed out (110: Connection
timed out) while reading client request line, client: 77.223.64.124, server:
0.0.0.0:80
2012/09/19 01:33:01 [debug] 48557#0: *30 close http connection: 42
2012/09/19 01:33:01 [debug] 48557#0: *30 reusable connection: 0
2012/09/19 01:33:01 [debug] 48557#0: *30 free: 00000000007B85E0, unused: 48
2012/09/19 01:33:01 [debug] 48557#0: *31 event timer del: 32: 1348003981827
2012/09/19 01:33:01 [info] 48557#0: *31 client timed out (110: Connection
timed out) while reading client request line, client: 77.223.64.124, server:
0.0.0.0:80
2012/09/19 01:33:01 [debug] 48557#0: *31 close http connection: 32
2012/09/19 01:33:01 [debug] 48557#0: *31 reusable connection: 0
2012/09/19 01:33:01 [debug] 48557#0: *31 free: 00000000006FE1B0, unused: 48
2012/09/19 01:33:01 [debug] 48557#0: *32 event timer del: 43: 1348003981827
2012/09/19 01:33:01 [info] 48557#0: *32 client timed out (110: Connection
timed out) while reading client request line, client: 77.223.64.124, server:
0.0.0.0:80
2012/09/19 01:33:01 [debug] 48557#0: *32 close http connection: 43
2012/09/19 01:33:01 [debug] 48557#0: *32 reusable connection: 0
2012/09/19 01:33:01 [debug] 48557#0: *32 free: 00000000006FE2C0, unused: 48
2012/09/19 01:33:01 [debug] 48557#0: *33 event timer del: 44: 1348003981827
2012/09/19 01:33:01 [info] 48557#0: *33 client timed out (110: Connection
timed out) while reading client request line, client: 77.223.64.124, server:
0.0.0.0:80
2012/09/19 01:33:01 [debug] 48557#0: *33 close http connection: 44
2012/09/19 01:33:01 [debug] 48557#0: *33 reusable connection: 0
2012/09/19 01:33:01 [debug] 48557#0: *33 free: 00000000006FE3D0, unused: 48
2012/09/19 01:33:01 [debug] 48557#0: *34 event timer del: 45: 1348003981827

и так далее, все что было открыто ранее. Как я понимаю, именно эти
соединения и влияют на показатель "reading" в nginx_status. Через какое-то
время это опять повторяется.

Разве при нормальной работе браузеры открывают столько соединений и после
этого "молчат" в них? И что это за юзерагент такой - "USER_AGENT:
Mozilla/5.0 (Windows NT 5.1) AppleWebKit/537.1 (KHTML, like Gecko)
Chrome/21.0.1180.89 Safari/537.1"??? В общем ничего не понимаю :)

Posted at Nginx Forum: http://forum.nginx.org/read.php?21,230818,230828#msg-230828