Re: /proc/stat btime accuracy problem

From: john stultz
Date: Tue Jun 07 2011 - 21:04:20 EST


On Tue, 2011-06-07 at 10:50 -0700, john stultz wrote:
> Maybe to get this back on coarse, could you provide some additional
> details about the machine where you're seeing this? Is there one
> specific driver that is putting out tons of output over the serial
> console? Or is there anything unique about the serial port or its
> settings (is it configured at 300 baud :)? What is the /proc/interrupts
> count after boot on one of these systems?

Sorry, I just remembered you already provided some of these details
below:

On Thu, 2011-06-02 at 00:34 -0600, Bjorn Helgaas wrote:
> Linux version 3.0.0-smp-DEV ...
> BH now rtc 1306992452 (start_kernel, before setup_arch)
> Printk 230K of numa=fake debug stuff (more than seems strictly
> necessary to me, but there it is). All this data goes into the log
> buffer, not to the UART, because the console hasn't been
> initialized yet.
[snip]
> console [ttyS0] enabled
> Now ttyS0 is enabled, so we dump the log buffer to the UART. I think
> this happens in console_unlock(), with interrupts disabled for the whole
> buffer.
>
> BH now rtc 1306992481 xt 1306992459 wtm -1306992457
> clocksource_register jiffies
> This RTC read is in clocksource_register(); note that xtime is now
> 22 seconds behind the RTC. The UART is running at 115200 baud,
> and 230K/(115200/10) = about 20 seconds, so this sort of matches
> the time I expect it to take to dump the buffer.


Ok. So having the 230k data backlog at console_unlock() seems to be part of the issue.

Maybe something like the following could help? By only holding irqs off for 1k chunks?

thanks
-john


diff --git a/kernel/printk.c b/kernel/printk.c
index 3518539..9703b22 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -1243,6 +1243,7 @@ void console_unlock(void)
unsigned long flags;
unsigned _con_start, _log_end;
unsigned wake_klogd = 0;
+ unsigned chunk_size, length;

if (console_suspended) {
up(&console_sem);
@@ -1251,14 +1252,18 @@ void console_unlock(void)

console_may_schedule = 0;

+ chunk_size = min(LOG_BUF_MASK, 1024); /* 1k chunks */
+
for ( ; ; ) {
spin_lock_irqsave(&logbuf_lock, flags);
wake_klogd |= log_start - log_end;
if (con_start == log_end)
break; /* Nothing to print */
+ length = (log_end - con_start) & LOG_BUF_MASK;
+ length = min(length , chunk_size);
_con_start = con_start;
- _log_end = log_end;
- con_start = log_end; /* Flush */
+ _log_end = (con_start + length) & LOG_BUF_MASK;
+ con_start = _log_end; /* Flush */
spin_unlock(&logbuf_lock);
stop_critical_timings(); /* don't trace print latency */
call_console_drivers(_con_start, _log_end);




--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/