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

  ...
[ message continues ]

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 Desnoyers

Computer Engineering Ph.D. Student, Ecole Polytechnique de Montreal

OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

-

This is very helpful.  Jon Smirl's answer seems to give the

rationale for supporting printk output in interrupt context.

I'm not sure, however, if extending the interrupt off period

to cover the console output is required.  It didn't until

Ingo changed it in 2.6.17. Maybe this was intentional to

allow printk output to drain before another (printk in

interrupt context) could even possibly be generated, but it

seems like overkill.
I'll continue looking at this.  It helps a lot to know about

the issues discussed in the prior thread.
Thanks,

 -- Tim
=============================

Tim Bird

Architecture Group Chair, CE Linux Forum

Senior Staff Engineer, Sony Corporation of America

=============================
-

Hmm, I see this at the beginning of the post-BK era (2.6.12-rc2):
	        spin_lock_irqsave(&logbuf_lock, flags);

		...

		spin_unlock(&logbuf_lock);

		call_console_drivers(_con_start, _log_end);

		local_irq_restore(flags);
--

Mathematics is the supreme nostalgia of our time.

-

Well, I need to do some more research.  This must be in

release_console_sem().  I was looking at vprintk, through

the ages.  At 2.6.16, it looked like this:
        spin_lock_irqsave(&logbuf_lock, flags);

        ...

              spin_unlock_irqrestore(&logbuf_lock, flags);

              console_may_schedule = 0;

              release_console_sem();
but the irq restore has been moving around to different places

in that function over the last few years.  I suspect that in the

common case the irqsave in vprintk is the one that disables

ints.
It appears that formerly interrupts were enabled in vprintk but

re-disabled immediately upon entering release_console_sem().

As it is now, they're held during formatting, buffering,

and output, which seems excessive.
It seems draconian to drain the entire buffer with ints disabled.

Is it possible to break this up and send out smaller chunks

at a time?  Maybe by putting a chunk loop in release_console_sem()?
Just an idea.  I can see that there are a lot of requirements

for this code, and the concurrency control has gotten

complex over the years.

 -- Tim
=============================

Tim Bird

Architecture Group Chair, CE Linux Forum

Senior Staff Engineer, Sony Corporation of America

=============================
-

Well, I believe someone got
DDetetccctted ed 113223 HHzz CPUCPU
in his dmesg, and now we have this 'draconian' locking. How can we

prevent mangled messages without it?

							Pavel

--

(english) http://www.livejournal.com/~pavelmachek

(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

-

The main interest seems to be to protect from mixed printk output

between different CPUs in process context. I don't think it would be

that bad if interrupts come and output error messages in the middle of a

printk, isn't it ?
therefore, could we do something like :
if (!in_irq())

  spin_lock(&logbuf_lock);

...

if (!in_irq())

  spin_unlock(&logbuf_lock);
? (yes, this is a crazy idea)
--

Mathieu Desnoyers

Computer Engineering Ph.D. Student, Ecole Polytechnique de Montreal

OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

-

Pavel

--

(english) http://www.livejournal.com/~pavelmachek

(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

-

Not in "preempt disable" sections though. Only in interrupt handlers.

But yes, I assume here that messages coming from interrupt handlers can

afford being interleaved.
--

Mathieu Desnoyers

Computer Engineering Ph.D. Student, Ecole Polytechnique de Montreal

OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

-

Well there are things we can do, yes, but I'd be worried that they've

give up the deterministic behavior we rely on quite heavily for

debugging. If event A happens before event B, we must see the message

from A before the one from B, even if B happens in irq context. 
And if event B is a hard lock up, we'd also like to be sure the

message for A actually gets out. If B happens in the interrupt that

comes in when we re-enable them, that won't happen.
(This is also a problem on unaccelerated video consoles, where

scrolling may actually be slower than 115kbps!)
--

Mathematics is the supreme nostalgia of our time.

-

Printk to the serial console uses polled I/O to get deterministic,

reliable, and -timely- output. If our very next statement (or interrupt)

may lock up the box, we want to be sure our printk has actually been

delivered before that happens.
Well, we could have a commandline option that made messages with a

priority below X go out buffered. But it'd be a lousy default from a

debugging perspective.
--

Mathematics is the supreme nostalgia of our time.

-

Whether the actual output uses polled I/O doesn't seem to matter.

release_console_sem() (which is where the chars drain out)

used to be called with interrupts enabled (up to at about v. 2.6.17).
While the cpu is in the printk code itself any submitted printks will go

to the log buffer.  It's the draining that's running with
Ingo moved the irq_restore to below the release_console_sem()

call, with this commit: a0f1ccfd8d...  Up until then it had

been before the call to release_console_sem.
Here's the code before Ingo's change:

		printk_cpu = UINT_MAX;

		spin_unlock_irqrestore(&logbuf_lock, flags);
		/*

		 * Console drivers may assume that per-cpu resources have

		 * been allocated. So unless they're explicitly marked as

		 * being able to cope (CON_ANYTIME) don't call them until

		 * this CPU is officially up.

		 */

		if (cpu_online(smp_processor_id()) || have_callable_console()) {

			console_may_schedule = 0;

			release_console_sem();

		} else {

			/* Release by hand to avoid flushing the buffer. */

			console_locked = 0;

			up(&console_sem);

		}
And here's the code after:

		printk_cpu = UINT_MAX;

		spin_unlock(&logbuf_lock);
		/*

		 * Console drivers may assume that per-cpu resources have

		 * been allocated. So unless they're explicitly marked as

		 * being able to cope (CON_ANYTIME) don't call them until

		 * this CPU is officially up.

		 */

		if (cpu_online(smp_processor_id()) || have_callable_console()) {

			console_may_schedule = 0;

			release_console_sem();

		} else {

			/* Release by hand to avoid flushing the buffer. */

			console_locked = 0;

			up(&console_sem);

		}

		lockdep_on();

		local_irq_restore(flags);
In even earlier versions of the kernel, the irqrestore was just before

the call to release_console_sem().
I'm just trying to see if the irq_restore can be moved back

where it was, or if there's more going on.

 -- Tim
=============================

Tim Bird

Architecture Group Chair, CE Linux Forum

Senior Staff ...
[ message continues ]