Hmm those D2C and Q2C times are bigger than what fio is reporting! Was this with log_avg_msec unset? If you can make this happen over even shorter periods (a couple of seconds tops) it might be feasible to turn on fio debugging and change fio source to exit if it calculates a submission time of 0... On 30 March 2017 at 21:32, Tarek <cashew250@xxxxxxxxx> wrote: > Blktrace -> blkparse -> btt vs. FIO doesn't match (D2C was on the > order of 10+ uS), fio 0uS. See details below > > Jobs: 1 (f=1): [w(1)][100.0%][r=0KiB/s,w=177MiB/s][r=0,w=45.4k > IOPS][eta 00m:00s] > random-0r-100w_4k_qd1_jobs_1: (groupid=0, jobs=1): err= 0: pid=22318: > Thu Mar 30 14:47:20 2017 > Description : [Random R/W 0/100 QD1 BLK 4k Jobs 1] > write: IOPS=43.2k, BW=168MiB/s (177MB/s)(1684MiB/10001msec) > slat (usec): min=1, max=3579, avg= 1.73, stdev=11.37 > clat (usec): min=0, max=3322, avg=20.08, stdev=11.15 > lat (usec): min=19, max=3584, avg=21.90, stdev=15.84 > > D2C MIN AVG MAX N > --------------- ------------- ------------- ------------- ----------- > fio 0.000016651 0.000018152 0.000045858 431084 > systemd-udevd 0.000010843 0.000122841 0.000400713 76 > > Q2C MIN AVG MAX N > --------------- ------------- ------------- ------------- ----------- > fio 0.000017209 0.000018905 0.000064686 431084 > systemd-udevd 0.000011829 0.000126970 0.000406939 76 > > On Mon, Mar 27, 2017 at 1:30 PM, Sitsofe Wheeler <sitsofe@xxxxxxxxx> wrote: >> Hi, >> >> Do you get the same effect when you don't set log_avg_msec? Do you >> know how far fio's timings are compared to blktrace? >> >> On 27 March 2017 at 15:36, Tarek <cashew250@xxxxxxxxx> wrote: >>> I don't have evidence to suggest that the min SLAT and CLAT are from >>> the same IO, speculation. Regardless, CLAT should not be 0 on any >>> device for a read. Nand read spec is 40uS. Flow is blkdiscard device, >>> precondition (seq fill twice, followed by 100GiB of random write), >>> then test. Any ideas? >>> >>> On Sat, Mar 25, 2017 at 3:29 AM, Sitsofe Wheeler <sitsofe@xxxxxxxxx> wrote: >>>> Hi, >>>> >>>> I don't know why the minimum clat is 0 usec (you might be able to >>>> investigate further by using blktrace on the device to see how much >>>> that disagrees with fio) but why do you believe that scenario happened >>>> on the exact same I/O(s) that had a 0 usec slat time? Do you have >>>> additional logs showing that was the case? >>>> >>>> On 24 March 2017 at 17:39, Tarek <cashew250@xxxxxxxxx> wrote: >>>>> Clat min is zero on a random read, how is that possible when NAND tR >>>>> spec is 20-60uS? Also isn't lat = slat + clat, 1 + 0 != 84 >>>>> >>>>> fio-2.15 >>>>> Starting 80 threads >>>>> >>>>> random-100r-0w_4k_qd1_jobs_16: (groupid=0, jobs=16): err= 0: >>>>> pid=22233: Tue Feb 21 15:41:33 2017 >>>>> Description : [Random R/W 100/0 QD1 BLK 4k Jobs 16] >>>>> read : io=1045.5GB, bw=609017KB/s, iops=152254, runt=1800001msec >>>>> slat (usec): min=1, max=6583, avg= 2.06, stdev= 1.01 >>>>> clat (usec): min=0, max=8728, avg=102.38, stdev=21.43 >>>>> lat (usec): min=84, max=8730, avg=104.52, stdev=21.45 >>>>> clat percentiles (usec): >>>>> | 1.00th=[ 85], 5.00th=[ 86], 10.00th=[ 87], 20.00th=[ 89], >>>>> | 30.00th=[ 91], 40.00th=[ 98], 50.00th=[ 101], 60.00th=[ 102], >>>>> | 70.00th=[ 104], 80.00th=[ 106], 90.00th=[ 116], 95.00th=[ 143], >>>>> | 99.00th=[ 175], 99.50th=[ 185], 99.90th=[ 225], 99.95th=[ 239], >>>>> | 99.99th=[ 270] >>>>> >>>>> >>>>> Fio Config: >>>>> thread >>>>> bs=4k >>>>> ioengine=libaio >>>>> direct=1 >>>>> buffered=0 >>>>> log_avg_msec=1000 >>>>> group_reporting=1 >>>>> rw=randread >>>>> numjobs=16 >>>>> iodepth=1 >>>>> time_based >>>>> runtime=1800 >>>>> refill_buffers >>>>> norandommap >>>>> filename=/dev/nvme0n1 -- Sitsofe | http://sucs.org/~sits/ -- To unsubscribe from this list: send the line "unsubscribe fio" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
