All of lore.kernel.org
 help / color / mirror / Atom feed
* No IOPS reported when "REPLAY_NO_STALL" is not set
@ 2014-04-10 18:25 Lakshmi
  2014-04-10 22:07 ` Jens Axboe
  0 siblings, 1 reply; 5+ messages in thread
From: Lakshmi @ 2014-04-10 18:25 UTC (permalink / raw)
  To: fio, Jens Axboe

[-- Attachment #1: Type: text/plain, Size: 1714 bytes --]

Hi Jens,

 I am seeing a strange problem. I have a 47KB Blkparsed binary file
and I tried replaying it with and without the "replay_no_stall"
option.

With the "replay_no_stall" option, I am seeing some IOPS
happening.Please see below.
WITH "REPLAY_NO_STALL=1"
=====================================================
job9: (g=0): rw=read, bs=4K-4K/4K-4K/4K-4K, ioengine=sync, iodepth=1
fio-2.1.7
Starting 1 process
Jobs: 1 (f=2): [M] [-.-% done] [1064KB/72KB/0KB /s] [266/18/0 iops]
[eta 00m:00s]
job9: (groupid=0, jobs=1): err= 0: pid=34226: Thu Apr 10 12:00:54 2014
  read : io=3792.0KB, bw=1126.3KB/s, iops=281, runt=  3367msec
    clat (usec): min=88, max=8536, avg=3546.19, stdev=1469.46
     lat (usec): min=88, max=8536, avg=3546.35, stdev=1469.47
=====================================================
However, when I don't set the "REPLAY_NO_STALL" option, I see 0
IOPS.Please see below
job9: (g=0): rw=read, bs=4K-4K/4K-4K/4K-4K, ioengine=sync, iodepth=1
fio-2.1.7
Starting 1 process

job9: (groupid=0, jobs=1): err= 0: pid=33979: Thu Apr 10 10:39:42 2014
  read : io=3792.0KB, bw=2004B/s, iops=0, runt=1937594msec
    clat (usec): min=87, max=14320, avg=4763.37, stdev=2001.45
     lat (usec): min=87, max=14320, avg=4763.52, stdev=2001.50
===========================================================

My starting time in the blkparsed binary file is 26.040173218 seconds
and last time is 26.150699031.

Attached is the binary file I am using to replay.

I understand replay_no_stall option doesnt respect the timestamps, but
without this option the job should be executing with the delays, and
not sure why no OPS are reported.

Any idea what is causing this strange behavior?Please help.

Thanks,
Lakshmi

[-- Attachment #2: file_54657438_1000lines.bin --]
[-- Type: application/octet-stream, Size: 48000 bytes --]

^ permalink raw reply	[flat|nested] 5+ messages in thread

* Re: No IOPS reported when "REPLAY_NO_STALL" is not set
  2014-04-10 18:25 No IOPS reported when "REPLAY_NO_STALL" is not set Lakshmi
@ 2014-04-10 22:07 ` Jens Axboe
  2014-04-11 15:36   ` Lakshmi
  0 siblings, 1 reply; 5+ messages in thread
From: Jens Axboe @ 2014-04-10 22:07 UTC (permalink / raw)
  To: Lakshmi, fio

On 04/10/2014 12:25 PM, Lakshmi wrote:
> Hi Jens,
>
>   I am seeing a strange problem. I have a 47KB Blkparsed binary file
> and I tried replaying it with and without the "replay_no_stall"
> option.
>
> With the "replay_no_stall" option, I am seeing some IOPS
> happening.Please see below.
> WITH "REPLAY_NO_STALL=1"
> =====================================================
> job9: (g=0): rw=read, bs=4K-4K/4K-4K/4K-4K, ioengine=sync, iodepth=1
> fio-2.1.7
> Starting 1 process
> Jobs: 1 (f=2): [M] [-.-% done] [1064KB/72KB/0KB /s] [266/18/0 iops]
> [eta 00m:00s]
> job9: (groupid=0, jobs=1): err= 0: pid=34226: Thu Apr 10 12:00:54 2014
>    read : io=3792.0KB, bw=1126.3KB/s, iops=281, runt=  3367msec
>      clat (usec): min=88, max=8536, avg=3546.19, stdev=1469.46
>       lat (usec): min=88, max=8536, avg=3546.35, stdev=1469.47
> =====================================================
> However, when I don't set the "REPLAY_NO_STALL" option, I see 0
> IOPS.Please see below
> job9: (g=0): rw=read, bs=4K-4K/4K-4K/4K-4K, ioengine=sync, iodepth=1
> fio-2.1.7
> Starting 1 process
>
> job9: (groupid=0, jobs=1): err= 0: pid=33979: Thu Apr 10 10:39:42 2014
>    read : io=3792.0KB, bw=2004B/s, iops=0, runt=1937594msec
>      clat (usec): min=87, max=14320, avg=4763.37, stdev=2001.45
>       lat (usec): min=87, max=14320, avg=4763.52, stdev=2001.50
> ===========================================================
>
> My starting time in the blkparsed binary file is 26.040173218 seconds
> and last time is 26.150699031.
>
> Attached is the binary file I am using to replay.
>
> I understand replay_no_stall option doesnt respect the timestamps, but
> without this option the job should be executing with the delays, and
> not sure why no OPS are reported.
>
> Any idea what is causing this strange behavior?Please help.

It reports no IOPS, because it's slow enough to not register any. The 
first trace in the file is at timestamp 0.00 relative, and the last one 
is at 31110.250640101. Check for yourself with:

cat file_54657438_1000lines.bin | blkparse - | less

-- 
Jens Axboe



^ permalink raw reply	[flat|nested] 5+ messages in thread

* Re: No IOPS reported when "REPLAY_NO_STALL" is not set
  2014-04-10 22:07 ` Jens Axboe
@ 2014-04-11 15:36   ` Lakshmi
  2014-04-11 15:47     ` Jens Axboe
  0 siblings, 1 reply; 5+ messages in thread
From: Lakshmi @ 2014-04-11 15:36 UTC (permalink / raw)
  To: Jens Axboe; +Cc: fio

[-- Attachment #1: Type: text/plain, Size: 3054 bytes --]

Hi Jens,

Thanks for the command. I was looking for something like this.
However, I am still confused on the time stamp calculation.
My Binary file had the starting time as "26.040173218 seconds" , but
with the below command,

cat file_54657438_1000lines.bin | blkparse - | less

  8,0   60        0     0.000000000 54657438  Q   R 24014152 + 8 [(null)]
  8,0   60        0    66.860158593 54657438  Q   R 805379152 +8 [(null)]
  8,0   60        0    80.644832628 54657438  Q   R 24014160 + 8 [(null)]

The first line starts at 0 timestamp and then 66sec etc. I dont
understand how the 66sec is calculated in the above blkparse command.
Shouldnt it be 26.040173218 sec ?

I do see 26.040173218 in the binary file and checked this using a
binary viewer.Attached is the binary viewer of the file.
Please help me understand.

Thanks,
Lakshmi

On Thu, Apr 10, 2014 at 5:07 PM, Jens Axboe <axboe@kernel.dk> wrote:
> On 04/10/2014 12:25 PM, Lakshmi wrote:
>>
>> Hi Jens,
>>
>>   I am seeing a strange problem. I have a 47KB Blkparsed binary file
>> and I tried replaying it with and without the "replay_no_stall"
>> option.
>>
>> With the "replay_no_stall" option, I am seeing some IOPS
>> happening.Please see below.
>> WITH "REPLAY_NO_STALL=1"
>> =====================================================
>> job9: (g=0): rw=read, bs=4K-4K/4K-4K/4K-4K, ioengine=sync, iodepth=1
>> fio-2.1.7
>> Starting 1 process
>> Jobs: 1 (f=2): [M] [-.-% done] [1064KB/72KB/0KB /s] [266/18/0 iops]
>> [eta 00m:00s]
>> job9: (groupid=0, jobs=1): err= 0: pid=34226: Thu Apr 10 12:00:54 2014
>>    read : io=3792.0KB, bw=1126.3KB/s, iops=281, runt=  3367msec
>>      clat (usec): min=88, max=8536, avg=3546.19, stdev=1469.46
>>       lat (usec): min=88, max=8536, avg=3546.35, stdev=1469.47
>> =====================================================
>> However, when I don't set the "REPLAY_NO_STALL" option, I see 0
>> IOPS.Please see below
>> job9: (g=0): rw=read, bs=4K-4K/4K-4K/4K-4K, ioengine=sync, iodepth=1
>> fio-2.1.7
>> Starting 1 process
>>
>> job9: (groupid=0, jobs=1): err= 0: pid=33979: Thu Apr 10 10:39:42 2014
>>    read : io=3792.0KB, bw=2004B/s, iops=0, runt=1937594msec
>>      clat (usec): min=87, max=14320, avg=4763.37, stdev=2001.45
>>       lat (usec): min=87, max=14320, avg=4763.52, stdev=2001.50
>> ===========================================================
>>
>> My starting time in the blkparsed binary file is 26.040173218 seconds
>> and last time is 26.150699031.
>>
>> Attached is the binary file I am using to replay.
>>
>> I understand replay_no_stall option doesnt respect the timestamps, but
>> without this option the job should be executing with the delays, and
>> not sure why no OPS are reported.
>>
>> Any idea what is causing this strange behavior?Please help.
>
>
> It reports no IOPS, because it's slow enough to not register any. The first
> trace in the file is at timestamp 0.00 relative, and the last one is at
> 31110.250640101. Check for yourself with:
>
> cat file_54657438_1000lines.bin | blkparse - | less
>
> --
> Jens Axboe
>

[-- Attachment #2: Binary_view_Timestamp.png --]
[-- Type: image/png, Size: 25344 bytes --]

^ permalink raw reply	[flat|nested] 5+ messages in thread

* Re: No IOPS reported when "REPLAY_NO_STALL" is not set
  2014-04-11 15:36   ` Lakshmi
@ 2014-04-11 15:47     ` Jens Axboe
  0 siblings, 0 replies; 5+ messages in thread
From: Jens Axboe @ 2014-04-11 15:47 UTC (permalink / raw)
  To: Lakshmi; +Cc: fio

On 04/11/2014 09:36 AM, Lakshmi wrote:
> Hi Jens,
>
> Thanks for the command. I was looking for something like this.
> However, I am still confused on the time stamp calculation.
> My Binary file had the starting time as "26.040173218 seconds" , but
> with the below command,
>
> cat file_54657438_1000lines.bin | blkparse - | less
>
>    8,0   60        0     0.000000000 54657438  Q   R 24014152 + 8 [(null)]
>    8,0   60        0    66.860158593 54657438  Q   R 805379152 +8 [(null)]
>    8,0   60        0    80.644832628 54657438  Q   R 24014160 + 8 [(null)]
>
> The first line starts at 0 timestamp and then 66sec etc. I dont
> understand how the 66sec is calculated in the above blkparse command.
> Shouldnt it be 26.040173218 sec ?
>
> I do see 26.040173218 in the binary file and checked this using a
> binary viewer.Attached is the binary viewer of the file.
> Please help me understand.

If you look at the binary, the first timestamp is indeed the one you 
highlight. This then becomes the time 0, since all the other events are 
relative to this one. So 0x403a0a48cac17c2e is time 0, next timestamp is 
0x403a0a585bee8aaf, or 66860158593 nanoseconds ahead, which is 66.86s 
further ahead in time.

I don't know where you get the 26.04 from?

-- 
Jens Axboe



^ permalink raw reply	[flat|nested] 5+ messages in thread

* No IOPS reported when "Replay_no_stall" is not set
@ 2014-04-10 17:21 Lakshmi
  0 siblings, 0 replies; 5+ messages in thread
From: Lakshmi @ 2014-04-10 17:21 UTC (permalink / raw)
  To: fio, Jens Axboe

[-- Attachment #1: Type: text/plain, Size: 4869 bytes --]

Hi Jens,

 I am seeing a strange problem. I have a 47KB Blkparsed binary file
and I tried replaying it with and without the "replay_no_stall"
option.

With the "replay_no_stall" option, I am seeing some IOPS
happening.Please see below.
WITH "REPLAY_NO_STALL=1"
============================================================
job9: (g=0): rw=read, bs=4K-4K/4K-4K/4K-4K, ioengine=sync, iodepth=1
fio-2.1.7
Starting 1 process
Jobs: 1 (f=2): [M] [-.-% done] [1064KB/72KB/0KB /s] [266/18/0 iops]
[eta 00m:00s]
job9: (groupid=0, jobs=1): err= 0: pid=34226: Thu Apr 10 12:00:54 2014
  read : io=3792.0KB, bw=1126.3KB/s, iops=281, runt=  3367msec
    clat (usec): min=88, max=8536, avg=3546.19, stdev=1469.46
     lat (usec): min=88, max=8536, avg=3546.35, stdev=1469.47
    clat percentiles (usec):
     |  1.00th=[  141],  5.00th=[  270], 10.00th=[ 1800], 20.00th=[ 2320],
     | 30.00th=[ 2800], 40.00th=[ 3216], 50.00th=[ 3664], 60.00th=[ 4048],
     | 70.00th=[ 4512], 80.00th=[ 4896], 90.00th=[ 5344], 95.00th=[ 5600],
     | 99.00th=[ 6176], 99.50th=[ 6560], 99.90th=[ 8512], 99.95th=[ 8512],
     | 99.99th=[ 8512]
    bw (KB  /s): min= 1027, max= 1280, per=100.00%, avg=1129.00, stdev=99.47
  write: io=212992B, bw=63258B/s, iops=15, runt=  3367msec
    clat (usec): min=39, max=65, avg=44.27, stdev= 4.10
     lat (usec): min=40, max=66, avg=44.92, stdev= 4.16
    clat percentiles (usec):
     |  1.00th=[   39],  5.00th=[   39], 10.00th=[   40], 20.00th=[   41],
     | 30.00th=[   42], 40.00th=[   43], 50.00th=[   43], 60.00th=[   45],
     | 70.00th=[   46], 80.00th=[   47], 90.00th=[   48], 95.00th=[   50],
     | 99.00th=[   65], 99.50th=[   65], 99.90th=[   65], 99.95th=[   65],
     | 99.99th=[   65]
    bw (KB  /s): min=   48, max=   79, per=100.00%, avg=63.17, stdev=11.03
    lat (usec) : 50=4.90%, 100=0.40%, 250=4.30%, 500=1.40%, 750=0.10%
    lat (msec) : 2=6.90%, 4=42.70%, 10=39.30%
  cpu          : usr=0.00%, sys=0.45%, ctx=1002, majf=0, minf=2
  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    : total=r=948/w=52/d=0, short=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=1
=========================================================
However, when I don't set the "REPLAY_NO_STALL" option, I see 0
IOPS.Please see below
job9: (g=0): rw=read, bs=4K-4K/4K-4K/4K-4K, ioengine=sync, iodepth=1
fio-2.1.7
Starting 1 process

job9: (groupid=0, jobs=1): err= 0: pid=33979: Thu Apr 10 10:39:42 2014
  read : io=3792.0KB, bw=2004B/s, iops=0, runt=1937594msec
    clat (usec): min=87, max=14320, avg=4763.37, stdev=2001.45
     lat (usec): min=87, max=14320, avg=4763.52, stdev=2001.50
    clat percentiles (usec):
     |  1.00th=[  199],  5.00th=[ 1624], 10.00th=[ 2256], 20.00th=[ 3088],
     | 30.00th=[ 3760], 40.00th=[ 4320], 50.00th=[ 4832], 60.00th=[ 5280],
     | 70.00th=[ 5728], 80.00th=[ 6496], 90.00th=[ 7264], 95.00th=[ 7840],
     | 99.00th=[ 8896], 99.50th=[10304], 99.90th=[14272], 99.95th=[14272],
     | 99.99th=[14272]
    bw (KB  /s): min=    0, max=   23, per=100.00%, avg= 3.24, stdev= 4.87
  write: io=212992B, bw=109B/s, iops=0, runt=1937594msec
    clat (usec): min=39, max=62, avg=48.46, stdev= 6.93
     lat (usec): min=39, max=64, avg=49.19, stdev= 7.36
    clat percentiles (usec):
     |  1.00th=[   39],  5.00th=[   39], 10.00th=[   40], 20.00th=[   42],
     | 30.00th=[   44], 40.00th=[   45], 50.00th=[   46], 60.00th=[   50],
     | 70.00th=[   54], 80.00th=[   57], 90.00th=[   58], 95.00th=[   59],
     | 99.00th=[   62], 99.50th=[   62], 99.90th=[   62], 99.95th=[   62],
     | 99.99th=[   62]
    bw (KB  /s): min=    0, max=    1, per=100.00%, avg= 0.09, stdev= 0.30
    lat (usec) : 50=3.10%, 100=2.20%, 250=3.40%, 500=0.40%, 750=0.10%
    lat (msec) : 2=3.10%, 4=25.20%, 10=62.00%, 20=0.50%
  cpu          : usr=0.00%, sys=0.00%, ctx=1066, majf=0, minf=2
  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    : total=r=948/w=52/d=0, short=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=1
=============================================================

My starting time in the blkparsed binary file is 26.040173218 seconds
and last time is 26.150699031.

Attached is the binary file I am using to replay.

I understand replay_no_stall option doesnt respect the timestamps, but
without this option the job should be executing with the delays, and
not sure why no OPS are reported.

Any idea what is causing this strange behavior?Please help.

Thanks,
Lakshmi

[-- Attachment #2: file_54657438_1000lines.bin --]
[-- Type: application/octet-stream, Size: 48000 bytes --]

^ permalink raw reply	[flat|nested] 5+ messages in thread

end of thread, other threads:[~2014-04-11 15:47 UTC | newest]

Thread overview: 5+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2014-04-10 18:25 No IOPS reported when "REPLAY_NO_STALL" is not set Lakshmi
2014-04-10 22:07 ` Jens Axboe
2014-04-11 15:36   ` Lakshmi
2014-04-11 15:47     ` Jens Axboe
  -- strict thread matches above, loose matches on Subject: below --
2014-04-10 17:21 No IOPS reported when "Replay_no_stall" " Lakshmi

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.