Using $upstream_cache_status in access.log

Nginx has a variable $upstream_cache_status. This can be used for any upstream. We are using it mainly for our WordPress + fastcgi_cache.

Define a new log_format in nginx.conf:

log_format rt_cache '$remote_addr - $upstream_cache_status [$time_local]  '
                    '"$request" $status $body_bytes_sent '
                    '"$http_referer" "$http_user_agent"';

Then in server block:

Either replace lines like:

access_log   /var/log/nginx/example.com.access.log;

With line:

access_log   /var/log/nginx/example.com.access.log rt_cache;

OR you can use multiple access logs like below:

access_log   /var/log/nginx/example.com.access.log;
access_log   /var/log/nginx/example.com.cache.log rt_cache;

Please note when using multiple logs, use separate file names.

Once you make above changes, reload nginx config and wait for log files to fill up!

Analysing cache efficiency:

HIT vs MISS vs etc

Run a command like below on your access.log file:

awk '{print $3}' access.log  | sort | uniq -c | sort -r

Sample output:

    800 HIT
    779 -
    392 BYPASS
     19 EXPIRED
     14 MISS

Note: dash (“-“) means request never reached to upstream module. Most likely it means return 403, return 444, and so on.

MISS Request URLs

awk '($3 ~ /MISS/)'  access.log | awk '{print $7}' | sort | uniq -c | sort -r

BYPASS Requests URLs

awk '($3 ~ /BYPASS/)'  access.log | awk '{print $7}' | sort | uniq -c | sort -r

MISS v/s BYPASS

MISS occurs when a pattern is configured to cache but at the time of request was not cached. In correct configuration, subsequent requests will be served from cache based on caching duration other parameters.

BYPASS occurs when a pattern was explicitly configured NOT to use cache. e.g. skipping cache for logged in user. Subsequent requests will also be bypassed.

Recommendations:

  1. If MISS are frequent, consider increasing cache size and/or duration.
  2. For BYPASS, analyse patterns. Many times we set requests with query strings to BYPASS cache. On high traffic site, it will be wise to cache output of certain requests with query strings, even that query_string alters outcome of pages. Be careful to not cache wp_nonce and auth_tokens. I will post more about this soon!

Must Read: Useful Commands to parse access.log

10 responses to “Using $upstream_cache_status in access.log”

  1. I’ve set up a test site following your instructions on enabling fastcgi_cache and the new phpopcache (using Nginx 1.41 and PHP 5.5.7). When I check the nginx-cache folder in /var/run it is accumulating files. I can purge them from the Nginx Helper plugin button and they go away, and they come back with more browsing of the site. However, when I set up this cache log there is nothing there. Also, when I check the headers after setting up the “add_header rt-Fastcgi-Cache $upstream_cache_status;” line, the header isn’t there at all. I’ve checked and double checked, but can’t find anything wrong. Can you think what would cause the header to not appear even though it seems to be caching? Also, the Nginx Helper plugin is adding it’s line to the HTML source saying it is working, however it does this even when I’m logged into the site and there should be no caching. I would appreciate any help greatly, as I’m stuck. Thanks.

    • To sum up – I guess you are not seeing rt-Fastcgi-Cache header in HTTP response.

      Did you add line add_header rt-Fastcgi-Cache $upstream_cache_status; inside /etc/nginx/nginx.conf and also reloaded nginx config (service nginx reload) ?

      If you are still facing issue, please send a URL to test site on your server here (if its publicly accessible).

  2. Thank you for your reply and please forgive me for not coming back to update this. It was very late and I had bee working too long on the same things — I made a stupid mistake. In fact, it did work fine once I started updating the correct server, lol. I had FileZilla open to one server and terminal open to another. I was saving my attempts to correctly configure on one server, but I was restarting the service on another, so nothing changed when I viewed it in the browser. Like I said, stupid mistake and I did that for a couple of hours! I’ll try to make sure any future questions are better founded. I tend to binge learn and I don’t know when to quit and get some rest. Thanks again, you have a great resource here and thank you so much for the Nginx Helper plugin.

    • No probs David. Sometimes it happens with us also.

      My colleague added some codes to each server so we get different text colors in terminal for every.

  3. Hi, Rahul Bansal. I’ve tested my site and found that there were so many “miss”, I followed your suggestion by increasing “keys_zone=wordpress” from 10m to 100m, “max_size” from 60m to 200m, “inactive” from 60m to 460m.

    But I still have too many “miss”:


    905 -
    4 updateing
    363 BYPASS
    1799 MISS
    12911 HIT
    1416 EXPIRED

    Any suggestion?

    BTW: I got 12911 hits + 1799 MISS + 1416 EXPIRED in the report but Google Analytics told me I have 7k pageviews. 16k – 7k = 9k, confused, the 9k traffics was an attack?