lkml.org 
[lkml]   [2009]   [Jan]   [2]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    Patch in this message
    /
    From
    Date
    SubjectRe: Bug: Status/Summary of slashdot leap-second crash on new years 2008-2009
    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


    \
     
     \ /
      Last update: 2009-01-03 03:27    [W:0.052 / U:29.984 seconds]
    ©2003-2016 Jasper Spaans. hosted at Digital OceanAdvertise on this site