Extracted from nginx blog, article from Rick Nelson · January 7, 2016

Using the NGINX Built-In Timing Variables

NGINX provides a number of built-in timing variables that you can include in log entries. All are measured in seconds with millisecond resolution.

• $request_time – Full request time, starting when NGINX reads the first byte from the client and ending when NGINX sends the last byte of the response body
• $upstream_connect_time – Time spent establishing a connection with an upstream server
• $upstream_header_time – Time between establishing a connection to an upstream server and receiving the first byte of the response header
• $upstream_response_time – Time between establishing a connection to an upstream server and receiving the last byte of the response body

Here is a sample log format called apm that includes these four NGINX timing variables along with some other useful information:

log_format apm '"$time_local" client=$remote_addr '
               'method=$request_method request="$request" '
               'request_length=$request_length '
               'status=$status bytes_sent=$bytes_sent '
               'body_bytes_sent=$body_bytes_sent '
               'referer=$http_referer '
               'user_agent="$http_user_agent" '
               'upstream_addr=$upstream_addr '
               'upstream_status=$upstream_status '
               'request_time=$request_time '
               'upstream_response_time=$upstream_response_time '
               'upstream_connect_time=$upstream_connect_time '
               'upstream_header_time=$upstream_header_time';

Using Application-Defined Timing Values

To drill down, we capture timings in the application itself and include them as response headers, which NGINX then captures in its access log. How granular you want to get is up to you.

To continue with our example, we have the application return the following response headers which record processing time for the indicated internal operations:

• db_read_time – Database lookup
• db_write_time – Database write
• analysis_time – Data analysis
• other_time – All other types of processing

NGINX captures the timing values from the response headers by creating corresponding variables, which it names by prepending the string $upstream_http_ to the header name (for example, $upstream_http_db_read_time corresponds to db_read_time). You can then include the variables in log entries just like standard NGINX variables.

Here is the previous sample log format extended to include the application header values:

log_format apm 'timestamp="$time_local" client=$remote_addr '
               'request="$request" request_length=$request_length '
               'bytes_sent=$bytes_sent '
               'body_bytes_sent=$body_bytes_sent '
               'referer=$http_referer '
               'user_agent="$http_user_agent" '
               'upstream_addr=$upstream_addr '
               'upstream_status=$upstream_status '
               'request_time=$request_time '
               'upstream_response_time=$upstream_response_time '
               'upstream_connect_time=$upstream_connect_time '
               'upstream_header_time=$upstream_header_time '
               'app_db_read_time=$upstream_http_db_read_time '
               'app_db_write_time=$upstream_http_db_write_time '
               'app_analysis_time=$upstream_http_analysis_time '
               'app_other_time=$upstream_http_other_time ';