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] [day] [month] [year] [list]
Message-ID: <BANLkTik259Z-0qRaPMn3FsJ0QWyo07s5nQ@mail.gmail.com>
Date:	Tue, 7 Jun 2011 22:16:58 -0600
From:	Bjorn Helgaas <bhelgaas@...gle.com>
To:	john stultz <johnstul@...ibm.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, Jun 7, 2011 at 7:03 PM, john stultz <johnstul@...ibm.com> wrote:
> 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);

That's a much better attempt than the disastrous one I made.  But it
didn't help at all, and I think I know one reason: if we reenable
interrupts every 1K, and I have 230K to dump, that's 230 additional
ticks we might get.  But with HZ=1000, that's only a quarter second of
wallclock time.

Even at 115200 baud, I think we can only print about 10 characters/ms.
 It doesn't seem reasonable to me to try to flush in chunks anywhere
near that small.

But something else must still be going on, because even when I *did*
turn the chunk size down to 100 or 10 or even 4 characters, we still
didn't recover any of that missing wallclock time.  I tried to verify
that interrupts were actually enabled by the local_irq_restore(), and
they were, but maybe there's still a priority issue or something.

I wonder if we could do something with the TSC, e.g., capture it
early, then use it in getboottime() to compute the delta back from the
current time.  Machines without a stable TSC would use the present
system.

Bjorn
--
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/