* Re: Has anyone run into write_bw_log and write_io_log recording segments of low numbers?
2017-02-15 22:57 ` Todd Lawall
@ 2017-02-16 5:53 ` Sitsofe Wheeler
0 siblings, 0 replies; 3+ messages in thread
From: Sitsofe Wheeler @ 2017-02-16 5:53 UTC (permalink / raw)
To: Todd Lawall; +Cc: fio
Hi,
Something to investigate is the latency at the problem point - I'm
going to guess you see latencies above 1 second in your fio log. Don't
forget you're not using direct=1 so you also have your operating
system's write buffering in the mix too.
Imagine I do a run where I lose network connectivity to my iSCSI
target for two seconds. During that point any I/O I was doing will now
take at least two seconds to complete. Let's pretend that the
I/O that happened took exactly two seconds to complete and was for a
256Kbytes block. This means that particular I/O's "I/Os per second" is
0 ((1 IO)/2 seconds gives 0 because we don't have fractional iops) but
its bandwidth is 128Kbytes/s (256Kbytes/2 seconds). This is
simplification because you still have your operating system's write
buffering but if that totally fills up this effect will come in to
play.
On Linux I have a slow device that delay's I/Os for 2000 milliseconds made with
dmsetup create zero1g --table '0 2097152 zero'
dmsetup create slow --table '0 2097152 delay /dev/mapper/zero1g 0 2000'
I ran fio against it
fio --name=slowtest --rw=read --filename /dev/mapper/slow --runtime=5s
--write_bw_log=slowtest --write_iops_log=slowtest
--write_lat_log=slowtest --bs=64k --direct=1
slowtest: (g=0): rw=read,
bs=64.0KiB-64.0KiB,64.0KiB-64.0KiB,64.0KiB-64.0KiB, ioengine=psync,
iodepth=1
fio-2.17-48-g93f58-dirty
Starting 1 process
Jobs: 1 (f=1): [R(1)][0.0%][r=0KiB/s,w=0KiB/s][r=0,w=0 IOPS][eta 13h:39m:06s]
slowtest: (groupid=0, jobs=1): err= 0: pid=21804: Thu Feb 16 05:46:49 2017
read: IOPS=0, BW=31.1KiB/s (32.8kB/s)(192KiB/6012msec)
clat (usec): min=2003.9k, max=2003.1k, avg=2003914.67, stdev=46.20
lat (usec): min=2003.9k, max=2003.1k, avg=2003916.33, stdev=45.62
clat percentiles (msec):
| 1.00th=[ 2008], 5.00th=[ 2008], 10.00th=[ 2008], 20.00th=[ 2008],
| 30.00th=[ 2008], 40.00th=[ 2008], 50.00th=[ 2008], 60.00th=[ 2008],
| 70.00th=[ 2008], 80.00th=[ 2008], 90.00th=[ 2008], 95.00th=[ 2008],
| 99.00th=[ 2008], 99.50th=[ 2008], 99.90th=[ 2008], 99.95th=[ 2008],
| 99.99th=[ 2008]
bw ( KiB/s): min= 32, max= 32, per=0.10%, avg=32.00, stdev= 0.00
lat (msec) : >=2000=100.00%
cpu : usr=0.00%, sys=0.00%, ctx=3, majf=0, minf=32
IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
issued rwt: total=3,0,0, short=0,0,0, dropped=0,0,0
latency : target=0, window=0, percentile=100.00%, depth=1
Run status group 0 (all jobs):
READ: bw=31.1KiB/s (32.8kB/s), 31.1KiB/s-31.1KiB/s
(32.8kB/s-32.8kB/s), io=192KiB (197kB), run=6012-6012msec
Examining the files I see this:
# head slowtest_*
==> slowtest_bw.1.log <==
2004, 32, 0, 65536
4007, 32, 0, 65536
6011, 32, 0, 65536
==> slowtest_clat.1.log <==
2003, 2003887, 0, 65536
4007, 2003889, 0, 65536
6011, 2003968, 0, 65536
==> slowtest_iops.1.log <==
2004, 1, 0, 65536
4007, 1, 0, 65536
6011, 1, 0, 65536
==> slowtest_lat.1.log <==
2003, 2003889, 0, 65536
4007, 2003891, 0, 65536
6011, 2003969, 0, 65536
On 15 February 2017 at 22:57, Todd Lawall <tlawall@pivot3.com> wrote:
> Sorry, forgot to mention that this is on a windows client, running version fio-2.16-1-g3ab9.
>
>
> From: fio-owner@vger.kernel.org <fio-owner@vger.kernel.org> on behalf of Todd Lawall <tlawall@pivot3.com>
> Subject: Has anyone run into write_bw_log and write_io_log recording segments of low numbers?
>
> I've been running fio on an iSCSI volume where I can monitor things like the network traffic (to ensure that indeed it is flowing) as well as on the machine the volume is hosted on. I'm seeing a steady state of 300MB/s, but when I stop the FIO process and writes the detailed bandwidth and iops logs, there's segments where iops drop to 0, but bandwidth for the same time point is somewhere around the single digits or teens.
>
> Has anyone else seen this behavior? Does anyone have an idea why I might be seeing this? Here is the job file I ran:
>
> [global]
> ioengine=windowsaio
> do_verify=0
> offset=0
> write_bw_log=C:\\haggis\\manualfio\\stats-running
> write_iops_log=C:\\haggis\\manualfio\\stats-running
> write_lat_log=C:\\haggis\\manualfio\\stats-running
> verify=crc32c-intel
> runtime=292000
> thread
>
> [fio-0]
> filename=\\.\PhysicalDrive1
> iodepth=1
> blocksize=256k
> readwrite=write
>
> [fio-1]
> filename=\\.\PhysicalDrive2
> iodepth=1
> blocksize=256k
> readwrite=write
--
Sitsofe | http://sucs.org/~sits/
^ permalink raw reply [flat|nested] 3+ messages in thread