I recently ran into a problem at work where the response to a request was particularly slow, so I wanted a way to analyze which step of the request was taking longer so I could find the cause of the problem further. After searching the web, I found a very useful method, the curl command, which can help you analyze the time spent on each part of the request.

The curl command provides the -w parameter, which is explained in the manpage as follows

 1 2 3 4 5 6 7  -w, --write-out Make curl display information on stdout after a completed transfer. The format is a string that may contain plain text mixed with any number of variables. The format can be specified as a literal "string", or you can have curl read the format from a file with "@filename" and to tell curl to read the format from stdin you write "@-". The variables present in the output format will be substituted by the value or text that curl thinks fit, as described below. All variables are specified as %{vari‐ able_name} and to output a normal % you just write them as %%. You can output a newline by using \n, a carriage return with \r and a tab space with \t. 

It can print certain information in a specified format, it can use certain variables, and it supports \n, \t and \r escape characters. There are many variables provided, such as status_code, local_port, size_download, etc. In this article we will only focus on variables related to the request time (variables starting with time_).

First, write the following to the text file curl-format.txt.

 1 2 3 4 5 6 7 8 9  ➜ ~ cat curl-format.txt time_namelookup: %{time_namelookup}\n time_connect: %{time_connect}\n time_appconnect: %{time_appconnect}\n time_redirect: %{time_redirect}\n time_pretransfer: %{time_pretransfer}\n time_starttransfer: %{time_starttransfer}\n ----------\n time_total: %{time_total}\n 

So what do all these variables mean? Let me explain.

• time_namelookup : the time when DNS domain name is resolved, which is the process of converting https://zhihu.com into an ip address
• time_connect : the time of TCP connection establishment, that is, the time of three handshakes
• time_appconnect : the time it takes for SSL/SSH and other upper layer protocols to establish a connection, such as connect/handshake
• time_redirect : the time from the beginning to the last request transaction
• time_pretransfer : the time from the start of the request to the start of the response transmission
• time_starttransfer : the time from the start of the request until the first byte will be transferred
• time_total : the total time spent on this request

Let’s look at the time of a simple request without redirection and without SSL protocol.

 1 2 3 4 5 6 7 8 9  ➜ ~ curl -w "@curl-format.txt" -o /dev/null -s -L "http://cizixs.com" time_namelookup: 0.012 time_connect: 0.227 time_appconnect: 0.000 time_redirect: 0.000 time_pretransfer: 0.227 time_starttransfer: 0.443 ---------- time_total: 0.867 

You can see that the time of each step of this request is printed out, and the unit of each number is seconds, so that you can analyze which step is more time-consuming, and it is convenient to locate the problem. The meaning of each parameter of this command.

• -w : read the format of the information to be printed from the file
• -o /dev/null : discard the response, because we don’t care about it here, only about the time consumption of the request
• -s : don’t print the progress bar

From this output, we can calculate the time for each step.

• DNS query: 12ms
• TCP connection time: pretransfter(227) - namelookup(12) = 215ms
• Server processing time: starttransfter(443) - pretransfer(227) = 216ms
• Content transfer time: total(867) - starttransfer(443) = 424ms

 1 2 3 4 5 6 7 8 9  ➜ ~ curl -w "@curl-format.txt" -o /dev/null -s -L "https://baidu.com" time_namelookup: 0.012 time_connect: 0.018 time_appconnect: 0.328 time_redirect: 0.356 time_pretransfer: 0.018 time_starttransfer: 0.027 ---------- time_total: 0.384 
You can see that both time_appconnect and time_redirect are not 0 anymore, where the SSL protocol processing time is 328-18=310ms. And the time for pretransfer and starttransfer have both been reduced, which is the time for requests after redirection.