Re: [lkp-robot] [torture] b151f93a71: INFO:rcu_preempt_detected_stalls_on_CPUs/tasks

[Paul E. McKenney <paulmck@linux.vnet.ibm.com>]

[-- Attachment #1: Type: text/plain, Size: 45170 bytes --]

On Tue, Nov 28, 2017 at 09:35:54AM -0800, Paul E. McKenney wrote:
> On Tue, Nov 28, 2017 at 06:10:08PM +0100, Thomas Gleixner wrote:
> > On Tue, 28 Nov 2017, Paul E. McKenney wrote:
> > > On Tue, Nov 28, 2017 at 05:47:35PM +0100, Thomas Gleixner wrote:
> > > diff --git a/kernel/time/timer.c b/kernel/time/timer.c
> > > index db774b0f217e..a3321bb565db 100644
> > > --- a/kernel/time/timer.c
> > > +++ b/kernel/time/timer.c
> > > @@ -1803,7 +1803,7 @@ signed long __sched schedule_timeout(signed long timeout)
> > >  		idx = timer_get_idx(&timer.timer);
> > >  		idx_now = calc_wheel_index(j, base->clk);
> > >  		raw_spin_unlock_irqrestore(&base->lock, flags);
> > > -		pr_info("%s: Waylayed timer idx: %u idx_now: %u\n", __func__, idx, idx_now);
> > > +		pr_info("%s: Waylayed timer base->clk: %#lx jiffies: %#lx base->next_expiry: %#lx timer->flags: %#x timer->expires %#lx idx: %u idx_now: %u\n", __func__, base->clk, j, base->next_expiry, timer.timer.flags, timer.timer.expires, idx, idx_now);
> > 
> > Please print idx and idx_now as hex values. It's simpler to decode that way.
> 
> Here you go!  Starting tests at this end, focusing on TREE01 and TREE04.
> BTW, TREE04 doesn't do any CPU hotplug, providing a counterexample to
> my long-held assumption that this only happened in the presence of CPU
> hotplug operations.

And here is output with changes discussed on IRC.  TREE04 managed to
have not one but two overlapping RCU CPU stall warnings, one for RCU-bh
and the second for RCU-sched.  TREE04 and TREE04.  HZ=1000.

------------------------------------------------------------------------
TREE04
------------------------------------------------------------------------

[   28.336052] INFO: rcu_bh detected stalls on CPUs/tasks:
[   28.347354] 	1-...!: (14 ticks this GP) idle=c2a/1/4611686018427387904 softirq=0/0 fqs=3 last_accelerate: 0000/dad0, nonlazy_posted: 0, LD
[   28.349312] 	2-...!: (81 GPs behind) idle=892/1/4611686018427387904 softirq=0/0 fqs=3 last_accelerate: 0000/dad0, nonlazy_posted: 0, LD
[   28.351338] 	3-...!: (11 GPs behind) idle=31e/1/4611686018427387904 softirq=0/0 fqs=3 last_accelerate: 0000/dad0, nonlazy_posted: 0, LD
[   28.353177] 	4-...!: (81 GPs behind) idle=dd6/1/4611686018427387904 softirq=0/0 fqs=3 last_accelerate: 0000/dad0, nonlazy_posted: 0, LD
[   28.354966] 	5-...!: (81 GPs behind) idle=cbe/1/4611686018427387904 softirq=0/0 fqs=3 last_accelerate: 0000/dad0, nonlazy_posted: 0, LD
[   28.356866] 	7-...!: (81 GPs behind) idle=fa2/1/4611686018427387904 softirq=0/0 fqs=3 last_accelerate: 0000/dad0, nonlazy_posted: 0, LD
[   28.358698] 	(detected by 0, t=21002 jiffies, g=-219, c=-220, q=0)
[   28.359697] Sending NMI from CPU 0 to CPUs 1:
[   28.360694] NMI backtrace for cpu 1
[   28.360897] CPU: 1 PID: 771 Comm: rcu_torture_rea Not tainted 4.15.0-rc1+ #1
[   28.360899] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
[   28.360923] task: ffff95965de172c0 task.stack: ffffa09d80bcc000
[   28.361249] RIP: 0010:delay_tsc+0x30/0x50
[   28.361250] RSP: 0018:ffffa09d80bcfe50 EFLAGS: 00000206
[   28.361253] RAX: 000000100247c65a RBX: 000000000000000d RCX: 0000000000084130
[   28.361254] RDX: 0000001000000000 RSI: 00000010023f852a RDI: 00000000001e717e
[   28.361256] RBP: ffffa09d80bcfe90 R08: 0000000000000001 R09: 0000000000000101
[   28.361257] R10: 0000000000000000 R11: ffffa09d80bcfe58 R12: 0000000001b42b8a
[   28.361259] R13: ffffffffffffff24 R14: 00000006a7ca1638 R15: ffffffffffffff25
[   28.361261] FS:  0000000000000000(0000) GS:ffff95965fc40000(0000) knlGS:0000000000000000
[   28.361267] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   28.361269] CR2: 0000000008d98b40 CR3: 000000000820a000 CR4: 00000000000006e0
[   28.361269] Call Trace:
[   28.361604]  rcu_read_delay+0xab/0xf0
[   28.361809]  rcu_torture_reader+0x175/0x2e0
[   28.361837]  ? rcu_torture_reader+0x2e0/0x2e0
[   28.361864]  ? kthread+0xf0/0x130
[   28.361866]  kthread+0xf0/0x130
[   28.361938]  ? rcu_torture_timer_cb+0x10/0x10
[   28.361940]  ? kthread_destroy_worker+0x40/0x40
[   28.362012]  ? call_usermodehelper_exec_async+0x11c/0x120
[   28.362059]  ret_from_fork+0x1f/0x30
[   28.362106] Code: 03 10 5a 0f ae e8 0f 31 48 c1 e2 20 48 89 d6 48 09 c6 0f ae e8 0f 31 48 c1 e2 20 48 09 d0 48 89 c1 48 29 f1 48 39 cf 76 19 f3 90 <65> 8b 0d f9 02 10 5a 41 39 c8 74 db 48 29 c6 41 89 c8 48 01 f7 
[   28.362281] INFO: NMI handler (nmi_cpu_backtrace_handler) took too long to run: 1.540 msecs
[   28.362458] Sending NMI from CPU 0 to CPUs 2:
[   28.362489] NMI backtrace for cpu 2
[   28.362512] CPU: 2 PID: 775 Comm: rcu_torture_rea Not tainted 4.15.0-rc1+ #1
[   28.362513] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
[   28.362515] task: ffff95965e348000 task.stack: ffffa09d8151c000
[   28.362519] RIP: 0010:kthread_should_stop+0x0/0x30
[   28.362520] RSP: 0000:ffffa09d8151fe70 EFLAGS: 00000246
[   28.362523] RAX: 0000000000000001 RBX: ffffffffa7b79a60 RCX: 000000000000000a
[   28.362524] RDX: 0000000000000000 RSI: 00000000fffffe01 RDI: ffffffffa61d6272
[   28.362525] RBP: ffffa09d8151ff00 R08: 0000000000000002 R09: 0000000000000101
[   28.362527] R10: 0000000000000000 R11: ffffa09d8151fe58 R12: ffffffffffffff24
[   28.362528] R13: 0000000000000000 R14: 00000006aa8d6d83 R15: ffffffffffffff25
[   28.362530] FS:  0000000000000000(0000) GS:ffff95965fc80000(0000) knlGS:0000000000000000
[   28.362543] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   28.362548] CR2: 0000000000000000 CR3: 000000000820a000 CR4: 00000000000006e0
[   28.362549] Call Trace:
[   28.362585]  torture_must_stop+0x16/0x20
[   28.362607]  rcu_torture_reader+0xf4/0x2e0
[   28.362611]  ? rcu_torture_reader+0x2e0/0x2e0
[   28.362613]  ? kthread+0xf0/0x130
[   28.362615]  kthread+0xf0/0x130
[   28.362618]  ? rcu_torture_timer_cb+0x10/0x10
[   28.362620]  ? kthread_destroy_worker+0x40/0x40
[   28.362623]  ret_from_fork+0x1f/0x30
[   28.362625] Code: 90 66 2e 0f 1f 84 00 00 00 00 00 48 8b 4f 40 48 89 d0 be 00 10 00 00 48 c7 c2 e0 6b 1c a6 48 89 c7 e8 65 a8 89 00 48 98 c3 90 90 <65> 48 8b 04 25 00 c4 00 00 f6 40 4e 20 74 11 48 8b 80 b8 05 00 
[   28.363476] Sending NMI from CPU 0 to CPUs 3:
[   28.363509] NMI backtrace for cpu 3
[   28.363529] CPU: 3 PID: 774 Comm: rcu_torture_rea Not tainted 4.15.0-rc1+ #1
[   28.363530] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
[   28.363532] task: ffff95965e34f2c0 task.stack: ffffa09d81514000
[   28.363547] RIP: 0010:native_sched_clock+0x28/0x70
[   28.363548] RSP: 0000:ffffa09d81517e70 EFLAGS: 00000a47
[   28.363549] RAX: 033b0c542f257800 RBX: ffffffffa7b79a60 RCX: 0000000000000000
[   28.363550] RDX: 0000000000000004 RSI: 0000000040291878 RDI: 0000000000000001
[   28.363551] RBP: ffffa09d81517f00 R08: 0000000000000003 R09: 0000000000000101
[   28.363552] R10: 0000000000000000 R11: ffffa09d81517e58 R12: ffffffffffffff24
[   28.363553] R13: 0000000000000000 R14: 00000006aa9cf9f2 R15: ffffffffffffff25
[   28.363554] FS:  0000000000000000(0000) GS:ffff95965fcc0000(0000) knlGS:0000000000000000
[   28.363558] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   28.363559] CR2: 0000000000000000 CR3: 000000000820a000 CR4: 00000000000006e0
[   28.363561] Call Trace:
[   28.363582]  trace_clock_local+0x5/0x10
[   28.363598]  rcu_torture_reader+0x146/0x2e0
[   28.363602]  ? rcu_torture_reader+0x2e0/0x2e0
[   28.363605]  ? kthread+0xf0/0x130
[   28.363606]  kthread+0xf0/0x130
[   28.363608]  ? rcu_torture_timer_cb+0x10/0x10
[   28.363610]  ? kthread_destroy_worker+0x40/0x40
[   28.363616]  ret_from_fork+0x1f/0x30
[   28.363618] Code: 00 00 00 0f 1f 44 00 00 0f 31 48 c1 e2 20 48 09 c2 65 8b 0d cb 67 9f 5a 83 e1 01 48 c1 e1 04 65 8b b1 80 77 01 00 89 f0 48 f7 e2 <65> 48 8b b9 88 77 01 00 48 81 c1 80 77 01 00 65 8b 49 04 48 0f 
[   28.364496] Sending NMI from CPU 0 to CPUs 4:
[   28.364558] NMI backtrace for cpu 4
[   28.364580] CPU: 4 PID: 776 Comm: rcu_torture_rea Not tainted 4.15.0-rc1+ #1
[   28.364581] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
[   28.364583] task: ffff95965e349980 task.stack: ffffa09d81524000
[   28.364594] RIP: 0010:rcu_read_delay+0x21/0xf0
[   28.364595] RSP: 0000:ffffa09d81527e58 EFLAGS: 00000246
[   28.364596] RAX: 00000000000011b7 RBX: ffffffffa7b79a60 RCX: 00000000000aae60
[   28.364597] RDX: 000000000004121f RSI: 0000000000000001 RDI: ffffa09d81527e90
[   28.364598] RBP: ffffa09d81527e90 R08: 0000000000000004 R09: 0000000000000001
[   28.364599] R10: 0000000000000000 R11: 0000000000000000 R12: ffffffffffffff24
[   28.364600] R13: 0000000000000000 R14: 00000006aaac8262 R15: ffffffffffffff25
[   28.364602] FS:  0000000000000000(0000) GS:ffff95965fd00000(0000) knlGS:0000000000000000
[   28.364606] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   28.364607] CR2: 0000000000000000 CR3: 000000000820a000 CR4: 00000000000006e0
[   28.364608] Call Trace:
[   28.364615]  rcu_torture_reader+0x175/0x2e0
[   28.364618]  ? rcu_torture_reader+0x2e0/0x2e0
[   28.364622]  ? kthread+0xf0/0x130
[   28.364623]  kthread+0xf0/0x130
[   28.364625]  ? rcu_torture_timer_cb+0x10/0x10
[   28.364626]  ? kthread_destroy_worker+0x40/0x40
[   28.364633]  ret_from_fork+0x1f/0x30
[   28.364635] Code: 7c 0a ff ff e9 d4 fe ff ff 90 41 55 41 54 55 53 48 89 fd e8 d2 14 08 00 48 63 0d ff 5f 4d 02 31 d2 48 69 c9 a0 86 01 00 48 f7 f1 <48> 85 d2 74 4c 48 89 ef e8 b2 14 08 00 48 63 15 df 5f 4d 02 48 
[   28.365511] Sending NMI from CPU 0 to CPUs 5:
[   28.365568] NMI backtrace for cpu 5
[   28.365590] CPU: 5 PID: 777 Comm: rcu_torture_rea Not tainted 4.15.0-rc1+ #1
[   28.365591] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
[   28.365593] task: ffff95965e34b300 task.stack: ffffa09d8152c000
[   28.365600] RIP: 0010:delay_tsc+0x30/0x50
[   28.365601] RSP: 0000:ffffa09d8152fe50 EFLAGS: 00000206
[   28.365604] RAX: 0000001002e258ec RBX: 0000000000000030 RCX: 00000000001b1080
[   28.365605] RDX: 0000001000000000 RSI: 0000001002c7486c RDI: 00000000001e713d
[   28.365606] RBP: ffffa09d8152fe90 R08: 0000000000000005 R09: 0000000000000101
[   28.365608] R10: 0000000000000000 R11: ffffa09d8152fe58 R12: 0000000001b4e144
[   28.365609] R13: ffffffffffffff24 R14: 00000006aa8ff1b1 R15: ffffffffffffff25
[   28.365611] FS:  0000000000000000(0000) GS:ffff95965fd40000(0000) knlGS:0000000000000000
[   28.365616] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   28.365617] CR2: 0000000000000000 CR3: 000000000820a000 CR4: 00000000000006e0
[   28.365618] Call Trace:
[   28.365626]  rcu_read_delay+0xab/0xf0
[   28.365631]  rcu_torture_reader+0x175/0x2e0
[   28.365634]  ? rcu_torture_reader+0x2e0/0x2e0
[   28.365638]  ? kthread+0xf0/0x130
[   28.365640]  kthread+0xf0/0x130
[   28.365643]  ? rcu_torture_timer_cb+0x10/0x10
[   28.365645]  ? kthread_destroy_worker+0x40/0x40
[   28.365650]  ret_from_fork+0x1f/0x30
[   28.365652] Code: 03 10 5a 0f ae e8 0f 31 48 c1 e2 20 48 89 d6 48 09 c6 0f ae e8 0f 31 48 c1 e2 20 48 09 d0 48 89 c1 48 29 f1 48 39 cf 76 19 f3 90 <65> 8b 0d f9 02 10 5a 41 39 c8 74 db 48 29 c6 41 89 c8 48 01 f7 
[   28.366528] Sending NMI from CPU 0 to CPUs 7:
[   28.366582] NMI backtrace for cpu 7
[   28.366606] CPU: 7 PID: 773 Comm: rcu_torture_rea Not tainted 4.15.0-rc1+ #1
[   28.366607] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
[   28.366609] task: ffff95965e34a640 task.stack: ffffa09d8150c000
[   28.366613] RIP: 0010:delay_tsc+0x1a/0x50
[   28.366615] RSP: 0000:ffffa09d8150fe50 EFLAGS: 00000246
[   28.366617] RAX: 0000001003014a92 RBX: ffffffffa7b79a60 RCX: 0000000000000007
[   28.366618] RDX: 0000001000000000 RSI: 0000001002fe3cda RDI: 000000000006169a
[   28.366619] RBP: ffffa09d8150fe90 R08: 0000000000000007 R09: 0000000000000001
[   28.366621] R10: 0000000000000000 R11: 0000000000000002 R12: ffffffffffffff24
[   28.366622] R13: 0000000000000000 R14: 00000006aaca0452 R15: ffffffffffffff25
[   28.366624] FS:  0000000000000000(0000) GS:ffff95965fdc0000(0000) knlGS:0000000000000000
[   28.366629] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   28.366630] CR2: 0000000000000000 CR3: 000000000820a000 CR4: 00000000000006e0
[   28.366631] Call Trace:
[   28.366635]  rcu_read_delay+0xe8/0xf0
[   28.366639]  rcu_torture_reader+0x175/0x2e0
[   28.366642]  ? rcu_torture_reader+0x2e0/0x2e0
[   28.366644]  ? kthread+0xf0/0x130
[   28.366646]  kthread+0xf0/0x130
[   28.366648]  ? rcu_torture_timer_cb+0x10/0x10
[   28.366651]  ? kthread_destroy_worker+0x40/0x40
[   28.366654]  ret_from_fork+0x1f/0x30
[   28.366655] Code: 00 00 00 f7 e2 48 8d 7a 01 ff 25 e2 80 5f 00 66 90 65 44 8b 05 28 03 10 5a 0f ae e8 0f 31 48 c1 e2 20 48 89 d6 48 09 c6 0f ae e8 <0f> 31 48 c1 e2 20 48 09 d0 48 89 c1 48 29 f1 48 39 cf 76 19 f3 
[   28.367562] rcu_bh kthread starved for 21016 jiffies! g18446744073709551397 c18446744073709551396 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x402 ->cpu=1
[   28.367567] rcu_bh          I15008     9      2 0x80080000
[   28.367589] Call Trace:
[   28.367606]  ? __schedule+0x316/0x6b0
[   28.367607]  schedule+0x2d/0x80
[   28.367610]  schedule_timeout+0x159/0x3f0
[   28.367625]  ? __next_timer_interrupt+0xc0/0xc0
[   28.367629]  rcu_gp_kthread+0x627/0xd90
[   28.367646]  ? migrate_swap_stop+0x160/0x180
[   28.367649]  kthread+0xf0/0x130
[   28.367655]  ? rcu_barrier_sched+0x10/0x10
[   28.367657]  ? kthread_destroy_worker+0x40/0x40
[   28.367659]  ret_from_fork+0x1f/0x30
[   28.567094] schedule_timeout: Waylayed timer base->clk: 0xfffb88d4 jiffies: 0xfffbdbb7 base->next_expiry: 0xfffb88d4 timer->flags: 0x5800001 timer->expires 0xfffb88d5 idx: 16 idx_now: ee base->pending_map           500000 400000000000000   1000000000000              40               0               2               0               0               0
[   30.330055] INFO: rcu_sched detected stalls on CPUs/tasks:
[   30.331770] 	1-...!: (88 GPs behind) idle=c36/1/4611686018427387904 softirq=0/0 fqs=0 last_accelerate: 0000/e29a, nonlazy_posted: 0, LD
[   30.335218] 	4-...!: (88 GPs behind) idle=de2/1/4611686018427387904 softirq=0/0 fqs=0 last_accelerate: 0000/e29a, nonlazy_posted: 0, LD
[   30.337537] 	5-...!: (88 GPs behind) idle=cca/1/4611686018427387904 softirq=0/0 fqs=0 last_accelerate: 0000/e29a, nonlazy_posted: 0, LD
[   30.339869] 	7-...!: (0 ticks this GP) idle=fae/1/4611686018427387904 softirq=0/0 fqs=0 last_accelerate: 0000/e29a, nonlazy_posted: 0, LD
[   30.342199] 	(detected by 0, t=21002 jiffies, g=-212, c=-213, q=80)
[   30.343442] Sending NMI from CPU 0 to CPUs 1:
[   30.344302] NMI backtrace for cpu 1
[   30.344328] CPU: 1 PID: 771 Comm: rcu_torture_rea Not tainted 4.15.0-rc1+ #1
[   30.344329] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
[   30.344331] task: ffff95965de172c0 task.stack: ffffa09d80bcc000
[   30.344347] RIP: 0010:torture_random+0x0/0x50
[   30.344348] RSP: 0018:ffffa09d80bcfe50 EFLAGS: 00000202
[   30.344351] RAX: 0000000000000e40 RBX: ffffffffa7b79a60 RCX: 00000000000aae60
[   30.344352] RDX: 000000000006afb0 RSI: 0000000000000001 RDI: ffffa09d80bcfe90
[   30.344353] RBP: ffffa09d80bcfe90 R08: 0000000000000001 R09: 0000000000000101
[   30.344355] R10: 0000000000000000 R11: ffffa09d80bcfe58 R12: ffffffffffffff27
[   30.344356] R13: 0000000000000000 R14: 0000000720ada1cc R15: ffffffffffffff27
[   30.344358] FS:  0000000000000000(0000) GS:ffff95965fc40000(0000) knlGS:0000000000000000
[   30.344364] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   30.344365] CR2: 0000000008d98b40 CR3: 000000000820a000 CR4: 00000000000006e0
[   30.344366] Call Trace:
[   30.344381]  rcu_read_delay+0x2e/0xf0
[   30.344387]  rcu_torture_reader+0x175/0x2e0
[   30.344390]  ? rcu_torture_reader+0x2e0/0x2e0
[   30.344395]  ? kthread+0xf0/0x130
[   30.344396]  kthread+0xf0/0x130
[   30.344399]  ? rcu_torture_timer_cb+0x10/0x10
[   30.344401]  ? kthread_destroy_worker+0x40/0x40
[   30.344407]  ? call_usermodehelper_exec_async+0x11c/0x120
[   30.344416]  ret_from_fork+0x1f/0x30
[   30.344418] Code: 00 66 2e 0f 1f 84 00 00 00 00 00 31 c0 c3 0f 1f 00 66 2e 0f 1f 84 00 00 00 00 00 8b 05 4a e0 d2 00 85 c0 0f 95 c0 c3 0f 1f 40 00 <48> 83 6f 08 01 78 14 48 69 07 01 15 61 02 48 05 65 fc 8c 1c 48 
[   30.345302] Sending NMI from CPU 0 to CPUs 4:
[   30.345329] NMI backtrace for cpu 4
[   30.345359] CPU: 4 PID: 776 Comm: rcu_torture_rea Not tainted 4.15.0-rc1+ #1
[   30.345361] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
[   30.345364] task: ffff95965e349980 task.stack: ffffa09d81524000
[   30.345375] RIP: 0010:rcu_torture_reader+0xc5/0x2e0
[   30.345376] RSP: 0000:ffffa09d81527e80 EFLAGS: 00000213
[   30.345379] RAX: 0000000000000001 RBX: ffffffffa7b79a60 RCX: 000000000000000a
[   30.345380] RDX: ffffffffa64462c0 RSI: 0000000000000001 RDI: ffffa09d81527e90
[   30.345382] RBP: ffffa09d81527f00 R08: 0000000000000004 R09: ffff95965fd1a040
[   30.345383] R10: 0000000000000000 R11: 0000000000000000 R12: ffffffffffffff27
[   30.345384] R13: 0000000000000000 R14: 0000000720bd3427 R15: ffffffffffffff27
[   30.345386] FS:  0000000000000000(0000) GS:ffff95965fd00000(0000) knlGS:0000000000000000
[   30.345392] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   30.345393] CR2: 0000000000000000 CR3: 000000000820a000 CR4: 00000000000006e0
[   30.345445] Call Trace:
[   30.345455]  ? rcu_torture_reader+0x2e0/0x2e0
[   30.345459]  ? kthread+0xf0/0x130
[   30.345461]  kthread+0xf0/0x130
[   30.345464]  ? rcu_torture_timer_cb+0x10/0x10
[   30.345466]  ? kthread_destroy_worker+0x40/0x40
[   30.345473]  ret_from_fork+0x1f/0x30
[   30.345476] Code: f8 00 00 00 48 8b 15 53 51 4d 02 4c 89 e0 4d 63 d5 4c 29 f8 b9 0a 00 00 00 65 4a ff 04 d5 20 0f 01 00 48 83 7a 30 01 48 83 d8 ff <48> 83 f8 0a 48 0f 47 c1 65 48 ff 04 c5 c0 0e 01 00 48 8b 05 1b 
[   30.346316] Sending NMI from CPU 0 to CPUs 5:
[   30.346336] NMI backtrace for cpu 5
[   30.346358] CPU: 5 PID: 777 Comm: rcu_torture_rea Not tainted 4.15.0-rc1+ #1
[   30.346359] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
[   30.346361] task: ffff95965e34b300 task.stack: ffffa09d8152c000
[   30.346369] RIP: 0010:delay_tsc+0x30/0x50
[   30.346371] RSP: 0000:ffffa09d8152fe50 EFLAGS: 00000202
[   30.346373] RAX: 00000010ee6c68c7 RBX: 000000000000001e RCX: 0000000000191a4c
[   30.346374] RDX: 0000001000000000 RSI: 00000010ee534e7b RDI: 00000000001e713d
[   30.346376] RBP: ffffa09d8152fe90 R08: 0000000000000005 R09: 0000000000000001
[   30.346377] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000001d2d4b3
[   30.346378] R13: ffffffffffffff27 R14: 000000071f8edc6b R15: ffffffffffffff27
[   30.346380] FS:  0000000000000000(0000) GS:ffff95965fd40000(0000) knlGS:0000000000000000
[   30.346385] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   30.346386] CR2: 0000000000000000 CR3: 000000000820a000 CR4: 00000000000006e0
[   30.346387] Call Trace:
[   30.346392]  rcu_read_delay+0xab/0xf0
[   30.346395]  rcu_torture_reader+0x175/0x2e0
[   30.346398]  ? rcu_torture_reader+0x2e0/0x2e0
[   30.346400]  ? kthread+0xf0/0x130
[   30.346402]  kthread+0xf0/0x130
[   30.346404]  ? rcu_torture_timer_cb+0x10/0x10
[   30.346406]  ? kthread_destroy_worker+0x40/0x40
[   30.346409]  ret_from_fork+0x1f/0x30
[   30.346410] Code: 03 10 5a 0f ae e8 0f 31 48 c1 e2 20 48 89 d6 48 09 c6 0f ae e8 0f 31 48 c1 e2 20 48 09 d0 48 89 c1 48 29 f1 48 39 cf 76 19 f3 90 <65> 8b 0d f9 02 10 5a 41 39 c8 74 db 48 29 c6 41 89 c8 48 01 f7 
[   30.347331] Sending NMI from CPU 0 to CPUs 7:
[   30.347360] NMI backtrace for cpu 7
[   30.347389] CPU: 7 PID: 773 Comm: rcu_torture_rea Not tainted 4.15.0-rc1+ #1
[   30.347391] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
[   30.347393] task: ffff95965e34a640 task.stack: ffffa09d8150c000
[   30.347403] RIP: 0010:delay_tsc+0x30/0x50
[   30.347405] RSP: 0000:ffffa09d8150fe50 EFLAGS: 00000216
[   30.347407] RAX: 00000010ee8b5168 RBX: 0000000000000022 RCX: 0000000000074d6c
[   30.347408] RDX: 0000001000000000 RSI: 00000010ee8403fc RDI: 00000000001e7101
[   30.347409] RBP: ffffa09d8150fe90 R08: 0000000000000007 R09: 0000000000000001
[   30.347410] R10: 0000000000000000 R11: 0000000000000010 R12: 0000000001d2ea95
[   30.347412] R13: ffffffffffffff27 R14: 000000071fe45867 R15: ffffffffffffff27
[   30.347414] FS:  0000000000000000(0000) GS:ffff95965fdc0000(0000) knlGS:0000000000000000
[   30.347419] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   30.347421] CR2: 0000000000000000 CR3: 000000000820a000 CR4: 00000000000006e0
[   30.347422] Call Trace:
[   30.347432]  rcu_read_delay+0xab/0xf0
[   30.347436]  rcu_torture_reader+0x175/0x2e0
[   30.347440]  ? rcu_torture_reader+0x2e0/0x2e0
[   30.347444]  ? kthread+0xf0/0x130
[   30.347445]  kthread+0xf0/0x130
[   30.347448]  ? rcu_torture_timer_cb+0x10/0x10
[   30.347451]  ? kthread_destroy_worker+0x40/0x40
[   30.347456]  ret_from_fork+0x1f/0x30
[   30.347459] Code: 03 10 5a 0f ae e8 0f 31 48 c1 e2 20 48 89 d6 48 09 c6 0f ae e8 0f 31 48 c1 e2 20 48 09 d0 48 89 c1 48 29 f1 48 39 cf 76 19 f3 90 <65> 8b 0d f9 02 10 5a 41 39 c8 74 db 48 29 c6 41 89 c8 48 01 f7 
[   30.348367] rcu_sched kthread starved for 21002 jiffies! g18446744073709551404 c18446744073709551403 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x402 ->cpu=7
[   30.348370] rcu_sched       I15008     8      2 0x80080000
[   30.348398] Call Trace:
[   30.348405]  ? __schedule+0x316/0x6b0
[   30.348410]  schedule+0x2d/0x80
[   30.348414]  schedule_timeout+0x159/0x3f0
[   30.348422]  ? __next_timer_interrupt+0xc0/0xc0
[   30.348428]  rcu_gp_kthread+0x627/0xd90
[   30.348436]  ? migrate_swap_stop+0x161/0x180
[   30.348439]  kthread+0xf0/0x130
[   30.348444]  ? rcu_barrier_sched+0x10/0x10
[   30.348446]  ? kthread_destroy_worker+0x40/0x40
[   30.348448]  ret_from_fork+0x1f/0x30
[   30.371242] schedule_timeout: Waylayed timer base->clk: 0xfffb884b jiffies: 0xfffbe2c3 base->next_expiry: 0xfffb884a timer->flags: 0x20c00007 timer->expires 0xfffb9093 idx: 83 idx_now: f2 base->pending_map             1000               0   1020000000008    800000000000               0               2               0               0               0
[   30.600337] clocksource: timekeeping watchdog on CPU1: Marking clocksource 'tsc' as unstable because the skew is too large:

And the qemu command is as follows:

qemu-system-x86_64 -enable-kvm -nographic -smp 8 -serial file:/home/paulmck/public_git/linux-rcu/tools/testing/selftests/rcutorture/res/2017.11.28-11:58:02/TREE04/console.log -m 512 -kernel /home/paulmck/public_git/linux-rcu/tools/testing/selftests/rcutorture/res/2017.11.28-11:58:02/TREE04/bzImage -append "noapic selinux=0 initcall_debug debug console=ttyS0 rcutorture.torture_type=rcu_bh rcutree.rcu_fanout_leaf=4 rcutorture.n_barrier_cbs=4 rcutorture.stat_interval=15 rcutorture.shutdown_secs=1800 rcutorture.test_no_idle_hz=1 rcutorture.verbose=1"

You will of course want to adjust the -serial and -kernel parameters.

------------------------------------------------------------------------
TREE04.2
------------------------------------------------------------------------

[   27.630095] INFO: rcu_bh detected stalls on CPUs/tasks:
[   27.632352] 	1-...!: (20 GPs behind) idle=fc6/1/4611686018427387904 softirq=0/0 fqs=2 last_accelerate: 0000/d80e, nonlazy_posted: 0, LD
[   27.634299] 	3-...!: (121 GPs behind) idle=c32/1/4611686018427387904 softirq=0/0 fqs=2 last_accelerate: 0000/d80e, nonlazy_posted: 0, LD
[   27.636244] 	4-...!: (121 GPs behind) idle=c92/1/4611686018427387904 softirq=0/0 fqs=2 last_accelerate: 0000/d80e, nonlazy_posted: 0, LD
[   27.638271] 	6-...!: (54 GPs behind) idle=93e/1/4611686018427387904 softirq=0/0 fqs=2 last_accelerate: 0000/d80e, nonlazy_posted: 0, LD
[   27.640210] 	(detected by 0, t=21002 jiffies, g=-179, c=-180, q=0)
[   27.641179] Sending NMI from CPU 0 to CPUs 1:
[   27.641926] NMI backtrace for cpu 1
[   27.641946] CPU: 1 PID: 769 Comm: rcu_torture_rea Not tainted 4.15.0-rc1+ #1
[   27.641947] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
[   27.641949] task: ffff96c7dde2b300 task.stack: ffffaa3180d7c000
[   27.641961] RIP: 0010:delay_tsc+0x30/0x50
[   27.641962] RSP: 0000:ffffaa3180d7fe50 EFLAGS: 00000216
[   27.641963] RAX: 0000000f94f40c86 RBX: ffffffffb3979a90 RCX: 000000000004bc7e
[   27.641964] RDX: 0000000f00000000 RSI: 0000000f94ef5008 RDI: 000000000006171a
[   27.641965] RBP: ffffaa3180d7fe90 R08: 0000000000000001 R09: ffff96c7dfc5a040
[   27.641966] R10: 0000000000000000 R11: ffffaa3180d7fe58 R12: ffffffffffffff4c
[   27.641967] R13: 0000000000000000 R14: 000000067f2f5cf8 R15: ffffffffffffff4d
[   27.641968] FS:  0000000000000000(0000) GS:ffff96c7dfc40000(0000) knlGS:0000000000000000
[   27.641973] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   27.641974] CR2: ffffaa31802f0000 CR3: 000000001780a000 CR4: 00000000000006e0
[   27.641975] Call Trace:
[   27.641995]  rcu_read_delay+0xe8/0xf0
[   27.641999]  rcu_torture_reader+0x175/0x2e0
[   27.642001]  ? rcu_torture_reader+0x2e0/0x2e0
[   27.642005]  ? kthread+0xf0/0x130
[   27.642007]  kthread+0xf0/0x130
[   27.642009]  ? rcu_torture_timer_cb+0x10/0x10
[   27.642010]  ? kthread_destroy_worker+0x40/0x40
[   27.642016]  ? call_usermodehelper_exec_async+0x11c/0x120
[   27.642023]  ret_from_fork+0x1f/0x30
[   27.642025] Code: 03 30 4e 0f ae e8 0f 31 48 c1 e2 20 48 89 d6 48 09 c6 0f ae e8 0f 31 48 c1 e2 20 48 09 d0 48 89 c1 48 29 f1 48 39 cf 76 19 f3 90 <65> 8b 0d f9 02 30 4e 41 39 c8 74 db 48 29 c6 41 89 c8 48 01 f7 
[   27.642920] Sending NMI from CPU 0 to CPUs 3:
[   27.642939] NMI backtrace for cpu 3
[   27.642956] CPU: 3 PID: 775 Comm: rcu_torture_rea Not tainted 4.15.0-rc1+ #1
[   27.642956] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
[   27.642958] task: ffff96c7dde20000 task.stack: ffffaa3180d94000
[   27.642962] RIP: 0010:delay_tsc+0x30/0x50
[   27.642962] RSP: 0018:ffffaa3180d97e50 EFLAGS: 00000216
[   27.642964] RAX: 0000000f9513283c RBX: 000000000000000e RCX: 00000000001c6e1e
[   27.642965] RDX: 0000000f00000000 RSI: 0000000f94f6ba1e RDI: 00000000001e8454
[   27.642966] RBP: ffffaa3180d97e90 R08: 0000000000000003 R09: 0000000000000001
[   27.642967] R10: 0000000000000000 R11: 0000000000000282 R12: 0000000001a93a71
[   27.642968] R13: ffffffffffffff4c R14: 000000067d0c49dd R15: ffffffffffffff4d
[   27.642969] FS:  0000000000000000(0000) GS:ffff96c7dfcc0000(0000) knlGS:0000000000000000
[   27.642973] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   27.642974] CR2: 0000000008382b40 CR3: 000000001df34000 CR4: 00000000000006e0
[   27.642974] Call Trace:
[   27.642978]  rcu_read_delay+0xab/0xf0
[   27.642980]  rcu_torture_reader+0x175/0x2e0
[   27.642982]  ? rcu_torture_reader+0x2e0/0x2e0
[   27.642984]  ? kthread+0xf0/0x130
[   27.642985]  kthread+0xf0/0x130
[   27.642987]  ? rcu_torture_timer_cb+0x10/0x10
[   27.642988]  ? kthread_destroy_worker+0x40/0x40
[   27.642991]  ? call_usermodehelper_exec_async+0x11c/0x120
[   27.642993]  ret_from_fork+0x1f/0x30
[   27.642994] Code: 03 30 4e 0f ae e8 0f 31 48 c1 e2 20 48 89 d6 48 09 c6 0f ae e8 0f 31 48 c1 e2 20 48 09 d0 48 89 c1 48 29 f1 48 39 cf 76 19 f3 90 <65> 8b 0d f9 02 30 4e 41 39 c8 74 db 48 29 c6 41 89 c8 48 01 f7 
[   27.643940] Sending NMI from CPU 0 to CPUs 4:
[   27.643962] NMI backtrace for cpu 4
[   27.643983] CPU: 4 PID: 770 Comm: rcu_torture_rea Not tainted 4.15.0-rc1+ #1
[   27.643984] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
[   27.643986] task: ffff96c7dde2bfc0 task.stack: ffffaa318151c000
[   27.643994] RIP: 0010:rcu_read_delay+0x46/0xf0
[   27.643995] RSP: 0018:ffffaa318151fe58 EFLAGS: 00000206
[   27.643997] RAX: 000000000014888f RBX: ffffffffb3979a90 RCX: 0000000000000af0
[   27.643998] RDX: 00000000000006fb RSI: 0000000000000001 RDI: ffffaa318151fe90
[   27.643999] RBP: ffffaa318151fe90 R08: 0000000000000004 R09: ffff96c7dfd1a040
[   27.644000] R10: 0000000000000000 R11: ffffaa318151fe58 R12: ffffffffffffff4c
[   27.644001] R13: 0000000000000000 R14: 000000067f50d977 R15: ffffffffffffff4d
[   27.644003] FS:  0000000000000000(0000) GS:ffff96c7dfd00000(0000) knlGS:0000000000000000
[   27.644007] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   27.644008] CR2: 00000000f7dbdf80 CR3: 000000001780a000 CR4: 00000000000006e0
[   27.644009] Call Trace:
[   27.644015]  rcu_torture_reader+0x175/0x2e0
[   27.644018]  ? rcu_torture_reader+0x2e0/0x2e0
[   27.644021]  ? kthread+0xf0/0x130
[   27.644022]  kthread+0xf0/0x130
[   27.644024]  ? rcu_torture_timer_cb+0x10/0x10
[   27.644025]  ? kthread_destroy_worker+0x40/0x40
[   27.644031]  ret_from_fork+0x1f/0x30
[   27.644032] Code: 86 01 00 48 f7 f1 48 85 d2 74 4c 48 89 ef e8 b2 14 08 00 48 63 15 df 5f 4d 02 48 8d 14 92 48 8d 0c 92 31 d2 48 c1 e1 04 48 f7 f1 <48> 85 d2 0f 84 8f 00 00 00 65 8b 05 ba 77 b6 4e a9 ff ff ff 7f 
[   27.644955] Sending NMI from CPU 0 to CPUs 6:
[   27.644973] NMI backtrace for cpu 6
[   27.644990] CPU: 6 PID: 773 Comm: rcu_torture_rea Not tainted 4.15.0-rc1+ #1
[   27.644990] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
[   27.644992] task: ffff96c7debc2640 task.stack: ffffaa318152c000
[   27.644995] RIP: 0010:delay_tsc+0x1c/0x50
[   27.644996] RSP: 0000:ffffaa318152fe50 EFLAGS: 00000246
[   27.644998] RAX: 0000000095510f68 RBX: ffffffffb3979a90 RCX: 0000000000000006
[   27.644999] RDX: 000000000000000f RSI: 0000000f954b5738 RDI: 0000000000061754
[   27.644999] RBP: ffffaa318152fe90 R08: 0000000000000006 R09: 0000000000000001
[   27.645000] R10: 0000000000000000 R11: ffffaa318152fe58 R12: ffffffffffffff4c
[   27.645001] R13: 0000000000000000 R14: 000000067f5d7e21 R15: ffffffffffffff4d
[   27.645003] FS:  0000000000000000(0000) GS:ffff96c7dfd80000(0000) knlGS:0000000000000000
[   27.645006] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   27.645007] CR2: 0000000000000000 CR3: 000000001780a000 CR4: 00000000000006e0
[   27.645007] Call Trace:
[   27.645010]  rcu_read_delay+0xe8/0xf0
[   27.645012]  rcu_torture_reader+0x175/0x2e0
[   27.645014]  ? rcu_torture_reader+0x2e0/0x2e0
[   27.645016]  ? kthread+0xf0/0x130
[   27.645017]  kthread+0xf0/0x130
[   27.645019]  ? rcu_torture_timer_cb+0x10/0x10
[   27.645020]  ? kthread_destroy_worker+0x40/0x40
[   27.645022]  ret_from_fork+0x1f/0x30
[   27.645023] Code: 00 f7 e2 48 8d 7a 01 ff 25 e2 80 5f 00 66 90 65 44 8b 05 28 03 30 4e 0f ae e8 0f 31 48 c1 e2 20 48 89 d6 48 09 c6 0f ae e8 0f 31 <48> c1 e2 20 48 09 d0 48 89 c1 48 29 f1 48 39 cf 76 19 f3 90 65 
[   27.645975] rcu_bh kthread starved for 20835 jiffies! g18446744073709551437 c18446744073709551436 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x402 ->cpu=2
[   27.645988] rcu_bh          I15008     9      2 0x80080000
[   27.646000] Call Trace:
[   27.646011]  ? __schedule+0x316/0x6b0
[   27.646013]  schedule+0x2d/0x80
[   27.646017]  schedule_timeout+0x159/0x3f0
[   27.646025]  ? __next_timer_interrupt+0xc0/0xc0
[   27.646029]  rcu_gp_kthread+0x627/0xd90
[   27.646036]  ? migrate_swap_stop+0x160/0x180
[   27.646039]  kthread+0xf0/0x130
[   27.646041]  ? rcu_barrier_sched+0x10/0x10
[   27.646043]  ? kthread_destroy_worker+0x40/0x40
[   27.646048]  ret_from_fork+0x1f/0x30
[   27.646111] schedule_timeout: Waylayed timer base->clk: 0xfffb86af jiffies: 0xfffbd81e base->next_expiry: 0xfffb86af timer->flags: 0xbc00002 timer->expires 0xfffb86ae idx: 2f idx_now: ed base->pending_map     800000000000       100000000     10000000000               0          200040               2               0               0               0
[   33.898125] INFO: rcu_sched detected stalls on CPUs/tasks:
[   33.899348] 	1-...!: (47 GPs behind) idle=01a/1/4611686018427387904 softirq=0/0 fqs=0 last_accelerate: 0000/f08a, nonlazy_posted: 0, LD
[   33.901444] 	2-...!: (15 GPs behind) idle=b3a/1/4611686018427387904 softirq=0/0 fqs=0 last_accelerate: 0000/f08a, nonlazy_posted: 0, LD
[   33.903620] 	4-...!: (42 GPs behind) idle=ce6/1/4611686018427387904 softirq=0/0 fqs=0 last_accelerate: 0000/f08a, nonlazy_posted: 0, LD
[   33.905677] 	5-...!: (0 ticks this GP) idle=bbe/1/4611686018427387904 softirq=0/0 fqs=0 last_accelerate: 0000/f08a, nonlazy_posted: 0, LD
[   33.907820] 	6-...!: (24 ticks this GP) idle=992/1/4611686018427387904 softirq=1/1 fqs=0 last_accelerate: 0000/f08a, nonlazy_posted: 0, LD
[   33.909911] 	7-...!: (36 ticks this GP) idle=176/1/4611686018427387904 softirq=2/2 fqs=0 last_accelerate: 0000/f08a, nonlazy_posted: 0, LD
[   33.912077] 	(detected by 0, t=21002 jiffies, g=-213, c=-214, q=34)
[   33.913168] Sending NMI from CPU 0 to CPUs 1:
[   33.913923] NMI backtrace for cpu 1
[   33.913944] CPU: 1 PID: 769 Comm: rcu_torture_rea Not tainted 4.15.0-rc1+ #1
[   33.913945] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
[   33.913947] task: ffff96c7dde2b300 task.stack: ffffaa3180d7c000
[   33.913954] RIP: 0010:__local_bh_enable_ip+0x28/0x50
[   33.913955] RSP: 0000:ffffaa3180d7fe78 EFLAGS: 00000246
[   33.913957] RAX: 0000000000000000 RBX: ffffffffb3979a90 RCX: 000000000000000a
[   33.913958] RDX: ffffffffb22462c0 RSI: 00000000fffffe01 RDI: ffffffffb14a58e0
[   33.913958] RBP: ffffaa3180d7ff00 R08: 0000000000000001 R09: 0000000000000001
[   33.913959] R10: 0000000000000000 R11: ffffaa3180d7fe00 R12: ffffffffffffff62
[   33.913960] R13: 0000000000000000 R14: 00000007f508d9b1 R15: ffffffffffffff62
[   33.913961] FS:  0000000000000000(0000) GS:ffff96c7dfc40000(0000) knlGS:0000000000000000
[   33.913966] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   33.913967] CR2: ffffaa31802f0000 CR3: 000000001780a000 CR4: 00000000000006e0
[   33.913968] Call Trace:
[   33.913977]  rcu_torture_reader+0xe3/0x2e0
[   33.913980]  ? rcu_torture_reader+0x2e0/0x2e0
[   33.913984]  ? kthread+0xf0/0x130
[   33.913985]  kthread+0xf0/0x130
[   33.913987]  ? rcu_torture_timer_cb+0x10/0x10
[   33.913988]  ? kthread_destroy_worker+0x40/0x40
[   33.913992]  ? call_usermodehelper_exec_async+0x11c/0x120
[   33.913998]  ret_from_fork+0x1f/0x30
[   33.914000] Code: c3 66 90 83 ee 01 65 8b 05 36 3b bb 4e f7 de a9 00 00 0f 00 75 1d 65 01 35 26 3b bb 4e 65 8b 05 1f 3b bb 4e a9 00 ff 1f 00 74 0c <65> ff 0d 11 3b bb 4e c3 0f ff eb df 65 8b 05 75 ee bb 4e 85 c0 
[   33.914918] Sending NMI from CPU 0 to CPUs 2:
[   33.914936] NMI backtrace for cpu 2
[   33.914953] CPU: 2 PID: 771 Comm: rcu_torture_rea Not tainted 4.15.0-rc1+ #1
[   33.914954] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
[   33.914955] task: ffff96c7de184c80 task.stack: ffffaa318149c000
[   33.914962] RIP: 0010:__local_bh_enable_ip+0x28/0x50
[   33.914963] RSP: 0000:ffffaa318149fe78 EFLAGS: 00000246
[   33.914964] RAX: 0000000000000000 RBX: ffffffffb3979a90 RCX: 000000000000000a
[   33.914965] RDX: ffffffffb22462c0 RSI: 00000000fffffe01 RDI: ffffffffb14a58e0
[   33.914966] RBP: ffffaa318149ff00 R08: 0000000000000002 R09: 0000000000000001
[   33.914967] R10: 0000000000000000 R11: 0000000000000000 R12: ffffffffffffff62
[   33.914968] R13: 0000000000000000 R14: 00000007f5186150 R15: ffffffffffffff62
[   33.914970] FS:  0000000000000000(0000) GS:ffff96c7dfc80000(0000) knlGS:0000000000000000
[   33.914974] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   33.914975] CR2: 0000000000000000 CR3: 000000001780a000 CR4: 00000000000006e0
[   33.914976] Call Trace:
[   33.914985]  rcu_torture_reader+0xe3/0x2e0
[   33.914988]  ? rcu_torture_reader+0x2e0/0x2e0
[   33.914992]  ? kthread+0xf0/0x130
[   33.914993]  kthread+0xf0/0x130
[   33.914995]  ? rcu_torture_timer_cb+0x10/0x10
[   33.914996]  ? kthread_destroy_worker+0x40/0x40
[   33.915000]  ? call_usermodehelper_exec_async+0x11c/0x120
[   33.915006]  ret_from_fork+0x1f/0x30
[   33.915007] Code: c3 66 90 83 ee 01 65 8b 05 36 3b bb 4e f7 de a9 00 00 0f 00 75 1d 65 01 35 26 3b bb 4e 65 8b 05 1f 3b bb 4e a9 00 ff 1f 00 74 0c <65> ff 0d 11 3b bb 4e c3 0f ff eb df 65 8b 05 75 ee bb 4e 85 c0 
[   33.915934] Sending NMI from CPU 0 to CPUs 4:
[   33.915956] NMI backtrace for cpu 4
[   33.915977] CPU: 4 PID: 770 Comm: rcu_torture_rea Not tainted 4.15.0-rc1+ #1
[   33.915978] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
[   33.915980] task: ffff96c7dde2bfc0 task.stack: ffffaa318151c000
[   33.915990] RIP: 0010:delay_tsc+0x30/0x50
[   33.915990] RSP: 0018:ffffaa318151fe50 EFLAGS: 00000216
[   33.915992] RAX: 000000127f0117e3 RBX: 0000000000000013 RCX: 00000000000556dc
[   33.915993] RDX: 0000001200000000 RSI: 000000127efbc107 RDI: 00000000001e73d2
[   33.915994] RBP: ffffaa318151fe90 R08: 0000000000000004 R09: ffff96c7dfd1a040
[   33.915995] R10: 0000000000000000 R11: ffffaa318151fe58 R12: 000000000209089c
[   33.915996] R13: ffffffffffffff62 R14: 00000007f349a167 R15: ffffffffffffff62
[   33.915998] FS:  0000000000000000(0000) GS:ffff96c7dfd00000(0000) knlGS:0000000000000000
[   33.916002] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   33.916003] CR2: 00000000f7dbdf80 CR3: 000000001780a000 CR4: 00000000000006e0
[   33.916004] Call Trace:
[   33.916012]  rcu_read_delay+0xab/0xf0
[   33.916016]  rcu_torture_reader+0x175/0x2e0
[   33.916018]  ? rcu_torture_reader+0x2e0/0x2e0
[   33.916021]  ? kthread+0xf0/0x130
[   33.916023]  kthread+0xf0/0x130
[   33.916024]  ? rcu_torture_timer_cb+0x10/0x10
[   33.916026]  ? kthread_destroy_worker+0x40/0x40
[   33.916031]  ret_from_fork+0x1f/0x30
[   33.916033] Code: 03 30 4e 0f ae e8 0f 31 48 c1 e2 20 48 89 d6 48 09 c6 0f ae e8 0f 31 48 c1 e2 20 48 09 d0 48 89 c1 48 29 f1 48 39 cf 76 19 f3 90 <65> 8b 0d f9 02 30 4e 41 39 c8 74 db 48 29 c6 41 89 c8 48 01 f7 
[   33.916949] Sending NMI from CPU 0 to CPUs 5:
[   33.916968] NMI backtrace for cpu 5
[   33.916985] CPU: 5 PID: 774 Comm: rcu_torture_rea Not tainted 4.15.0-rc1+ #1
[   33.916986] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
[   33.916987] task: ffff96c7debc0cc0 task.stack: ffffaa3181534000
[   33.916990] RIP: 0010:rcu_read_delay+0x46/0xf0
[   33.916991] RSP: 0018:ffffaa3181537e58 EFLAGS: 00000206
[   33.916993] RAX: 00000000000aa73b RBX: ffffffffb3979a90 RCX: 0000000000000af0
[   33.916994] RDX: 00000000000008aa RSI: 0000000000000001 RDI: ffffaa3181537e90
[   33.916995] RBP: ffffaa3181537e90 R08: 0000000000000005 R09: 0000000000000001
[   33.916995] R10: 0000000000000000 R11: 0000000000000002 R12: ffffffffffffff62
[   33.916996] R13: 0000000000000000 R14: 00000007f5376188 R15: ffffffffffffff62
[   33.916998] FS:  0000000000000000(0000) GS:ffff96c7dfd40000(0000) knlGS:0000000000000000
[   33.917001] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   33.917002] CR2: 00000000f7eb3010 CR3: 000000001780a000 CR4: 00000000000006e0
[   33.917003] Call Trace:
[   33.917007]  rcu_torture_reader+0x175/0x2e0
[   33.917009]  ? rcu_torture_reader+0x2e0/0x2e0
[   33.917011]  ? kthread+0xf0/0x130
[   33.917012]  kthread+0xf0/0x130
[   33.917014]  ? rcu_torture_timer_cb+0x10/0x10
[   33.917015]  ? kthread_destroy_worker+0x40/0x40
[   33.917017]  ret_from_fork+0x1f/0x30
[   33.917019] Code: 86 01 00 48 f7 f1 48 85 d2 74 4c 48 89 ef e8 b2 14 08 00 48 63 15 df 5f 4d 02 48 8d 14 92 48 8d 0c 92 31 d2 48 c1 e1 04 48 f7 f1 <48> 85 d2 0f 84 8f 00 00 00 65 8b 05 ba 77 b6 4e a9 ff ff ff 7f 
[   33.917964] Sending NMI from CPU 0 to CPUs 6:
[   33.917981] NMI backtrace for cpu 6
[   33.917999] CPU: 6 PID: 773 Comm: rcu_torture_rea Not tainted 4.15.0-rc1+ #1
[   33.918000] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
[   33.918001] task: ffff96c7debc2640 task.stack: ffffaa318152c000
[   33.918008] RIP: 0010:native_sched_clock+0x7/0x70
[   33.918009] RSP: 0000:ffffaa318152fe70 EFLAGS: 00000282
[   33.918010] RAX: 000000007f3eed81 RBX: ffffffffb3979a90 RCX: 000000000000000a
[   33.918011] RDX: 0000000000000012 RSI: 00000000fffffe01 RDI: 0000000000000001
[   33.918012] RBP: ffffaa318152ff00 R08: 0000000000000006 R09: 0000000000000101
[   33.918013] R10: 0000000000000000 R11: ffffaa318152fe58 R12: ffffffffffffff62
[   33.918014] R13: 0000000000000000 R14: 00000007f546e075 R15: ffffffffffffff62
[   33.918016] FS:  0000000000000000(0000) GS:ffff96c7dfd80000(0000) knlGS:0000000000000000
[   33.918019] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   33.918020] CR2: 0000000000000000 CR3: 000000001780a000 CR4: 00000000000006e0
[   33.918021] Call Trace:
[   33.918026]  trace_clock_local+0x5/0x10
[   33.918029]  rcu_torture_reader+0x146/0x2e0
[   33.918031]  ? rcu_torture_reader+0x2e0/0x2e0
[   33.918033]  ? kthread+0xf0/0x130
[   33.918034]  kthread+0xf0/0x130
[   33.918035]  ? rcu_torture_timer_cb+0x10/0x10
[   33.918037]  ? kthread_destroy_worker+0x40/0x40
[   33.918039]  ret_from_fork+0x1f/0x30
[   33.918041] Code: 89 47 04 65 8b 05 fa 67 bf 4e 39 c2 75 c6 f3 c3 0f 1f 40 00 c3 0f 1f 44 00 00 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 0f 31 <48> c1 e2 20 48 09 c2 65 8b 0d cb 67 bf 4e 83 e1 01 48 c1 e1 04 
[   33.918979] Sending NMI from CPU 0 to CPUs 7:
[   33.918997] NMI backtrace for cpu 7
[   33.919013] CPU: 7 PID: 772 Comm: rcu_torture_rea Not tainted 4.15.0-rc1+ #1
[   33.919014] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
[   33.919015] task: ffff96c7debc72c0 task.stack: ffffaa3181524000
[   33.919021] RIP: 0010:delay_tsc+0x1c/0x50
[   33.919022] RSP: 0018:ffffaa3181527e50 EFLAGS: 00000246
[   33.919024] RAX: 000000007f5dd538 RBX: 0000000000000026 RCX: 0000000000000007
[   33.919025] RDX: 0000000000000012 RSI: 000000127f4c7028 RDI: 00000000001e736b
[   33.919026] RBP: ffffaa3181527e90 R08: 0000000000000007 R09: 0000000000000101
[   33.919027] R10: 0000000000000000 R11: ffffaa3181527e58 R12: 0000000002095dd0
[   33.919028] R13: ffffffffffffff62 R14: 00000007f49676e8 R15: ffffffffffffff62
[   33.919029] FS:  0000000000000000(0000) GS:ffff96c7dfdc0000(0000) knlGS:0000000000000000
[   33.919033] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   33.919033] CR2: 00000000f7ecbca3 CR3: 000000001780a000 CR4: 00000000000006e0
[   33.919034] Call Trace:
[   33.919038]  rcu_read_delay+0xab/0xf0
[   33.919040]  rcu_torture_reader+0x175/0x2e0
[   33.919042]  ? rcu_torture_reader+0x2e0/0x2e0
[   33.919044]  ? kthread+0xf0/0x130
[   33.919045]  kthread+0xf0/0x130
[   33.919046]  ? rcu_torture_timer_cb+0x10/0x10
[   33.919048]  ? kthread_destroy_worker+0x40/0x40
[   33.919050]  ret_from_fork+0x1f/0x30
[   33.919051] Code: 00 f7 e2 48 8d 7a 01 ff 25 e2 80 5f 00 66 90 65 44 8b 05 28 03 30 4e 0f ae e8 0f 31 48 c1 e2 20 48 89 d6 48 09 c6 0f ae e8 0f 31 <48> c1 e2 20 48 09 d0 48 89 c1 48 29 f1 48 39 cf 76 19 f3 90 65 
[   33.919997] rcu_sched kthread starved for 21019 jiffies! g18446744073709551403 c18446744073709551402 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x402 ->cpu=5
[   33.919999] rcu_sched       I15008     8      2 0x80080000
[   33.920013] Call Trace:
[   33.920020]  ? __schedule+0x316/0x6b0
[   33.920022]  schedule+0x2d/0x80
[   33.920024]  schedule_timeout+0x159/0x3f0
[   33.920035]  ? __next_timer_interrupt+0xc0/0xc0
[   33.920038]  rcu_gp_kthread+0x627/0xd90
[   33.920046]  ? migrate_swap_stop+0x161/0x180
[   33.920049]  kthread+0xf0/0x130
[   33.920051]  ? rcu_barrier_sched+0x10/0x10
[   33.920052]  ? kthread_destroy_worker+0x40/0x40
[   33.920056]  ret_from_fork+0x1f/0x30
[   33.920133] schedule_timeout: Waylayed timer base->clk: 0xfffb86c3 jiffies: 0xfffbf0a0 base->next_expiry: 0xfffb86c3 timer->flags: 0x34000005 timer->expires 0xfffb9e83 idx: d0 idx_now: f9 base->pending_map                8               0     10000000000           10000               0               2               0               0               0

And the qemu command is as follows:

qemu-system-x86_64 -enable-kvm -nographic -smp 8 -serial file:/home/paulmck/public_git/linux-rcu/tools/testing/selftests/rcutorture/res/2017.11.28-11:58:02/TREE04.2/console.log -m 512 -kernel /home/paulmck/public_git/linux-rcu/tools/testing/selftests/rcutorture/res/2017.11.28-11:58:02/TREE04/bzImage -append "noapic selinux=0 initcall_debug debug console=ttyS0 rcutorture.torture_type=rcu_bh rcutree.rcu_fanout_leaf=4 rcutorture.n_barrier_cbs=4 rcutorture.stat_interval=15 rcutorture.shutdown_secs=1800 rcutorture.test_no_idle_hz=1 rcutorture.verbose=1"