This below is a summary of some real-world performance investigation I recently went through. The tools I used are installed on all linux systems, but I know some people don't know them and would...
This below is a summary of some real-world performance investigation I recently went through. The tools I used are installed on all linux systems, but I know some people don't know them and would straight up jump to heavyweight log analysis services and what not, or writing their own solution.
Let's say you have request log sampling in a bunch of log files that contain lines like these:
127.0.0.1 [2021-05-27 23:28:34.460] "GET /static/images/flags/2/54@3x.webp HTTP/2" 200 1806 TLSv1.3 HIT-CLUSTER SessionID:(null) Cache:max-age=31536000
127.0.0.1 [2021-05-27 23:51:22.019] "GET /pl/player/123456/changelog/ HTTP/1.1" 200 16524 TLSv1.2 MISS-CLUSTER SessionID:(null) Cache:
You might recognize Fastly logs there (IP anonymized). Now, there's a lot you might care about in this log file, but in my case, I wanted to get a breakdown of hits vs misses by URL.
So, first step, let's concatenate all the log files with cat *.log > all.txt, so we can work off a single file.
Then, let's split the file in two: hits and misses. There are a few different values for them, the majority are covered by either HIT-CLUSTER or MISS-CLUSTER. We can do this by just grepping for them like so:
grep HIT-CLUSTER all.txt > hits.txt; grep MISS-CLUSTER all.txt > misses.txt
However, we only care about url and whether it's a hit or a miss. So let's clean up those hits and misses with cut. The way cut works, it takes a delimiter (-d) and cuts the input based on that; you then give it a range of "fields" (-f) that you want.
In our case, if we cut based on spaces, we end up with for example: 127.0.0.1 [2021-05-27 23:28:34.460] "GET /static/images/flags/2/54@3x.webp HTTP/2" 200 1806 TLSv1.3 HIT-CLUSTER SessionID:(null) Cache:max-age=31536000.
We care about the 5th value only. So let's do: cut -d" " -f5 to get that. We will also sort the result, because future operations will require us to work on a sorted list of values.
cut -d" " -f5 hits.txt | sort > hits-sorted.txt; cut -d" " -f5 misses.txt | sort > misses-sorted.txt
Now we can start doing some neat stuff. wc (wordcount) is an awesome utility, it lets you count characters, words or lines very easily. wc -l counts lines in an input, since we're operating with one value per line we can easily count our hits and misses already:
$ wc -l hits-sorted.txt misses-sorted.txt
132523 hits-sorted.txt
220779 misses-sorted.txt
353302 total
220779 / 132523 is a 1:1.66 ratio of hits to misses. That's not great…
Alright, now I'm also interested in how many unique URLs are hit versus missed. uniq tool deduplicates immediate sequences, so the input has to be sorted in order to deduplicate our entire file. We already did that. We can now count our urls with uniq < hits-sorted.txt | wc -l; uniq < misses-sorted.txt | wc -l. We get 49778 and 201178, respectively. It's to be expected that most of our cache misses would be in "rarer" urls; this gives us a 1:4 ratio of cached to uncached URL.
Let's say we want to dig down further into which URLs are most often hitting the cache, specifically. We can add -c to uniq in order to get a duplicate count in front of our URLs. To get the top ones at the top, we can then use sort, in reverse sort mode (-r), and it also needs to be numeric sort, not alphabetic (-n). head lets us get the top 10.
$ uniq -c < hits-sorted.txt | sort -nr | head
815 /static/app/webfonts/fa-solid-900.woff2?d720146f1999
793 /static/app/images/1.png
786 /static/app/fonts/nunito-v9-latin-ext_latin-regular.woff2?d720146f1999
760 /static/CACHE/js/output.cee5c4089626.js
758 /static/images/crest/3/light/notfound.png
757 /static/CACHE/css/output.4f2b59394c83.css
756 /static/app/webfonts/fa-regular-400.woff2?d720146f1999
754 /static/app/css/images/loading.gif?d720146f1999
750 /static/app/css/images/prev.png?d720146f1999
745 /static/app/css/images/next.png?d720146f1999
And same for misses:
$ uniq -c < misses-sorted.txt | sort -nr | head
56 /
14 /player/237678/
13 /players/
12 /teams/
11 /players/top/
<snip>
So far this tells us static files are most often hit, and for misses it also tells us… something, but we can't quite track it down yet (and we won't, not in this post). We're not adjusting for how often the page is hit as a whole, this is still just high-level analysis.
One last thing I want to show you! Let's take everything we learned and analyze those URLs by prefix instead. We can cut our URLs again by slash with cut -d"/". If we want the first prefix, we can do -f1-2, or -f1-3 for the first two prefixes. Let's look!
cut -d'/' -f1-2 < hits-sorted.txt | uniq -c | sort -nr | head
100189 /static
5948 /es
3069 /player
2480 /fr
2476 /es-mx
2295 /pt-br
2094 /tr
1939 /it
1692 /ru
1626 /de
cut -d'/' -f1-2 < misses-sorted.txt | uniq -c | sort -nr | head
66132 /static
18578 /es
17448 /player
17064 /tr
11379 /fr
9624 /pt-br
8730 /es-mx
7993 /ru
7689 /zh-hant
7441 /it
This gives us hit-miss ratios by prefix. Neat, huh?