SOAP POST request lag

[Vitaliy Okulov]

Ок, спасибо. Будем копать дальше.

20 мая 2009 г. 16:39 пользователь Igor Sysoev <is at rambler-co.ru> написал:

> 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
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://nginx.org/pipermail/nginx-ru/attachments/20090520/bdbf2667/attachment.html>