t/aio-ring: add cache hit statistics

Pretty nifty to run it on a drive that will eventually end up being
fully cached, and watch the hit rates climb:

sudo taskset -c 0 t/aio-ring /dev/sde3
polled=0, fixedbufs=1, buffered=1
  QD=32, sq_ring=33, cq_ring=66
submitter=4269
IOPS=477, IOS/call=1/0, inflight=32 (head=50 tail=50), Cachehit=0.00%
IOPS=447, IOS/call=1/1, inflight=32 (head=35 tail=35), Cachehit=0.00%
IOPS=419, IOS/call=1/1, inflight=32 (head=58 tail=58), Cachehit=0.00%
[...]
IOPS=483, IOS/call=1/1, inflight=32 (head=63 tail=63), Cachehit=5.80%
IOPS=452, IOS/call=1/1, inflight=32 (head=53 tail=53), Cachehit=4.65%
IOPS=459, IOS/call=1/1, inflight=32 (head=50 tail=50), Cachehit=5.45%
[...]
IOPS=484, IOS/call=1/1, inflight=32 (head=22 tail=22), Cachehit=11.16%
IOPS=494, IOS/call=1/1, inflight=32 (head=54 tail=54), Cachehit=11.34%
IOPS=508, IOS/call=1/1, inflight=32 (head=34 tail=34), Cachehit=12.99%
[...]
IOPS=606, IOS/call=1/1, inflight=32 (head=18 tail=18), Cachehit=26.07%
IOPS=573, IOS/call=1/1, inflight=32 (head=63 tail=63), Cachehit=26.70%
IOPS=561, IOS/call=1/1, inflight=32 (head=30 tail=30), Cachehit=23.53%
[...]
IOPS=916, IOS/call=1/1, inflight=32 (head=63 tail=63), Cachehit=59.06%
IOPS=882, IOS/call=1/1, inflight=32 (head=21 tail=32), Cachehit=61.79%
IOPS=984, IOS/call=1/1, inflight=32 (head=22 tail=22), Cachehit=63.87%
[...]
IOPS=1993, IOS/call=7/7, inflight=32 (head=58 tail=4), Cachehit=86.75%
IOPS=2260, IOS/call=5/5, inflight=32 (head=12 tail=16), Cachehit=87.15%
IOPS=1957, IOS/call=4/4, inflight=17 (head=7 tail=10), Cachehit=86.78%
[...]
IOPS=3606, IOS/call=7/7, inflight=32 (head=26 tail=35), Cachehit=93.47%
IOPS=3487, IOS/call=6/6, inflight=28 (head=23 tail=31), Cachehit=92.59%
IOPS=3379, IOS/call=7/7, inflight=26 (head=38 tail=40), Cachehit=92.66%
[...]
IOPS=4590, IOS/call=6/6, inflight=26 (head=38 tail=46), Cachehit=95.64%
IOPS=5464, IOS/call=7/7, inflight=28 (head=22 tail=24), Cachehit=95.94%
IOPS=4896, IOS/call=8/8, inflight=18 (head=44 tail=51), Cachehit=95.62%
[...]
IOPS=7736, IOS/call=8/8, inflight=24 (head=25 tail=29), Cachehit=97.35%
IOPS=6632, IOS/call=8/7, inflight=27 (head=54 tail=61), Cachehit=97.28%
IOPS=8488, IOS/call=8/8, inflight=22 (head=33 tail=39), Cachehit=97.33%
[...]
IOPS=10696, IOS/call=8/8, inflight=16 (head=63 tail=64), Cachehit=98.11%
IOPS=11874, IOS/call=7/7, inflight=17 (head=56 tail=56), Cachehit=98.31%
IOPS=11488, IOS/call=8/7, inflight=23 (head=54 tail=57), Cachehit=98.17%
[...]
IOPS=15472, IOS/call=8/8, inflight=17 (head=11 tail=17), Cachehit=98.58%
IOPS=18656, IOS/call=8/7, inflight=22 (head=50 tail=59), Cachehit=98.95%
IOPS=19408, IOS/call=8/8, inflight=18 (head=58 tail=63), Cachehit=99.01%
[...]
IOPS=54768, IOS/call=8/7, inflight=19 (head=63 tail=3), Cachehit=99.64%
IOPS=62888, IOS/call=8/7, inflight=21 (head=51 tail=53), Cachehit=99.73%
IOPS=71656, IOS/call=7/7, inflight=24 (head=28 tail=36), Cachehit=99.75%
[...]
IOPS=125320, IOS/call=8/8, inflight=22 (head=42 tail=46), Cachehit=99.85%
IOPS=201808, IOS/call=8/8, inflight=17 (head=27 tail=35), Cachehit=99.90%
IOPS=390325, IOS/call=7/7, inflight=22 (head=23 tail=27), Cachehit=99.94%
[...]
IOPS=834056, IOS/call=8/8, inflight=8 (head=23 tail=27), Cachehit=100.00%
IOPS=837520, IOS/call=8/8, inflight=8 (head=13 tail=17), Cachehit=100.00%
IOPS=833232, IOS/call=8/8, inflight=8 (head=51 tail=57), Cachehit=100.00%

It's also a nice visual into how high a cache hit rate has to be on a
rotational drive to make a substantial impact on performance.

Signed-off-by: Jens Axboe <axboe@kernel.dk>

diff --git a/t/aio-ring.c b/t/aio-ring.c
index 322f2ffa23e344bebf7a4956c306af848298ca1d..c813c4e7f1de1283c49cd0dc80c19b3bb9274bea 100644 (file)
--- a/t/aio-ring.c
+++ b/t/aio-ring.c
@@ -30,6 +30,8 @@
 #define IOCTX_FLAG_SQTHREAD    (1 << 3)        /* Use SQ thread */
 #define IOCTX_FLAG_SQWQ                (1 << 4)        /* Use SQ wq */
 
+#define IOEV_RES2_CACHEHIT     (1 << 0)
+
 #define barrier()      __asm__ __volatile__("": : :"memory")
 
 #define min(a, b)              ((a < b) ? (a) : (b))
@@ -87,6 +89,7 @@ struct submitter {
        unsigned long reaps;
        unsigned long done;
        unsigned long calls;
+       unsigned long cachehit, cachemiss;
        volatile int finish;
        char filename[128];
 };
@@ -206,6 +209,10 @@ static int reap_events(struct submitter *s)
                        printf("offset=%lu, size=%lu\n", (unsigned long) iocb->u.c.offset, (unsigned long) iocb->u.c.nbytes);
                        return -1;
                }
+               if (ev->res2 & IOEV_RES2_CACHEHIT)
+                       s->cachehit++;
+               else
+                       s->cachemiss++;
                reaped++;
                head++;
                if (head == ring->nr_events)
@@ -333,7 +340,7 @@ static void arm_sig_int(void)
 int main(int argc, char *argv[])
 {
        struct submitter *s = &submitters[0];
-       unsigned long done, calls, reap;
+       unsigned long done, calls, reap, cache_hit, cache_miss;
        int flags = 0, err;
        int j;
        size_t size;
@@ -410,27 +417,42 @@ int main(int argc, char *argv[])
 
        pthread_create(&s->thread, NULL, submitter_fn, s);
 
-       reap = calls = done = 0;
+       cache_hit = cache_miss = reap = calls = done = 0;
        do {
                unsigned long this_done = 0;
                unsigned long this_reap = 0;
                unsigned long this_call = 0;
+               unsigned long this_cache_hit = 0;
+               unsigned long this_cache_miss = 0;
                unsigned long rpc = 0, ipc = 0;
+               double hit = 0.0;
 
                sleep(1);
                this_done += s->done;
                this_call += s->calls;
                this_reap += s->reaps;
+               this_cache_hit += s->cachehit;
+               this_cache_miss += s->cachemiss;
+               if (this_cache_hit && this_cache_miss) {
+                       unsigned long hits, total;
+
+                       hits = this_cache_hit - cache_hit;
+                       total = hits + this_cache_miss - cache_miss;
+                       hit = (double) hits / (double) total;
+                       hit *= 100.0;
+               }
                if (this_call - calls) {
                        rpc = (this_done - done) / (this_call - calls);
                        ipc = (this_reap - reap) / (this_call - calls);
                }
-               printf("IOPS=%lu, IOS/call=%lu/%lu, inflight=%u (head=%d tail=%d), %lu, %lu\n",
+               printf("IOPS=%lu, IOS/call=%lu/%lu, inflight=%u (head=%d tail=%d), Cachehit=%0.2f%%\n",
                                this_done - done, rpc, ipc, s->inflight,
-                               s->cq_ring->head, s->cq_ring->tail, s->reaps, s->done);
+                               s->cq_ring->head, s->cq_ring->tail, hit);
                done = this_done;
                calls = this_call;
                reap = this_reap;
+               cache_hit = s->cachehit;
+               cache_miss = s->cachemiss;
        } while (!finish);
 
        pthread_join(s->thread, &ret);