* Tim Bird ([email protected]) wrote:
> I've been looking at 'IRQ off' latency in the Linux kernel, on
> version 2.6.22 for target using an ARM processor.
> I use a serial console, at 115200 bps.
>
> I've noticed that calls to printk disable interrupts for
> excessively long times. I have a long test printk of
> over 200 chars, that holds interrupts off for 24 milliseconds.
>
Hi Tim,
It might help to read this thread I posted on LKML in January 2006
explaining the problem, which led to some discussion about the issue.
http://lkml.org/lkml/2006/6/3/48
Using the LTTng tracer, I got the exact instruction responsible for
disabling interrupts for so long. It is explained in my presentation
referred to by the same email.
Mathieu
> The kernel drops ticks in this case. I changed to HZ=1000
> to more easily see the dropped ticks, and I'm losing about
> 23 ticks (no surprise there).
>
> I see long interrupt off periods for vprintk and release_console_sem,
> both in kernel/printk.c
>
> Results with HRT disabled, HZ=1000:
>
> Below is output from a test printk I inserted into sys_sync().
> I have PRINTK_TIMES turned on.
>
> /proc # sync
> [ 2292.851106] I'm now in the sys_sync system call, performing an extremely long
> printk with lots of words that go on and on and on and if it gets any longer I
> just might scream but that's beside the point, as a test of interrupt disable ti
> me for the printk system itself.
> [ 2292.895751] interval=44816825, jiffies=22
> [ 2292.904529] This is a shorter string - will we drop jiffies here??
> [ 2292.933729] interval=29173886, jiffies=23
> /proc # sync
> [ 2296.353092] I'm now in the sys_sync system call, performing an extremely long
> printk with lots of words that go on and on and on and if it gets any longer I
> just might scream but that's beside the point, as a test of interrupt disable ti
> me for the printk system itself.
> [ 2296.377637] interval=24573237, jiffies=1
> [ 2296.381856] This is a shorter string - will we drop jiffies here??
> [ 2296.388356] interval=6488141, jiffies=1
>
> --------------------------
>
> Data from irq_latency measurement tool
> Notes:
> * 24 ms vprintk = long printk
> * 6 ms printk = shorter printk
> * 4 ms printk = timing report printks
> * I don't know what the heck that preempt_schedule_irq is doing in there.
> I only saw that once, on this test.
>
> /proc # cat irq_latency
> irq latency worst 20 @ CPU 0
> filter: 0
> 0.024348 vprintk
> 0.024348 vprintk
> 0.024343 vprintk
> 0.006439 vprintk
> 0.006439 vprintk
> 0.006338 vprintk
> 0.004260 preempt_schedule_irq
> 0.004248 vprintk
> 0.004248 vprintk
> 0.004247 vprintk
> 0.004072 vprintk
> 0.003966 vprintk
> 0.000345 latency_start
> 0.000158 mpu_timer1 26
> 0.000157 mpu_timer1 26
> 0.000157 mpu_timer1 26
> 0.000156 mpu_timer1 26
> 0.000151 mpu_timer1 26
> 0.000150 mpu_timer1 26
> 0.000150 mpu_timer1 26
>
> It looks like vprintk() holds off interrupts for the entire
> duration of outputting the data to the serial console.
> release_console_sem() appears to as well.
>
> The local_irq_save and restore appear to have been added
> in February, 2007 by Mathieu.
>
> Are these are really needed, with all this other locking
> going on? Any ideas for fixing this?
> -- Tim
>
> =============================
> Tim Bird
> Architecture Group Chair, CE Linux Forum
> Senior Staff Engineer, Sony Corporation of America
> =============================
>
--
Mathieu Desnoyers
Computer Engineering Ph.D. Student, Ecole Polytechnique de Montreal
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F BA06 3F25 A8FE 3BAE 9A68
-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
[Index of Archives]
[Kernel Newbies]
[Netfilter]
[Bugtraq]
[Photo]
[Stuff]
[Gimp]
[Yosemite News]
[MIPS Linux]
[ARM Linux]
[Linux Security]
[Linux RAID]
[Video 4 Linux]
[Linux for the blind]
[Linux Resources]
