Opened 11 years ago

Closed 11 years ago

#356 closed defect (worksforme)

$request_time and $upstream_response_time exactly the same since 1.3.15

Reported by: Mathieu Martin Owned by:
Priority: minor Milestone:
Component: nginx-core Version: 1.3.x
Keywords: upstream, time Cc:
uname -a: Linux (removed) 2.6.32-358.6.1.el6.x86_64 #1 SMP Tue Apr 23 19:29:00 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux
nginx -V: nginx version: nginx/1.4.1
built by gcc 4.4.7 20120313 (Red Hat 4.4.7-3) (GCC)
TLS SNI support enabled
configure arguments: --prefix=/opt/nginx-1.4.1 --conf-path=/etc/nginx/nginx.conf --sbin-path=/opt/nginx-1.4.1/sbin/nginx --with-http_ssl_module --with-http_gzip_static_module --with-http_realip_module

Description

Since deploying nginx 1.4.1, we've noticed that $request_time and $upstream_response_time are exactly the same (for requests served with the help of an upstream server). We've observed this situation on hundreds of requests.

I'm seeing this on CentOS 6.4, installing from source.

I've checked a few versions.

The following versions are fine (the times are slightly different): 1.2.7, 1.2.8, 1.2.9, 1.3.10, 1.3.12, 1.3.14

The following versions have the problem (the times are precisely the same): 1.3.15, 1.4.0, 1.4.1

This is my first time reporting a bug here. Please let me know if you want me to clean up my bug report, or if anything's amiss.

Thanks for the awesome work.

Mat

Change History (1)

comment:1 by Maxim Dounin, 11 years ago

Resolution: worksforme
Status: newclosed

As of 1.3.15, $request_time calculation was slightly changed due to some optimizations introduced, and for a first request in a connection it no longer includes time between opening a connection and reading a first byte from a client. It still works correctly though. With the following configuration:

    log_format foo "request_time:$request_time "
                   "upstream_response_time:$upstream_response_time";
    access_log /path/to/log foo;

I see the following in logs by typing a request by hand with telnet:

request_time:5.102 upstream_response_time:0.182
Note: See TracTickets for help on using tickets.