fio benchmark latency explanation

Question

I have used fio for benchmarking my SSD. However, I'm confused about the reported latency when fsync=1 (sync the dirty buffer to disk after every write()) parameter is specified.

$ fio --name=test_seq_write --filename=test_seq --size=2G --readwrite=write --fsync=1
test_seq_write: (g=0): rw=write, bs=4K-4K/4K-4K/4K-4K, ioengine=sync, iodepth=1
fio-2.1.3
Starting 1 process
test_seq_write: Laying out IO file(s) (1 file(s) / 2048MB)
Jobs: 1 (f=1): [W] [100.0% done] [0KB/31968KB/0KB /s] [0/7992/0 iops] [eta 00m:00s]
test_seq_write: (groupid=0, jobs=1): err= 0: pid=10994: Thu Oct 26 09:09:19 2017
  write: io=2048.0MB, bw=35647KB/s, iops=8911, runt= 58831msec
    clat (usec): min=2, max=1099, avg= 9.42, stdev=18.19
     lat (usec): min=2, max=1099, avg= 9.56, stdev=18.28

Here, the iops is 8911, so the latency should be roughly around 100us. However, the reported latency is 9us. I am curious does fio include the time for fsync? I'm reading fio doc but found no explanation.

Answer 1

(Oh gosh, please don't use creaky old versions of fio if you have any choice - so many bugs have been fixed since fio 2.1.3 that you're really doing yourself a disservice by continuing to use it (and it doesn't take much to build newer fio versions). Take a look at which fio release we're up to now: https://github.com/axboe/fio/releases )

The answer below applies to fio 3.4 and older. See a later answer to this question for fio 3.5 and newer.

---

The fsyncs are a separate fio operation to the regular I/Os (see https://github.com/axboe/fio/blob/0bcf41cdc22dfee6b3f3b2ba9a533b4b103c70c2/io_u.c#L2170 for where they are queued up) so yes they should be counted . [Update] However, fio explicitly excludes I/Os that aren't reads, writes or trims from statistics gathering (see https://github.com/axboe/fio/blob/0bcf41cdc22dfee6b3f3b2ba9a533b4b103c70c2/io_u.c#L1823 ).

So

does fio include the time for fsync [in the I/O latency statistics]?

No fio does not include fsync time in latency statistics. The fsync's will impact the total bandwidth but this will go unattributed.

Note: fsync is a heavy operation because on Linux it ensures:

1. The I/O has been acknowledged as being received by the "disk" and isn't just in Linux's page cache.
2. Metadata associated with the entire file has been flushed to disk. For complicated reasons this may mean you have end up waiting for the data/metadata of other files to be flushed too...
3. The "disk" has acknowledged the I/O has reached stable storage upon it (i.e. it's not just inside a "disk" cache that can't survive losing power).

It's typical when benchmarking that you are more interested in ensuring only 1. because at least then you are closer to testing the speed of the disk (as opposed to the Linux's caching) whereas the other points are to do with ensuring data integrity. If this is your case too, I would suggest you use direct=1 with fio and stop using fsync because then each I/O will bypass Linux's page cache and won't return until the disk has acknowledged it received the I/O. Thus each I/O will have the "latency to disk" built into its time but as stated this does NOT imply points 2 or 3. Also note not all filesystems support this option (which is a pity).

[Original speculation]

However it could [also] be the case that the write I/Os complete quickly, the fsyncs complete quickly but the space between each submission is non-zero (essentially due to fio having to do work). So Do I/O -> I/O completes -> Do non-I/O work -> Do I/O etc. Thus you CANNOT deduce an I/Os latency from the IOPs achieved (you can only give it an upper bound).

PS: you can turn on per I/O logging with modern fio versions (http://fio.readthedocs.io/en/latest/fio_doc.html#cmdoption-arg-write-lat-log , http://fio.readthedocs.io/en/latest/fio_doc.html#log-file-formats , http://fio.readthedocs.io/en/latest/fio_doc.html#cmdoption-arg-log-avg-msec (log_avg_msec must be 0 / unset)) but note that fsyncs are also exempted from this logging. Make sure you are saving the logs somewhere which won't interfere with the test and be aware that per I/O logging grows extremely quickly so it's a good idea not to do too much I/O when you are in this mode.

PPS: This question would have been better sent to the fio mailing list (https://github.com/axboe/fio/blob/fio-3.1/README#L58 ).

Answer 2

fio 3.5 or later is now able to report fsync latencies! You will see this information when doing a workload which conforms to all of the following:

• Performs some form of write
• Has one of fsync/fdatasync/sync_file_range set
• The --output-format is normal (there will be a fsync/fdatasync/sync_file_range section) or json/json+ (the values are recorded under the "sync" direction).

Here's an example of the normal output showing fsync latencies:

$ ./fio --filename=/tmp/fio.tmp --size=1m --bs=512 --name=go --rw=write --fdatasync=1
go: (g=0): rw=write, bs=(R) 512B-512B, (W) 512B-512B, (T) 512B-512B, ioengine=psync, iodepth=1
[...]
go: (groupid=0, jobs=1): err= 0: pid=26958: Wed Feb 21 14:06:11 2018
  write: IOPS=512k, BW=250MiB/s (262MB/s)(1024KiB/4msec)
    clat (nsec): min=673, max=12144, avg=709.40, stdev=260.94
[...]
  lat (usec)   : 2=0.05%, 4=0.05%, 20=0.05%
  fsync/fdatasync/sync_file_range:
    sync (nsec): min=353, max=5307, avg=364.78, stdev=115.66
    sync percentiles (nsec):
     |  1.00th=[  358],  5.00th=[  358], 10.00th=[  358], 20.00th=[  362],
     | 30.00th=[  362], 40.00th=[  362], 50.00th=[  362], 60.00th=[  362],
     | 70.00th=[  362], 80.00th=[  362], 90.00th=[  366], 95.00th=[  366],
     | 99.00th=[  370], 99.50th=[  370], 99.90th=[  402], 99.95th=[ 2064],
     | 99.99th=[ 5280]
[...]

So in answer to your question:

I am curious does fio include the time for fsync?

In fio 3.3 and below no (see the updates in https://stackoverflow.com/a/46968852/9109338 ). In fio 3.5 and above, sort of - fio doesn't include fsync in the lat/clat latencies (after all it can't know what I/Os the fsync latency should be attributed as it can't retrieve that information) but it accounts and reports fsync latencies on their own.