A probable minor mistake in HOWTO page

A probable minor mistake in HOWTO page

[Mansour Shafaei Moghaddam]

Hi,

I found a minor mistake in the Fio's HOWTO page. According to this
document the "wait" command considers the offset as the number of
milliseconds which it must hold on before submitting the next I/O. A
very simple experiment with a short trace including those "wait"
commands shows that the numbers that you put as offset are interpreted
as the time for submission of next I/O not the amount of wait time
between them. In other words, the value in offset field is the
absolute delay from the beginning of run not the relative delay.

P.S.: The version of fio I have been working on is 2.1.11, but I saw
the same explanation in more recent versions' HOWTO page as well. So,
decided to share it with you.

Mansour

Re: A probable minor mistake in HOWTO page

[Jens Axboe]

On 04/07/2015 11:23 AM, Mansour Shafaei Moghaddam wrote:
> Hi,
>
> I found a minor mistake in the Fio's HOWTO page. According to this
> document the "wait" command considers the offset as the number of
> milliseconds which it must hold on before submitting the next I/O. A
> very simple experiment with a short trace including those "wait"
> commands shows that the numbers that you put as offset are interpreted
> as the time for submission of next I/O not the amount of wait time
> between them. In other words, the value in offset field is the
> absolute delay from the beginning of run not the relative delay.
>
> P.S.: The version of fio I have been working on is 2.1.11, but I saw
> the same explanation in more recent versions' HOWTO page as well. So,
> decided to share it with you.

Thanks, updated. It is indeed a relative time.

-- 
Jens Axboe

Re: A probable minor mistake in HOWTO page

[Mansour Shafaei Moghaddam]

But I still think that the time is not relative to anything except the
beginning of the job i.e., 0:00:00. I again tried running the
following trace:

io version 2 iolog
/dev/sde add
/dev/sde open
/dev/sde read 1499999997952 16384
/dev/sde read 4499992682496 16384
/dev/sde read 4499992682496 16384
/dev/sde wait 3000 16384
/dev/sde read 4499992682496 16384
/dev/sde read 4499992682496 16384
/dev/sde read 4499992682496 16384
/dev/sde wait 5000 16384
/dev/sde read 1499999997952 16384
/dev/sde read 4499993485312 16384
/dev/sde read 4499993485312 16384
/dev/sde read 4499993485312 16384
/dev/sde read 4499993485312 16384
/dev/sde read 4499993485312 16384
/dev/sde close

with the job file shown below:


[global]
log_offset=1
direct=1
ioengine=sync
[read-phase]
write_lat_log=test
read_iolog=testtrace

Here is what I see in the clat file:


22, 22165, 0, 16384, 1499999997952
48, 25752, 0, 16384, 4499992682496
58, 10044, 0, 16384, 4499992682496
2907, 8123, 0, 16384, 4499992682496
2917, 10077, 0, 16384, 4499992682496
2927, 10002, 0, 16384, 4499992682496
4918, 18610, 0, 16384, 1499999997952
4942, 24021, 0, 16384, 4499993485312
4952, 10018, 0, 16384, 4499993485312
4962, 10017, 0, 16384, 4499993485312
4972, 10030, 0, 16384, 4499993485312
4982, 10029, 0, 16384, 4499993485312

As you can see submission times are like
(22,....,2907,.....,4918,...). So the given value as offset is being
interpreted as absolute delay. In other words it is the time stamp for
the IO right after that. If it is less than the current time of the
job it will be ignored. Otherwise, it will be applied.


On Fri, Apr 24, 2015 at 12:46 PM, Jens Axboe <axboe@kernel.dk> wrote:
> On 04/07/2015 11:23 AM, Mansour Shafaei Moghaddam wrote:
>>
>> Hi,
>>
>> I found a minor mistake in the Fio's HOWTO page. According to this
>> document the "wait" command considers the offset as the number of
>> milliseconds which it must hold on before submitting the next I/O. A
>> very simple experiment with a short trace including those "wait"
>> commands shows that the numbers that you put as offset are interpreted
>> as the time for submission of next I/O not the amount of wait time
>> between them. In other words, the value in offset field is the
>> absolute delay from the beginning of run not the relative delay.
>>
>> P.S.: The version of fio I have been working on is 2.1.11, but I saw
>> the same explanation in more recent versions' HOWTO page as well. So,
>> decided to share it with you.
>
>
> Thanks, updated. It is indeed a relative time.
>
> --
> Jens Axboe
>

Re: A probable minor mistake in HOWTO page

[Jens Axboe]

On 04/24/2015 11:10 AM, Mansour Shafaei Moghaddam wrote:
> But I still think that the time is not relative to anything except the
> beginning of the job i.e., 0:00:00. I again tried running the
> following trace:
>
> io version 2 iolog
> /dev/sde add
> /dev/sde open
> /dev/sde read 1499999997952 16384
> /dev/sde read 4499992682496 16384
> /dev/sde read 4499992682496 16384
> /dev/sde wait 3000 16384
> /dev/sde read 4499992682496 16384
> /dev/sde read 4499992682496 16384
> /dev/sde read 4499992682496 16384
> /dev/sde wait 5000 16384
> /dev/sde read 1499999997952 16384
> /dev/sde read 4499993485312 16384
> /dev/sde read 4499993485312 16384
> /dev/sde read 4499993485312 16384
> /dev/sde read 4499993485312 16384
> /dev/sde read 4499993485312 16384
> /dev/sde close
>
> with the job file shown below:
>
>
> [global]
> log_offset=1
> direct=1
> ioengine=sync
> [read-phase]
> write_lat_log=test
> read_iolog=testtrace
>
> Here is what I see in the clat file:
>
>
> 22, 22165, 0, 16384, 1499999997952
> 48, 25752, 0, 16384, 4499992682496
> 58, 10044, 0, 16384, 4499992682496
> 2907, 8123, 0, 16384, 4499992682496
> 2917, 10077, 0, 16384, 4499992682496
> 2927, 10002, 0, 16384, 4499992682496
> 4918, 18610, 0, 16384, 1499999997952
> 4942, 24021, 0, 16384, 4499993485312
> 4952, 10018, 0, 16384, 4499993485312
> 4962, 10017, 0, 16384, 4499993485312
> 4972, 10030, 0, 16384, 4499993485312
> 4982, 10029, 0, 16384, 4499993485312
>
> As you can see submission times are like
> (22,....,2907,.....,4918,...). So the given value as offset is being
> interpreted as absolute delay. In other words it is the time stamp for
> the IO right after that. If it is less than the current time of the
> job it will be ignored. Otherwise, it will be applied.

Yeah, I was too quick, looking at the code, on reading the log, we store 
offset in delay directly:

if (rw == DDIR_WAIT) {
         ipo->delay = offset;
} else {

and on retrieval, we factor in the 'td' time offset as an absolute delay.

-- 
Jens Axboe

Re: A probable minor mistake in HOWTO page

[Mansour Shafaei Moghaddam]

Thanks for your response and also your consideration.

Good Luck



On Fri, Apr 24, 2015 at 1:16 PM, Jens Axboe <axboe@kernel.dk> wrote:
> On 04/24/2015 11:10 AM, Mansour Shafaei Moghaddam wrote:
>>
>> But I still think that the time is not relative to anything except the
>> beginning of the job i.e., 0:00:00. I again tried running the
>> following trace:
>>
>> io version 2 iolog
>> /dev/sde add
>> /dev/sde open
>> /dev/sde read 1499999997952 16384
>> /dev/sde read 4499992682496 16384
>> /dev/sde read 4499992682496 16384
>> /dev/sde wait 3000 16384
>> /dev/sde read 4499992682496 16384
>> /dev/sde read 4499992682496 16384
>> /dev/sde read 4499992682496 16384
>> /dev/sde wait 5000 16384
>> /dev/sde read 1499999997952 16384
>> /dev/sde read 4499993485312 16384
>> /dev/sde read 4499993485312 16384
>> /dev/sde read 4499993485312 16384
>> /dev/sde read 4499993485312 16384
>> /dev/sde read 4499993485312 16384
>> /dev/sde close
>>
>> with the job file shown below:
>>
>>
>> [global]
>> log_offset=1
>> direct=1
>> ioengine=sync
>> [read-phase]
>> write_lat_log=test
>> read_iolog=testtrace
>>
>> Here is what I see in the clat file:
>>
>>
>> 22, 22165, 0, 16384, 1499999997952
>> 48, 25752, 0, 16384, 4499992682496
>> 58, 10044, 0, 16384, 4499992682496
>> 2907, 8123, 0, 16384, 4499992682496
>> 2917, 10077, 0, 16384, 4499992682496
>> 2927, 10002, 0, 16384, 4499992682496
>> 4918, 18610, 0, 16384, 1499999997952
>> 4942, 24021, 0, 16384, 4499993485312
>> 4952, 10018, 0, 16384, 4499993485312
>> 4962, 10017, 0, 16384, 4499993485312
>> 4972, 10030, 0, 16384, 4499993485312
>> 4982, 10029, 0, 16384, 4499993485312
>>
>> As you can see submission times are like
>> (22,....,2907,.....,4918,...). So the given value as offset is being
>> interpreted as absolute delay. In other words it is the time stamp for
>> the IO right after that. If it is less than the current time of the
>> job it will be ignored. Otherwise, it will be applied.
>
>
> Yeah, I was too quick, looking at the code, on reading the log, we store
> offset in delay directly:
>
> if (rw == DDIR_WAIT) {
>         ipo->delay = offset;
> } else {
>
> and on retrieval, we factor in the 'td' time offset as an absolute delay.
>
> --
> Jens Axboe
>