linux-kernel - Re: IRQ off latency of printk is very high

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <20071025222804.GA13954@Krystal>
Date:	Thu, 25 Oct 2007 18:28:04 -0400
From:	Mathieu Desnoyers <mathieu.desnoyers@...ymtl.ca>
To:	Tim Bird <tim.bird@...sony.com>
Cc:	linux kernel <linux-kernel@...r.kernel.org>,
	Ingo Molnar <mingo@...hat.com>
Subject: Re: IRQ off latency of printk is very high

* Tim Bird (tim.bird@...sony.com) 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 majordomo@...r.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/