On Fri 02-05-14 14:22:20, Andrew Morton wrote: > From: Will Deacon <will.dea...@arm.com> > Subject: printk: print initial logbuf contents before re-enabling interrupts > > When running on a hideously slow system (~10Mhz FPGA) with a bunch of > debug printk invocations on the timer interrupt path, we end up filling > the log buffer faster than we can drain it. > > The reason is that console_unlock (which is responsible for moving > messages out of logbuf to hand over to the console driver) removes one > message at a time, briefly re-enabling interrupts between each of them. > If the interrupt path prints more than a single message, then we can > easily generate more messages than we can print for a regular, recurring > interrupt (e.g. a 1khz timer). This results in messages getting silently > dropped, leading to counter-intuitive, incomplete printk traces on the > console. > > Rather than run the console_unlock loop with interrupts disabled (which > has obvious latency problems), this patch records the sequence number of > the last message in the log buffer after taking the logbuf_lock. We can > then print this fixed amount of work before re-enabling interrupts again, > making sure we keep up with ourself. Other CPUs could still potentially > flood the buffer, but there's little that we can do to protect against > that. I really dislike this patch. It goes completely against my efforts of lowering irq latency caused by printing to console (which are the problems I have observed ;). My opinion is that when you are printing from each and every interrupt which happens so often, then you have a problem and disabling IRQs in printk so that your interrupt doesn't happen that often seems like a poor solution to me. You could as well just ratelimit your debug messages, couldn't you?
Honza > Signed-off-by: Will Deacon <will.dea...@arm.com> > Acked-by: Peter Zijlstra <pet...@infradead.org> > Cc: Kay Sievers <k...@vrfy.org> > Cc: Jan Kara <j...@suse.cz> > Signed-off-by: Andrew Morton <a...@linux-foundation.org> > --- > > kernel/printk/printk.c | 9 +++++++++ > 1 file changed, 9 insertions(+) > > diff -puN > kernel/printk/printk.c~printk-print-initial-logbuf-contents-before-re-enabling-interrupts > kernel/printk/printk.c > --- > a/kernel/printk/printk.c~printk-print-initial-logbuf-contents-before-re-enabling-interrupts > +++ a/kernel/printk/printk.c > @@ -2147,10 +2147,13 @@ void console_unlock(void) > again: > for (;;) { > struct printk_log *msg; > + u64 console_end_seq; > size_t len; > int level; > > raw_spin_lock_irqsave(&logbuf_lock, flags); > + console_end_seq = log_next_seq; > +again_noirq: > if (seen_seq != log_next_seq) { > wake_klogd = true; > seen_seq = log_next_seq; > @@ -2195,6 +2198,12 @@ skip: > stop_critical_timings(); /* don't trace print latency */ > call_console_drivers(level, text, len); > start_critical_timings(); > + > + if (console_seq < console_end_seq) { > + raw_spin_lock(&logbuf_lock); > + goto again_noirq; > + } > + > local_irq_restore(flags); > } > console_locked = 0; > _ > > Patches currently in -mm which might be from will.dea...@arm.com are > > origin.patch > printk-print-initial-logbuf-contents-before-re-enabling-interrupts.patch > printk-report-dropping-of-messages-from-logbuf.patch > documentation-devicetree-bindings-add-documentation-for-the-apm-x-gene-soc-rtc-dts-binding.patch > drivers-rtc-add-apm-x-gene-soc-rtc-driver.patch > arm64-add-apm-x-gene-soc-rtc-dts-entry.patch > linux-next.patch > -- Jan Kara <j...@suse.cz> SUSE Labs, CR -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/