SCHED_FIFO: sleep times longer than expected (AGAIN)

Harald Kirsch (kir@iitb.fhg.de)
Fri, 23 Aug 1996 10:27:47 +0200

My problem is that a SCHED_FIFO process using a driver I'm writing is
not scheduled every jiffy although I could check that the timer
interrupt is run every 10ms and wakes up the process. I suppose
swapping cannot be the reason, because I call mlockall(MCL_FUTURE)
after allocating all necessary space with calloc.

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
>to switch off the ethernet device (for a test period). The xmit timeout
>really looks like such a problem: the driver tries to output data to the
>network card, but the card just doesnt want to acknowledge it, and the
>kernel waits until a previously started error-correcting timer stops the
>operation.

Now that I've changed the ethernet card from Scheider&Koch to 3c509 I
experience the same behaviour. Sleep times of sometimes 100ms and more
with a SCHED_FIFO process, while timer interrupts are obviously handled.

I must admit, I have no idea of how to find out where the kernel
"loops". Any idea appreciated!

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

I'm working on
i468 with 30BogoMips
16MB
Linux 2.0.7
The machine is diskless, i.e. it mounts everything via nfs.

Regards,
Harald.
-------------------------------------------------+------------------
Harald Kirsch, kir@iitb.fhg.de, +49 721 6091 384 | This message is
FhG/IITB, Fraunhoferstr.1, 76131 Karlsruhe | subject oriented.