LKML Archive on lore.kernel.org
 help / Atom feed
* [interval_tree_test_init] BUG: soft lockup - CPU#0 stuck for 23s! [swapper/0:1]
@ 2017-11-07  4:41 Fengguang Wu
  2017-11-07 16:58 ` Davidlohr Bueso
  0 siblings, 1 reply; 4+ messages in thread
From: Fengguang Wu @ 2017-11-07  4:41 UTC (permalink / raw)
  To: Davidlohr Bueso, Chris Wilson; +Cc: linux-kernel, Linus Torvalds


Hi Davidlohr,

Here is a warning in v4.14-rc8 -- it's not necessarily a new bug.

[  265.102312] xz_dec_test: module loaded
[  265.111774] xz_dec_test: Create a device node with 'mknod xz_dec_test c 246 0' and write .xz files to it.
[  265.160320] atomic64_test: passed for x86-64 platform with CX8 and with SSE
[  265.181966] glob: 64 self-tests passed, 0 failed
[  265.196996] interval tree insert/remove
[  292.348094] watchdog: BUG: soft lockup - CPU#0 stuck for 23s! [swapper/0:1]
[  292.348094] irq event stamp: 6190340
[  292.396418] hardirqs last  enabled at (6190339): [<ffffffff81fb006b>] restore_regs_and_iret+0x0/0x1d
[  292.396418] hardirqs last disabled at (6190340): [<ffffffff81fb0cb8>] apic_timer_interrupt+0x98/0xb0
[  292.396418] softirqs last  enabled at (6182242): [<ffffffff81fb2942>] __do_softirq+0x382/0x3f7
[  292.396418] softirqs last disabled at (6182235): [<ffffffff810b6696>] irq_exit+0x51/0x7b
[  292.396418] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.14.0-rc8 #40
[  292.396418] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[  292.396418] task: ffff880072bf4040 task.stack: ffffc9000031c000
[  292.396418] RIP: 0010:interval_tree_insert+0x4c/0xd4
[  292.396418] RSP: 0000:ffffc9000031fe00 EFLAGS: 00000283 ORIG_RAX: ffffffffffffff10
[  292.396418] RAX: 00000000ffffffff RBX: ffff88005168f140 RCX: ffffffff85224ce8
[  292.396418] RDX: ffff880072bf4040 RSI: ffffffff85224ce0 RDI: ffff88005168f140
[  292.396418] RBP: ffffc9000031fe40 R08: ffffffff81684389 R09: 0000000000000001
[  292.396418] R10: ffff880074caeb20 R11: ffff8800728011d8 R12: ffff88005168e1e0
[  292.396418] R13: ffff88005168e038 R14: 000000000d04b0ab R15: ffff88005168e030
[  292.396418] FS:  0000000000000000(0000) GS:ffff880075000000(0000) knlGS:0000000000000000
[  292.396418] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  292.396418] CR2: 0000000000000000 CR3: 0000000002869001 CR4: 00000000000206b0
[  292.396418] Call Trace:
[  292.396418]  interval_tree_test_init+0x193/0x3a8
[  292.396418]  ? mempool_alloc_slab+0x35/0x35
[  292.396418]  ? interval_tree_test_exit+0x17/0x17
[  292.396418]  ? do_early_param+0xc0/0xc0
[  292.396418]  do_one_initcall+0xa2/0x176
[  292.396418]  ? do_early_param+0xc0/0xc0
[  292.396418]  kernel_init_freeable+0x1f0/0x2ac
[  292.396418]  ? rest_init+0x293/0x293
[  292.396418]  kernel_init+0xf/0x147
[  292.396418]  ? rest_init+0x293/0x293
[  292.396418]  ret_from_fork+0x2a/0x40
[  292.396418] Code: 8b 43 18 4c 8b 73 20 4c 8b 6d d0 c6 45 cf 01 48 89 45 c0 eb 43 e8 b9 13 ae ff 4d 3b 74 24 28 76 0a e8 ad 13 ae ff 4d 89 74 24 28 <e8> a3 13 ae ff 48 8b 45 c0 49 3b 44 24 18 73 0c e8 93 13 ae ff 
[  292.396418] Kernel panic - not syncing: softlockup: hung tasks
[  292.396418] CPU: 0 PID: 1 Comm: swapper/0 Tainted: G             L  4.14.0-rc8 #40
[  292.396418] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[  292.396418] Call Trace:
[  292.396418]  <IRQ>
[  292.396418]  dump_stack+0xb8/0x10e
[  292.396418]  panic+0xfb/0x2c7
[  292.396418]  watchdog_timer_fn+0x229/0x25c
[  292.396418]  __hrtimer_run_queues+0x322/0x53a
[  292.396418]  ? __touch_watchdog+0x1c/0x1c
[  292.396418]  hrtimer_interrupt+0xc1/0x1dc
[  292.396418]  smp_apic_timer_interrupt+0x142/0x25e
[  292.396418]  apic_timer_interrupt+0x9d/0xb0
[  292.396418]  </IRQ>
[  292.396418] RIP: 0010:interval_tree_insert+0x4c/0xd4
[  292.396418] RSP: 0000:ffffc9000031fe00 EFLAGS: 00000283 ORIG_RAX: ffffffffffffff10
[  292.396418] RAX: 00000000ffffffff RBX: ffff88005168f140 RCX: ffffffff85224ce8
[  292.396418] RDX: ffff880072bf4040 RSI: ffffffff85224ce0 RDI: ffff88005168f140
[  292.396418] RBP: ffffc9000031fe40 R08: ffffffff81684389 R09: 0000000000000001
[  292.396418] R10: ffff880074caeb20 R11: ffff8800728011d8 R12: ffff88005168e1e0
[  292.396418] R13: ffff88005168e038 R14: 000000000d04b0ab R15: ffff88005168e030
[  292.396418]  ? __sw_hweight8+0x32/0x32
[  292.396418]  interval_tree_test_init+0x193/0x3a8
[  292.396418]  ? mempool_alloc_slab+0x35/0x35
[  292.396418]  ? interval_tree_test_exit+0x17/0x17
[  292.396418]  ? do_early_param+0xc0/0xc0
[  292.396418]  do_one_initcall+0xa2/0x176
[  292.396418]  ? do_early_param+0xc0/0xc0
[  292.396418]  kernel_init_freeable+0x1f0/0x2ac
[  292.396418]  ? rest_init+0x293/0x293
[  292.396418]  kernel_init+0xf/0x147
[  292.396418]  ? rest_init+0x293/0x293
[  292.396418]  ret_from_fork+0x2a/0x40
[  292.396418] Kernel Offset: disabled

Thanks,
Fengguang

^ permalink raw reply	[flat|nested] 4+ messages in thread

* Re: [interval_tree_test_init] BUG: soft lockup - CPU#0 stuck for 23s! [swapper/0:1]
  2017-11-07  4:41 [interval_tree_test_init] BUG: soft lockup - CPU#0 stuck for 23s! [swapper/0:1] Fengguang Wu
@ 2017-11-07 16:58 ` Davidlohr Bueso
  2017-11-08  7:26   ` Fengguang Wu
  0 siblings, 1 reply; 4+ messages in thread
From: Davidlohr Bueso @ 2017-11-07 16:58 UTC (permalink / raw)
  To: Fengguang Wu; +Cc: Chris Wilson, linux-kernel, Linus Torvalds

On Tue, 07 Nov 2017, Fengguang Wu wrote:

>[  265.102312] xz_dec_test: module loaded
>[  265.111774] xz_dec_test: Create a device node with 'mknod xz_dec_test c 246 0' and write .xz files to it.
>[  265.160320] atomic64_test: passed for x86-64 platform with CX8 and with SSE
>[  265.181966] glob: 64 self-tests passed, 0 failed
>[  265.196996] interval tree insert/remove
>[  292.348094] watchdog: BUG: soft lockup - CPU#0 stuck for 23s! [swapper/0:1]
>[  292.348094] irq event stamp: 6190340
>[  292.396418] hardirqs last  enabled at (6190339): [<ffffffff81fb006b>] restore_regs_and_iret+0x0/0x1d
>[  292.396418] hardirqs last disabled at (6190340): [<ffffffff81fb0cb8>] apic_timer_interrupt+0x98/0xb0
>[  292.396418] softirqs last  enabled at (6182242): [<ffffffff81fb2942>] __do_softirq+0x382/0x3f7
>[  292.396418] softirqs last disabled at (6182235): [<ffffffff810b6696>] irq_exit+0x51/0x7b
>[  292.396418] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.14.0-rc8 #40
>[  292.396418] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
>[  292.396418] task: ffff880072bf4040 task.stack: ffffc9000031c000
>[  292.396418] RIP: 0010:interval_tree_insert+0x4c/0xd4

That would be:

     for (i = 0; i < perf_loops; i++) {
	 for (j = 0; j < nnodes; j++)
		interval_tree_insert(nodes + j, &root);
	 for (j = 0; j < nnodes; j++)
		interval_tree_remove(nodes + j, &root);
     }

Which if you are using the default params would end up doing insert() 10 million times.
How about decrementing perf_loops, it's pretty high.

diff --git a/lib/interval_tree_test.c b/lib/interval_tree_test.c
index 0e343fd29570..1dbdf3704247 100644
--- a/lib/interval_tree_test.c
+++ b/lib/interval_tree_test.c
@@ -11,7 +11,7 @@
        MODULE_PARM_DESC(name, msg);
 
 __param(int, nnodes, 100, "Number of nodes in the interval tree");
-__param(int, perf_loops, 100000, "Number of iterations modifying the tree");
+__param(int, perf_loops, 1000, "Number of iterations modifying the tree");
 
 __param(int, nsearches, 100, "Number of searches to the interval tree");
 __param(int, search_loops, 10000, "Number of iterations searching the tree");

If that works I guess we'd have to limit the max values for such parameters
to avoid soft lockups. The same applies to your rbtree test report.

Thanks,
Davidlohr

^ permalink raw reply	[flat|nested] 4+ messages in thread

* Re: [interval_tree_test_init] BUG: soft lockup - CPU#0 stuck for 23s! [swapper/0:1]
  2017-11-07 16:58 ` Davidlohr Bueso
@ 2017-11-08  7:26   ` Fengguang Wu
  2017-11-09 16:17     ` Davidlohr Bueso
  0 siblings, 1 reply; 4+ messages in thread
From: Fengguang Wu @ 2017-11-08  7:26 UTC (permalink / raw)
  To: Davidlohr Bueso; +Cc: Chris Wilson, linux-kernel, Linus Torvalds

On Tue, Nov 07, 2017 at 08:58:14AM -0800, Davidlohr Bueso wrote:
>On Tue, 07 Nov 2017, Fengguang Wu wrote:
>
>>[  265.102312] xz_dec_test: module loaded
>>[  265.111774] xz_dec_test: Create a device node with 'mknod xz_dec_test c 246 0' and write .xz files to it.
>>[  265.160320] atomic64_test: passed for x86-64 platform with CX8 and with SSE
>>[  265.181966] glob: 64 self-tests passed, 0 failed
>>[  265.196996] interval tree insert/remove
>>[  292.348094] watchdog: BUG: soft lockup - CPU#0 stuck for 23s! [swapper/0:1]
>>[  292.348094] irq event stamp: 6190340
>>[  292.396418] hardirqs last  enabled at (6190339): [<ffffffff81fb006b>] restore_regs_and_iret+0x0/0x1d
>>[  292.396418] hardirqs last disabled at (6190340): [<ffffffff81fb0cb8>] apic_timer_interrupt+0x98/0xb0
>>[  292.396418] softirqs last  enabled at (6182242): [<ffffffff81fb2942>] __do_softirq+0x382/0x3f7
>>[  292.396418] softirqs last disabled at (6182235): [<ffffffff810b6696>] irq_exit+0x51/0x7b
>>[  292.396418] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.14.0-rc8 #40
>>[  292.396418] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
>>[  292.396418] task: ffff880072bf4040 task.stack: ffffc9000031c000
>>[  292.396418] RIP: 0010:interval_tree_insert+0x4c/0xd4
>
>That would be:
>
>     for (i = 0; i < perf_loops; i++) {
>	 for (j = 0; j < nnodes; j++)
>		interval_tree_insert(nodes + j, &root);
>	 for (j = 0; j < nnodes; j++)
>		interval_tree_remove(nodes + j, &root);
>     }
>
>Which if you are using the default params would end up doing insert() 10 million times.
>How about decrementing perf_loops, it's pretty high.

It works! Thank you!

Tested-by: Fengguang Wu <fengguang.wu@intel.com>

Fengguang

>diff --git a/lib/interval_tree_test.c b/lib/interval_tree_test.c
>index 0e343fd29570..1dbdf3704247 100644
>--- a/lib/interval_tree_test.c
>+++ b/lib/interval_tree_test.c
>@@ -11,7 +11,7 @@
>        MODULE_PARM_DESC(name, msg);
>
> __param(int, nnodes, 100, "Number of nodes in the interval tree");
>-__param(int, perf_loops, 100000, "Number of iterations modifying the tree");
>+__param(int, perf_loops, 1000, "Number of iterations modifying the tree");
>
> __param(int, nsearches, 100, "Number of searches to the interval tree");
> __param(int, search_loops, 10000, "Number of iterations searching the tree");
>
>If that works I guess we'd have to limit the max values for such parameters
>to avoid soft lockups. The same applies to your rbtree test report.
>
>Thanks,
>Davidlohr
>

^ permalink raw reply	[flat|nested] 4+ messages in thread

* Re: [interval_tree_test_init] BUG: soft lockup - CPU#0 stuck for 23s! [swapper/0:1]
  2017-11-08  7:26   ` Fengguang Wu
@ 2017-11-09 16:17     ` Davidlohr Bueso
  0 siblings, 0 replies; 4+ messages in thread
From: Davidlohr Bueso @ 2017-11-09 16:17 UTC (permalink / raw)
  To: Fengguang Wu, akpm; +Cc: Chris Wilson, linux-kernel, Linus Torvalds

On Wed, 08 Nov 2017, Fengguang Wu wrote:

>On Tue, Nov 07, 2017 at 08:58:14AM -0800, Davidlohr Bueso wrote:
>>On Tue, 07 Nov 2017, Fengguang Wu wrote:
>>
>>>[  265.102312] xz_dec_test: module loaded
>>>[  265.111774] xz_dec_test: Create a device node with 'mknod xz_dec_test c 246 0' and write .xz files to it.
>>>[  265.160320] atomic64_test: passed for x86-64 platform with CX8 and with SSE
>>>[  265.181966] glob: 64 self-tests passed, 0 failed
>>>[  265.196996] interval tree insert/remove
>>>[  292.348094] watchdog: BUG: soft lockup - CPU#0 stuck for 23s! [swapper/0:1]
>>>[  292.348094] irq event stamp: 6190340
>>>[  292.396418] hardirqs last  enabled at (6190339): [<ffffffff81fb006b>] restore_regs_and_iret+0x0/0x1d
>>>[  292.396418] hardirqs last disabled at (6190340): [<ffffffff81fb0cb8>] apic_timer_interrupt+0x98/0xb0
>>>[  292.396418] softirqs last  enabled at (6182242): [<ffffffff81fb2942>] __do_softirq+0x382/0x3f7
>>>[  292.396418] softirqs last disabled at (6182235): [<ffffffff810b6696>] irq_exit+0x51/0x7b
>>>[  292.396418] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.14.0-rc8 #40
>>>[  292.396418] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
>>>[  292.396418] task: ffff880072bf4040 task.stack: ffffc9000031c000
>>>[  292.396418] RIP: 0010:interval_tree_insert+0x4c/0xd4
>>
>>That would be:
>>
>>    for (i = 0; i < perf_loops; i++) {
>>	 for (j = 0; j < nnodes; j++)
>>		interval_tree_insert(nodes + j, &root);
>>	 for (j = 0; j < nnodes; j++)
>>		interval_tree_remove(nodes + j, &root);
>>    }
>>
>>Which if you are using the default params would end up doing insert() 10 million times.
>>How about decrementing perf_loops, it's pretty high.
>
>It works! Thank you!
>
>Tested-by: Fengguang Wu <fengguang.wu@intel.com>
>
>Fengguang
>
>>diff --git a/lib/interval_tree_test.c b/lib/interval_tree_test.c
>>index 0e343fd29570..1dbdf3704247 100644
>>--- a/lib/interval_tree_test.c
>>+++ b/lib/interval_tree_test.c
>>@@ -11,7 +11,7 @@
>>       MODULE_PARM_DESC(name, msg);
>>
>>__param(int, nnodes, 100, "Number of nodes in the interval tree");
>>-__param(int, perf_loops, 100000, "Number of iterations modifying the tree");
>>+__param(int, perf_loops, 1000, "Number of iterations modifying the tree");
>>
>>__param(int, nsearches, 100, "Number of searches to the interval tree");
>>__param(int, search_loops, 10000, "Number of iterations searching the tree");
>>
>>If that works I guess we'd have to limit the max values for such parameters
>>to avoid soft lockups. The same applies to your rbtree test report.

I've decided to not do this as different users might be ok with the risk,
just not the default.

Cc'ing akpm.

Thanks,
Davidlohr

--------8<--------------------------------------------------
[PATCH] lib/rbtree-test: lower default params

Fengguang reported soft lockups while running the rbtree
and interval tree test modules. The logic for these tests
all occur in init phase, and we currently are pounding
with the default values for number of nodes and number
of iterations of each test. Reduce the later by two
orders of magnitude. This does not influence the value
of the tests in that one thousand times by default is
enough to get the picture.

Reported-by: Fengguang Wu <fengguang.wu@intel.com>
Signed-off-by: Davidlohr Bueso <dbueso@suse.de>
---
 lib/interval_tree_test.c | 4 ++--
 lib/rbtree_test.c        | 2 +-
 2 files changed, 3 insertions(+), 3 deletions(-)

diff --git a/lib/interval_tree_test.c b/lib/interval_tree_test.c
index 0e343fd29570..835242e74aaa 100644
--- a/lib/interval_tree_test.c
+++ b/lib/interval_tree_test.c
@@ -11,10 +11,10 @@
 	MODULE_PARM_DESC(name, msg);
 
 __param(int, nnodes, 100, "Number of nodes in the interval tree");
-__param(int, perf_loops, 100000, "Number of iterations modifying the tree");
+__param(int, perf_loops, 1000, "Number of iterations modifying the tree");
 
 __param(int, nsearches, 100, "Number of searches to the interval tree");
-__param(int, search_loops, 10000, "Number of iterations searching the tree");
+__param(int, search_loops, 1000, "Number of iterations searching the tree");
 __param(bool, search_all, false, "Searches will iterate all nodes in the tree");
 
 __param(uint, max_endpoint, ~0, "Largest value for the interval's endpoint");
diff --git a/lib/rbtree_test.c b/lib/rbtree_test.c
index 191a238e5a9d..7d36c1e27ff6 100644
--- a/lib/rbtree_test.c
+++ b/lib/rbtree_test.c
@@ -11,7 +11,7 @@
 	MODULE_PARM_DESC(name, msg);
 
 __param(int, nnodes, 100, "Number of nodes in the rb-tree");
-__param(int, perf_loops, 100000, "Number of iterations modifying the rb-tree");
+__param(int, perf_loops, 1000, "Number of iterations modifying the rb-tree");
 __param(int, check_loops, 100, "Number of iterations modifying and verifying the rb-tree");
 
 struct test_node {
-- 
2.13.6

^ permalink raw reply	[flat|nested] 4+ messages in thread

end of thread, back to index

Thread overview: 4+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2017-11-07  4:41 [interval_tree_test_init] BUG: soft lockup - CPU#0 stuck for 23s! [swapper/0:1] Fengguang Wu
2017-11-07 16:58 ` Davidlohr Bueso
2017-11-08  7:26   ` Fengguang Wu
2017-11-09 16:17     ` Davidlohr Bueso

LKML Archive on lore.kernel.org

Archives are clonable:
	git clone --mirror https://lore.kernel.org/lkml/0 lkml/git/0.git
	git clone --mirror https://lore.kernel.org/lkml/1 lkml/git/1.git
	git clone --mirror https://lore.kernel.org/lkml/2 lkml/git/2.git
	git clone --mirror https://lore.kernel.org/lkml/3 lkml/git/3.git
	git clone --mirror https://lore.kernel.org/lkml/4 lkml/git/4.git
	git clone --mirror https://lore.kernel.org/lkml/5 lkml/git/5.git
	git clone --mirror https://lore.kernel.org/lkml/6 lkml/git/6.git
	git clone --mirror https://lore.kernel.org/lkml/7 lkml/git/7.git

	# If you have public-inbox 1.1+ installed, you may
	# initialize and index your mirror using the following commands:
	public-inbox-init -V2 lkml lkml/ https://lore.kernel.org/lkml \
		linux-kernel@vger.kernel.org linux-kernel@archiver.kernel.org
	public-inbox-index lkml


Newsgroup available over NNTP:
	nntp://nntp.lore.kernel.org/org.kernel.vger.linux-kernel


AGPL code for this site: git clone https://public-inbox.org/ public-inbox