Re: [lkp] [printk] 34578dc67f: EIP is at vprintk_emit+0x1ea/0x600

From: Sergey Senozhatsky
Date: Thu Feb 25 2016 - 00:11:12 EST

Next message: Ross Green: "Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17"
Previous message: Qiang Zhao: "RE: [PATCH v2 2/7] QE: Add ucc hdlc document to bindings"
In reply to: Sergey Senozhatsky: "Re: [lkp] [printk] 34578dc67f: EIP is at vprintk_emit+0x1ea/0x600"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

Hello,

On (02/25/16 00:12), Sergey Senozhatsky wrote:
[..]
> > > I want to be sure that the patch in printk() did not introduce
> > > a deadlock that is visible only under a high printk load.
>
> I'll do more tests, certainly.

No behavioral change between linux-next and linux-next modulo printk patches was observed.

next-20160224

git revert 8a30bf8ff5e07a589ad43363b06ea361ad723a0e 2822460a0ea97656ae71b2b4ddac087f79c5876a b6751672d3ac1d3d876fd5ea7ec579956eee4d6b

set PREEMPT_NONE

CONFIG_PREEMPT_NONE=y
# CONFIG_PREEMPT_VOLUNTARY is not set
# CONFIG_PREEMPT is not set
CONFIG_PREEMPT_COUNT=y

add PANIC of softlockup and panic on hung_task

CONFIG_LOCKUP_DETECTOR=y
CONFIG_HARDLOCKUP_DETECTOR=y
CONFIG_BOOTPARAM_HARDLOCKUP_PANIC=y
CONFIG_BOOTPARAM_HARDLOCKUP_PANIC_VALUE=1
CONFIG_BOOTPARAM_SOFTLOCKUP_PANIC=y <<
CONFIG_BOOTPARAM_SOFTLOCKUP_PANIC_VALUE=1
CONFIG_DETECT_HUNG_TASK=y
CONFIG_DEFAULT_HUNG_TASK_TIMEOUT=11
CONFIG_BOOTPARAM_HUNG_TASK_PANIC=y <<
CONFIG_BOOTPARAM_HUNG_TASK_PANIC_VALUE=1
CONFIG_WQ_WATCHDOG=y
CONFIG_PANIC_ON_OOPS=y
CONFIG_PANIC_ON_OOPS_VALUE=1
CONFIG_PANIC_TIMEOUT=23

modify watchdog timeout (so it detects lockup sooner) and add
printk() flood -- the code does not even disable preemption,
just busy looping, we have PREEMPT_NONE kernel.

git diff

diff --git a/drivers/block/zram/zram_drv.c b/drivers/block/zram/zram_drv.c
index 46055db..8759dbb 100644
--- a/drivers/block/zram/zram_drv.c
+++ b/drivers/block/zram/zram_drv.c
@@ -1410,6 +1410,21 @@ static int __init zram_init(void)
{
int ret;

+ /*unsigned long flags;*/
+ u64 s, e;
+
+ /*preempt_disable();*/
+ s = local_clock() >> 31UL;
+ while (1) {
+ e = local_clock() >> 31UL;
+ if (e - s > 10)
+ goto out;
+ pr_err(">>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>\n");
+ }
+out:
+ /*preempt_enable();*/
+
+
ret = class_register(&zram_control_class);
if (ret) {
pr_err("Unable to register zram-control class\n");
diff --git a/kernel/watchdog.c b/kernel/watchdog.c
index b3ace6e..8655364 100644
--- a/kernel/watchdog.c
+++ b/kernel/watchdog.c
@@ -54,7 +54,7 @@ static unsigned long __read_mostly watchdog_enabled = SOFT_WATCHDOG_ENABLED;
int __read_mostly nmi_watchdog_enabled;
int __read_mostly soft_watchdog_enabled;
int __read_mostly watchdog_user_enabled;
-int __read_mostly watchdog_thresh = 10;
+int __read_mostly watchdog_thresh = 1;

#ifdef CONFIG_SMP
int __read_mostly sysctl_softlockup_all_cpu_backtrace;

---

The test (unpatched linux-next)

NMI watchdog: BUG: soft lockup - CPU#2 stuck for 3s! [modprobe:418]
Modules linked in: ...
irq event stamp: 40679
hardirqs last enabled at (40679): [<ffffffff8108b771>] vprintk_emit+0x3f0/0x499
hardirqs last disabled at (40678): [<ffffffff8108b3d4>] vprintk_emit+0x53/0x499
softirqs last enabled at (35360): [<ffffffff810475e9>] __do_softirq+0x2d8
softirqs last disabled at (35357): [<ffffffff810478ce>] irq_exit+0x41/0x95
CPU: 2 PID: 418 Comm: modprobe Tainted: G O 4.5.0-rc5-next-20160224-dbg-00012-gfedb791-dirty #187
Hardware name: ...
task: ffff88013290ce00 ti: ffff880131f98000 task.ti: ffff880131f98000
RIP: 0010:[<ffffffff8108b2d8>] [<ffffffff8108b2d8>] console_unlock+0x3ad/0x456
RSP: 0018:ffff880131f9bbc8 EFLAGS: 00000246
RAX: ffff88013290ce00 RBX: ffffffff82891fdc RCX: 00000000ffffffff
RDX: ffffffff812c99a8 RSI: 0000000000000001 RDI: ffffffff8108b2d5
RBP: ffff880131f9bc08 R08: 0000000000000000 R09: 0000000000000000
R10: 00000000ffff00ff R11: 000000000000042b R12: 0000000000000000
R13: 0000000000000246 R14: 0000000000000003 R15: 0000000000000001
S: 00007fe6ed4fd700(0000) GS:ffff880137d00000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007fe6eb905000 CR3: 00000000bb7fc000 CR4: 00000000000006e0
Stack:
0000000000000000 0000000000000029 000000000001a128 00000000ffffffff
0000000000000003 0000000000000028 ffffffff82877602 0000000000000028
ffff880131f9bc60 ffffffff8108b7cb 0000000000000000 0000000000000000
Call Trace:
[<ffffffff8108b7cb>] vprintk_emit+0x44a/0x499
[<ffffffffa01f0000>] ? 0xffffffffa01f0000
[<ffffffff8108b931>] vprintk_default+0x1d/0x1f
[<ffffffff810f1b21>] printk+0x48/0x50
[<ffffffffa01f0032>] zram_init+0x32/0x1000 [zram]
[<ffffffff81000402>] do_one_initcall+0xe7/0x16
[<ffffffff810f1d5f>] ? do_init_module+0x27/0x1d9
[<ffffffff81093619>] ? rcu_read_lock_sched_held+0x61/0x69
[<ffffffff811330fa>] ? kmem_cache_alloc_trace+0x138/0x1d0
[<ffffffff810f1d5f>] ? do_init_module+0x27/0x1d9
[<ffffffff810f1d97>] do_init_module+0x5f/0x1d9
[<ffffffff810b2b2c>] load_module+0x19da/0x1eb8
[<ffffffff810830c4>] ? lock_acquire+0x10f/0x1a3
[<ffffffff810b3109>] SyS_init_module+0xff/0x125
[<ffffffff810b3109>] ? SyS_init_module+0xff/0x125
[<ffffffff8150e525>] entry_SYSCALL_64_fastpath+0x18/0xa8
Code: 89 05 11 cc 80 01 4c 89 35 0e cc 80 01 88 d0 83 e2 fe 83 e0 1e 88 53 0f 0f b6 c0 89 05 f2 cb 80 01 eb 9e e8 9e 5a ff ff 41 55 9d <e9> ed fe ff ff 48 83 3d 3b cd 80 01 00 c7 05 3d cd 80 01 00 00

Kernel panic - not syncing: softlockup: hung tasks
CPU: 2 PID: 418 Comm: modprobe Tainted: G O L 4.5.0-rc5-next-20160224-dbg-00012-gfedb791-dirty #187
Hardware name: ...
0000000000000000 ffff880137d03d68 ffffffff8123334d ffffffff817ad7c7
ffff880137d03df8 ffff880137d03de8 ffffffff810f124e ffffffff00000008
ffff880137d03df8 ffff880137d03d90 0000000000000000 00000000ffffffff
Call Trace:
<IRQ> [<ffffffff8123334d>] dump_stack+0x67/0x90
[<ffffffff810f124e>] panic+0xd1/0x212
[<ffffffff8107d1c1>] ? down_trylock+0x2d/0x37
[<ffffffff810c12c5>] watchdog_timer_fn+0x18e/0x1b0
[<ffffffff8109cee9>] __hrtimer_run_queues+0x1ee/0x418
[<ffffffff810c1137>] ? __touch_watchdog+0x1c/0x1c
[<ffffffff8109d2af>] hrtimer_interrupt+0xa8/0x192
[<ffffffff810354cd>] hpet_interrupt_handler+0x2a/0x31
[<ffffffff8108ccd8>] handle_irq_event_percpu+0xd2/0x2e4
[<ffffffff8108cf22>] handle_irq_event+0x38/0x56
[<ffffffff8108fc63>] handle_edge_irq+0xd9/0xfb
[<ffffffff810174ad>] handle_irq+0x1c/0x20
[<ffffffff81510795>] do_IRQ+0x85/0x1
[<ffffffff8150ee86>] common_interrupt+0x86/0x86
<EOI> [<ffffffff812c99a8>] ? vt_console_print+0x2f9/0x308
[<ffffffff8108b2d5>] ? console_unlock+0x3aa/0x456
[<ffffffff8108b2d8>] ? console_unlock+0x3ad/0x456
[<ffffffff8108b7cb>] vprintk_emit+0x44a/0x499
[<ffffffffa01f0000>] ? 0xffffffffa01f0000
[<ffffffff8108b931>] vprintk_default+0x1d/0x1f
[<ffffffff810f1b21>] printk+0x48/0x50
[<ffffffffa01f0032>] zram_init+0x32/0x1000 [zram]
[<ffffffff81000402>] do_one_initcall+0xe7/0x16c
[<ffffffff810f1d5f>] ? do_init_module+0x27/0x1d9
[<ffffffff81093619>] ? rcu_read_lock_sched_held+0x61/0x69
[<ffffffff811330fa>] ? kmem_cache_alloc_trace+0x138/0x1d0
[<ffffffff810f1d5f>] ? do_init_module+0x27/0x1d9
[<ffffffff810f1d97>] do_init_module+0x5f/0x1d9
[<ffffffff810b2b2c>] load_module+0x19da/0x1eb8
[<ffffffff810830c4>] ? lock_acquire+0x10f/0x1a3
[<ffffffff810b3109>] SyS_init_module+0xff/0x125
[<ffffffff810b3109>] ? SyS_init_module+0xff/0x125
[<ffffffff8150e525>] entry_SYSCALL_64_fastpath+0x18/0xa8

so in this test printk()->console_unlock() was performed on the same CPU.
but in general those can be different CPUs. one busy spinning doing printk(),
the other busy spinning doing console_unlock()->call_console_drivers().

-ss

Next message: Ross Green: "Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17"
Previous message: Qiang Zhao: "RE: [PATCH v2 2/7] QE: Add ucc hdlc document to bindings"
In reply to: Sergey Senozhatsky: "Re: [lkp] [printk] 34578dc67f: EIP is at vprintk_emit+0x1ea/0x600"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]