Re: SCHED_FIFO: sleep times longer than expected (AGAIN)

Ingo Molnar (mingo@pc5829.hil.siemens.at)
Fri, 23 Aug 1996 11:29:03 +0200 (MET DST)


On Fri, 23 Aug 1996, Harald Kirsch wrote:

> Ingo Molnar <mingo@pc5829.hil.siemens.at> wrote in a personal message to
> me:
> >You most probably have found
> >a bug. Try somehow to identify the point where the kernel "loops". Or try

[this quote was a bit out of context ...]

> A typical timing log I get looks like this:
> timer -- timer service routine of my driver
> read -- immediatly after reading data
> wait/start,
> wait/end -- immediatly before and after
> interruptible_sleep_on
> The times are those from do_gettimeofday. The output is produced with
> printk post-mortem, i.e. there is no printk e.g. in the timer service
> routine.
>
> rti834 overflow, status=0x14a8, last sleep=0.075978
> stamp[63] = 0.001496 at 840787263.009563 by timer
> stamp[62] = 0.000074 at 840787263.008067 by read
> stamp[61] = 0.008468 at 840787263.007993 by wait/end
> stamp[60] = 0.010016 at 840787262.999525 by timer
> stamp[59] = 0.009966 at 840787262.989509 by timer
> stamp[58] = 0.010019 at 840787262.979543 by timer
> stamp[57] = 0.010085 at 840787262.969524 by timer
> stamp[56] = 0.010007 at 840787262.959439 by timer
> stamp[55] = 0.009890 at 840787262.949432 by timer
> stamp[54] = 0.007545 at 840787262.939542 by timer
> stamp[53] = 0.000995 at 840787262.931997 by wait/start
> stamp[52] = 0.000074 at 840787262.931002 by read
> stamp[51] = 0.000474 at 840787262.930928 by wait/end
> stamp[50] = 0.008822 at 840787262.930454 by timer
> stamp[49] = 0.000863 at 840787262.921632 by wait/start

if i read your log right, then your program is blocking on a read()
operation. Thats pretty much normal ... there is no "looping", your
program is waiting for the read request to finish.

run a program that does something like this:

for(;;);

and if >this< program gets interrupted for 100 msecs, then we have a
problem :)

-- mingo