t/io_uring: add support for latency tracking
authorJens Axboe <axboe@kernel.dk>
Sat, 25 Sep 2021 20:25:05 +0000 (14:25 -0600)
committerJens Axboe <axboe@kernel.dk>
Sat, 25 Sep 2021 20:25:05 +0000 (14:25 -0600)
commit932131c944b10f2a03f4028318c454c98eca489f
treedf6ba67c624203c52cce88bb722794c69efbde3a
parent6c5d3a1c08bda1bbf22187c7b80573400e1c1053
t/io_uring: add support for latency tracking

This will display the latency percentiles for the run when done, per
submitter thread. It takes two arguments:

-t<x> Enable latency tracking if x is non-zero
-T<Y> Set TSC clock rate to Y Hz

The tsc rate can be programatically deduced (fio does this), for now
pass it in. dmesg will generally tell you:

tsc: Refined TSC clocksource calibration: 3699.889 MHz

and you'd then do:

-t1 -T3699889000

for that. Here's an example, synchronous optane gen2 read:

[...]
IOPS=254118, BW=124MiB/s, IOS/call=0/0, inflight=(1)
IOPS=255024, BW=124MiB/s, IOS/call=0/0, inflight=(1)
IOPS=255100, BW=124MiB/s, IOS/call=0/0, inflight=(1)
IOPS=254791, BW=124MiB/s, IOS/call=0/0, inflight=(1)
^CExiting on signal 2
IOPS=100086, BW=48MiB/s, IOS/call=1/1, inflight=(1)
515102: Latency percentiles:
    percentiles (nsec):
     |  1.0000th=[ 3857],  5.0000th=[ 3857], 10.0000th=[ 3857],
     | 20.0000th=[ 3857], 30.0000th=[ 3857], 40.0000th=[ 3892],
     | 50.0000th=[ 3892], 60.0000th=[ 3892], 70.0000th=[ 3892],
     | 80.0000th=[ 3892], 90.0000th=[ 3961], 95.0000th=[ 3961],
     | 99.9000th=[ 8752], 99.5000th=[ 8752], 99.9000th=[ 8752],
     | 99.9500th=[ 9064], 99.9900th=[ 9755]

Or a higher depth run:

IOPS=3549568, BW=1733MiB/s, IOS/call=32/32, inflight=(64)
IOPS=3547712, BW=1732MiB/s, IOS/call=32/31, inflight=(111)
IOPS=3549504, BW=1733MiB/s, IOS/call=32/31, inflight=(128)
^CExiting on signal 2
IOPS=1413600, BW=690MiB/s, IOS/call=32/32, inflight=(35)
515078: Latency percentiles:
    percentiles (nsec):
     |  1.0000th=[13630],  5.0000th=[14322], 10.0000th=[15291],
     | 20.0000th=[16121], 30.0000th=[20065], 40.0000th=[21726],
     | 50.0000th=[22279], 60.0000th=[26154], 70.0000th=[27814],
     | 80.0000th=[28368], 90.0000th=[33903], 95.0000th=[34180],
     | 99.9000th=[52862], 99.5000th=[52862], 99.9000th=[52862],
     | 99.9500th=[56183], 99.9900th=[67807]

Note that latency tracking isn't cheap, even if we tried to do it in the
cheapest way possible. The peak workload shown here will run at ~3.7M
IOPS without tracking, and as shown about 3.55M with tracking enabled.

Signed-off-by: Jens Axboe <axboe@kernel.dk>
t/io_uring.c