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
=============================
On Thu, Oct 25, 2007 at 12:44:31PM -0700, Tim Bird 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.
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.
Kindof a bummer for realtime, but also rather hard to get around.
> 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.
2000bits @ 115200bps -> 17.4ms
> Are these are really needed, with all this other locking
> going on? Any ideas for fixing this?
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.
Matt Mackall wrote:
> On Thu, Oct 25, 2007 at 12:44:31PM -0700, Tim Bird 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.
>
> 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.
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
ints off.
> Kindof a bummer for realtime, but also rather hard to get around.
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 Engineer, Sony Corporation of America
=============================
* 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
Mathieu Desnoyers wrote:
> 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
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
=============================
On Thu, Oct 25, 2007 at 03:52:28PM -0700, Tim Bird wrote:
> Mathieu Desnoyers wrote:
> > 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
>
> 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.
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.
Matt Mackall wrote:
> On Thu, Oct 25, 2007 at 03:52:28PM -0700, Tim Bird wrote:
>> Mathieu Desnoyers wrote:
>>> 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
>> 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.
>
> 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);
>
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
=============================
On Thu, Oct 25, 2007 at 04:41:55PM -0700, Tim Bird wrote:
> Matt Mackall wrote:
> > On Thu, Oct 25, 2007 at 03:52:28PM -0700, Tim Bird wrote:
> >> Mathieu Desnoyers wrote:
> >>> 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
> >> 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.
> >
> > 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);
> >
>
> 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()?
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.
>>>>> "MM" == Matt Mackall <[email protected]> writes:
MM> Well there are things we can do, yes, but I'd be worried that
MM> they've give up the deterministic behavior we rely on quite
MM> heavily for debugging. If event A happens before event B, we must
MM> see the message from A before the one from B, even if B happens in
MM> irq context.
MM> And if event B is a hard lock up, we'd also like to be sure the
MM> message for A actually gets out. If B happens in the interrupt
MM> that comes in when we re-enable them, that won't happen.
I can see the concerns, but right now it all leads to disabling serial
console for real-time servers. That is even less helpful for
debugging.
/Benny
On Fri, Oct 26, 2007 at 02:57:18PM +0200, Benny Amorsen wrote:
> >>>>> "MM" == Matt Mackall <[email protected]> writes:
>
> MM> Well there are things we can do, yes, but I'd be worried that
> MM> they've give up the deterministic behavior we rely on quite
> MM> heavily for debugging. If event A happens before event B, we must
> MM> see the message from A before the one from B, even if B happens in
> MM> irq context.
>
> MM> And if event B is a hard lock up, we'd also like to be sure the
> MM> message for A actually gets out. If B happens in the interrupt
> MM> that comes in when we re-enable them, that won't happen.
>
> I can see the concerns, but right now it all leads to disabling serial
> console for real-time servers. That is even less helpful for
> debugging.
That's not clear. No data is often better than false or misleading
data.
--
Mathematics is the supreme nostalgia of our time.
Hi!
> > 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);
> >
>
> 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()?
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
* Pavel Machek ([email protected]) wrote:
> Hi!
>
> > > 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);
> > >
> >
> > 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()?
>
> 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
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
> --
> (english) http://www.livejournal.com/~pavelmachek
> (cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html
--
Mathieu Desnoyers
Computer Engineering Ph.D. Student, Ecole Polytechnique de Montreal
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F BA06 3F25 A8FE 3BAE 9A68
Hi!
> > > 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()?
> >
> > 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?
>
> 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)
Two messages in atomic sections on different cpus could still be mixed
:-). But yes, something like this may be the way to go.
Pavel
--
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html
* Pavel Machek ([email protected]) wrote:
> Hi!
>
> > > > 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()?
> > >
> > > 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?
> >
> > 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)
>
> Two messages in atomic sections on different cpus could still be mixed
> :-). But yes, something like this may be the way to go.
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
> Pavel
> --
> (english) http://www.livejournal.com/~pavelmachek
> (cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html
--
Mathieu Desnoyers
Computer Engineering Ph.D. Student, Ecole Polytechnique de Montreal
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F BA06 3F25 A8FE 3BAE 9A68