runtime resets eta after countdown

runtime resets eta after countdown

[Vasu Kulkarni]

I see the following issue with my testing,  runtime always resets  eta to some higher number after countdown to 0

[randon_rw1]
rw=randrw
iodepth=8
runtime=24
ioengine=sync
filename=/dev/mapper/mpathdeo:/dev/mapper/mpathdep


or

[randon_rw1]
rw=randrw
iodepth=4
runtime=24
ioengine=sync
filename=/dev/mapper/mpathdeo
filename=/dev/mapper/mpathdep

both devices have 8 paths

mpathdep (23035376338373633) dm-7 FUSIONIO,ION LUN
size=382G features='3 queue_if_no_path pg_init_retries 50' hwhandler='1 alua' wp=rw
|-+- policy='queue-length 0' prio=130 status=active
| |- 0:0:1:5 sdk  8:160  active ready running
| |- 1:0:1:5 sdl  8:176  active ready running
| |- 1:0:0:5 sdaa 65:160 active ready running
| `- 0:0:0:5 sdab 65:176 active ready running
`-+- policy='queue-length 0' prio=1 status=enabled
  |- 1:0:2:5 sdar 66:176 active ready running
  |- 0:0:2:5 sdas 66:192 active ready running
  |- 0:0:3:5 sdbi 67:192 active ready running
  `- 1:0:3:5 sdbh 67:176 active ready running
mpathdeo (26361306637636532) dm-6 FUSIONIO,ION LUN
size=345G features='3 queue_if_no_path pg_init_retries 50' hwhandler='1 alua' wp=rw
|-+- policy='queue-length 0' prio=130 status=active
| |- 0:0:2:4 sdap 66:144 active ready running
| |- 1:0:2:4 sdaq 66:160 active ready running
| |- 1:0:3:4 sdbf 67:144 active ready running
| `- 0:0:3:4 sdbg 67:160 active ready running
`-+- policy='queue-length 0' prio=1 status=enabled
  |- 1:0:1:4 sdj  8:144  active ready running
  |- 0:0:1:4 sdi  8:128  active ready running
  |- 0:0:0:4 sdy  65:128 active ready running
  `- 1:0:0:4 sdz  65:144 active ready running


runtime gradually decreases from 24 seconds to 1 seconds and then eta is reset back to 4hours,  if there is only one device the runtime works properly

[root@auto-rhel65 ~]# fio /automation/fio/ioprofile1.fio 
randon_rw1: (g=0): rw=randrw, bs=4K-4K/4K-4K/4K-4K, ioengine=sync, iodepth=4
fio-2.1.7
Starting 1 process
^Cbs: 1 (f=1): [m] [0.2% done] [30232KB/30788KB/0KB /s] [7558/7697/0 iops] [eta 04h:02m:32s]


[root@auto-rhel65 ~]# fio -v
fio-2.1.7

[root@auto-rhel65 ~]# uname -a
Linux auto-rhel65 2.6.32-422.el6.x86_64 #1 SMP Mon Oct 7 17:58:55 EDT 2013 x86_64 x86_64 x86_64 GNU/Linux

RE: runtime resets eta after countdown

[Carl Zwanzig]

Hi

I have noticed similar effects but haven't had the time to characterize them. Whatever it is, it's been in the code for a long time.

z!

Re: runtime resets eta after countdown

[Vasu Kulkarni]

What is the workaround for this issue? I tried SIGINT but it doesn't always generate the numbers 

randon_rw1: (groupid=0, jobs=1): err= 0: pid=29726: Mon Apr 21 00:20:13 2014
    lat (usec) : 2=0.04%, 4=32.08%, 10=17.79%, 20=0.03%, 50=8.33%
    lat (usec) : 100=41.23%, 250=0.41%, 500=0.02%, 750=0.01%, 1000=0.01%
    lat (msec) : 2=0.01%, 4=0.01%, 10=0.03%, 20=0.01%, 50=0.01%
    lat (msec) : 100=0.01%, 250=0.01%, 500=0.01%
  cpu          : usr=0.00%, sys=0.00%, ctx=11640791, majf=3, minf=47
  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=9359258/w=9362934/d=0, short=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=8

Run status group 0 (all jobs):

Re: runtime resets eta after countdown

[Jens Axboe]

On 04/20/2014 11:08 AM, Vasu Kulkarni wrote:
> I see the following issue with my testing,  runtime always resets  eta to some higher number after countdown to 0
> 
> [randon_rw1]
> rw=randrw
> iodepth=8
> runtime=24
> ioengine=sync
> filename=/dev/mapper/mpathdeo:/dev/mapper/mpathdep
> 
> 
> or
> 
> [randon_rw1]
> rw=randrw
> iodepth=4
> runtime=24
> ioengine=sync
> filename=/dev/mapper/mpathdeo
> filename=/dev/mapper/mpathdep
> 
> both devices have 8 paths
> 
> mpathdep (23035376338373633) dm-7 FUSIONIO,ION LUN
> size=382G features='3 queue_if_no_path pg_init_retries 50' hwhandler='1 alua' wp=rw
> |-+- policy='queue-length 0' prio=130 status=active
> | |- 0:0:1:5 sdk  8:160  active ready running
> | |- 1:0:1:5 sdl  8:176  active ready running
> | |- 1:0:0:5 sdaa 65:160 active ready running
> | `- 0:0:0:5 sdab 65:176 active ready running
> `-+- policy='queue-length 0' prio=1 status=enabled
>   |- 1:0:2:5 sdar 66:176 active ready running
>   |- 0:0:2:5 sdas 66:192 active ready running
>   |- 0:0:3:5 sdbi 67:192 active ready running
>   `- 1:0:3:5 sdbh 67:176 active ready running
> mpathdeo (26361306637636532) dm-6 FUSIONIO,ION LUN
> size=345G features='3 queue_if_no_path pg_init_retries 50' hwhandler='1 alua' wp=rw
> |-+- policy='queue-length 0' prio=130 status=active
> | |- 0:0:2:4 sdap 66:144 active ready running
> | |- 1:0:2:4 sdaq 66:160 active ready running
> | |- 1:0:3:4 sdbf 67:144 active ready running
> | `- 0:0:3:4 sdbg 67:160 active ready running
> `-+- policy='queue-length 0' prio=1 status=enabled
>   |- 1:0:1:4 sdj  8:144  active ready running
>   |- 0:0:1:4 sdi  8:128  active ready running
>   |- 0:0:0:4 sdy  65:128 active ready running
>   `- 1:0:0:4 sdz  65:144 active ready running
> 
> 
> runtime gradually decreases from 24 seconds to 1 seconds and then eta is reset back to 4hours,  if there is only one device the runtime works properly

Just tried this with current fio -git, and it seems to work fine. Counts
down from 24s to 0, then quits and displays results. Can you try and
download the latest snapshot and re-test?

http://brick.kernel.dk/snaps/fio-git-latest.tar.gz

-- 
Jens Axboe

Re: runtime resets eta after countdown

[Vasu Kulkarni]

> 
> http://brick.kernel.dk/snaps/fio-git-latest.tar.gz

Tried most of the scenario's with the above git and its working fine. Thanks 

Re: runtime resets eta after countdown

[Vasu Kulkarni]

On Apr 21, 2014, at 11:56 AM, Vasu Kulkarni <vasu.kulkarni@gmail.com> wrote:

>> 
>> http://brick.kernel.dk/snaps/fio-git-latest.tar.gz
> 
> Tried most of the scenario's with the above git and its working fine. Thanks 
	
      I still see 1/5 runs still exhibit the problem where eta is getting reset, Will paths going offline and coming back online affect eta in anyway, runtime is in the range of 45minutes ? 
      Is there any logs that i can provide that will help debug this issue. Thanks.

Re: runtime resets eta after countdown

[Jens Axboe]

On 04/22/2014 10:22 AM, Vasu Kulkarni wrote:
> 
> On Apr 21, 2014, at 11:56 AM, Vasu Kulkarni <vasu.kulkarni@gmail.com> wrote:
> 
>>>
>>> http://brick.kernel.dk/snaps/fio-git-latest.tar.gz
>>
>> Tried most of the scenario's with the above git and its working fine. Thanks 
> 	
>       I still see 1/5 runs still exhibit the problem where eta is getting reset, Will paths going offline and coming back online affect eta in anyway, runtime is in the range of 45minutes ? 
>       Is there any logs that i can provide that will help debug this issue. Thanks.

OK, sounds like there's still a bug there, just triggers a bit
differently. I'll take a look at this.

-- 
Jens Axboe