SOAP POST request lag

[Igor Sysoev]

On Sun, May 17, 2009 at 06:56:55PM +0400, Vitaliy Okulov wrote:

> Коллеги, кто может подсказать почему возникает лаг в 50 секунд при POST
> запросе от SOAP клиента, может ли в этом виноват nginx? При томже запросе
> напрямую (то есть без nginx сервера) все работает без проблем.

Насколько я могу судить из приведённого лога, ядро в первом случае не
присылает новые события в течение 50 секунд, а потом и 60 (после второго
таймаута соединение закрывается). То есть, nginx вроде отрабатывает нормально.

> Debug лог:
> 
> 2009/05/17 18:43:15 [debug] 20128#0: *598 event timer del: 206:
> 1242571455407
> 2009/05/17 18:43:15 [debug] 20128#0: *598 generic phase: 0
> 2009/05/17 18:43:15 [debug] 20128#0: *598 generic phase: 1
> 2009/05/17 18:43:15 [debug] 20128#0: *598 find location for
> "/webservices.php/user_content"
> 2009/05/17 18:43:15 [debug] 20128#0: *598 find location: "/"
> 2009/05/17 18:43:15 [debug] 20128#0: *598 using configuration "/"
> 2009/05/17 18:43:15 [debug] 20128#0: *598 http cl:258589 max:62914560
> 2009/05/17 18:43:15 [debug] 20128#0: *598 generic phase: 3
> 2009/05/17 18:43:15 [debug] 20128#0: *598 post rewrite phase: 4
> 2009/05/17 18:43:15 [debug] 20128#0: *598 generic phase: 5
> 2009/05/17 18:43:15 [debug] 20128#0: *598 generic phase: 6
> 2009/05/17 18:43:15 [debug] 20128#0: *598 access phase: 7
> 2009/05/17 18:43:15 [debug] 20128#0: *598 access phase: 8
> 2009/05/17 18:43:15 [debug] 20128#0: *598 access phase: 9
> 2009/05/17 18:43:15 [debug] 20128#0: *598 post access phase: 10
> 2009/05/17 18:43:15 [debug] 20128#0: *598 malloc: 000000000094B000:4096
> 2009/05/17 18:43:15 [debug] 20128#0: *598 http client request body preread
> 819
> 2009/05/17 18:43:15 [debug] 20128#0: *598 malloc: 000000000118B000:131072
> 2009/05/17 18:43:15 [debug] 20128#0: *598 http read client request body
> 2009/05/17 18:43:15 [debug] 20128#0: *598 recv: eof:0, avail:3320, err:0
> 2009/05/17 18:43:15 [debug] 20128#0: *598 recv: fd:206 7664 of 131072
> 2009/05/17 18:43:15 [debug] 20128#0: *598 http client request body recv 7664
> 2009/05/17 18:43:15 [debug] 20128#0: *598 http client request body rest
> 250106
> 2009/05/17 18:43:15 [debug] 20128#0: *598 event timer add: 206:
> 60000:1242571455407
> 2009/05/17 18:43:15 [debug] 20128#0: *598 post event 0000000000D2B690
> 2009/05/17 18:43:15 [debug] 20128#0: *598 delete posted event
> 0000000000D2B690
> 2009/05/17 18:43:15 [debug] 20128#0: *598 http read client request body
> 2009/05/17 18:43:15 [debug] 20128#0: *598 recv: eof:0, avail:8688, err:0
> 2009/05/17 18:43:15 [debug] 20128#0: *598 recv: fd:206 8688 of 123408
> 2009/05/17 18:43:15 [debug] 20128#0: *598 http client request body recv 8688
> 2009/05/17 18:43:15 [debug] 20128#0: *598 http client request body rest
> 241418
> 2009/05/17 18:43:15 [debug] 20128#0: *598 event timer: 206, old:
> 1242571455407, new: 1242571455408
> 2009/05/17 18:43:15 [debug] 20128#0: *598 post event 0000000000D2B690
> 2009/05/17 18:43:15 [debug] 20128#0: *598 delete posted event
> 0000000000D2B690
> 2009/05/17 18:43:15 [debug] 20128#0: *598 http read client request body
> 2009/05/17 18:43:15 [debug] 20128#0: *598 recv: eof:0, avail:4344, err:0
> 2009/05/17 18:43:15 [debug] 20128#0: *598 recv: fd:206 13032 of 114720
> 2009/05/17 18:43:15 [debug] 20128#0: *598 http client request body recv
> 13032
> 2009/05/17 18:43:15 [debug] 20128#0: *598 http client request body rest
> 228386
> 2009/05/17 18:43:15 [debug] 20128#0: *598 event timer: 206, old:
> 1242571455407, new: 1242571455409
> 2009/05/17 18:43:15 [debug] 20128#0: *598 post event 0000000000D2B690
> 2009/05/17 18:43:15 [debug] 20128#0: *598 delete posted event
> 0000000000D2B690
> 2009/05/17 18:43:15 [debug] 20128#0: *598 http read client request body
> 2009/05/17 18:43:15 [debug] 20128#0: *598 recv: eof:0, avail:8688, err:0
> 2009/05/17 18:43:15 [debug] 20128#0: *598 recv: fd:206 20272 of 101688
> 2009/05/17 18:43:15 [debug] 20128#0: *598 http client request body recv
> 20272
> 2009/05/17 18:43:15 [debug] 20128#0: *598 http client request body rest
> 208114
> 2009/05/17 18:43:15 [debug] 20128#0: *598 event timer: 206, old:
> 1242571455407, new: 1242571455409
> 2009/05/17 18:43:15 [debug] 20128#0: *598 post event 0000000000D2B690
> 2009/05/17 18:43:15 [debug] 20128#0: *598 delete posted event
> 0000000000D2B690
> 2009/05/17 18:43:15 [debug] 20128#0: *598 http read client request body
> 2009/05/17 18:43:15 [debug] 20128#0: *598 recv: eof:0, avail:11584, err:0
> 2009/05/17 18:43:15 [debug] 20128#0: *598 recv: fd:206 11584 of 81416
> 2009/05/17 18:43:15 [debug] 20128#0: *598 http client request body recv
> 11584
> 2009/05/17 18:43:15 [debug] 20128#0: *598 http client request body rest
> 196530
> 2009/05/17 18:43:15 [debug] 20128#0: *598 event timer: 206, old:
> 1242571455407, new: 1242571455409
> 2009/05/17 18:43:15 [debug] 20128#0: *598 post event 0000000000D2B690
> 2009/05/17 18:43:15 [debug] 20128#0: *598 delete posted event
> 0000000000D2B690
> 2009/05/17 18:43:15 [debug] 20128#0: *598 http read client request body
> 2009/05/17 18:43:15 [debug] 20128#0: *598 recv: eof:0, avail:4344, err:0
> 2009/05/17 18:43:15 [debug] 20128#0: *598 recv: fd:206 4344 of 69832
> 2009/05/17 18:43:15 [debug] 20128#0: *598 http client request body recv 4344
> 2009/05/17 18:43:15 [debug] 20128#0: *598 http client request body rest
> 192186
> 2009/05/17 *18:43:15* [debug] 20128#0: *598 event timer: 206, old:
> 1242571455407, new: 1242571455409
> 2009/05/17 *18:44:06* [debug] 20128#0: *598 http read client request body
> 2009/05/17 18:44:06 [debug] 20128#0: *598 recv: eof:0, avail:1448, err:0
> 2009/05/17 18:44:06 [debug] 20128#0: *598 recv: fd:206 1448 of 65488
> 2009/05/17 18:44:06 [debug] 20128#0: *598 http client request body recv 1448
> 2009/05/17 18:44:06 [debug] 20128#0: *598 http client request body rest
> 190738
> 2009/05/17 18:44:06 [debug] 20128#0: *598 event timer del: 206:
> 1242571455407
> 2009/05/17 18:44:06 [debug] 20128#0: *598 event timer add: 206:
> 60000:1242571506913
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http read client request body
> 2009/05/17 18:44:07 [debug] 20128#0: *598 recv: eof:0, avail:2896, err:0
> 2009/05/17 18:44:07 [debug] 20128#0: *598 recv: fd:206 2896 of 64040
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body recv 2896
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body rest
> 187842
> 2009/05/17 18:44:07 [debug] 20128#0: *598 event timer: 206, old:
> 1242571506913, new: 1242571507013
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http read client request body
> 2009/05/17 18:44:07 [debug] 20128#0: *598 recv: eof:0, avail:2896, err:0
> 2009/05/17 18:44:07 [debug] 20128#0: *598 recv: fd:206 4344 of 61144
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body recv 4344
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body rest
> 183498
> 2009/05/17 18:44:07 [debug] 20128#0: *598 event timer: 206, old:
> 1242571506913, new: 1242571507014
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http read client request body
> 2009/05/17 18:44:07 [debug] 20128#0: *598 recv: eof:0, avail:5792, err:0
> 2009/05/17 18:44:07 [debug] 20128#0: *598 recv: fd:206 5792 of 56800
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body recv 5792
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body rest
> 177706
> 2009/05/17 18:44:07 [debug] 20128#0: *598 event timer: 206, old:
> 1242571506913, new: 1242571507014
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http read client request body
> 2009/05/17 18:44:07 [debug] 20128#0: *598 recv: eof:0, avail:1448, err:0
> 2009/05/17 18:44:07 [debug] 20128#0: *598 recv: fd:206 1448 of 51008
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body recv 1448
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body rest
> 176258
> 2009/05/17 18:44:07 [debug] 20128#0: *598 event timer: 206, old:
> 1242571506913, new: 1242571507014
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http read client request body
> 2009/05/17 18:44:07 [debug] 20128#0: *598 recv: eof:0, avail:5792, err:0
> 2009/05/17 18:44:07 [debug] 20128#0: *598 recv: fd:206 5792 of 49560
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body recv 5792
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body rest
> 170466
> 2009/05/17 18:44:07 [debug] 20128#0: *598 event timer: 206, old:
> 1242571506913, new: 1242571507014
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http read client request body
> 2009/05/17 18:44:07 [debug] 20128#0: *598 recv: eof:0, avail:2896, err:0
> 2009/05/17 18:44:07 [debug] 20128#0: *598 recv: fd:206 2896 of 43768
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body recv 2896
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body rest
> 167570
> 2009/05/17 18:44:07 [debug] 20128#0: *598 event timer: 206, old:
> 1242571506913, new: 1242571507014
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http read client request body
> 2009/05/17 18:44:07 [debug] 20128#0: *598 recv: eof:0, avail:5296, err:0
> 2009/05/17 18:44:07 [debug] 20128#0: *598 recv: fd:206 5296 of 40872
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body recv 5296
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body rest
> 162274
> 2009/05/17 18:44:07 [debug] 20128#0: *598 event timer: 206, old:
> 1242571506913, new: 1242571507014
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http read client request body
> 2009/05/17 18:44:07 [debug] 20128#0: *598 recv: eof:0, avail:8688, err:0
> 2009/05/17 18:44:07 [debug] 20128#0: *598 recv: fd:206 8688 of 35576
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body recv 8688
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body rest
> 153586
> 2009/05/17 18:44:07 [debug] 20128#0: *598 event timer: 206, old:
> 1242571506913, new: 1242571507014
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http read client request body
> 2009/05/17 18:44:07 [debug] 20128#0: *598 recv: eof:0, avail:1448, err:0
> 2009/05/17 18:44:07 [debug] 20128#0: *598 recv: fd:206 7240 of 26888
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body recv 7240
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body rest
> 146346
> 2009/05/17 18:44:07 [debug] 20128#0: *598 event timer: 206, old:
> 1242571506913, new: 1242571507015
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http read client request body
> 2009/05/17 18:44:07 [debug] 20128#0: *598 recv: eof:0, avail:2896, err:0
> 2009/05/17 18:44:07 [debug] 20128#0: *598 recv: fd:206 7240 of 19648
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body recv 7240
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body rest
> 139106
> 2009/05/17 18:44:07 [debug] 20128#0: *598 event timer: 206, old:
> 1242571506913, new: 1242571507015
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http read client request body
> 2009/05/17 18:44:07 [debug] 20128#0: *598 recv: eof:0, avail:1448, err:0
> 2009/05/17 18:44:07 [debug] 20128#0: *598 recv: fd:206 8688 of 12408
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body recv 8688
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body rest
> 130418
> 2009/05/17 18:44:07 [debug] 20128#0: *598 event timer: 206, old:
> 1242571506913, new: 1242571507015
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http read client request body
> 2009/05/17 18:44:07 [debug] 20128#0: *598 recv: eof:0, avail:5792, err:0
> 2009/05/17 18:44:07 [debug] 20128#0: *598 recv: fd:206 3720 of 3720
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body recv 3720
> 2009/05/17 18:44:07 [debug] 20128#0: *598 add cleanup: 000000000094B238
> 2009/05/17 18:44:07 [debug] 20128#0: *598 hashed path:
> /var/nginx/client_body_temp/0000000003
> 2009/05/17 18:44:07 [debug] 20128#0: *598 temp fd:211
> 2009/05/17 18:44:07 [warn] 20128#0: *598 a client request body is buffered
> to a temporary file /var/nginx/client_body_temp/0000000003, client: x.x.x.x,
> server: example.com, request: "POST /webservices.php/user_content HTTP/1.1",
> host: "example.com"
> 2009/05/17 18:44:07 [debug] 20128#0: *598 write: 211, 000000000118B000,
> 131072, 0
> 2009/05/17 18:44:07 [debug] 20128#0: *598 recv: eof:0, avail:2072, err:0
> 2009/05/17 18:44:07 [debug] 20128#0: *598 recv: fd:206 2072 of 126698
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body recv 2072
> 2009/05/17 18:44:07 [debug] 20128#0: *598 http client request body rest
> 124626
> 2009/05/17 18:44:07 [debug] 20128#0: *598 event timer: 206, old:
> 1242571506913, new: 1242571507015
> 2009/05/17 18:45:06 [debug] 20128#0: *598 event timer del: 206:
> 1242571506913
> 2009/05/17 18:45:06 [debug] 20128#0: *598 http finalize request: 408,
> "/webservices.php/user_content?"
> 2009/05/17 18:45:06 [debug] 20128#0: *598 http close request
> 2009/05/17 18:45:06 [debug] 20128#0: *598 http log handler
> 2009/05/17 18:45:06 [debug] 20128#0: *598 run cleanup: 000000000094B238
> 2009/05/17 18:45:06 [debug] 20128#0: *598 file cleanup: fd:211
> 2009/05/17 18:45:06 [debug] 20128#0: *598 free: 000000000118B000
> 2009/05/17 18:45:06 [debug] 20128#0: *598 free: 000000000094A000, unused: 8
> 2009/05/17 18:45:06 [debug] 20128#0: *598 free: 000000000094B000, unused:
> 3344
> 2009/05/17 18:45:06 [debug] 20128#0: *598 close http connection: 206
> 2009/05/17 18:45:06 [debug] 20128#0: *598 free: 00000000005EA400
> 2009/05/17 18:45:06 [debug] 20128#0: *598 free: 00000000005E2800
> 2009/05/17 18:45:06 [debug] 20128#0: *598 free: 0000000000918600, unused: 8
> 2009/05/17 18:45:06 [debug] 20128#0: *598 free: 0000000000918700, unused:
> 112

-- 
Игорь Сысоев
http://sysoev.ru