Discrepancies between response time in server logs and chrome developer tools

Question

I was load testing a site and noticed a fairly big difference between the timing information I received from the web server (in this case, a tornado web server) and Chrome Developer Tools. The web server provides a service running as a process (actually, a couple of processes managed by supervisor) behind nginx. There is also a web interface to interact with this service. This tornado web server retrieves queries fairly fast (30ms on average). However, Chrome Developer Tools shows a much slower response time (around 240ms).

Every query retrieves some information and needs to query additional resources (mainly, images). I thought that was the main reason for such a big difference, but I tried using curl and time_starttransfer measures 172ms.

On the other hand, using this logging directive for nginx:

log_format timed_combined '$remote_addr - $remote_user [$time_local] '
    '"$request" $status $body_bytes_sent '
    '"$http_referer" "$http_user_agent" '
    '$request_time $upstream_response_time $pipe';

I was able to check that request_time and upstream_response_time are actually quite small (45 ms).

What could be the cause for such a discrepancy in response times?

UPDATE

This is a screenshot from Firebug:

I don't think I can figure out latency with that limited information.

UPDATE 2

I was able to get better information with curl. I'm not sure if it is accurate, though:

    time_namelookup:  0.000
       time_connect:  0.062
    time_appconnect:  0.000
   time_pretransfer:  0.062
      time_redirect:  0.000
 time_starttransfer:  0.172
                    ----------
         time_total:  0.240

From what I can see, time_starttransfer - time_pretransfer = content_generation, so 0.172 - 0.062 = 0.110s. However, looking at the logs, the web server reports 0.044s and request_time from nginx agrees (0.045s). Furthermore, time_connect in the curl output, which I think is supposed to be the latency, is not so large (0.062s).

The interesting thing is that time_starttransfer - time_connect*2 = 0.048 is similar to the time reported by nginx or tornado (0.048 vs 0.044). But this calculation is not supposed to be correct. Does anyone know what is the correct way to justify the difference between response times in chrome developer tools/curl vs web server/nginx?

Answer 1

TL; DR

You are comparing apples with oranges... Check your RTD with ping.

HTTP request procesing

The simplified (yet still pretty complex) set of steps that occur for a single HTTP(S) request are as follows:

1. The client does a DNS lookup to resolve the host name in the URL.
2. The client establishes a TCP connection to the host server.
3. The client optionally goes through a TLS negotiation (for HTTPS connections only).
4. The client finally sends the request across the connection - the start of this stage is when the client is about to send the first byte.
5. The web server receives the request and starts processing it.
6. The web server starts sending the response.
7. The client starts receiving it - i.e. it recieves the first byte of the response.
8. The server continues to stream the data to the server until it reaches the end of the response.
9. The client receives the last of the data.

As you can see, the web server is only really aware of steps 5 to 8 (as a lot of the initial connection setup will be outside of its control) and can only measure 5-6 and 5-8. However, the client is aware of steps 1 to 9. In addition, it can measure the exact opposite list of data points.

Network latency

Any request or response has to be transmitted across the network (usually the Internet for a public service) and so incurs a delay as the data is transmitted from machine to machine. The shortest time this can take between 2 machines (from one to the other and back again) is called the Round Trip Time (RTT) or Round Trip Delay (RTD). This affects all communications and is usually measured using tools like ping.

This RTD affects all communications and HTTP requests are no exception, so it will be very close to the sum of the delays between steps 4-5 and 6-7 in the above steps.

Net result

Putting that all together, then, you should find that curl has measured steps 1-4 (well, to the start of 4) for you as returned by time_pretransfer. In addition, it has also measured 1-7 (likewise the start of 7) for you as time_starttransfer. The server, however, has measured the time for 5-6.

You are missing the time between 4-5 and 6-7, which we have seen above is basically the RTD.

You should therefore find that time_starttransfer = time_pretransfer + request_time + RTD