One upstream connection blocks another upstream connection
Lars Jeppesen
jeppesen.lars at gmail.com
Tue Mar 13 13:10:03 UTC 2018
Hi,
I’m investing a problem where I get delays in requests that is proxied to
an upstream service.
By looking at the debug log it seems that one request is blocking the
worker so it can’t complete another requests.
If you look at the log below request *352 is handled by worker 18728. This
worker then starts to process request *360 but for reason it is blocked at
13:53:53 until 13:54:03. How can that happen ?
The upstream service for request *360 doesn’t send any data in the time
interval 13:53:53-15:54:03.
But the upstream service for request *352 responses nearly immediately.
(I have examined the communication between nginx and the upstream in
wireshark)
Another observation, in the time interval 13:53:53-15:54:03 the worker
process seems to be in state D (uninterruptible sleep)
So my question is: What can block worker 18728 so it doesn’t complete
request *352
OS: Redhat 7.4
Nginx: 1.12.2
Hopefully I have provided enough details.
Thanks in advance
Lars
---------------- nginx debug error log
---------------------------------------------------------------------
2018/03/09 13:53:40 [debug] 18726#0: *249 input buf #95517
2018/03/09 13:53:32 [debug] 18728#0: *189 pipe temp offset: 588029952
2018/03/09 13:53:40 [debug] 18726#0: *249 input buf #95518
2018/03/09 13:53:32 [debug] 18728#0: *189 readv: eof:0, avail:1
2018/03/09 13:53:40 [debug] 18726#0: *249 pipe offset: 368738304
2018/03/09 13:53:32 [debug] 18728#0: *189 readv: 2, last:4096
2018/03/09 13:53:40 [debug] 18726#0: *249 pipe buf ls:1 0000556CF522BAF0,
pos 0000556CF522BAF0, size: 4096
2018/03/09 13:53:40 [debug] 18726#0: *249 pipe buf ls:1 0000556CF5233250,
pos 0000556CF5233250, size: 4096
2018/03/09 13:53:32 [debug] 18728#0: *189 pipe recv chain: 8192
2018/03/09 13:53:40 [debug] 18726#0: *249 pipe buf ls:1 0000556CF522EB20,
pos 0000556CF522EB20, size: 4096
2018/03/09 13:53:32 [debug] 18728#0: *189 input buf #144060
2018/03/09 13:53:40 [debug] 18726#0: *249 size: 8192
2018/03/09 13:53:32 [debug] 18728#0: *189 input buf #144061
2018/03/09 13:53:40 [debug] 18726#0: *249 writev: 22, 8192, 368738304
2018/03/09 13:53:32 [debug] 18728#0: *189 pipe offset: 588029952
2018/03/09 13:53:32 [debug] 18728#0: *189 pipe buf ls:1 0000556CF5220480,
pos 0000556CF5220480, size: 4096
2018/03/09 13:53:32 [debug] 18728#0: *189 pipe buf ls:1 0000556CF5233250,
pos 0000556CF5233250, size: 4096
2018/03/09 13:53:40 [debug] 18726#0: *249 pipe temp offset: 368746496
2018/03/09 13:53:32 [debug] 18728#0: *189 pipe buf ls:1 0000556CF522CAF0,
pos 0000556CF522CAF0, size: 4096
2018/03/09 13:53:53 [debug] 18729#0: *352 writev: 418 of 418
2018/03/09 13:53:40 [debug] 18726#0: *249 readv: eof:0, avail:1
2018/03/09 13:53:32 [debug] 18728#0: *189 size: 8192
2018/03/09 13:53:53 [debug] 18729#0: *352 chain writer out: 0000000000000000
2018/03/09 13:53:40 [debug] 18726#0: *249 readv: 2, last:4096
2018/03/09 13:53:53 [debug] 18729#0: *352 event timer del: 14: 1520603638051
2018/03/09 13:53:32 [debug] 18728#0: *189 writev: 18, 8192, 588029952
2018/03/09 13:53:53 [debug] 18729#0: *352 event timer add: 14:
86400000:1520690033051
----------- lines removed ------------------------------------------
2018/03/09 13:53:53 [debug] 18729#0: *360 pipe buf in s:1 t:1 f:0
0000556CF5232240, pos 0000556CF5232240, size: 4096 file: 0, size: 0
2018/03/09 13:53:53 [debug] 18729#0: *360 pipe buf free s:0 t:1 f:0
0000556CF5236280, pos 0000556CF5236280, size: 75 file: 0, size: 0
2018/03/09 13:53:53 [debug] 18729#0: *360 pipe length: -1
2018/03/09 13:53:53 [debug] 18729#0: *360 event timer: 18, old:
1520690033267, new: 1520690033348
2018/03/09 13:53:53 [debug] 18729#0: *360 event timer add: 16:
86400000:1520690033348
2018/03/09 13:53:53 [debug] 18729#0: *360 http upstream request:
"/download_stream/http://127.0.0.1:46766/5ad8c4fe-c9a5-4d3e-ad57-18ad8
18bc29f.pcap?"
2018/03/09 13:53:53 [debug] 18729#0: *360 http upstream dummy handler
2018/03/09 13:54:03 [debug] 18729#0: *360 http upstream request:
"/download_stream/http://127.0.0.1:46766/5ad8c4fe-c9a5-4d3e-ad57-18ad8
18bc29f.pcap?"
2018/03/09 13:54:03 [debug] 18729#0: *360 http upstream process upstream
2018/03/09 13:54:03 [debug] 18729#0: *360 pipe read upstream: 1
2018/03/09 13:54:03 [debug] 18729#0: *360 readv: eof:1, avail:1
----------- lines removed ------------------------------------------
2018/03/09 13:54:03 [debug] 18729#0: *360 SSL_write: -1
2018/03/09 13:54:03 [debug] 18729#0: *360 SSL_get_error: 3
2018/03/09 13:54:03 [debug] 18729#0: *360 http write filter 0000556CF5235600
2018/03/09 13:54:03 [debug] 18729#0: *360 http copy filter: -2
"/download_stream/http://127.0.0.1:46766/5ad8c4fe-c9a5-4d3e-ad57-18ad818
bc29f.pcap?"
2018/03/09 13:54:03 [debug] 18729#0: *360 http writer output filter: -2,
"/download_stream/http://127.0.0.1:46766/5ad8c4fe-c9a5-4d3e-ad
57-18ad818bc29f.pcap?"
2018/03/09 13:54:03 [debug] 18729#0: *360 event timer: 16, old:
1520690043209, new: 1520690043209
2018/03/09 13:54:03 [debug] 18729#0: *352 http upstream request:
"/1/search/74dc9b3c-dd89-11e6-9b3b-0894ef39879c/99fbbec6-a6f5-4f42-82f
6-5cc2f9651f45?"
2018/03/09 13:54:03 [debug] 18729#0: *352 http upstream process header
2018/03/09 13:54:03 [debug] 18729#0: *352 malloc: 0000556CF524C2D0:4096
2018/03/09 13:54:03 [debug] 18729#0: *352 recv: eof:1, avail:1
2018/03/09 13:54:03 [debug] 18729#0: *352 recv: fd:14 278 of 4096
2018/03/09 13:54:03 [debug] 18729#0: *352 http proxy status 200 "200 OK"
2018/03/09 13:54:03 [debug] 18729#0: *352 http proxy header: "Syncuuid:
5304cf38-1cd8-11e6-bddc-0894ef1af70f"
2018/03/09 13:54:03 [debug] 18729#0: *352 http proxy header:
"Content-Length: 78"
2018/03/09 13:54:03 [debug] 18729#0: *352 http proxy header: "Syncmagic: 3"
2018/03/09 13:54:03 [debug] 18729#0: *352 http proxy header: "Content-Type:
application/json"
2018/03/09 13:54:03 [debug] 18729#0: *352 http proxy header: "Server:
Pandion/7.3.3-3933"
2018/03/09 13:54:03 [debug] 18729#0: *352 http proxy header:
"Transfer-Encoding: chunked"
2018/03/09 13:54:03 [debug] 18729#0: *352 http proxy header done
2018/03/09 13:54:03 [debug] 18729#0: *352 HTTP/1.1 200 OK
Date: Fri, 09 Mar 2018 13:54:03 GMT
Content-Type: application/json
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.nginx.org/pipermail/nginx/attachments/20180313/3b6f5ddd/attachment-0001.html>
More information about the nginx
mailing list