32

I've started using Nginx as a reverse proxy for a set of servers that provide some sort of service.

The service can be rather slow at times (its running on Java and the JVM sometimes gets stuck in "full garbage collection" that may take several seconds), so I've set the proxy_connect_timeout to 2 seconds, which will give Nginx enough time to figure out that the service is stuck on GC and will not respond in time, and it should pass the request to a different server.

I've also set proxy_read_timeout to prevent the reverse proxy from getting stuck if the service itself takes too much time to compute the response - again, it should move the request to another server that should be free enough to return a timely response.

I've run some benchmarks and I can see clearly that the proxy_connect_timeout works properly as some requests return exactly on the time specified for the connection timeout, as the service is stuck and doesn't accept incoming connections (the service is using Jetty as an embedded servlet container). The proxy_read_timeout also works, as I can see requests that return after the timeout specified there.

The problem is that I would have expected to see some requests that timeout after proxy_read_timeout + proxy_connect_timeout, or almost that length of time, if the service is stuck and won't accept connections when Nginx tries to access it, but before Nginx can timeout - it gets released and starts processing, but is too slow and Nginx would abort because of the read timeout. I believe that the service has such cases, but after running several benchmarks, totaling several millions of requests - I failed to see a single request that returns in anything above proxy_read_timeout (which is the larger timeout).

I would appreciate any comment on this issue, though I think that could be due to a bug in Nginx (I have yet to look at the code, so this is just an assumption) that the timeout counter doesn't get reset after the connection is successful, if Nginx didn't read anything from the upstream server.

Guss
  • 2,670
  • 5
  • 34
  • 59
  • 2
    What version of NGINX? I think I remember something similar in an older version (about 0.6/7 maybe) but it was fixed in a more recent version (The latest stable version is 1.0.5), but that might be wrong. Still knowing your version would help –  Aug 18 '11 at 09:38
  • Notice that docs say `proxy_read_timeout` isn't the "global timeout", but between 2 read operations. – poige Aug 20 '11 at 01:59
  • @Sam: I'm using Nginx 1.0.0. @poige - yes, I'm aware of that, which is why I expect the total timeout to be `proxy_read_timeout + proxy_connect_timeout`. – Guss Aug 20 '11 at 09:29
  • 1
    As a side note, you should probably research some concurrent garbage collection tuning for your JVM: http://en.wikipedia.org/wiki/Garbage_collection_(computer_science)#Stop-the-world_vs._incremental_vs._concurrent – polynomial Aug 21 '11 at 02:44
  • @polynomial: we did but according to our benchmarks the concurrent garbage collection feature results in more CPU time lost to GC overall compared to "stop the world" GC, hence we prefer investing in Nginx tuning :-) – Guss Aug 21 '11 at 16:27

2 Answers2

32

I was actually unable to reproduce this on:

2011/08/20 20:08:43 [notice] 8925#0: nginx/0.8.53
2011/08/20 20:08:43 [notice] 8925#0: built by gcc 4.1.2 20080704 (Red Hat 4.1.2-48)
2011/08/20 20:08:43 [notice] 8925#0: OS: Linux 2.6.39.1-x86_64-linode19

I set this up in my nginx.conf:

proxy_connect_timeout   10;
proxy_send_timeout      15;
proxy_read_timeout      20;

I then setup two test servers. One that would just timeout on the SYN, and one that would accept connections but never respond:

upstream dev_edge {
  server 127.0.0.1:2280 max_fails=0 fail_timeout=0s; # SYN timeout
  server 10.4.1.1:22 max_fails=0 fail_timeout=0s; # accept but never responds
}

Then I sent in one test connection:

[m4@ben conf]$ telnet localhost 2480
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
GET / HTTP/1.1
Host: localhost

HTTP/1.1 504 Gateway Time-out
Server: nginx
Date: Sun, 21 Aug 2011 03:12:03 GMT
Content-Type: text/html
Content-Length: 176
Connection: keep-alive

Then watched error_log which showed this:

2011/08/20 20:11:43 [error] 8927#0: *1 upstream timed out (110: Connection timed out) while connecting to upstream, client: 127.0.0.1, server: ben.dev.b0.lt, request: "GET / HTTP/1.1", upstream: "http://10.4.1.1:22/", host: "localhost"

then:

2011/08/20 20:12:03 [error] 8927#0: *1 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 127.0.0.1, server: ben.dev.b0.lt, request: "GET / HTTP/1.1", upstream: "http://127.0.0.1:2280/", host: "localhost"

And then the access.log which has the expected 30s timeout (10+20):

504:32.931:10.003, 20.008:.:176 1 127.0.0.1 localrhost - [20/Aug/2011:20:12:03 -0700] "GET / HTTP/1.1" "-" "-" "-" dev_edge 10.4.1.1:22, 127.0.0.1:2280 -

Here is the log format I'm using which includes the individual upstream timeouts:

log_format  edge  '$status:$request_time:$upstream_response_time:$pipe:$body_bytes_sent $connection $remote_addr $host $remote_user [$time_local] "$request" "$http_referer" "$http_user_agent" "$http_x_forwarded_for" $edge $upstream_addr $upstream_cache_status';
polynomial
  • 4,016
  • 14
  • 24
  • 1
    My question above, in your scenario, is more like this: suppose a test server that accepts the connection after a random time between 0 and 20 seconds, and then waits a random time between 19 seconds and 21 seconds before answering. Then run a simple benchmark against it. I'd expect to see about 50% of the requests result with a 10 seconds timeout, 25% result with a 20~30 seconds timeout and 25% will receive a successful response. In such a case, how many **successful** requests will take more then 20 seconds to complete? In my benchmark, none of them are - and that troubles me. – Guss Aug 21 '11 at 16:41
  • I tested by setting up random loss on the SYN and then having a CGI that spit out lines really slowly for about 50 seconds. I was able to see requests taking a lot longer than both timeouts combined but still being successful: box.access.log 200:69.814:67.100:.:1579 33 127.0.0.1 test.host - [21/Aug/2011:20:30:52 -0700] "GET /huugs HTTP/1.1" "-" "-" "-" dev_edge 127.0.0.1:2280 - – polynomial Aug 22 '11 at 03:30
  • Ok, that is weird on a whole different level :-). One possible explanation is that it takes time for Nginx to write the request (`proxy_send_timeout`) and as you've set it to higher then `proxy_connection_timeout`, that can actually account for any delay over the 20 seconds `proxy_read_timeout`. When you say "spit out lines really slowly" - what do you mean? – Guss Aug 22 '11 at 09:05
  • sleep 1 between printing lines of HTML in the body of the response. Just exposing how the proxy_read_timeout is between reads not the entire read. – polynomial Aug 22 '11 at 22:54
  • 1
    Ah, I see. Well, this is definitely not my case and I'm sorry for not making it clear in my OP. In my case, the application server completes the entire processing before returning any kind of response, and then returns everything at once - so the `proxy_read_timeout` either fails the request completely or allows it completely. This also explains the difference between the behavior you see and the behavior I see. – Guss Aug 24 '11 at 10:50
7

The problem is that I would have expected to see some requests that timeout after proxy_read_timeout + proxy_connect_timeout, or almost that length of time, if the service is stuck and won't accept connections when Nginx tries to access it, but before Nginx can timeout - it gets released and starts processing, but is too slow and Nginx would abort because of the read timeout.

Connect timeout means TCP stalls when handshaking (for e. g., there were no SYN_ACKs). TCP would re-try sending SYNs, but you've given only to 2 sec. to Nginx to go use another Server, so it simply has no time for re-sending SYNs.

UPD.: Couldn't find in docs, but tcpdump shows that there's 3 sec. delay between 1st sent SYN and the 2nd attempt to send SYN.

poige
  • 9,448
  • 2
  • 25
  • 52
  • 1
    I don't think this is exactly that I'm asking - the question is: if the upstream gets stuck and returns the SYN_ACK after 1.999 seconds, why won't nginx continue with the process with the current upstream? – Guss Aug 20 '11 at 09:28
  • Well, you can use sniffer if you want to be sure exactly. It might turn out that there're no ACKs in < 2 sec at all. – poige Aug 20 '11 at 12:20
  • I can't really use a sniffer because I expect to see this behavior happen where there is a a high load on the system. The explanation of there are never ACKs later then some X but earlier then 2 seconds, even when considering millions of requests, seems non-plausible. – Guss Aug 21 '11 at 16:24