Has anyone run into write_bw_log and write_io_log recording segments of low numbers?

Has anyone run into write_bw_log and write_io_log recording segments of low numbers?

[Todd Lawall]

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        

Re: Has anyone run into write_bw_log and write_io_log recording segments of low numbers?

[Todd Lawall]

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>
Sent: Wednesday, February 15, 2017 3:28 PM
To: fio@vger.kernel.org
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        --
To unsubscribe from this list: send the line "unsubscribe fio" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html


VGER.KERNEL.ORG - Majordomo info
vger.kernel.org
Very short Majordomo intro. Send request in email to address  To subscribe a list (``linux-kernel'' is given as an example), use following ...

    

Re: Has anyone run into write_bw_log and write_io_log recording segments of low numbers?

[Sitsofe Wheeler]

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/