lkml.org 
[lkml]   [2010]   [Oct]   [8]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
SubjectRe: [PATCH] Fix a complex race in hrtimer code.
From
On Thu, Oct 7, 2010 at 7:33 PM, Salman Qazi <sqazi@google.com> wrote:
> The race is described as follows:
>
> CPU X                                 CPU Y
> remove_hrtimer
> // state & QUEUED == 0
> timer->state = CALLBACK
> unlock timer base
> timer->f(n) //very long
>                                  hrtimer_start
>                                    lock timer base
>                                    remove_hrtimer // no effect
>                                    hrtimer_enqueue
>                                    timer->state = CALLBACK |
>                                                   QUEUED
>                                    unlock timer base
>                                  hrtimer_start
>                                    lock timer base
>                                    remove_hrtimer
>                                        mode = INACTIVE
>                                        // CALLBACK bit lost!
>                                    switch_hrtimer_base
>                                            CALLBACK bit not set:
>                                                    timer->base
>                                                    changes to a
>                                                    different CPU.
> lock this CPU's timer base
>
> Bug reproducible and fix testable using a kernel module that hrtimer_start()s
> a timer with a very long running callback from multiple CPUs:
>
> MODULE_LICENSE("GPL");
>
> static long timer_func_time = 1000;
> module_param(timer_func_time, long, 0600);
> static long timer_starts = 2500;
> module_param(timer_starts, long, 0600);
> static long timer_expire = 1000;
> module_param(timer_expire, long, 0600);
>
> DEFINE_PER_CPU(struct task_struct *, hrtimer_thread);
>
> /* There are other issues, like deadlocks between multiple hrtimer_start observed
>  * calls, at least in 2.6.34 that this lock works around.  Will look into
>  * those later.
>  */
> static DEFINE_SPINLOCK(blah_lock);
>
> static ktime_t mytime;
> static struct hrtimer timer;
>
> static enum hrtimer_restart timer_restart(struct hrtimer *timer)
> {
>        unsigned long i;
>        /* We have to make the callback longer to improve the
>         * probability of having a race.
>         */
>        for (i = 0; i < timer_func_time / 100; i++) {
>                touch_nmi_watchdog();
>                touch_softlockup_watchdog();
>                udelay(100);
>        }
>
>        return HRTIMER_NORESTART;
> }
>
> static int restart_hrtimer_repeatedly(void *input)
> {
>        int i;
>        unsigned long range;
>        while (!kthread_should_stop()) {
>                for (i = 0; i < timer_starts; i++) {
>                        /* Avoid deadlocks for now */
>                        spin_lock(&blah_lock);
>                        hrtimer_start(&timer, mytime, HRTIMER_MODE_REL);
>                        spin_unlock(&blah_lock);
>                        touch_nmi_watchdog();
>                        touch_softlockup_watchdog();
>                }
>                cond_resched();
>        }
>        hrtimer_cancel(&timer);
>        return 0;
> }
>
> static int hrtimer_unit_test_init(void)
> {
>        int cpu;
>        mytime = ktime_set(0, 0);
>        mytime = ktime_add_ns(mytime, timer_expire);
>        hrtimer_init(&timer, CLOCK_MONOTONIC, HRTIMER_MODE_REL);
>        timer.function = timer_restart;
>        for_each_online_cpu(cpu) {
>                per_cpu(hrtimer_thread, cpu) = kthread_create(
>                        restart_hrtimer_repeatedly, NULL, "hrtimer_test/%d",
>                        cpu);
>                if (IS_ERR(per_cpu(hrtimer_thread, cpu))) {
>                       printk(KERN_ERR
>                                "Failed to create hrtimer test thread\n");
>                        BUG();
>                }
>                kthread_bind(per_cpu(hrtimer_thread, cpu), cpu);
>                wake_up_process(per_cpu(hrtimer_thread, cpu));
>        }
>        return 0;
> }
>
> static void hrtimer_unit_test_exit(void)
> {
>        int cpu;
>        for_each_online_cpu(cpu) {
>                (void)kthread_stop(per_cpu(hrtimer_thread, cpu));
>        }
> }
>
> module_init(hrtimer_unit_test_init);
> module_exit(hrtimer_unit_test_exit);
> ---
>  kernel/hrtimer.c |    7 +++++--
>  1 files changed, 5 insertions(+), 2 deletions(-)
>
> diff --git a/kernel/hrtimer.c b/kernel/hrtimer.c
> index 1decafb..4769c51 100644
> --- a/kernel/hrtimer.c
> +++ b/kernel/hrtimer.c
> @@ -944,8 +944,8 @@ remove_hrtimer(struct hrtimer *timer, struct hrtimer_clock_base *base)
>                debug_deactivate(timer);
>                timer_stats_hrtimer_clear_start_info(timer);
>                reprogram = base->cpu_base == &__get_cpu_var(hrtimer_bases);
> -               __remove_hrtimer(timer, base, HRTIMER_STATE_INACTIVE,
> -                                reprogram);
> +               __remove_hrtimer(timer, base,
> +                                (timer->state & HRTIMER_STATE_CALLBACK), reprogram);
>                return 1;
>        }
>        return 0;
> @@ -1231,6 +1231,9 @@ static void __run_hrtimer(struct hrtimer *timer, ktime_t *now)
>                BUG_ON(timer->state != HRTIMER_STATE_CALLBACK);
>                enqueue_hrtimer(timer, base);
>        }
> +
> +       BUG_ON(!(timer->state & HRTIMER_STATE_CALLBACK));
> +
>        timer->state &= ~HRTIMER_STATE_CALLBACK;
>  }
>
>
>

Oh, I forgot to include the crash dumps that we can produce in less
than a minute without this patch by
enabling NMI watchdog. Basically, we get rb_tree corruption that
results an in infinite loop in rb_insert_color.
I am not sure about the exact sequence of events from the original
loss of CALLBACK bit to this corruption in 2.6.36 (as I first debugged
it in 2.6.26 *twenty six*), however having the patch makes it go away,
just like
it does for similar corruption in 2.6.26:

cim7:~# [ 143.712006] BUG: NMI Watchdog detected LOCKUP on CPU1, ip
ffffffff8120b09a, registers:
[ 143.712006] CPU 1
[ 143.712006] Modules linked in: hrtimer_unit_test ipv6 sata_sil tg3
msr cpuid eeprom genrtc
[ 143.712006]
[ 143.712006] Pid: 4925, comm: hrtimer_test/1 Not tainted
2.6.36-smp-DEV #4 Unicorn_QCS_00 /E7320,6300ESB
[ 143.712006] RIP: 0010:[<ffffffff8120b09a>] [<ffffffff8120b09a>]
rb_insert_color+0x6a/0xe5
[ 143.712006] RSP: 0018:ffff880013e83dd8 EFLAGS: 00000082
[ 143.712006] RAX: 0000000000000000 RBX: ffffffffa000d680 RCX: ffffffffa000d680
[ 143.712006] RDX: ffffffffa000d680 RSI: ffff88001440f298 RDI: ffffffffa000d680
[ 143.712006] RBP: ffff880013e83e00 R08: 0000000000000000 R09: ffffffff818e7178
[ 143.712006] R10: ffff8800081a2000 R11: ffff88000bc65d70 R12: ffffffffa000d680
[ 143.712006] R13: ffffffffa000d680 R14: ffff88001440f298 R15: ffffffffa000d680
[ 143.712006] FS: 0000000000000000(0000) GS:ffff88000c400000(0000)
knlGS:0000000000000000
[ 143.712006] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 143.712006] CR2: 00000000f686a000 CR3: 00000000080db000 CR4: 00000000000006e0
[ 143.712006] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 143.712006] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[ 143.712006] Process hrtimer_test/1 (pid: 4925, threadinfo
ffff880013e82000, task ffff88000bd69740)
[ 143.712006] Stack:
[ 143.712006] ffffffffa000d680 0000000000000000 ffffffffa000d688
ffff88001440f288
[ 143.712006] <0> ffff88001440f288 ffff880013e83e30 ffffffff81085645
ffffffffa000d680
[ 143.712006] <0> 000000203856036c 0000000000000000 0000000000000001
ffff880013e83eb0
[ 143.712006] Call Trace:
[ 143.712006] [<ffffffff81085645>] enqueue_hrtimer+0x9d/0xae
[ 143.712006] [<ffffffff81086092>] __hrtimer_start_range_ns+0x1a8/0x2a6
[ 143.712006] [<ffffffffa000d155>] ?
restart_hrtimer_repeatedly+0x0/0x84 [hrtimer_unit_test]
[ 143.712006] [<ffffffff810861a8>] hrtimer_start+0x18/0x1a
[ 143.712006] [<ffffffffa000d189>]
restart_hrtimer_repeatedly+0x34/0x84 [hrtimer_unit_test]
[ 143.712006] [<ffffffffa000d155>] ?
restart_hrtimer_repeatedly+0x0/0x84 [hrtimer_unit_test]
[ 143.712006] [<ffffffff81082223>] kthread+0x82/0x8a
[ 143.712006] [<ffffffff81031994>] kernel_thread_helper+0x4/0x10
[ 143.712006] [<ffffffff810821a1>] ? kthread+0x0/0x8a
[ 143.712006] [<ffffffff81031990>] ? kernel_thread_helper+0x0/0x10
[ 143.712006] Code: 74 05 49 89 df eb 0e 4c 89 f6 48 89 df 49 89 dd
e8 ec fe ff ff 49 83 0f 01 4c 89 f6 4c 89 e7 49 83 24 24 fe e8 38 ff
ff ff eb 52 <48> 85 c0 74 1d 48 8b 10 f6 c2 01 75 15 48 83 ca 01 4d 89
e5 48
[ 143.712006] ---[ end trace a701d1f011c8230f ]---
[ 143.712006] Kernel panic - not syncing: Non maskable interrupt
[ 143.712006] Pid: 4925, comm: hrtimer_test/1 Tainted: G D
2.6.36-smp-DEV #4
[ 143.712006] Call Trace:
[ 143.712006] <NMI> [<ffffffff8144a6d8>] panic+0x91/0x197
[ 143.712006] [<ffffffff8144d96c>] die_nmi+0xa4/0xe2
[ 143.712006] [<ffffffff8144dfd0>] nmi_watchdog_tick+0xff/0x16d
[ 143.712006] [<ffffffff8144d4db>] do_nmi+0xe2/0x29c
[ 143.712006] [<ffffffff8144cf3a>] nmi+0x1a/0x20
[ 143.712006] [<ffffffff8120b09a>] ? rb_insert_color+0x6a/0xe5
[ 143.712006] <<EOE>> [<ffffffff81085645>] enqueue_hrtimer+0x9d/0xae
[ 143.712006] [<ffffffff81086092>] __hrtimer_start_range_ns+0x1a8/0x2a6
[ 143.712006] [<ffffffffa000d155>] ?
restart_hrtimer_repeatedly+0x0/0x84 [hrtimer_unit_test]
[ 143.712006] [<ffffffff810861a8>] hrtimer_start+0x18/0x1a
[ 143.712006] [<ffffffffa000d189>]
restart_hrtimer_repeatedly+0x34/0x84 [hrtimer_unit_test]
[ 143.712006] [<ffffffffa000d155>] ?
restart_hrtimer_repeatedly+0x0/0x84 [hrtimer_unit_test]
[ 143.712006] [<ffffffff81082223>] kthread+0x82/0x8a
[ 143.712006] [<ffffffff81031994>] kernel_thread_helper+0x4/0x10
[ 143.712006] [<ffffffff810821a1>] ? kthread+0x0/0x8a
[ 143.712006] [<ffffffff81031990>] ? kernel_thread_helper+0x0/0x10
[ 143.712006] Rebooting in 10 seconds..
Booting...
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

\
 
 \ /
  Last update: 2010-10-08 20:03    [W:0.158 / U:0.152 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site