Re: RCU CPU stall console spews leads to soft lockup disabled is reasonable ?

From: Zhang Zhen
Date: Wed Jan 21 2015 - 04:06:43 EST

Next message: Asaf Vertz: "[PATCH] usb: gadget: zero: fix format string warnings"
Previous message: Boris Brezillon: "[GIT PULL] drm: Add Atmel HLCDC driver"
In reply to: Zhang Zhen: "Re: RCU CPU stall console spews leads to soft lockup disabled is reasonable ?"
Next in thread: Paul E. McKenney: "Re: RCU CPU stall console spews leads to soft lockup disabled is reasonable ?"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

On 2015/1/21 15:02, Paul E. McKenney wrote:
> On Wed, Jan 21, 2015 at 02:54:05PM +0800, Zhang Zhen wrote:
>> On 2015/1/21 11:13, Zhang Zhen wrote:
>>> On 2015/1/21 10:26, Zhang Zhen wrote:
>>>> On 2015/1/20 23:25, Don Zickus wrote:
>
> [ . . . ]
>
>>> Sorry, i made a mistake, the log above is based on v3.10.63.
>>> I have tested the latest upstream kernel (based on ec6f34e5b552),
>>> but my test case can't triggered RCU stall warning.
>>>
>>
>> I used git bisect to find the bad commit, but found a irrelevant
>> commit(db5d711e2db776 zram: avoid null access when fail to alloc meta).
>> Before this commit, my test case can easily trigger RCU stall warning,
>> but after this commit, my test case can't trigger RCU stall warning.
>
> I have lost track of exactly what kernel you are using. If you are
> using a recent kernel (v3.18 or thereabouts), one thing to try is to
> apply my stack of RCU CPU stall-warning changes that are on their way
> in, please see v3.19-rc1..630181c4a915 in -rcu, which is at:
>
> git://git.kernel.org/pub/scm/linux/kernel/git/paulmck/linux-rcu.git
>
> These handle the problems that Dave Jones and a few others located this
> past December. Could you please give them a spin?
>

Yeah, my test case can easily trigger RCU stall-warning based on commit 630181c4a915
in your linux-rcu git tree.

In my .config, CONFIG_RCU_CPU_STALL_TIMEOUT=21.
Before commented out touch_softlockup_watchdog() in touch_nmi_watchdog:

/ #
/ # echo 60 > /proc/sys/kernel/watchdog_thresh
[ 21.885200] NMI watchdog: disabled (cpu0): hardware events not enabled
/ # busybox insmod softlockup_test.ko
[ 47.900117] INFO: rcu_sched detected stalls on CPUs/tasks:
[ 47.900117] (detected by 0, t=5252 jiffies, g=-202, c=-203, q=7)
[ 47.900117] All QSes seen, last rcu_sched kthread activity 5252 (4294904271-4294899019), jiffies_till_next_fqs=1
[ 47.900117] busybox R running task 0 42 41 0x00000008
[ 47.900117] ffffffff81afaf40 ffff88007fa03d98 ffffffff810781c0 ffffffff81a5e5f8
[ 47.900117] ffffffff81a45d80 ffff88007fa03dd8 ffffffff810af723 0000000000000083
[ 47.900117] ffff88007fa13580 ffffffff81a45d80 ffffffff81a45d80 ffffffff810c43e0
[ 47.900117] Call Trace:
[ 47.900117] <IRQ> [<ffffffff810781c0>] sched_show_task+0xb0/0x110
[ 47.900117] [<ffffffff810af723>] print_other_cpu_stall+0x2d3/0x2f0
[ 47.900117] [<ffffffff810c43e0>] ? tick_nohz_handler+0xc0/0xc0
[ 47.900117] [<ffffffff810af8b8>] __rcu_pending+0x178/0x220
[ 47.900117] [<ffffffff810b02a5>] rcu_check_callbacks+0x105/0x190
[ 47.900117] [<ffffffff810c43e0>] ? tick_nohz_handler+0xc0/0xc0
[ 47.900117] [<ffffffff810b3582>] update_process_times+0x32/0x60
[ 47.900117] [<ffffffff810c41e2>] tick_sched_handle+0x32/0x80
[ 47.900117] [<ffffffff810c442d>] tick_sched_timer+0x4d/0x90
[ 47.900117] [<ffffffff810b5b57>] __run_hrtimer+0xc7/0x1c0
[ 47.900117] [<ffffffff810b5e37>] hrtimer_interrupt+0xe7/0x220
[ 47.900117] [<ffffffffa0005000>] ? 0xffffffffa0005000
[ 47.900117] [<ffffffff81035654>] local_apic_timer_interrupt+0x34/0x60
[ 47.900117] [<ffffffff81035d8c>] smp_apic_timer_interrupt+0x3c/0x60
[ 47.900117] [<ffffffff814ff02a>] apic_timer_interrupt+0x6a/0x70
[ 47.900117] <EOI> [<ffffffff814fdaa0>] ? _raw_spin_lock+0x20/0x30
[ 47.900117] [<ffffffffa000505d>] test_init+0x5d/0x1000 [softlockup_test]
[ 47.900117] [<ffffffffa0005000>] ? 0xffffffffa0005000
[ 47.900117] [<ffffffff81000288>] do_one_initcall+0xb8/0x1d0
[ 47.900117] [<ffffffff81168794>] ? __vunmap+0x94/0xf0
[ 47.900117] [<ffffffff810ce36b>] do_init_module+0x2b/0x1b0
[ 47.900117] [<ffffffff810d09b5>] load_module+0x585/0x5f0
[ 47.900117] [<ffffffff810cdd40>] ? mod_sysfs_teardown+0x150/0x150
[ 47.900117] [<ffffffff810d0bbb>] SyS_init_module+0x9b/0xc0
[ 47.900117] [<ffffffff814fe252>] system_call_fastpath+0x12/0x17
[ 47.900117] rcu_sched kthread starved for 5252 jiffies!

After commented out touch_softlockup_watchdog() in touch_nmi_watchdog:

/ #
/ # echo 60 > /proc/sys/kernel/watchdog_thresh
[ 123.011980] NMI watchdog: disabled (cpu0): hardware events not enabled
/ # busybox insmod softlockup_test.ko
[ 150.912055] INFO: rcu_sched detected stalls on CPUs/tasks:
[ 150.912055] (detected by 0, t=5252 jiffies, g=-198, c=-199, q=6)
[ 150.912055] All QSes seen, last rcu_sched kthread activity 5252 (4294930024-4294924772), jiffies_till_next_fqs=1
[ 150.912055] busybox R running task 0 42 41 0x00000008
[ 150.912055] ffffffff81afaf40 ffff88007fa03d98 ffffffff810781c0 ffffffff81a5e5f8
[ 150.912055] ffffffff81a45d80 ffff88007fa03dd8 ffffffff810af723 0000000000000083
[ 150.912055] ffff88007fa13580 ffffffff81a45d80 ffffffff81a45d80 ffffffff810c43e0
[ 150.912055] Call Trace:
[ 150.912055] <IRQ> [<ffffffff810781c0>] sched_show_task+0xb0/0x110
[ 150.912055] [<ffffffff810af723>] print_other_cpu_stall+0x2d3/0x2f0
[ 150.912055] [<ffffffff810c43e0>] ? tick_nohz_handler+0xc0/0xc0
[ 150.912055] [<ffffffff810af8b8>] __rcu_pending+0x178/0x220
[ 150.912055] [<ffffffff810b02a5>] rcu_check_callbacks+0x105/0x190
[ 150.912055] [<ffffffff810c43e0>] ? tick_nohz_handler+0xc0/0xc0
[ 150.912055] [<ffffffff810b3582>] update_process_times+0x32/0x60
[ 150.912055] [<ffffffff810c41e2>] tick_sched_handle+0x32/0x80
[ 150.912055] [<ffffffff810c442d>] tick_sched_timer+0x4d/0x90
[ 150.912055] [<ffffffff810b5b57>] __run_hrtimer+0xc7/0x1c0
[ 150.912055] [<ffffffff810b5e37>] hrtimer_interrupt+0xe7/0x220
[ 150.912055] [<ffffffffa0005000>] ? 0xffffffffa0005000
[ 150.912055] [<ffffffff81035654>] local_apic_timer_interrupt+0x34/0x60
[ 150.912055] [<ffffffff81035d8c>] smp_apic_timer_interrupt+0x3c/0x60
[ 150.912055] [<ffffffff814ff02a>] apic_timer_interrupt+0x6a/0x70
[ 150.912055] <EOI> [<ffffffff814fda90>] ? _raw_spin_lock+0x20/0x30
[ 150.912055] [<ffffffffa000505d>] test_init+0x5d/0x1000 [softlockup_test]
[ 150.912055] [<ffffffffa0005000>] ? 0xffffffffa0005000
[ 150.912055] [<ffffffff81000288>] do_one_initcall+0xb8/0x1d0
[ 150.912055] [<ffffffff81168784>] ? __vunmap+0x94/0xf0
[ 150.912055] [<ffffffff810ce36b>] do_init_module+0x2b/0x1b0
[ 150.912055] [<ffffffff810d09b5>] load_module+0x585/0x5f0
[ 150.912055] [<ffffffff810cdd40>] ? mod_sysfs_teardown+0x150/0x150
[ 150.912055] [<ffffffff810d0bbb>] SyS_init_module+0x9b/0xc0
[ 150.912055] [<ffffffff814fe252>] system_call_fastpath+0x12/0x17
[ 150.912055] rcu_sched kthread starved for 5252 jiffies!
...
...
[ 291.009857] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 135s! [busybox:42]
[ 291.010286] Modules linked in: softlockup_test(O+)
[ 291.010944] CPU: 0 PID: 42 Comm: busybox Tainted: G O 3.19.0-rc1-0.27-default+ #3
[ 291.011356] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2007
[ 291.011674] task: ffff88007d3e61d0 ti: ffff88007d3fc000 task.ti: ffff88007d3fc000
[ 291.012066] RIP: 0010:[<ffffffff814fda90>] [<ffffffff814fda90>] _raw_spin_lock+0x20/0x30
[ 291.012205] RSP: 0018:ffff88007d3ffdd8 EFLAGS: 00000202
[ 291.012205] RAX: 0000000000000000 RBX: ffff88007cc1e250 RCX: 0000000000012a40
[ 291.012205] RDX: 0000000000000001 RSI: 0000000000000246 RDI: ffff88007d3ffde8
[ 291.012205] RBP: ffff88007d3ffdd8 R08: ffff88007fa12a40 R09: 000000000000b806
[ 291.012205] R10: 0000000000000000 R11: ffff88007d3ffcd8 R12: ffffffff8107b1a4
[ 291.012205] R13: ffff88007d3ffd68 R14: 0000000000000000 R15: 0000000000000000
[ 291.012205] FS: 00000000007fd880(0063) GS:ffff88007fa00000(0000) knlGS:0000000000000000
[ 291.012205] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 291.012205] CR2: 000000000081c87f CR3: 000000007d3f1000 CR4: 00000000000006f0
[ 291.012205] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 291.012205] DR3: 0000000000000000 DR6: 0000000000000000 DR7: 0000000000000000
[ 291.012205] Stack:
[ 291.012205] ffff88007d3ffe08 ffffffffa000505d ffff880000020000 0000000000000000
[ 291.012205] ffffffffa0005000 ffffffff81a19250 ffff88007d3ffe78 ffffffff81000288
[ 291.012205] ffff88007d317540 0000000000000020 ffff88007d317540 0000000000000001
[ 291.012205] Call Trace:
[ 291.012205] [<ffffffffa000505d>] test_init+0x5d/0x1000 [softlockup_test]
[ 291.012205] [<ffffffffa0005000>] ? 0xffffffffa0005000
[ 291.012205] [<ffffffff81000288>] do_one_initcall+0xb8/0x1d0
[ 291.012205] [<ffffffff81168784>] ? __vunmap+0x94/0xf0
[ 291.012205] [<ffffffff810ce36b>] do_init_module+0x2b/0x1b0
[ 291.012205] [<ffffffff810d09b5>] load_module+0x585/0x5f0
[ 291.012205] [<ffffffff810cdd40>] ? mod_sysfs_teardown+0x150/0x150
[ 291.012205] [<ffffffff810d0bbb>] SyS_init_module+0x9b/0xc0
[ 291.012205] [<ffffffff814fe252>] system_call_fastpath+0x12/0x17
[ 291.012205] Code: 89 d0 c9 c3 0f 1f 80 00 00 00 00 55 48 89 e5 b8 00 00 01 00 3e 0f c1 07 89 c2 c1 ea 10 66 39 d0 75 0b eb 11 0f 1f 80 00 00 00 00 <f3> 90 0f b7 07 66 39 c2 75 f6 c9 c3 0f 1f 40 00 55 48 89 e5 9c

> Thanx, Paul
>
>> I'm totally confused.
>>
>> My test case:
>>
>> //
>> #include <linux/kernel.h>
>> #include <linux/module.h>
>> #include <linux/spinlock.h>
>> #include <linux/slab.h>
>> #include <linux/kthread.h>
>>
>> struct foo {
>> int a;
>> char b;
>> long c;
>> };
>>
>> struct foo gbl_foo = {1, 'a', 2};
>> struct foo *pgbl_foo = &gbl_foo;
>>
>> static int my_kthread(void *data)
>> {
>> DEFINE_SPINLOCK(foo_mutex);
>> struct foo *new_fp;
>> struct foo *old_fp;
>>
>> new_fp = kmalloc(sizeof(*new_fp), GFP_KERNEL);
>> spin_lock(&foo_mutex);
>> old_fp = pgbl_foo;
>> *new_fp = *old_fp;
>> new_fp->a = 2;
>> rcu_assign_pointer(pgbl_foo, new_fp);
>> spin_unlock(&foo_mutex);
>> synchronize_rcu();
>> kfree(old_fp);
>>
>> return 0;
>> }
>>
>> static int hello_start(void)
>> {
>> struct task_struct *my_task = NULL;
>> DEFINE_SPINLOCK(hello_lock);
>>
>> my_task = kthread_run(my_kthread, NULL, "my_thread%d", 1);
>>
>> spin_lock_init(&hello_lock);
>> spin_lock(&hello_lock);
>> spin_lock(&hello_lock);
>> return 0;
>> }
>>
>> static int __init test_init(void)
>> {
>> hello_start();
>>
>> printk(KERN_INFO "Module init\n");
>> return 0;
>> }
>>
>> static void __exit test_exit(void)
>> {
>> printk(KERN_INFO "Module exit!\n");
>> }
>>
>> module_init(test_init)
>> module_exit(test_exit)
>> MODULE_LICENSE("GPL");
>> //
>>>>>
>>>>> Cheers,
>>>>> Don
>>>>>
>>>>> diff --git a/kernel/watchdog.c b/kernel/watchdog.c
>>>>> index 70bf118..833c015 100644
>>>>> --- a/kernel/watchdog.c
>>>>> +++ b/kernel/watchdog.c
>>>>> @@ -209,7 +209,7 @@ void touch_nmi_watchdog(void)
>>>>> * going off.
>>>>> */
>>>>> raw_cpu_write(watchdog_nmi_touch, true);
>>>>> - touch_softlockup_watchdog();
>>>>> + //touch_softlockup_watchdog();
>>>>> }
>>>>> EXPORT_SYMBOL(touch_nmi_watchdog);
>>>>>
>>>>>
>>>>> .
>>>>>
>>>>
>>>
>>
>>
>
>
> .
>

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

Next message: Asaf Vertz: "[PATCH] usb: gadget: zero: fix format string warnings"
Previous message: Boris Brezillon: "[GIT PULL] drm: Add Atmel HLCDC driver"
In reply to: Zhang Zhen: "Re: RCU CPU stall console spews leads to soft lockup disabled is reasonable ?"
Next in thread: Paul E. McKenney: "Re: RCU CPU stall console spews leads to soft lockup disabled is reasonable ?"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]