Use the curl command to analyze the time consumed by the request

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

-w, --write-out <format>
              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.

➜  ~ 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.

➜  ~ 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

To a more complex, access to the home page of Baidu, with redirects and SSL protocols in between.

➜  ~ 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.

Table of Contents