Welcome! Log In Create A New Profile

Advanced

Re: Strange log entries (upstream time/request_time)

Maxim Dounin
October 27, 2011 10:34AM
Hello!

On Thu, Oct 27, 2011 at 09:58:01AM -0400, rsawer wrote:

> Hi,
>
> I'm running a simple nginx->memcache->backend architecture, and I'm
> currently facing some backend problems.
>
> While debugging the situation I've run on some strange log entries which
> look like nginx was incorrectly giving the summary request_time value :
>
>
> 91.180.100.2 www.mydomain.com "23/Oct/2011:22:30:05 +0200"
> "10.1.0.41:11211 : 10.1.0.48:90" "GET /images/footer-simple.gif
> HTTP/1.1" 200 (404 : 200) UP_RESPONSE 0.001 : 60.001 request_time
> 120.004
>
> So, nginx check's for content in memcache, memcache (10.1.0.41) gives
> 404 in less than 1ms, then nginx goes to the overloaded apache backend,
> which gives 200 status content in 60 seconds. What bothers me is the
> $request_time value, which shows that it took's 120second for nginx to
> handle the request, and it's not the sum of memcache and backend
> request_time.
>
> For example I'm giving you another log entry where nginx evaluates the
> value correctly:
>
> 91.180.100.1 www.mydomain.com "23/Oct/2011:21:11:03 +0200"
> "10.1.0.41:11211 : 10.1.0.48:82, 10.1.0.46:82" "GET
> /?zanpid=1563268107744039936 HTTP/1.1" 301 (404 : 502, 301) UP_RESPONSE
> 0.001 : 67.387, 35.46
> 6 request_time 102.854
>
> Here you see that memcache + backends reponse values are equal to the
> $request_time value, and this is what I see in my logs by default, the
> problematic situation occurs very rarely.
>
> Here is my logformat:
> log_format upstream '$remote_addr $host "$time_local" "$upstream_addr"
> "$request" $status ($upstream_status) UP_RESPONSE
> $upstream_response_time request_time $request_time';
>
> Anybody can explain that behaviour?

The $request_time variable counts full request lifetime, including
reading request from client and sending response to client.

The 120.004 in log entry which bothers you may indicate that
client wasn't reading response fast enough (or just gave up
waiting and silently gone) and response was actually terminated
due to send_timeout (which defaults to 60s).

Maxim Dounin

_______________________________________________
nginx mailing list
nginx@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx
Subject Author Posted

Strange log entries (upstream time/request_time)

rsawer October 27, 2011 09:58AM

Re: Strange log entries (upstream time/request_time)

Maxim Dounin October 27, 2011 10:34AM

Re: Strange log entries (upstream time/request_time)

rsawer October 28, 2011 08:39AM



Sorry, only registered users may post in this forum.

Click here to login

Online Users

Guests: 220
Record Number of Users: 8 on April 13, 2023
Record Number of Guests: 421 on December 02, 2018
Powered by nginx      Powered by FreeBSD      PHP Powered      Powered by MariaDB      ipv6 ready