How To Track NGINX Response Time For Applications?

I have been working as a Linux Admin from last years and every day is a learning day. And sometimes you stuck with few things. During my work, I notice that there is something wrong, which is slowing down my NGINX web server and I had to track down the cause of the issue.

Scenario: My Server IP was 192.168.1.172
OS: CentOS 6.9

Well, NGINX has an inbuilt upstream module which allows NGINX to log response time trivial with its upstream response time variable and allows to calculate NGINX Response Time. Well with my Application there was lots task were going on like the use of REDIS and MySql insertion/update so it was really necessary to get an exact time for the same.

To get this total time (incoming of request to response request ) I decided to make few changes in NGINX log format and three variable ($request_time $upstream_response_time $pipe) appended in standard log format to calculate NGINX Response Time.

This is the default format with the three variables appended (combined) to it.

request_time – This will tell you the time taken to deal the request.
upstream_response_time – This is the time which is taken by the upstream server to respond.
pipe – it tells the ‘p’ in case the request was pipelined.

Let’s Start

Step 1: Make changes in Nginx Configuration

First, we need to make three change sin mail log format in NGINX configuration file /etc/nginx/nginx.conf

#vim /etc/nginx/nginx.conf

......................
.............................

http {
 include /etc/nginx/mime.types;
 default_type application/octet-stream;

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

 access_log /var/log/nginx/access.log main;
.....................................
.............................................

Step 2: Include Log Format

Now we need to use this main log format in our application log. So now we will modify our virtual host configuration for our application domain. Here just add main in last of the access_log

# vim /etc/nginx/conf.d/site1.conf
server {
 listen *:80;
 server_name site1.example.com;

 access_log /var/log/nginx/site1.exmaple.com_access_log main;
 error_log /var/log/nginx/site1.exmaple.com_error.log;
location / {
 root /var/www/html/site1;
 index index.html index.htm;
 }
}

Save File with :wq!

Step 3: Restart Nginx And Look LOGs

Now restart Nginx server and out for log file. we should see these change log output and you will notice that there are 3 new directives (0.018, 0.018,.).

#service nginx restart
#vim /var/log/nginx/site1.exmaple.com_access_log 54.249.79.62 - - [02/Jun/2017:17:12:28 +0530] "GET /index.html HTTP/1.1" 200 179 "-" "Mozilla/5.0 (Devlik; Aqua20/2.1; +http://www.assel.com/war.php)" 0.018 0.018 .

Well now we have request time, server upstream time, here in this example www.assel.com came to our server from 54.249.79.62 . our server took 0.018 sec to serve this request and ‘.’ show there is no pipelining.

After some analysis, we can figure out what was causing a slow down on our server and we can fix this. Nginx logging variable can give us list of information like cookies, HTTP headers etc.you can find documentation on these variables on Nginx core variable page

Watch Video.