* BUG: option runtime not working during a particular failure mode.
@ 2008-10-06 22:04 Shawn Lewis
2008-10-07 9:30 ` Jens Axboe
0 siblings, 1 reply; 7+ messages in thread
From: Shawn Lewis @ 2008-10-06 22:04 UTC (permalink / raw)
To: fio
Hi,
I have a random read load in which fio hung on a machine. It is
time_based with runtime=60. A few of the disks in question experienced
errors at the same time so I would expect fio to fail or stop after
60- seconds.
I haven't tried to debug this in depth yet. Jens I thought an answer
might jump out at you. If not I'll take a look.
Full disclosure: I modified the config and the strace output to show
fewer disks then were actually being accessed.
Here is the config file:
[sda-randomaccess]
filename=/export/sda3/
datafile.tmp
rw=randread
bs=64k
ioengine=sync
time_based=1
runtime=3600
bwavgtime=5000
direct=1
thread=1
[sdb-randomaccess]
filename=/export/sdb3/datafile.tmp
rw=randread
bs=64k
ioengine=sync
time_based=1
runtime=3600
bwavgtime=5000
direct=1
thread=1
[sdc-randomaccess]
filename=/export/sdc3/datafile.tmp
rw=randread
bs=64k
ioengine=sync
time_based=1
runtime=3600
bwavgtime=5000
direct=1
thread=1
[sdd-randomaccess]
filename=/export/sdd3/datafile.tmp
rw=randread
bs=64k
ioengine=sync
time_based=1
runtime=3600
bwavgtime=5000
direct=1
thread=1
We get some hints from strace. It looks like we're just doing the
sig_alrm loop. But why aren't hitting runtime? Are the other threads
stopped already for some reason?
static void sig_alrm(int sig)
{
if (threads) {
update_io_ticks();
print_thread_status();
status_timer_arm();
}
}
strace. This is repeated over and over:
--- SIGALRM (Alarm clock) @ 0 (0) ---
open("/sys/block/sdd/stat", O_RDONLY) = 8
fstat(8, {st_mode=S_IFREG|0444, st_size=4096, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x2aaaadf29000
read(8, "15490269 238448 1950476298 87"..., 4096) = 105
close(8) = 0
munmap(0x2aaaadf29000, 4096) = 0
open("/sys/block/sdc/stat", O_RDONLY) = 8
fstat(8, {st_mode=S_IFREG|0444, st_size=4096, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x2aaaadf29000
read(8, "15489598 238450 1950388618 86"..., 4096) = 105
close(8) = 0
munmap(0x2aaaadf29000, 4096) = 0
open("/sys/block/sda/stat", O_RDONLY) = 8
fstat(8, {st_mode=S_IFREG|0444, st_size=4096, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x2aaaadf29000
read(8, "15368259 237021 1934418422 103"..., 4096) = 105
close(8) = 0
munmap(0x2aaaadf29000, 4096) = 0
open("/sys/block/sdb/stat", O_RDONLY) = 8
fstat(8, {st_mode=S_IFREG|0444, st_size=4096, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x2aaaadf29000
read(8, "15665652 241115 1972572554 101"..., 4096) = 105
close(8) = 0
munmap(0x2aaaadf29000, 4096) = 0
setitimer(ITIMER_REAL, {it_interval={0, 0}, it_value={0, 250000}}, NULL) = 0
rt_sigreturn(0x5875e0) = -1 EINTR (Interrupted system call)
nanosleep({0, 10000000}, NULL) = 0
nanosleep({0, 10000000}, NULL) = 0
nanosleep({0, 10000000}, NULL) = 0
nanosleep({0, 10000000}, NULL) = 0
nanosleep({0, 10000000}, NULL) = 0
nanosleep({0, 10000000}, NULL) = 0
nanosleep({0, 10000000}, NULL) = 0
nanosleep({0, 10000000}, NULL) = 0
nanosleep({0, 10000000}, NULL) = 0
nanosleep({0, 10000000}, NULL) = 0
nanosleep({0, 10000000}, NULL) = 0
nanosleep({0, 10000000}, NULL) = 0
nanosleep({0, 10000000}, NULL) = 0
nanosleep({0, 10000000}, NULL) = 0
nanosleep({0, 10000000}, NULL) = 0
nanosleep({0, 10000000}, NULL) = 0
nanosleep({0, 10000000}, NULL) = 0
nanosleep({0, 10000000}, NULL) = 0
nanosleep({0, 10000000}, NULL) = 0
nanosleep({0, 10000000}, NULL) = 0
nanosleep({0, 10000000}, NULL) = 0
nanosleep({0, 10000000}, NULL) = 0
nanosleep({0, 10000000}, 0) = ? ERESTART_RESTARTBLOCK (To
be restarted)
Thanks,
Shawn
^ permalink raw reply [flat|nested] 7+ messages in thread* Re: BUG: option runtime not working during a particular failure mode.
2008-10-06 22:04 BUG: option runtime not working during a particular failure mode Shawn Lewis
@ 2008-10-07 9:30 ` Jens Axboe
2008-10-07 16:28 ` Shawn Lewis
0 siblings, 1 reply; 7+ messages in thread
From: Jens Axboe @ 2008-10-07 9:30 UTC (permalink / raw)
To: Shawn Lewis; +Cc: fio
On Mon, Oct 06 2008, Shawn Lewis wrote:
> Hi,
>
> I have a random read load in which fio hung on a machine. It is
> time_based with runtime=60. A few of the disks in question experienced
> errors at the same time so I would expect fio to fail or stop after
> 60- seconds.
>
> I haven't tried to debug this in depth yet. Jens I thought an answer
> might jump out at you. If not I'll take a look.
>
> Full disclosure: I modified the config and the strace output to show
> fewer disks then were actually being accessed.
>
> Here is the config file:
> [sda-randomaccess]
> filename=/export/sda3/
> datafile.tmp
> rw=randread
> bs=64k
> ioengine=sync
> time_based=1
> runtime=3600
> bwavgtime=5000
> direct=1
> thread=1
>
> [sdb-randomaccess]
> filename=/export/sdb3/datafile.tmp
> rw=randread
> bs=64k
> ioengine=sync
> time_based=1
> runtime=3600
> bwavgtime=5000
> direct=1
> thread=1
>
> [sdc-randomaccess]
> filename=/export/sdc3/datafile.tmp
> rw=randread
> bs=64k
> ioengine=sync
> time_based=1
> runtime=3600
> bwavgtime=5000
> direct=1
> thread=1
>
> [sdd-randomaccess]
> filename=/export/sdd3/datafile.tmp
> rw=randread
> bs=64k
> ioengine=sync
> time_based=1
> runtime=3600
> bwavgtime=5000
> direct=1
> thread=1
>
>
> We get some hints from strace. It looks like we're just doing the
> sig_alrm loop. But why aren't hitting runtime? Are the other threads
> stopped already for some reason?
>
> static void sig_alrm(int sig)
> {
> if (threads) {
> update_io_ticks();
> print_thread_status();
> status_timer_arm();
> }
> }
Good question. What are the other threads doing, have you poked around
to see what they are up to? You mention IO errors, so are some of the
threads stuck in error handling or did they all exit? If they did exit,
did they exit nicely or did they get killed by the kernel?
> strace. This is repeated over and over:
>
> --- SIGALRM (Alarm clock) @ 0 (0) ---
> open("/sys/block/sdd/stat", O_RDONLY) = 8
> fstat(8, {st_mode=S_IFREG|0444, st_size=4096, ...}) = 0
> mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
> 0) = 0x2aaaadf29000
> read(8, "15490269 238448 1950476298 87"..., 4096) = 105
> close(8) = 0
> munmap(0x2aaaadf29000, 4096) = 0
> open("/sys/block/sdc/stat", O_RDONLY) = 8
> fstat(8, {st_mode=S_IFREG|0444, st_size=4096, ...}) = 0
> mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
> 0) = 0x2aaaadf29000
> read(8, "15489598 238450 1950388618 86"..., 4096) = 105
> close(8) = 0
> munmap(0x2aaaadf29000, 4096) = 0
> open("/sys/block/sda/stat", O_RDONLY) = 8
> fstat(8, {st_mode=S_IFREG|0444, st_size=4096, ...}) = 0
> mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
> 0) = 0x2aaaadf29000
> read(8, "15368259 237021 1934418422 103"..., 4096) = 105
> close(8) = 0
> munmap(0x2aaaadf29000, 4096) = 0
> open("/sys/block/sdb/stat", O_RDONLY) = 8
> fstat(8, {st_mode=S_IFREG|0444, st_size=4096, ...}) = 0
> mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
> 0) = 0x2aaaadf29000
> read(8, "15665652 241115 1972572554 101"..., 4096) = 105
> close(8) = 0
> munmap(0x2aaaadf29000, 4096) = 0
> setitimer(ITIMER_REAL, {it_interval={0, 0}, it_value={0, 250000}}, NULL) = 0
> rt_sigreturn(0x5875e0) = -1 EINTR (Interrupted system call)
> nanosleep({0, 10000000}, NULL) = 0
> nanosleep({0, 10000000}, NULL) = 0
> nanosleep({0, 10000000}, NULL) = 0
> nanosleep({0, 10000000}, NULL) = 0
> nanosleep({0, 10000000}, NULL) = 0
> nanosleep({0, 10000000}, NULL) = 0
> nanosleep({0, 10000000}, NULL) = 0
> nanosleep({0, 10000000}, NULL) = 0
> nanosleep({0, 10000000}, NULL) = 0
> nanosleep({0, 10000000}, NULL) = 0
> nanosleep({0, 10000000}, NULL) = 0
> nanosleep({0, 10000000}, NULL) = 0
> nanosleep({0, 10000000}, NULL) = 0
> nanosleep({0, 10000000}, NULL) = 0
> nanosleep({0, 10000000}, NULL) = 0
> nanosleep({0, 10000000}, NULL) = 0
> nanosleep({0, 10000000}, NULL) = 0
> nanosleep({0, 10000000}, NULL) = 0
> nanosleep({0, 10000000}, NULL) = 0
> nanosleep({0, 10000000}, NULL) = 0
> nanosleep({0, 10000000}, NULL) = 0
> nanosleep({0, 10000000}, NULL) = 0
> nanosleep({0, 10000000}, 0) = ? ERESTART_RESTARTBLOCK (To
> be restarted)
>
>
> Thanks,
> Shawn
> --
> 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
--
Jens Axboe
^ permalink raw reply [flat|nested] 7+ messages in thread* Re: BUG: option runtime not working during a particular failure mode.
2008-10-07 9:30 ` Jens Axboe
@ 2008-10-07 16:28 ` Shawn Lewis
2008-10-08 11:01 ` Jens Axboe
0 siblings, 1 reply; 7+ messages in thread
From: Shawn Lewis @ 2008-10-07 16:28 UTC (permalink / raw)
To: Jens Axboe; +Cc: fio
On Tue, Oct 7, 2008 at 2:30 AM, Jens Axboe <jens.axboe@oracle.com> wrote:
> On Mon, Oct 06 2008, Shawn Lewis wrote:
>> Hi,
>>
>> I have a random read load in which fio hung on a machine. It is
>> time_based with runtime=60. A few of the disks in question experienced
>> errors at the same time so I would expect fio to fail or stop after
>> 60- seconds.
>>
>> I haven't tried to debug this in depth yet. Jens I thought an answer
>> might jump out at you. If not I'll take a look.
>>
>> Full disclosure: I modified the config and the strace output to show
>> fewer disks then were actually being accessed.
>>
>> Here is the config file:
>> [sda-randomaccess]
>> filename=/export/sda3/
>> datafile.tmp
>> rw=randread
>> bs=64k
>> ioengine=sync
>> time_based=1
>> runtime=3600
>> bwavgtime=5000
>> direct=1
>> thread=1
>>
>> [sdb-randomaccess]
>> filename=/export/sdb3/datafile.tmp
>> rw=randread
>> bs=64k
>> ioengine=sync
>> time_based=1
>> runtime=3600
>> bwavgtime=5000
>> direct=1
>> thread=1
>>
>> [sdc-randomaccess]
>> filename=/export/sdc3/datafile.tmp
>> rw=randread
>> bs=64k
>> ioengine=sync
>> time_based=1
>> runtime=3600
>> bwavgtime=5000
>> direct=1
>> thread=1
>>
>> [sdd-randomaccess]
>> filename=/export/sdd3/datafile.tmp
>> rw=randread
>> bs=64k
>> ioengine=sync
>> time_based=1
>> runtime=3600
>> bwavgtime=5000
>> direct=1
>> thread=1
>>
>>
>> We get some hints from strace. It looks like we're just doing the
>> sig_alrm loop. But why aren't hitting runtime? Are the other threads
>> stopped already for some reason?
>>
>> static void sig_alrm(int sig)
>> {
>> if (threads) {
>> update_io_ticks();
>> print_thread_status();
>> status_timer_arm();
>> }
>> }
>
> Good question. What are the other threads doing, have you poked around
> to see what they are up to? You mention IO errors, so are some of the
> threads stuck in error handling or did they all exit? If they did exit,
> did they exit nicely or did they get killed by the kernel?
There was only one thread running as far as I could tell. I don't
think the kernel killed them.
>
>> strace. This is repeated over and over:
>>
>> --- SIGALRM (Alarm clock) @ 0 (0) ---
>> open("/sys/block/sdd/stat", O_RDONLY) = 8
>> fstat(8, {st_mode=S_IFREG|0444, st_size=4096, ...}) = 0
>> mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
>> 0) = 0x2aaaadf29000
>> read(8, "15490269 238448 1950476298 87"..., 4096) = 105
>> close(8) = 0
>> munmap(0x2aaaadf29000, 4096) = 0
>> open("/sys/block/sdc/stat", O_RDONLY) = 8
>> fstat(8, {st_mode=S_IFREG|0444, st_size=4096, ...}) = 0
>> mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
>> 0) = 0x2aaaadf29000
>> read(8, "15489598 238450 1950388618 86"..., 4096) = 105
>> close(8) = 0
>> munmap(0x2aaaadf29000, 4096) = 0
>> open("/sys/block/sda/stat", O_RDONLY) = 8
>> fstat(8, {st_mode=S_IFREG|0444, st_size=4096, ...}) = 0
>> mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
>> 0) = 0x2aaaadf29000
>> read(8, "15368259 237021 1934418422 103"..., 4096) = 105
>> close(8) = 0
>> munmap(0x2aaaadf29000, 4096) = 0
>> open("/sys/block/sdb/stat", O_RDONLY) = 8
>> fstat(8, {st_mode=S_IFREG|0444, st_size=4096, ...}) = 0
>> mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
>> 0) = 0x2aaaadf29000
>> read(8, "15665652 241115 1972572554 101"..., 4096) = 105
>> close(8) = 0
>> munmap(0x2aaaadf29000, 4096) = 0
>> setitimer(ITIMER_REAL, {it_interval={0, 0}, it_value={0, 250000}}, NULL) = 0
>> rt_sigreturn(0x5875e0) = -1 EINTR (Interrupted system call)
>> nanosleep({0, 10000000}, NULL) = 0
>> nanosleep({0, 10000000}, NULL) = 0
>> nanosleep({0, 10000000}, NULL) = 0
>> nanosleep({0, 10000000}, NULL) = 0
>> nanosleep({0, 10000000}, NULL) = 0
>> nanosleep({0, 10000000}, NULL) = 0
>> nanosleep({0, 10000000}, NULL) = 0
>> nanosleep({0, 10000000}, NULL) = 0
>> nanosleep({0, 10000000}, NULL) = 0
>> nanosleep({0, 10000000}, NULL) = 0
>> nanosleep({0, 10000000}, NULL) = 0
>> nanosleep({0, 10000000}, NULL) = 0
>> nanosleep({0, 10000000}, NULL) = 0
>> nanosleep({0, 10000000}, NULL) = 0
>> nanosleep({0, 10000000}, NULL) = 0
>> nanosleep({0, 10000000}, NULL) = 0
>> nanosleep({0, 10000000}, NULL) = 0
>> nanosleep({0, 10000000}, NULL) = 0
>> nanosleep({0, 10000000}, NULL) = 0
>> nanosleep({0, 10000000}, NULL) = 0
>> nanosleep({0, 10000000}, NULL) = 0
>> nanosleep({0, 10000000}, NULL) = 0
>> nanosleep({0, 10000000}, 0) = ? ERESTART_RESTARTBLOCK (To
>> be restarted)
>>
>>
>> Thanks,
>> Shawn
>> --
>> 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
>
> --
> Jens Axboe
>
>
^ permalink raw reply [flat|nested] 7+ messages in thread* Re: BUG: option runtime not working during a particular failure mode.
2008-10-07 16:28 ` Shawn Lewis
@ 2008-10-08 11:01 ` Jens Axboe
2008-10-08 11:17 ` Jens Axboe
0 siblings, 1 reply; 7+ messages in thread
From: Jens Axboe @ 2008-10-08 11:01 UTC (permalink / raw)
To: Shawn Lewis; +Cc: fio
On Tue, Oct 07 2008, Shawn Lewis wrote:
> On Tue, Oct 7, 2008 at 2:30 AM, Jens Axboe <jens.axboe@oracle.com> wrote:
> > On Mon, Oct 06 2008, Shawn Lewis wrote:
> >> Hi,
> >>
> >> I have a random read load in which fio hung on a machine. It is
> >> time_based with runtime=60. A few of the disks in question experienced
> >> errors at the same time so I would expect fio to fail or stop after
> >> 60- seconds.
> >>
> >> I haven't tried to debug this in depth yet. Jens I thought an answer
> >> might jump out at you. If not I'll take a look.
> >>
> >> Full disclosure: I modified the config and the strace output to show
> >> fewer disks then were actually being accessed.
> >>
> >> Here is the config file:
> >> [sda-randomaccess]
> >> filename=/export/sda3/
> >> datafile.tmp
> >> rw=randread
> >> bs=64k
> >> ioengine=sync
> >> time_based=1
> >> runtime=3600
> >> bwavgtime=5000
> >> direct=1
> >> thread=1
> >>
> >> [sdb-randomaccess]
> >> filename=/export/sdb3/datafile.tmp
> >> rw=randread
> >> bs=64k
> >> ioengine=sync
> >> time_based=1
> >> runtime=3600
> >> bwavgtime=5000
> >> direct=1
> >> thread=1
> >>
> >> [sdc-randomaccess]
> >> filename=/export/sdc3/datafile.tmp
> >> rw=randread
> >> bs=64k
> >> ioengine=sync
> >> time_based=1
> >> runtime=3600
> >> bwavgtime=5000
> >> direct=1
> >> thread=1
> >>
> >> [sdd-randomaccess]
> >> filename=/export/sdd3/datafile.tmp
> >> rw=randread
> >> bs=64k
> >> ioengine=sync
> >> time_based=1
> >> runtime=3600
> >> bwavgtime=5000
> >> direct=1
> >> thread=1
> >>
> >>
> >> We get some hints from strace. It looks like we're just doing the
> >> sig_alrm loop. But why aren't hitting runtime? Are the other threads
> >> stopped already for some reason?
> >>
> >> static void sig_alrm(int sig)
> >> {
> >> if (threads) {
> >> update_io_ticks();
> >> print_thread_status();
> >> status_timer_arm();
> >> }
> >> }
> >
> > Good question. What are the other threads doing, have you poked around
> > to see what they are up to? You mention IO errors, so are some of the
> > threads stuck in error handling or did they all exit? If they did exit,
> > did they exit nicely or did they get killed by the kernel?
> There was only one thread running as far as I could tell. I don't
> think the kernel killed them.
Unless you have an oops in the kernel, they were likely not killed. What
version of fio is this? Fio used to have problems detecting missing
threads/processes, but it should be solid now.
I haven't been able to (artificially) reproduce this case. I guess, for
safety, I could add a forced exit in the sigalrm loop if we exceeded
ther untime (plus a little margin).
--
Jens Axboe
^ permalink raw reply [flat|nested] 7+ messages in thread* Re: BUG: option runtime not working during a particular failure mode.
2008-10-08 11:01 ` Jens Axboe
@ 2008-10-08 11:17 ` Jens Axboe
2008-10-08 16:24 ` Shawn Lewis
0 siblings, 1 reply; 7+ messages in thread
From: Jens Axboe @ 2008-10-08 11:17 UTC (permalink / raw)
To: Shawn Lewis; +Cc: fio
On Wed, Oct 08 2008, Jens Axboe wrote:
> On Tue, Oct 07 2008, Shawn Lewis wrote:
> > On Tue, Oct 7, 2008 at 2:30 AM, Jens Axboe <jens.axboe@oracle.com> wrote:
> > > On Mon, Oct 06 2008, Shawn Lewis wrote:
> > >> Hi,
> > >>
> > >> I have a random read load in which fio hung on a machine. It is
> > >> time_based with runtime=60. A few of the disks in question experienced
> > >> errors at the same time so I would expect fio to fail or stop after
> > >> 60- seconds.
> > >>
> > >> I haven't tried to debug this in depth yet. Jens I thought an answer
> > >> might jump out at you. If not I'll take a look.
> > >>
> > >> Full disclosure: I modified the config and the strace output to show
> > >> fewer disks then were actually being accessed.
> > >>
> > >> Here is the config file:
> > >> [sda-randomaccess]
> > >> filename=/export/sda3/
> > >> datafile.tmp
> > >> rw=randread
> > >> bs=64k
> > >> ioengine=sync
> > >> time_based=1
> > >> runtime=3600
> > >> bwavgtime=5000
> > >> direct=1
> > >> thread=1
> > >>
> > >> [sdb-randomaccess]
> > >> filename=/export/sdb3/datafile.tmp
> > >> rw=randread
> > >> bs=64k
> > >> ioengine=sync
> > >> time_based=1
> > >> runtime=3600
> > >> bwavgtime=5000
> > >> direct=1
> > >> thread=1
> > >>
> > >> [sdc-randomaccess]
> > >> filename=/export/sdc3/datafile.tmp
> > >> rw=randread
> > >> bs=64k
> > >> ioengine=sync
> > >> time_based=1
> > >> runtime=3600
> > >> bwavgtime=5000
> > >> direct=1
> > >> thread=1
> > >>
> > >> [sdd-randomaccess]
> > >> filename=/export/sdd3/datafile.tmp
> > >> rw=randread
> > >> bs=64k
> > >> ioengine=sync
> > >> time_based=1
> > >> runtime=3600
> > >> bwavgtime=5000
> > >> direct=1
> > >> thread=1
> > >>
> > >>
> > >> We get some hints from strace. It looks like we're just doing the
> > >> sig_alrm loop. But why aren't hitting runtime? Are the other threads
> > >> stopped already for some reason?
> > >>
> > >> static void sig_alrm(int sig)
> > >> {
> > >> if (threads) {
> > >> update_io_ticks();
> > >> print_thread_status();
> > >> status_timer_arm();
> > >> }
> > >> }
> > >
> > > Good question. What are the other threads doing, have you poked around
> > > to see what they are up to? You mention IO errors, so are some of the
> > > threads stuck in error handling or did they all exit? If they did exit,
> > > did they exit nicely or did they get killed by the kernel?
> > There was only one thread running as far as I could tell. I don't
> > think the kernel killed them.
>
> Unless you have an oops in the kernel, they were likely not killed. What
> version of fio is this? Fio used to have problems detecting missing
> threads/processes, but it should be solid now.
>
> I haven't been able to (artificially) reproduce this case. I guess, for
> safety, I could add a forced exit in the sigalrm loop if we exceeded
> ther untime (plus a little margin).
Something like this should force fio to quit, when it detects such a
situation. I guess it would be hard for you to reproduce this situation,
correct?
diff --git a/fio.c b/fio.c
index 773f106..1ba227e 100644
--- a/fio.c
+++ b/fio.c
@@ -71,7 +71,7 @@ void td_set_runstate(struct thread_data *td, int runstate)
td->runstate = runstate;
}
-static void terminate_threads(int group_id)
+static void terminate_threads(int group_id, int force)
{
struct thread_data *td;
int i;
@@ -88,7 +88,7 @@ static void terminate_threads(int group_id)
/*
* if the thread is running, just let it exit
*/
- if (td->runstate < TD_RUNNING)
+ if (td->runstate < TD_RUNNING || force)
kill(td->pid, SIGQUIT);
else {
struct ioengine_ops *ops = td->io_ops;
@@ -107,8 +107,32 @@ static void status_timer_arm(void)
setitimer(ITIMER_REAL, &itimer, NULL);
}
+static int overtime(void)
+{
+ unsigned long elapsed;
+
+ if (!def_thread.o.timeout)
+ return 0;
+
+ /*
+ * Allow for 10 seconds of slack, this is supposed to be a last
+ * measure to make fio exit
+ */
+ elapsed = mtime_since_genesis() / 1000;
+ if (elapsed > def_thread.o.timeout + 10) {
+ log_err("fio: runtime seems way exceeded, yet fio is still "
+ "alive. Forcing quit.\n");
+ terminate_threads(TERMINATE_ALL, 1);
+ return 1;
+ }
+
+ return 0;
+}
+
static void sig_alrm(int fio_unused sig)
{
+ if (overtime())
+ return;
if (threads) {
update_io_ticks();
print_thread_status();
@@ -121,7 +145,7 @@ static void sig_int(int sig)
if (threads) {
printf("\nfio: terminating on signal %d\n", sig);
fflush(stdout);
- terminate_threads(TERMINATE_ALL);
+ terminate_threads(TERMINATE_ALL, 1);
}
}
@@ -132,7 +156,7 @@ static void sig_ill(int fio_unused sig)
log_err("fio: illegal instruction. your cpu does not support "
"the sse4.2 instruction for crc32c\n");
- terminate_threads(TERMINATE_ALL);
+ terminate_threads(TERMINATE_ALL, 1);
exit(4);
}
@@ -631,7 +655,7 @@ sync_done:
if (check_min_rate(td, &comp_time)) {
if (exitall_on_terminate)
- terminate_threads(td->groupid);
+ terminate_threads(td->groupid, 0);
td_verror(td, EIO, "check_min_rate");
break;
}
@@ -1053,7 +1077,7 @@ static void *thread_main(void *data)
}
if (exitall_on_terminate)
- terminate_threads(td->groupid);
+ terminate_threads(td->groupid, 0);
err:
if (td->error)
@@ -1189,7 +1213,7 @@ reaped:
}
if (*nr_running == cputhreads && !pending && realthreads)
- terminate_threads(TERMINATE_ALL);
+ terminate_threads(TERMINATE_ALL, 0);
}
/*
diff --git a/fio.h b/fio.h
index 63cd83f..3ec0591 100644
--- a/fio.h
+++ b/fio.h
@@ -705,6 +705,7 @@ extern unsigned long done_secs;
extern char *job_section;
extern struct thread_data *threads;
+extern struct thread_data def_thread;
#define td_read(td) ((td)->o.td_ddir & TD_DDIR_READ)
#define td_write(td) ((td)->o.td_ddir & TD_DDIR_WRITE)
--
Jens Axboe
^ permalink raw reply related [flat|nested] 7+ messages in thread* Re: BUG: option runtime not working during a particular failure mode.
2008-10-08 11:17 ` Jens Axboe
@ 2008-10-08 16:24 ` Shawn Lewis
2008-10-08 17:23 ` Jens Axboe
0 siblings, 1 reply; 7+ messages in thread
From: Shawn Lewis @ 2008-10-08 16:24 UTC (permalink / raw)
To: Jens Axboe; +Cc: fio
It is fio 1.17.2. I thought we synced up about a month ago but it
looks like there are much newer versions available. Sorry about that.
Anyway this patch looks good as a final protection.
On Wed, Oct 8, 2008 at 4:17 AM, Jens Axboe <jens.axboe@oracle.com> wrote:
> On Wed, Oct 08 2008, Jens Axboe wrote:
>> On Tue, Oct 07 2008, Shawn Lewis wrote:
>> > On Tue, Oct 7, 2008 at 2:30 AM, Jens Axboe <jens.axboe@oracle.com> wrote:
>> > > On Mon, Oct 06 2008, Shawn Lewis wrote:
>> > >> Hi,
>> > >>
>> > >> I have a random read load in which fio hung on a machine. It is
>> > >> time_based with runtime=60. A few of the disks in question experienced
>> > >> errors at the same time so I would expect fio to fail or stop after
>> > >> 60- seconds.
>> > >>
>> > >> I haven't tried to debug this in depth yet. Jens I thought an answer
>> > >> might jump out at you. If not I'll take a look.
>> > >>
>> > >> Full disclosure: I modified the config and the strace output to show
>> > >> fewer disks then were actually being accessed.
>> > >>
>> > >> Here is the config file:
>> > >> [sda-randomaccess]
>> > >> filename=/export/sda3/
>> > >> datafile.tmp
>> > >> rw=randread
>> > >> bs=64k
>> > >> ioengine=sync
>> > >> time_based=1
>> > >> runtime=3600
>> > >> bwavgtime=5000
>> > >> direct=1
>> > >> thread=1
>> > >>
>> > >> [sdb-randomaccess]
>> > >> filename=/export/sdb3/datafile.tmp
>> > >> rw=randread
>> > >> bs=64k
>> > >> ioengine=sync
>> > >> time_based=1
>> > >> runtime=3600
>> > >> bwavgtime=5000
>> > >> direct=1
>> > >> thread=1
>> > >>
>> > >> [sdc-randomaccess]
>> > >> filename=/export/sdc3/datafile.tmp
>> > >> rw=randread
>> > >> bs=64k
>> > >> ioengine=sync
>> > >> time_based=1
>> > >> runtime=3600
>> > >> bwavgtime=5000
>> > >> direct=1
>> > >> thread=1
>> > >>
>> > >> [sdd-randomaccess]
>> > >> filename=/export/sdd3/datafile.tmp
>> > >> rw=randread
>> > >> bs=64k
>> > >> ioengine=sync
>> > >> time_based=1
>> > >> runtime=3600
>> > >> bwavgtime=5000
>> > >> direct=1
>> > >> thread=1
>> > >>
>> > >>
>> > >> We get some hints from strace. It looks like we're just doing the
>> > >> sig_alrm loop. But why aren't hitting runtime? Are the other threads
>> > >> stopped already for some reason?
>> > >>
>> > >> static void sig_alrm(int sig)
>> > >> {
>> > >> if (threads) {
>> > >> update_io_ticks();
>> > >> print_thread_status();
>> > >> status_timer_arm();
>> > >> }
>> > >> }
>> > >
>> > > Good question. What are the other threads doing, have you poked around
>> > > to see what they are up to? You mention IO errors, so are some of the
>> > > threads stuck in error handling or did they all exit? If they did exit,
>> > > did they exit nicely or did they get killed by the kernel?
>> > There was only one thread running as far as I could tell. I don't
>> > think the kernel killed them.
>>
>> Unless you have an oops in the kernel, they were likely not killed. What
>> version of fio is this? Fio used to have problems detecting missing
>> threads/processes, but it should be solid now.
>>
>> I haven't been able to (artificially) reproduce this case. I guess, for
>> safety, I could add a forced exit in the sigalrm loop if we exceeded
>> ther untime (plus a little margin).
>
> Something like this should force fio to quit, when it detects such a
> situation. I guess it would be hard for you to reproduce this situation,
> correct?
>
>
> diff --git a/fio.c b/fio.c
> index 773f106..1ba227e 100644
> --- a/fio.c
> +++ b/fio.c
> @@ -71,7 +71,7 @@ void td_set_runstate(struct thread_data *td, int runstate)
> td->runstate = runstate;
> }
>
> -static void terminate_threads(int group_id)
> +static void terminate_threads(int group_id, int force)
> {
> struct thread_data *td;
> int i;
> @@ -88,7 +88,7 @@ static void terminate_threads(int group_id)
> /*
> * if the thread is running, just let it exit
> */
> - if (td->runstate < TD_RUNNING)
> + if (td->runstate < TD_RUNNING || force)
> kill(td->pid, SIGQUIT);
> else {
> struct ioengine_ops *ops = td->io_ops;
> @@ -107,8 +107,32 @@ static void status_timer_arm(void)
> setitimer(ITIMER_REAL, &itimer, NULL);
> }
>
> +static int overtime(void)
> +{
> + unsigned long elapsed;
> +
> + if (!def_thread.o.timeout)
> + return 0;
> +
> + /*
> + * Allow for 10 seconds of slack, this is supposed to be a last
> + * measure to make fio exit
> + */
> + elapsed = mtime_since_genesis() / 1000;
> + if (elapsed > def_thread.o.timeout + 10) {
> + log_err("fio: runtime seems way exceeded, yet fio is still "
> + "alive. Forcing quit.\n");
> + terminate_threads(TERMINATE_ALL, 1);
> + return 1;
> + }
> +
> + return 0;
> +}
> +
> static void sig_alrm(int fio_unused sig)
> {
> + if (overtime())
> + return;
> if (threads) {
> update_io_ticks();
> print_thread_status();
> @@ -121,7 +145,7 @@ static void sig_int(int sig)
> if (threads) {
> printf("\nfio: terminating on signal %d\n", sig);
> fflush(stdout);
> - terminate_threads(TERMINATE_ALL);
> + terminate_threads(TERMINATE_ALL, 1);
> }
> }
>
> @@ -132,7 +156,7 @@ static void sig_ill(int fio_unused sig)
>
> log_err("fio: illegal instruction. your cpu does not support "
> "the sse4.2 instruction for crc32c\n");
> - terminate_threads(TERMINATE_ALL);
> + terminate_threads(TERMINATE_ALL, 1);
> exit(4);
> }
>
> @@ -631,7 +655,7 @@ sync_done:
>
> if (check_min_rate(td, &comp_time)) {
> if (exitall_on_terminate)
> - terminate_threads(td->groupid);
> + terminate_threads(td->groupid, 0);
> td_verror(td, EIO, "check_min_rate");
> break;
> }
> @@ -1053,7 +1077,7 @@ static void *thread_main(void *data)
> }
>
> if (exitall_on_terminate)
> - terminate_threads(td->groupid);
> + terminate_threads(td->groupid, 0);
>
> err:
> if (td->error)
> @@ -1189,7 +1213,7 @@ reaped:
> }
>
> if (*nr_running == cputhreads && !pending && realthreads)
> - terminate_threads(TERMINATE_ALL);
> + terminate_threads(TERMINATE_ALL, 0);
> }
>
> /*
> diff --git a/fio.h b/fio.h
> index 63cd83f..3ec0591 100644
> --- a/fio.h
> +++ b/fio.h
> @@ -705,6 +705,7 @@ extern unsigned long done_secs;
> extern char *job_section;
>
> extern struct thread_data *threads;
> +extern struct thread_data def_thread;
>
> #define td_read(td) ((td)->o.td_ddir & TD_DDIR_READ)
> #define td_write(td) ((td)->o.td_ddir & TD_DDIR_WRITE)
>
> --
> Jens Axboe
>
>
^ permalink raw reply [flat|nested] 7+ messages in thread* Re: BUG: option runtime not working during a particular failure mode.
2008-10-08 16:24 ` Shawn Lewis
@ 2008-10-08 17:23 ` Jens Axboe
0 siblings, 0 replies; 7+ messages in thread
From: Jens Axboe @ 2008-10-08 17:23 UTC (permalink / raw)
To: Shawn Lewis; +Cc: fio
On Wed, Oct 08 2008, Shawn Lewis wrote:
> It is fio 1.17.2. I thought we synced up about a month ago but it
> looks like there are much newer versions available. Sorry about that.
Ah ok, then the later version will surely be an improvement in that
respect.
> Anyway this patch looks good as a final protection.
Yes I think so too, I'll go ahead and commit it.
--
Jens Axboe
^ permalink raw reply [flat|nested] 7+ messages in thread
end of thread, other threads:[~2008-10-08 17:23 UTC | newest]
Thread overview: 7+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2008-10-06 22:04 BUG: option runtime not working during a particular failure mode Shawn Lewis
2008-10-07 9:30 ` Jens Axboe
2008-10-07 16:28 ` Shawn Lewis
2008-10-08 11:01 ` Jens Axboe
2008-10-08 11:17 ` Jens Axboe
2008-10-08 16:24 ` Shawn Lewis
2008-10-08 17:23 ` Jens Axboe
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.