Discrepancies between response time in server logs and chrome creation tools

Question

I downloaded the site testing and noticed a rather big difference between the time information received from the web server (in this case, the tornado web server ) and Chrome Developer Tools. The web server provides a service that runs as a process (in fact, a couple of processes controlled by a supervisor) for nginx. There is also a web interface for interacting with this service. This tornado web server receives requests quite quickly (on average 30 ms). However, Chrome Developer Tools shows a much slower response time (about 240 ms).

Each request retrieves some information and requires a request for additional resources (mainly images). I thought this was the main reason for such a big difference, but I tried to use curl and time_starttransfer measures of 172ms.

On the other hand, using this registration 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 verify that request_time and upstream_response_time are actually quite small (45 ms).

What could be the reason for this discrepancy in response time?

UPDATE

This is a screenshot from Firebug:

I don’t think I can understand latency with this limited information.

UPDATE 2

I was able to get the best curled information. I'm not sure how accurate this is:

  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 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). Moreover, time_connect in the output of curl, which I suppose should be a delay, is not so large (0,062s).

Interestingly, time_starttransfer - time_connect*2 = 0.048 similar to the time registered by nginx or tornado (0.048 against 0.044). But this calculation does not have to be correct. Does anyone know what is the right way to justify the difference between response time in developer chrome tools / curl vs web server / nginx?

Answer 1

TL DR

You are comparing apples to oranges ... Test your RTD for ping .

HTTP request processing

A simplified (but still rather complex) set of steps that are performed for a single HTTP (S) request is as follows:

• The client performs a DNS lookup to resolve the hostname in the URL.
• The client establishes a TCP connection with the host server.
• The client does not necessarily go through TLS negotiation (only for HTTPS connections).
• The client finally sends the request through the connection - the beginning of this step is when the client is about to send the first byte.
• The web server receives the request and begins to process it.
• The web server begins to send a response.
• The client begins to receive it, that is, it receives the first byte of the response.
• The server continues to transmit data to the server until it reaches the end of the response.
• The client receives the latest data.

As you can see, the web server really only knows steps 5 through 8 (since most of the initial connection settings will be out of control) and can only measure 5-6 and 5-8. However, the client knows steps 1 through 9. In addition, he can measure the exact opposite list of data points.

Network delay

Any request or response must be transmitted over the network (usually the Internet for public service) and therefore takes a delay because the data is transferred from machine to machine. The shortest time that can be required between two machines (from one to the other and vice versa) is called Shutdown Time (RTT) or Shutdown Delay (RTD) . This affects all communications and is usually measured using tools like ping .

This RTD affects all messages, 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.

Final result

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

You do not have enough time between 4-5 and 6-7, as we saw above, this is mainly RTD.

Therefore, you should find that time_starttransfer = time_pretransfer + request_time + RTD

Answer 2

The client does not know what is happening on the server. He does not know when the request reaches the other end, and when the other end began to send a response.

You are trying to compare a number measured from two endpoints, but there is a significant delay between them, and they are limited in communication.

If you really want to understand this delay in detail, you should find out how TCP works. I just note that the connection action is not something immediate or one action, it involves the exchange of packets between the server and the client. The same can be said about data transfer.