IRQ off latency of printk is very high

[Tim Bird <tim.bird@am.sony.com>]

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.

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
=============================