lkml.org 
[lkml]   [2012]   [Apr]   [5]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
Patch in this message
/
Date
From
SubjectRe: [PATCH] clocksource, prevent overflow in clocksource_cyc2ns
On 04/05/2012 05:27 AM, Prarit Bhargava wrote:
>> So what kernel version are you using?
> I retested using top of the linux.git tree, running
>
> echo 1> /proc/sys/kernel/sysrq
> for i in `seq 10000`; do sleep 1000& done
> echo t> /proc/sysrq-trigger
>
> and I no longer see a problem. However, if I increase the number of threads to
> 1000/cpu I get
>
> Clocksource %s unstable (delta = -429565427)
> Clocksource switching to hpet

Yea, so this is with the 12minute + stall starving the system from irqs?
Again, its all a matter of degree.

>
>> to narrow down if you're problem is currently present in mainline or only in
>> older kernels, as that will help us find the proper fix.
> If I hack in (sorry for the cut-and-paste)
>
> diff --git a/kernel/time/clocksource.c b/kernel/time/clocksource.c
> index c958338..f38b8d0 100644
> --- a/kernel/time/clocksource.c
> +++ b/kernel/time/clocksource.c
> @@ -279,11 +279,16 @@ static void clocksource_watchdog(unsigned long data)
> continue;
> }
>
> - wd_nsec = clocksource_cyc2ns((wdnow - cs->wd_last)& watchdog->m
> - watchdog->mult, watchdog->shift);
> + /*wd_nsec = clocksource_cyc2ns((wdnow - cs->wd_last)& watchdog-
> + watchdog->mult, watchdog->shift);*/
> + wd_nsec = mult_frac(((wdnow - cs->wd_last), watchdog->mult,
> + 1UL<< watchdog->shift);
> +
> + /*cs_nsec = clocksource_cyc2ns((csnow - cs->cs_last)&
> + cs->mask, cs->mult, cs->shift);*/
> + cs_nsec = mult_frac(((csnow - cs->cs_last), cs->mult,
> + 1UL<< cs->shift);
>
> - cs_nsec = clocksource_cyc2ns((csnow - cs->cs_last)&
> - cs->mask, cs->mult, cs->shift);
> cs->cs_last = csnow;
> cs->wd_last = wdnow;
>
>
> then I don't see unstable messages.
>
> I think the problem is still here but it only happens in extreme cases.

I suspect if you were closely watching the clock you'd probably see
some odd time inconsistencies as well. Its all due to running outside
the expected bounds of the system. If you were to use the acpi_pm
clocksource and stall the system for 10+ minutes, when you returned the
system clock would be 10 minutes behind.

I think if 10 minutes printk dumps is going to be expected behavior
(which given the size of these machines, isn't unreasonable), we may
need to find a way to allow printk to take a break every so often and
allow irqs to happen. Disabling irqs for 10+ minutes can cause all sorts
of system trouble. I've seen scsi adapters hang if their heart beat
code didn't get an irq every 10 minutes or so.

I had proposed something like this awhile back, but the issue cropping
up there was lost time due to long printks holding off irqs while we're
using the jiffies clocks in early boot, so it was at a much smaller scale.

Could you give the following a try and let me know if it helps?

thanks
-john


Only flush 1k chunks max from console_unlock to allow IRQ starvation
from happening.

NOT FOR INCLUSION

Signed-off-by: John Stultz <john.stultz@linaro.org>

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

if (console_suspended) {
up(&console_sem);
@@ -1280,15 +1281,18 @@ void console_unlock(void)

console_may_schedule = 0;

+ chunk_size = min(LOG_BUF_MASK, 1024); /* 1k chunks */
again:
for ( ; ; ) {
raw_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 */
raw_spin_unlock(&logbuf_lock);
stop_critical_timings(); /* don't trace print latency */
call_console_drivers(_con_start, _log_end);


\
 
 \ /
  Last update: 2012-04-05 18:49    [W:0.221 / U:0.200 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site