Re: Bug: Status/Summary of slashdot leap-second crash on new years 2008-2009

Duane Griffin
2009-01-03T02:24:19Z

On Fri, Jan 02, 2009 at 06:21:14PM -0600, Chris Adams wrote:
> Once upon a time, Linas Vepstas <linasvepstas@gmail.com> said:
> > Below follows a summary of the reported crashes. I'm ignoring the
> > zillions of "mine didn't crash" reports, or the "you're a paranoid
> > conspiracy theorist, its random chance" reports.
>
> I have reproduced this and got a stack trace (this is with Fedora 8 and
> kernel kernel-2.6.26.6-49.fc8.x86_64):
>
> #0 ktime_get_ts (ts=0xffffffff8158bb30) at include/asm/processor.h:691
> #1 0xffffffff8104c09a in ktime_get () at kernel/hrtimer.c:59
> #2 0xffffffff8102a39a in hrtick_start_fair (rq=0xffff810009013880,
> p=<value optimized out>) at kernel/sched.c:1064
> #3 0xffffffff8102decc in enqueue_task_fair (rq=0xffff810009013880,
> p=0xffff81003fb02d40, wakeup=1) at kernel/sched_fair.c:863
> #4 0xffffffff81029a08 in enqueue_task (rq=0xffffffff8158bb30,
> p=0xffff81003b8ac418, wakeup=-994836480) at kernel/sched.c:1550
> #5 0xffffffff81029a39 in activate_task (rq=0xffff810009013880,
> p=0xffff81003b8ac418, wakeup=20045) at kernel/sched.c:1614
> #6 0xffffffff8102be38 in try_to_wake_up (p=0xffff81003fb02d40,
> state=<value optimized out>, sync=0) at kernel/sched.c:2173
> #7 0xffffffff8102be9c in default_wake_function (curr=<value optimized out>,
> mode=998949912, sync=20045, key=0x4c4b40000) at kernel/sched.c:4366
> #8 0xffffffff810492ed in autoremove_wake_function (wait=0xffffffff8158bb30,
> mode=998949912, sync=20045, key=0x4c4b40000) at kernel/wait.c:132
> #9 0xffffffff810296a2 in __wake_up_common (q=0xffffffff813d3180, mode=1,
> nr_exclusive=1, sync=0, key=0x0) at kernel/sched.c:4387
> #10 0xffffffff8102b97b in __wake_up (q=0xffffffff813d3180, mode=1,
> nr_exclusive=1, key=0x0) at kernel/sched.c:4406
> #11 0xffffffff8103692f in wake_up_klogd () at kernel/printk.c:1005
> #12 0xffffffff81036abb in release_console_sem () at kernel/printk.c:1051
> #13 0xffffffff81036fd1 in vprintk (fmt=<value optimized out>,
> args=<value optimized out>) at kernel/printk.c:789
> #14 0xffffffff81037081 in printk (
> fmt=0xffffffff8158bb30 "yj$\201????\2008\001\t") at kernel/printk.c:613
> #15 0xffffffff8104ec16 in ntp_leap_second (timer=<value optimized out>)
> at kernel/time/ntp.c:143
> #16 0xffffffff8104b7a6 in run_hrtimer_pending (cpu_base=0xffff81000900f740)
> at kernel/hrtimer.c:1204
> #17 0xffffffff8104b86a in run_hrtimer_softirq (h=<value optimized out>)
> at kernel/hrtimer.c:1355
> #18 0xffffffff8103b31f in __do_softirq () at kernel/softirq.c:234
> #19 0xffffffff8100d52c in call_softirq () at include/asm/current_64.h:10
> #20 0xffffffff8100ed5e in do_softirq () at arch/x86/kernel/irq_64.c:262
> #21 0xffffffff8103b280 in irq_exit () at kernel/softirq.c:310
> #22 0xffffffff8101b0fe in smp_apic_timer_interrupt (regs=<value optimized out>)
> at arch/x86/kernel/apic_64.c:514
> #23 0xffffffff8100cf52 in apic_timer_interrupt ()
> at include/asm/current_64.h:10
> #24 0xffff81003b9d5a90 in ?? ()
> #25 0x0000000000000000 in ?? ()
>
>
> Basically (to my untrained eye), the leap second code is called from the
> timer interrupt handler, which holds xtime_lock. The leap second code
> does a printk to notify about the leap second. The printk code tries to
> wake up klogd (I assume to prioritize kernel messages), and (under some
> conditions), the scheduler attempts to get the current time, which tries
> to get xtime_lock => deadlock.
>
> I can only reproduce this if the system is busy. If the system is
> otherwise idle at the timer interrupt, I guess the scheduler doesn't try
> to get the time. I can run a "find / | xargs cat > /dev/nul" in one
> window and then trigger the leap second in another, and the system dies
> most of the time.
>
> I'm looking at the source for the RHEL 4 kernel 2.6.9-67.0.7.EL (which I
> had crash on a system), and the scheduler is enough different that I am
> not finding the path to the deadlock right off.
>
> In any case, the quick-n-dirty fix would be to not try to printk while
> holding xtime_lock (I think the NTP code is the only thing that does).
> However, it would be nice to still get the leap second notification, so
> some other fix would be better I guess.

How about just moving the printk out of the lock? I.e. something like
this:

diff --git a/kernel/time/ntp.c b/kernel/time/ntp.c
index f5f793d..ad3e2b7 100644
--- a/kernel/time/ntp.c
+++ b/kernel/time/ntp.c
@@ -140,8 +140,6 @@ static enum hrtimer_restart ntp_leap_second(struct hrtimer *timer)
xtime.tv_sec--;
wall_to_monotonic.tv_sec++;
time_state = TIME_OOP;
- printk(KERN_NOTICE "Clock: "
- "inserting leap second 23:59:60 UTC\n");
hrtimer_add_expires_ns(&leap_timer, NSEC_PER_SEC);
res = HRTIMER_RESTART;
break;
@@ -166,6 +164,10 @@ static enum hrtimer_restart ntp_leap_second(struct hrtimer *timer)

write_sequnlock(&xtime_lock);

+ if (res == HRTIMER_RESTART)
+ printk(KERN_NOTICE "Clock: "
+ "inserting leap second 23:59:60 UTC\n");
+
return res;
}

> --
> Chris Adams <cmadams@hiwaay.net>
> Systems and Network Administrator - HiWAAY Internet Services
> I don't speak for anybody but myself - that's enough trouble.

Cheers,
Duane.

--
"I never could learn to drink that blood and call it wine" - Bob Dylan