linux-kernel - Re: /proc/stat btime accuracy problem

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: <1307495037.3163.76.camel@work-vm>
Date:	Tue, 07 Jun 2011 18:03:57 -0700
From:	john stultz <johnstul@...ibm.com>
To:	Bjorn Helgaas <bhelgaas@...gle.com>
Cc:	Thomas Gleixner <tglx@...utronix.de>,
	"linux-kernel@...r.kernel.org" <linux-kernel@...r.kernel.org>,
	linux-serial@...r.kernel.org, Alan Cox <alan@...ux.intel.com>
Subject: Re: /proc/stat btime accuracy problem

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@...r.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/