SOAP POST request lag

[Vitaliy Okulov <vitaliy.okulov@xxxxxxxxx>]

Коллеги, кто может подсказать почему возникает лаг в 50 секунд при POST запросе от SOAP клиента, может ли в этом виноват nginx? При томже запросе напрямую (то есть без 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