Welcome! Log In Create A New Profile

Advanced

One upstream connection blocks another upstream connection

Lars Jeppesen
March 13, 2018 09:12AM
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
_______________________________________________
nginx mailing list
nginx@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx
Subject Author Posted

One upstream connection blocks another upstream connection

Lars Jeppesen March 13, 2018 09:12AM



Sorry, only registered users may post in this forum.

Click here to login

Online Users

Guests: 114
Record Number of Users: 8 on April 13, 2023
Record Number of Guests: 500 on July 15, 2024
Powered by nginx      Powered by FreeBSD      PHP Powered      Powered by MariaDB      ipv6 ready