tools/cachestat: Rewrite it so it makes more sense

cachstat separation between read and writes doesn't make much sense. During tests
its seen that a workload that is supposed to be completely in the missed category
appears to be 50% hit.

This patch rewrites the BCC tool to be more inline with Brendan Gregg's original
cachestat perf tool which makes more sense:
https://github.com/brendangregg/perf-tools/blob/master/fs/cachestat
http:https://www.brendangregg.com/blog/2014-12-31/linux-page-cache-hit-ratio.html

Fixes Issue: iovisor#1586
Signed-off-by: Joel Fernandes <[email protected]>

tools/cachestat.py

@@ -39,16 +39,13 @@ def get_meminfo():
  return result
 
 # set global variables
-rtaccess = 0
-wtaccess = 0
 mpa = 0
 mbd = 0
 apcl = 0
 apd = 0
-access = 0
+total = 0
 misses = 0
-rhits = 0
-whits = 0
+hits = 0
 debug = 0
 
 # args
@@ -116,9 +113,8 @@ def usage():
 # header
 if tstamp:
  print("%-8s " % "TIME", end="")
-print("%8s %8s %8s %10s %10s %12s %10s" %
- ("HITS", "MISSES", "DIRTIES",
- "READ_HIT%", "WRITE_HIT%", "BUFFERS_MB", "CACHED_MB"))
+print("%8s %8s %8s %8s %12s %10s" %
+ ("TOTAL", "MISSES", "HITS", "DIRTIES", "BUFFERS_MB", "CACHED_MB"))
 
 loop = 0
 exiting = 0
@@ -150,28 +146,29 @@ def usage():
  if re.match(b'account_page_dirtied', b.ksym(k.ip)) is not None:
  apd = max(0, v.value)
 
- # access = total cache access incl. reads(mpa) and writes(mbd)
- # misses = total of add to lru which we do when we write(mbd)
- # and also the mark the page dirty(same as mbd)
- access = (mpa + mbd)
- misses = (apcl + apd)
+ # total = total cache accesses without counting dirties
+ # misses = total of add to lru because of read misses
+ total = (mpa - mbd)
+ misses = (apcl - apd)
 
- # rtaccess is the read hit % during the sample period.
- # wtaccess is the write hit % during the smaple period.
- if mpa > 0:
- rtaccess = float(mpa) / (access + misses)
- if apcl > 0:
- wtaccess = float(apcl) / (access + misses)
+ if total < 0:
+ total = 0
 
- if wtaccess != 0:
- whits = 100 * wtaccess
- if rtaccess != 0:
- rhits = 100 * rtaccess
+ if misses < 0:
+ misses = 0
+
+ hits = total - misses
+
+ # If hits are < 0, then its possible misses are overestimated
+ # due to possibly page cache read ahead adding more pages than
+ # needed. In this case just assume misses as total and reset hits.
+ if hits < 0:
+ misses = total
+ hits = 0
 
  if debug:
- print("%d %d %d %d %d %d %f %f %d %d\n" %
- (mpa, mbd, apcl, apd, access, misses,
- rtaccess, wtaccess, rhits, whits))
+ print("%d %d %d %d %d %d %d\n" %
+ (mpa, mbd, apcl, apd, total, misses, hits))
 
  counts.clear()
 
@@ -182,21 +179,18 @@ def usage():
 
  if tstamp == 1:
  print("%-8s " % strftime("%H:%M:%S"), end="")
- print("%8d %8d %8d %9.1f%% %9.1f%% %12.0f %10.0f" %
- (access, misses, mbd, rhits, whits, buff, cached))
+ print("%8d %8d %8d %8d %12.0f %10.0f" %
+ (total, misses, hits, mbd, buff, cached))
 
  mpa = 0
  mbd = 0
  apcl = 0
  apd = 0
- access = 0
+ total = 0
  misses = 0
- rhits = 0
+ hits = 0
  cached = 0
  buff = 0
- whits = 0
- rtaccess = 0
- wtaccess = 0
 
  if exiting:
  print("Detaching...")

tools/cachestat_example.txt

@@ -15,61 +15,42 @@ examples:
  ./cachestat -T 1 5 # include timestamps with interval of one second for five iterations
 
 
-# ./cachestat 1
- HITS MISSES DIRTIES READ_HIT% WRITE_HIT% BUFFERS_MB CACHED_MB
- 0 58 0 0.0% 100.0% 0 11334
- 146113 0 0 100.0% 0.0% 0 11334
- 244143 0 0 100.0% 0.0% 0 11334
- 216833 0 0 100.0% 0.0% 0 11334
- 248209 0 0 100.0% 0.0% 0 11334
- 205825 0 0 100.0% 0.0% 0 11334
- 286654 0 0 100.0% 0.0% 0 11334
- 275850 0 0 100.0% 0.0% 0 11334
- 272883 0 0 100.0% 0.0% 0 11334
- 261633 0 0 100.0% 0.0% 0 11334
- 252826 0 0 100.0% 0.0% 0 11334
- 235253 70 3 100.0% 0.0% 0 11335
- 204946 0 0 100.0% 0.0% 0 11335
- 0 0 0 0.0% 0.0% 0 11335
- 0 0 0 0.0% 0.0% 0 11335
- 0 0 0 0.0% 0.0% 0 11335
-
-Above shows the reading of a 12GB file already cached in the OS page cache and again below with timestamps.
-
-# ./cachestat -T 1
-TIME HITS MISSES DIRTIES READ_HIT% WRITE_HIT% BUFFERS_MB CACHED_MB
-16:07:10 0 0 0 0.0% 0.0% 0 11336
-16:07:11 0 0 0 0.0% 0.0% 0 11336
-16:07:12 117849 0 0 100.0% 0.0% 0 11336
-16:07:13 212558 0 0 100.0% 0.0% 0 11336
-16:07:14 302559 1 0 100.0% 0.0% 0 11336
-16:07:15 309230 0 0 100.0% 0.0% 0 11336
-16:07:16 305701 0 0 100.0% 0.0% 0 11336
-16:07:17 312754 0 0 100.0% 0.0% 0 11336
-16:07:18 308406 0 0 100.0% 0.0% 0 11336
-16:07:19 298185 0 0 100.0% 0.0% 0 11336
-16:07:20 236128 0 0 100.0% 0.0% 0 11336
-16:07:21 257616 0 0 100.0% 0.0% 0 11336
-16:07:22 179792 0 0 100.0% 0.0% 0 11336
-
-Command used to generate the activity
-# dd if=/root/mnt2/testfile of=/dev/null bs=8192
-1442795+0 records in
-1442795+0 records out
-11819376640 bytes (12 GB) copied, 3.9301 s, 3.0 GB/s
-
-Below shows the dirty ratio increasing as we add a file to the page cache 
-# ./cachestat.py
- HITS MISSES DIRTIES READ_HIT% WRITE_HIT% BUFFERS_MB CACHED_MB
- 1074 44 13 94.9% 2.9% 1 223
- 2195 170 8 92.5% 6.8% 1 143
- 182 53 56 53.6% 1.3% 1 143
- 62480 40960 20480 40.6% 19.8% 1 223
- 7 2 5 22.2% 22.2% 1 223
- 348 0 0 100.0% 0.0% 1 223
- 0 0 0 0.0% 0.0% 1 223
- 0 0 0 0.0% 0.0% 1 223
- 0 0 0 0.0% 0.0% 1 223
- 0 0 0 0.0% 0.0% 1 223
-
-The file copied into page cache was named 80m with a size of 83886080 (83886080/4096) = 20480, this matches what we see under dirties
+Following commands show a 2GB file being read into the page cache.
+
+Command used to generate activity:
+# dd if=/root/tmpfile of=/dev/null bs=8192
+
+Output from cachestat running simultatenously:
+# ./tools/cachestat.py 1
+ TOTAL MISSES HITS DIRTIES BUFFERS_MB CACHED_MB
+ 1 0 1 0 8 283
+ 0 0 0 0 8 283
+ 0 0 0 2 8 283
+ 0 0 0 0 8 283
+ 10009 9173 836 2 9 369
+ 152032 152032 0 0 9 1028
+ 157408 157405 3 0 9 1707
+ 150432 150432 0 0 9 2331
+ 0 0 0 0 9 2331
+ 1 1 0 1 9 2331
+ 0 0 0 0 9 2331
+ 0 0 0 0 9 2331
+ 0 0 0 0 9 2331
+
+The misses counter reflects a 2GB file being read and almost everything being
+a page cache miss.
+
+Below shows an example of a new 100MB file added to page cache, by using
+the command: dd if=/dev/zero of=/root/tmpfile2 bs=4k count=$((256*100))
+
+# ./tools/cachestat.py 1
+ TOTAL MISSES HITS DIRTIES BUFFERS_MB CACHED_MB
+ 0 0 0 0 15 2440
+ 0 0 0 0 15 2440
+ 0 0 0 0 15 2440
+ 1758 0 1758 25603 15 2540
+ 0 0 0 0 15 2540
+ 0 0 0 0 15 2541
+
+~25600 pages are being dirtied (writes) which corresponds to the 100MB file
+added to the page cache.