All of lore.kernel.org
 help / color / mirror / Atom feed
From: Stefan Priebe - Profihost AG <s.priebe@profihost.ag>
To: qemu-stable@nongnu.org, "kvm@vger.kernel.org" <kvm@vger.kernel.org>
Subject: high i/o waits and 100% khugepaged with 4.4.4
Date: Wed, 9 Mar 2016 08:37:37 +0100	[thread overview]
Message-ID: <56DFD2C1.5080907@profihost.ag> (raw)
In-Reply-To: <56D575EE.9030007@profihost.ag>

Hello list,

while running vanilla 4.4.4 in guest and host.

I'm seeing pretty often 50% I/O waits while doing no disk I/O (storage
isn't even local) and 100% khugepaged. Guests are very laggy.

Example traces from guests:
[34578.974225] INFO: rcu_sched self-detected stall on CPU
[34578.974435] 	0-...: (1 ticks this GP) idle=6d3/140000000000001/0
softirq=1100707/1100707 fqs=0
[34578.974570] 	 (t=64960 jiffies g=1097919 c=1097918 q=0)
[34578.974693] rcu_sched kthread starved for 64960 jiffies! g1097919
c1097918 f0x0 s3 ->state=0x1
[34578.974861] Task dump for CPU 0:
[34578.974970] mysqld          R  running task        0  7782   6301
0x00080000
[34578.975111]  ffffffffb4c54980 ffff88013fc03d68 ffffffffb40aeeaf
0000000000000000
[34578.975257]  ffffffffb4c54980 ffff88013fc03d88 ffffffffb40b177d
0000000000000087
[34578.975395]  0000000000000000 ffff88013fc03db8 ffffffffb40da823
ffff88013fc15f80
[34578.975529] Call Trace:
[34578.975617]  <IRQ>  [<ffffffffb40aeeaf>] sched_show_task+0xaf/0x110
[34578.975782]  [<ffffffffb40b177d>] dump_cpu_task+0x3d/0x50
[34578.975927]  [<ffffffffb40da823>] rcu_dump_cpu_stacks+0x83/0xb0
[34578.976074]  [<ffffffffb40de9db>] rcu_check_callbacks+0x51b/0x7e0
[34578.976208]  [<ffffffffb40eb79c>] ? update_wall_time+0x23c/0x660
[34578.976331]  [<ffffffffb40cac51>] ?
__raw_callee_save___pv_queued_spin_unlock+0x11/0x20
[34578.976466]  [<ffffffffb40f39f0>] ? tick_nohz_handler+0xa0/0xa0
[34578.976586]  [<ffffffffb40e4978>] update_process_times+0x38/0x70
[34578.976701]  [<ffffffffb40f348e>] tick_sched_handle.isra.15+0x2e/0x70
[34578.976827]  [<ffffffffb40f3a38>] tick_sched_timer+0x48/0x80
[34578.976955]  [<ffffffffb40e51d3>] __hrtimer_run_queues+0xf3/0x260
[34578.977072]  [<ffffffffb40e59c8>] hrtimer_interrupt+0xa8/0x1a0
[34578.977197]  [<ffffffffb403da59>] local_apic_timer_interrupt+0x39/0x60
[34578.977328]  [<ffffffffb403e465>] smp_apic_timer_interrupt+0x45/0x60
[34578.977482]  [<ffffffffb46b19a7>] apic_timer_interrupt+0x87/0x90
[34578.977601]  <EOI>
[34592.724028] hrtimer: interrupt took 5213197 ns
[119322.536307] INFO: rcu_sched detected stalls on CPUs/tasks:
[119322.536550] 	1-...: (2804647 GPs behind) idle=1f0/0/0 softirq=7/8 fqs=0
[119322.536785] 	(detected by 0, t=85017 jiffies, g=3903684, c=3903683, q=0)
[119322.536932] Task dump for CPU 1:
[119322.537052] httpd           R  running task        0  3007      1
0x00080008
[119322.537213]  ffffffffb46ac94c ffff8800baa0b888 ffffffffb40e56d4
000000000000db00
[119322.537362]  ffff8800baa0c000 00000000000f423f ffff8800baa0b8c0
00000000000f423f
[119322.537533]  0000000000000000 ffff8800baa0b8a8 ffffffffb40e57dd
0000000000000000
[119322.541018] Call Trace:
[119322.542498]  [<ffffffffb46ac94c>] ? __schedule+0x34c/0x9a1
[119322.543969]  [<ffffffffb40e56d4>] ? hrtimer_try_to_cancel+0x24/0x110
[119322.545487]  [<ffffffffb40e57dd>] ? hrtimer_cancel+0x1d/0x30
[119322.560265]  [<ffffffffb46afd8c>] ?
schedule_hrtimeout_range_clock+0xbc/0x140
[119322.561573]  [<ffffffffb40e4c20>] ? update_rmtp+0x70/0x70
[119322.563051]  [<ffffffffb46afd80>] ?
schedule_hrtimeout_range_clock+0xb0/0x140
[119322.564621]  [<ffffffffb46afe23>] ? schedule_hrtimeout_range+0x13/0x20
[119322.566140]  [<ffffffffb41dc349>] ? poll_schedule_timeout+0x49/0x70
[119322.567643]  [<ffffffffb41dce0e>] ? do_select+0x71e/0x800
[119322.569121]  [<ffffffffb4159d2f>] ? __alloc_pages_nodemask+0x12f/0x240
[119322.570669]  [<ffffffffb40cac51>] ?
__raw_callee_save___pv_queued_spin_unlock+0x11/0x20
[119322.595353]  [<ffffffffb43d8958>] ? find_next_bit+0x18/0x20
[119322.596828]  [<ffffffffb43c3d90>] ? cpumask_any_but+0x30/0x40
[119322.598271]  [<ffffffffb40566b5>] ? flush_tlb_page+0x45/0xa0
[119322.599732]  [<ffffffffb40cac51>] ?
__raw_callee_save___pv_queued_spin_unlock+0x11/0x20
[119322.601260]  [<ffffffffb41dd0c7>] ? core_sys_select+0x1d7/0x2e0
[119322.602647]  [<ffffffffb4084b24>] ? wait_consider_task+0xe4/0xaf0
[119322.604431]  [<ffffffffb40cac51>] ?
__raw_callee_save___pv_queued_spin_unlock+0x11/0x20
[119322.605956]  [<ffffffffb404b58e>] ? kvm_clock_read+0x1e/0x20
[119322.607397]  [<ffffffffb404b599>] ? kvm_clock_get_cycles+0x9/0x10
[119322.608926]  [<ffffffffb40ea94e>] ? ktime_get_ts64+0x4e/0xf0
[119322.610355]  [<ffffffffb41dc6ce>] ? poll_select_set_timeout+0x6e/0x90
[119322.611806]  [<ffffffffb41dd284>] ? SyS_select+0xb4/0x100
[119322.613379]  [<ffffffffb46b0c6e>] ? entry_SYSCALL_64_fastpath+0x12/0x71
[119322.616261] rcu_sched kthread starved for 85017 jiffies! g3903684
c3903683 f0x0 s3 ->state=0x1
[122912.736848] INFO: rcu_sched detected stalls on CPUs/tasks:
[122912.740498] 	1-...: (0 ticks this GP) idle=692/0/0 softirq=23/23 fqs=0
[122912.741872] 	(detected by 0, t=78530 jiffies, g=4046836, c=4046835, q=0)
[122912.742965] Task dump for CPU 1:
[122912.743852] swapper/1       R  running task        0     0      1
0x00080000
[122912.744782]  7fffffffffffffff ffff88013abd3e58 ffffffffb4d2c4e0
0000000000000000
[122912.745722]  0000000000000000 ffff88013abd0000 ffffffffb40db815
ffff88013abd3e88
[122912.746673]  ffffffffb400f7be ffffffffb4d2c4e0 0000000000000000
ffff88013abd3e98
[122912.747608] Call Trace:
[122912.778023]  [<ffffffffb40db815>] ?
rcu_eqs_enter_common.isra.44+0x45/0x70
[122912.779562]  [<ffffffffb400f7be>] ? default_idle+0x1e/0xe0
[122912.780551]  [<ffffffffb400fe5f>] ? arch_cpu_idle+0xf/0x20
[122912.782185]  [<ffffffffb40c4672>] ? default_idle_call+0x32/0x40
[122912.783894]  [<ffffffffb40c48f8>] ? cpu_startup_entry+0x278/0x350
[122912.785521]  [<ffffffffb40f08bc>] ?
clockevents_register_device+0xdc/0x140
[122912.787265]  [<ffffffffb403c280>] ? start_secondary+0x150/0x180
[122912.799987] rcu_sched kthread starved for 78530 jiffies! g4046836
c4046835 f0x0 s3 ->state=0x1
[134835.866122] INFO: rcu_sched detected stalls on CPUs/tasks:
[134835.870001] 	(detected by 0, t=102857 jiffies, g=4534359, c=4534358,
q=0)
[134835.898377] All QSes seen, last rcu_sched kthread activity 92217
(4429503836-4429411619), jiffies_till_next_fqs=3, root ->qsmask 0x0
[134835.903445] postimap.pl     R  running task        0 21675  21551
0x00080000
[134835.905545]  ffffffffb4c54980 ffff88013fc03db8 ffffffffb40aeeaf
ffff88013fc15f80
[134835.910218]  ffffffffb4c54980 ffff88013fc03e38 ffffffffb40dec96
0000000000000000
[134835.914329]  ffffffffb40eb79c 0000000000000000 0000000000453057
ffff88013fc15f80
[134835.921559] Call Trace:
[134835.933856]  <IRQ>  [<ffffffffb40aeeaf>] sched_show_task+0xaf/0x110
[134835.935565]  [<ffffffffb40dec96>] rcu_check_callbacks+0x7d6/0x7e0
[134835.937192]  [<ffffffffb40eb79c>] ? update_wall_time+0x23c/0x660
[134835.968907]  [<ffffffffb40f39f0>] ? tick_nohz_handler+0xa0/0xa0
[134835.970542]  [<ffffffffb40e4978>] update_process_times+0x38/0x70
[134835.972226]  [<ffffffffb40f348e>] tick_sched_handle.isra.15+0x2e/0x70
[134835.974367]  [<ffffffffb40f3a38>] tick_sched_timer+0x48/0x80
[134835.975954]  [<ffffffffb40e51d3>] __hrtimer_run_queues+0xf3/0x260
[134835.977576]  [<ffffffffb40e59c8>] hrtimer_interrupt+0xa8/0x1a0
[134835.979197]  [<ffffffffb403da59>] local_apic_timer_interrupt+0x39/0x60
[134835.981159]  [<ffffffffb403e465>] smp_apic_timer_interrupt+0x45/0x60
[134835.982764]  [<ffffffffb46b19a7>] apic_timer_interrupt+0x87/0x90
[134835.984254]  <EOI>  [<ffffffffb43d079a>] ? copy_page+0xa/0x10
[134835.985880]  [<ffffffffb417d5cc>] ? wp_page_copy.isra.56+0xec/0x4d0
[134835.987472]  [<ffffffffb40cac51>] ?
__raw_callee_save___pv_queued_spin_unlock+0x11/0x20
[134835.989087]  [<ffffffffb417e619>] do_wp_page+0x99/0x630
[134835.990678]  [<ffffffffb418b9f9>] ? page_add_new_anon_rmap+0x89/0xf0
[134836.005064]  [<ffffffffb40cac51>] ?
__raw_callee_save___pv_queued_spin_unlock+0x11/0x20
[134836.006713]  [<ffffffffb4180c54>] __handle_mm_fault+0xb54/0x11f0
[134836.008325]  [<ffffffffb41813cf>] handle_mm_fault+0xdf/0x180
[134836.009925]  [<ffffffffb404f324>] __do_page_fault+0x164/0x380
[134836.011379]  [<ffffffffb404f650>] trace_do_page_fault+0x50/0x140
[134836.012951]  [<ffffffffb414ebe5>] ? __context_tracking_exit+0x15/0xc0
[134836.015158]  [<ffffffffb404b14e>] do_async_page_fault+0x1e/0xc0
[134836.016894]  [<ffffffffb400261f>] ? enter_from_user_mode+0x1f/0x50
[134836.018691]  [<ffffffffb46b2b28>] async_page_fault+0x28/0x30
[134836.020359] rcu_sched kthread starved for 92217 jiffies! g4534359
c4534358 f0x2 s3 ->state=0x100
[137471.816832] INFO: rcu_sched detected stalls on CPUs/tasks:
[137471.857390] 	(detected by 0, t=85069 jiffies, g=4627783, c=4627782, q=0)
[137471.859052] All QSes seen, last rcu_sched kthread activity 85069
(4432139793-4432054724), jiffies_till_next_fqs=3, root ->qsmask 0x0
[137471.862446] httpd           R  running task        0  3007      1
0x00080000
[137471.864229]  ffffffffb4c54980 ffff88013fc03db8 ffffffffb40aeeaf
ffff88013fc15f80
[137471.866044]  ffffffffb4c54980 ffff88013fc03e38 ffffffffb40dec96
0000000000000000
[137471.882408]  ffffffffb40eb79c 0000000000000000 0000000000469d47
ffff88013fc15f80
[137471.884110] Call Trace:
[137471.885795]  <IRQ>  [<ffffffffb40aeeaf>] sched_show_task+0xaf/0x110
[137471.888522]  [<ffffffffb40dec96>] rcu_check_callbacks+0x7d6/0x7e0
[137471.890338]  [<ffffffffb40eb79c>] ? update_wall_time+0x23c/0x660
[137471.892050]  [<ffffffffb40f39f0>] ? tick_nohz_handler+0xa0/0xa0
[137471.893864]  [<ffffffffb40e4978>] update_process_times+0x38/0x70
[137471.895762]  [<ffffffffb40f348e>] tick_sched_handle.isra.15+0x2e/0x70
[137471.898501]  [<ffffffffb40f3a38>] tick_sched_timer+0x48/0x80
[137471.920446]  [<ffffffffb40e51d3>] __hrtimer_run_queues+0xf3/0x260
[137471.922108]  [<ffffffffb40e59c8>] hrtimer_interrupt+0xa8/0x1a0
[137471.923962]  [<ffffffffb403da59>] local_apic_timer_interrupt+0x39/0x60
[137471.926198]  [<ffffffffb403e465>] smp_apic_timer_interrupt+0x45/0x60
[137471.928561]  [<ffffffffb46b19a7>] apic_timer_interrupt+0x87/0x90
[137471.930448]  <EOI>
[137471.930494] rcu_sched kthread starved for 85069 jiffies! g4627783
c4627782 f0x2 s3 ->state=0x0
[167969.408935] INFO: rcu_sched detected stalls on CPUs/tasks:
[167969.413404] 	(detected by 0, t=96556 jiffies, g=5879146, c=5879145, q=0)
[167969.414996] All QSes seen, last rcu_sched kthread activity 96556
(4462637574-4462541018), jiffies_till_next_fqs=3, root ->qsmask 0x0
[167969.418087] errorlogs.pl    R  running task        0 28042  27632
0x00080008
[167969.420832]  ffffffffb4c54980 ffff88013fc03db8 ffffffffb40aeeaf
ffff88013fc15f80
[167969.422695]  ffffffffb4c54980 ffff88013fc03e38 ffffffffb40dec96
0000000000000000
[167969.424535]  ffffffffb40eb79c 0000000000000000 000000000059b56a
ffff88013fc15f80
[167969.426385] Call Trace:
[167969.447415]  <IRQ>  [<ffffffffb40aeeaf>] sched_show_task+0xaf/0x110
[167969.449630]  [<ffffffffb40dec96>] rcu_check_callbacks+0x7d6/0x7e0
[167969.451648]  [<ffffffffb40eb79c>] ? update_wall_time+0x23c/0x660
[167969.453370]  [<ffffffffb40f39f0>] ? tick_nohz_handler+0xa0/0xa0
[167969.455248]  [<ffffffffb40e4978>] update_process_times+0x38/0x70
[167969.506267]  [<ffffffffb40f348e>] tick_sched_handle.isra.15+0x2e/0x70
[167969.508297]  [<ffffffffb40f3a38>] tick_sched_timer+0x48/0x80
[167969.510087]  [<ffffffffb40e51d3>] __hrtimer_run_queues+0xf3/0x260
[167969.511933]  [<ffffffffb40e59c8>] hrtimer_interrupt+0xa8/0x1a0
[167969.514086]  [<ffffffffb403da59>] local_apic_timer_interrupt+0x39/0x60
[167969.516147]  [<ffffffffb403e465>] smp_apic_timer_interrupt+0x45/0x60
[167969.518207]  [<ffffffffb46b19a7>] apic_timer_interrupt+0x87/0x90
[167969.520245]  <EOI>  [<ffffffffb407e45f>] ?
exit_to_usermode_loop+0x35/0x95
[167969.521974]  [<ffffffffb400298c>] prepare_exit_to_usermode+0x2c/0x40
[167969.529171]  [<ffffffffb46b172a>] retint_user+0x8/0x13
[167969.541963] rcu_sched kthread starved for 96556 jiffies! g5879146
c5879145 f0x2 s3 ->state=0x0
[168305.292972] INFO: rcu_sched detected stalls on CPUs/tasks:
[168305.296690] 	1-...: (3688 GPs behind) idle=779/140000000000001/0
softirq=53/54 fqs=148
[168305.298696] 	(detected by 0, t=108507 jiffies, g=5882834, c=5882833,
q=0)
[168305.300470] Task dump for CPU 1:
[168305.302430] cache           R  running task        0 28352   8202
0x00080000
[168305.332720]  ffffffffb40db815 0000000000000001 ffff880078600000
ffff880078603ec8
[168305.334690]  0000000000000001 00007faac90fc000 00007faac90fc000
00007faac90fb000
[168305.336768]  ffffffffb40db88a ffff880078603ef8 ffffffffb40de21e
ffff880078603f18
[168305.338859] Call Trace:
[168305.344683]  [<ffffffffb40db815>] ?
rcu_eqs_enter_common.isra.44+0x45/0x70
[168305.346720]  [<ffffffffb40db88a>] ? rcu_eqs_enter.isra.45+0x4a/0x50
[168305.349834]  [<ffffffffb40de21e>] ? rcu_user_enter+0xe/0x10
[168305.351878]  [<ffffffffb414ed3c>] ? __context_tracking_enter+0x5c/0x100
[168305.353859]  [<ffffffffb4002985>] ? prepare_exit_to_usermode+0x25/0x40
[168305.356386]  [<ffffffffb46b0dcc>] ? int_ret_from_sys_call+0x25/0x8f
[168305.358407] rcu_sched kthread starved for 108063 jiffies! g5882834
c5882833 f0x0 s3 ->state=0x0
[168415.226802] INFO: rcu_sched self-detected stall on CPU
[168415.232744] 	0-...: (1 ticks this GP) idle=ed5/140000000000001/0
softirq=5900968/5900968 fqs=0
[168415.234596] 	 (t=74832 jiffies g=5884663 c=5884662 q=0)
[168415.236529] rcu_sched kthread starved for 74832 jiffies! g5884663
c5884662 f0x0 s3 ->state=0x1
[168415.263182] Task dump for CPU 0:
[168415.265311] mysqld          R  running task        0  7782   6301
0x00080000
[168415.267510]  ffffffffb4c54980 ffff88013fc03d68 ffffffffb40aeeaf
0000000000000000
[168415.269905]  ffffffffb4c54980 ffff88013fc03d88 ffffffffb40b177d
0000000000000087
[168415.271675]  0000000000000000 ffff88013fc03db8 ffffffffb40da823
ffff88013fc15f80
[168415.273493] Call Trace:
[168415.275222]  <IRQ>  [<ffffffffb40aeeaf>] sched_show_task+0xaf/0x110
[168415.277104]  [<ffffffffb40b177d>] dump_cpu_task+0x3d/0x50
[168415.278945]  [<ffffffffb40da823>] rcu_dump_cpu_stacks+0x83/0xb0
[168415.280790]  [<ffffffffb40de9db>] rcu_check_callbacks+0x51b/0x7e0
[168415.286748]  [<ffffffffb40eb79c>] ? update_wall_time+0x23c/0x660
[168415.288463]  [<ffffffffb40cac51>] ?
__raw_callee_save___pv_queued_spin_unlock+0x11/0x20
[168415.290221]  [<ffffffffb40f39f0>] ? tick_nohz_handler+0xa0/0xa0
[168415.292032]  [<ffffffffb40e4978>] update_process_times+0x38/0x70
[168415.293965]  [<ffffffffb40f348e>] tick_sched_handle.isra.15+0x2e/0x70
[168415.319215]  [<ffffffffb40f3a38>] tick_sched_timer+0x48/0x80
[168415.321025]  [<ffffffffb40e51d3>] __hrtimer_run_queues+0xf3/0x260
[168415.322646]  [<ffffffffb40e59c8>] hrtimer_interrupt+0xa8/0x1a0
[168415.324319]  [<ffffffffb403da59>] local_apic_timer_interrupt+0x39/0x60
[168415.326172]  [<ffffffffb403e465>] smp_apic_timer_interrupt+0x45/0x60
[168415.328087]  [<ffffffffb46b19a7>] apic_timer_interrupt+0x87/0x90
[168415.342099]  <EOI>
[174655.145591] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 23s!
[kworker/0:1:34]
[174664.287031] Modules linked in: netconsole ipt_REJECT nf_reject_ipv4
xt_multiport iptable_filter ip_tables x_tables i2c_piix4 i2c_core
virtio_balloon shpchp button btrfs xor raid6_pq usbhid sg ata_generic
sd_mod floppy virtio_net virtio_scsi uhci_hcd ehci_hcd ata_piix usbcore
usb_common virtio_pci
[174664.291943] CPU: 0 PID: 34 Comm: kworker/0:1 Not tainted 4.4.4+4-ph #1
[174664.293948] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
BIOS rel-1.8.2-0-g33fbe13 by qemu-project.org 04/01/2014
[174664.296103] Workqueue: events nohz_kick_work_fn
[174664.298210] task: ffff8800bb97a500 ti: ffff8800bb9ac000 task.ti:
ffff8800bb9ac000
[174664.300258] RIP: 0010:[<ffffffffb40f916e>]  [<ffffffffb40f916e>]
smp_call_function_single+0x7e/0x110
[174664.302703] RSP: 0018:ffff8800bb9afd38  EFLAGS: 00000202
[174664.304796] RAX: 0000000000000001 RBX: 0000000000000001 RCX:
0000000000000000
[174664.306927] RDX: 0000000000000000 RSI: ffff88013fc16500 RDI:
0000000000000001
[174664.309005] RBP: ffff8800bb9afd78 R08: ffffffffb4d2c4e0 R09:
0000000000000000
[174664.311108] R10: 0000000000000001 R11: 0000000000000000 R12:
ffffffffb40f3410
[174664.313172] R13: 0000000000000000 R14: 0000000000000000 R15:
ffff88013b0055f8
[174664.315215] FS:  0000000000000000(0000) GS:ffff88013fc00000(0000)
knlGS:0000000000000000
[174664.317272] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[174664.319437] CR2: 00007f8d31bca140 CR3: 0000000067ca8000 CR4:
00000000001406f0
[174664.321582] Stack:
[174664.323333]  ffff8800bb9afdc8 ffff8800bb9afdc0 0000000000000000
0000000000000000
[174664.325303]  0000000000000000 0000000000000003 0000000000000000
ffffffffb40f3410
[174664.327245]  ffff8800bb9afdc8 ffffffffb40f94fb ffff880000000001
0000000000000000
[174664.329093] Call Trace:
[174664.330918]  [<ffffffffb40f3410>] ? nohz_full_kick_work_func+0x10/0x10
[174664.332761]  [<ffffffffb40f94fb>] smp_call_function_many+0x21b/0x260
[174664.334577]  [<ffffffffb40f41bb>] tick_nohz_full_kick_all+0x2b/0x40
[174664.336347]  [<ffffffffb40e82de>] nohz_kick_work_fn+0xe/0x10
[174664.338128]  [<ffffffffb409a6ad>] process_one_work+0x14d/0x3e0
[174664.339878]  [<ffffffffb409aa9a>] worker_thread+0x11a/0x440
[174664.341728]  [<ffffffffb46ac94c>] ? __schedule+0x34c/0x9a1
[174664.343471]  [<ffffffffb409a980>] ? process_scheduled_works+0x40/0x40
[174664.345282]  [<ffffffffb40a0b49>] kthread+0xc9/0xe0
[174664.347052]  [<ffffffffb40a0a80>] ? kthread_stop+0x100/0x100
[174664.348722]  [<ffffffffb46b0fcf>] ret_from_fork+0x3f/0x70
[174664.350407]  [<ffffffffb40a0a80>] ? kthread_stop+0x100/0x100
[174664.352117] Code: c0 74 0c 9c 58 0f 1f 44 00 00 f6 c4 02 74 62 85 c9
75 39 48 c7 c6 00 65 01 00 65 48 03 35 b3 0f f1 4b 8b 46 18 a8 01 74 09
f3 90 <8b> 46 18 a8 01 75 f7 83 4e 18 01 48 89 d1 89 df 4c 89 e2 e8 2a
[174673.096580] INFO: rcu_sched detected stalls on CPUs/tasks:
[174673.097711] 	1-...: (3024 GPs behind) idle=0d3/140000000000000/0
softirq=100/102 fqs=410
[174673.098797] 	(detected by 0, t=60016 jiffies, g=6158787, c=6158786, q=0)
[174673.099890] Task dump for CPU 1:
[174673.100977] cache           R  running task        0  4867   8202
0x0008000c
[174673.102094]  ffff8800787c8f00 ffff88002ad17ee8 ffffffffb404f324
00007ffc57ac18d0
[174673.103229]  0000000000000002 ffff8800787c8f68 0000005500000000
ffff880032e02e34
[174673.104370]  ffff88002ad17f58 0000000000000007 00007fc6ebffe6c8
0000000000000001
[174673.105516] Call Trace:
[174673.106649]  [<ffffffffb404f324>] ? __do_page_fault+0x164/0x380
[174673.107784]  [<ffffffffb404f650>] ? trace_do_page_fault+0x50/0x140
[174673.108917]  [<ffffffffb414ec38>] ? __context_tracking_exit+0x68/0xc0
[174673.110018]  [<ffffffffb404b14e>] ? do_async_page_fault+0x1e/0xc0
[174673.111090]  [<ffffffffb400261f>] ? enter_from_user_mode+0x1f/0x50
[174673.112129]  [<ffffffffb46b2b28>] ? async_page_fault+0x28/0x30
[174673.113159] rcu_sched kthread starved for 41595 jiffies! g6158787
c6158786 f0x0 s3 ->state=0x0
[177010.777871] INFO: rcu_sched detected stalls on CPUs/tasks:
[177010.779917] 	(detected by 1, t=95835 jiffies, g=6209468, c=6209467, q=0)
[177010.780936] All QSes seen, last rcu_sched kthread activity 93300
(4471678997-4471585697), jiffies_till_next_fqs=3, root ->qsmask 0x0
[177010.782969] swapper/1       R  running task        0     0      1
0x00080000
[177010.784008]  ffffffffb4c54980 ffff88013fd03db8 ffffffffb40aeeaf
ffff88013fd15f80
[177010.785071]  ffffffffb4c54980 ffff88013fd03e38 ffffffffb40dec96
0000000000000000
[177010.786126]  0000000000000002 0000000000000000 00000000005ebfbc
ffff88013fd15f80
[177010.787187] Call Trace:
[177010.788232]  <IRQ>  [<ffffffffb40aeeaf>] sched_show_task+0xaf/0x110
[177010.789329]  [<ffffffffb40dec96>] rcu_check_callbacks+0x7d6/0x7e0
[177010.790388]  [<ffffffffb40f39f0>] ? tick_nohz_handler+0xa0/0xa0
[177013.928795]  [<ffffffffb40e4978>] update_process_times+0x38/0x70
[177013.930670]  [<ffffffffb40f348e>] tick_sched_handle.isra.15+0x2e/0x70
[177013.932532]  [<ffffffffb40f3a38>] tick_sched_timer+0x48/0x80
[177013.934239]  [<ffffffffb40e51d3>] __hrtimer_run_queues+0xf3/0x260
[177013.935939]  [<ffffffffb40e59c8>] hrtimer_interrupt+0xa8/0x1a0
[177013.937650]  [<ffffffffb403da59>] local_apic_timer_interrupt+0x39/0x60
[177013.939272]  [<ffffffffb403e465>] smp_apic_timer_interrupt+0x45/0x60
[177013.940950]  [<ffffffffb46b19a7>] apic_timer_interrupt+0x87/0x90
[177013.942545]  <EOI>  [<ffffffffb404b936>] ? native_safe_halt+0x6/0x10
[177013.944211]  [<ffffffffb40db815>] ?
rcu_eqs_enter_common.isra.44+0x45/0x70
[177013.945831]  [<ffffffffb400f7be>] default_idle+0x1e/0xe0
[177013.947604]  [<ffffffffb400fe5f>] arch_cpu_idle+0xf/0x20
[177013.949723]  [<ffffffffb40c4672>] default_idle_call+0x32/0x40
[177013.951523]  [<ffffffffb40c48f8>] cpu_startup_entry+0x278/0x350
[177013.953365]  [<ffffffffb40f08bc>] ?
clockevents_register_device+0xdc/0x140
[177013.955637]  [<ffffffffb403c280>] start_secondary+0x150/0x180
[177013.957552] rcu_sched kthread starved for 93300 jiffies! g6209468
c6209467 f0x2 s3 ->state=0x100
[180287.076703] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 22s!
[mysqld:7909]
[180287.078785] Modules linked in: netconsole ipt_REJECT nf_reject_ipv4
xt_multiport iptable_filter ip_tables x_tables i2c_piix4 i2c_core
virtio_balloon shpchp button btrfs xor raid6_pq usbhid sg ata_generic
sd_mod floppy virtio_net virtio_scsi uhci_hcd ehci_hcd ata_piix usbcore
usb_common virtio_pci
[180287.082177] CPU: 0 PID: 7909 Comm: mysqld Tainted: G             L
4.4.4+4-ph #1
[180287.083252] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
BIOS rel-1.8.2-0-g33fbe13 by qemu-project.org 04/01/2014
[180287.084361] task: ffff88008108ca00 ti: ffff880093ec0000 task.ti:
ffff880093ec0000
[180287.085473] RIP: 0010:[<ffffffffb40f91aa>]  [<ffffffffb40f91aa>]
smp_call_function_single+0xba/0x110
[180287.086627] RSP: 0018:ffff880093ec3c08  EFLAGS: 00000202
[180287.087746] RAX: 0000000000000000 RBX: 0000000000000001 RCX:
0000000000000830
[180287.088872] RDX: 0000000000000001 RSI: 0000000000000002 RDI:
0000000000000292
[180287.089978] RBP: ffff880093ec3c48 R08: 0000000000000002 R09:
0000000000000000
[180287.091075] R10: 0000000000000000 R11: 0000000000000246 R12:
ffffffffb4056200
[180287.092174] R13: ffff880093ec3cb0 R14: 0000000000000000 R15:
ffff88003798f3d8
[180287.093271] FS:  00007efff4a12700(0000) GS:ffff88013fc00000(0000)
knlGS:0000000000000000
[180287.094385] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[180287.095500] CR2: 00007effee4b9648 CR3: 00000000374eb000 CR4:
00000000001406f0
[180287.096633] Stack:
[180287.097737]  ffff880093ec3c68 ffffffffb41ff693 0000000000000000
ffffffffb4056200
[180287.098871]  ffff880093ec3cb0 0000000000000003 0000000000000001
ffffffffb4056200
[180287.099991]  ffff880093ec3c98 ffffffffb40f94fb 0000000000000001
0000000000000000
[180287.101082] Call Trace:
[180287.102137]  [<ffffffffb41ff693>] ? generic_write_end+0x83/0xb0
[180287.103198]  [<ffffffffb4056200>] ? do_flush_tlb_all+0x50/0x50
[180287.104239]  [<ffffffffb4056200>] ? do_flush_tlb_all+0x50/0x50
[180287.105274]  [<ffffffffb40f94fb>] smp_call_function_many+0x21b/0x260
[180287.106301]  [<ffffffffb40563d5>] native_flush_tlb_others+0x45/0xb0
[180287.107316]  [<ffffffffb4056573>] flush_tlb_mm_range+0x73/0x170
[180287.108330]  [<ffffffffb417cf9b>] tlb_flush_mmu_tlbonly+0xbb/0xf0
[180287.109332]  [<ffffffffb417dad6>] tlb_flush_mmu+0x16/0x30
[180287.110325]  [<ffffffffb417db04>] tlb_finish_mmu+0x14/0x40
[180287.111313]  [<ffffffffb417fda3>] zap_page_range+0xc3/0x100
[180287.112306]  [<ffffffffb43307fe>] ? xfs_file_write_iter+0x9e/0x160
[180287.113301]  [<ffffffffb4191f23>] SyS_madvise+0x1d3/0x750
[180287.114297]  [<ffffffffb414ebe5>] ? __context_tracking_exit+0x15/0xc0
[180287.115295]  [<ffffffffb4002711>] ?
syscall_trace_enter_phase1+0xc1/0x110
[180287.116304]  [<ffffffffb46b0c6e>] entry_SYSCALL_64_fastpath+0x12/0x71
[180287.117299] Code: 89 e2 e8 2a fe ff ff 48 83 c4 30 5b 41 5c 5d c3 48
8d 75 d0 48 89 d1 89 df 4c 89 e2 e8 10 fe ff ff 8b 55 e8 83 e2 01 74 de
f3 90 <8b> 55 e8 83 e2 01 75 f6 eb d2 8b 05 1e bd e8 00 85 c0 75 94 80
[184001.330633] INFO: rcu_sched detected stalls on CPUs/tasks:
[184001.334236] 	(detected by 0, t=69401 jiffies, g=6441059, c=6441058, q=0)
[184001.336284] All QSes seen, last rcu_sched kthread activity 61291
(4478669591-4478608300), jiffies_till_next_fqs=3, root ->qsmask 0x0
[184001.340892] qpsmtpd-prefork R  running task        0  8115      1
0x00080008
[184001.405216]  ffffffffb4c54980 ffff88013fc03db8 ffffffffb40aeeaf
ffff88013fc15f80
[184001.407315]  ffffffffb4c54980 ffff88013fc03e38 ffffffffb40dec96
0000000000000000
[184001.409349]  ffffffffb40eb79c 0000000000000000 0000000000624863
ffff88013fc15f80
[184001.411426] Call Trace:
[184001.414412]  <IRQ>  [<ffffffffb40aeeaf>] sched_show_task+0xaf/0x110
[184001.417144]  [<ffffffffb40dec96>] rcu_check_callbacks+0x7d6/0x7e0
[184001.419168]  [<ffffffffb40eb79c>] ? update_wall_time+0x23c/0x660
[184001.421118]  [<ffffffffb40f39f0>] ? tick_nohz_handler+0xa0/0xa0
[184001.426614]  [<ffffffffb40e4978>] update_process_times+0x38/0x70
[184001.428529]  [<ffffffffb40f348e>] tick_sched_handle.isra.15+0x2e/0x70
[184001.430329]  [<ffffffffb40f3a38>] tick_sched_timer+0x48/0x80
[184001.432138]  [<ffffffffb40e51d3>] __hrtimer_run_queues+0xf3/0x260
[184001.434904]  [<ffffffffb40e59c8>] hrtimer_interrupt+0xa8/0x1a0
[184001.436684]  [<ffffffffb403da59>] local_apic_timer_interrupt+0x39/0x60
[184001.438394]  [<ffffffffb403e465>] smp_apic_timer_interrupt+0x45/0x60
[184001.440226]  [<ffffffffb46b19a7>] apic_timer_interrupt+0x87/0x90
[184001.441957]  <EOI>  [<ffffffffb407e45f>] ?
exit_to_usermode_loop+0x35/0x95
[184001.443841]  [<ffffffffb400298c>] prepare_exit_to_usermode+0x2c/0x40
[184001.445525]  [<ffffffffb46b172a>] retint_user+0x8/0x13
[184001.453298] rcu_sched kthread starved for 61291 jiffies! g6441059
c6441058 f0x2 s3 ->state=0x0
[184826.350576] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 31s!
[imap-login:4977]
[184826.355131] Modules linked in: netconsole ipt_REJECT nf_reject_ipv4
xt_multiport iptable_filter ip_tables x_tables i2c_piix4 i2c_core
virtio_balloon shpchp button btrfs xor raid6_pq usbhid sg ata_generic
sd_mod floppy virtio_net virtio_scsi uhci_hcd ehci_hcd ata_piix usbcore
usb_common virtio_pci
[184826.382655] CPU: 0 PID: 4977 Comm: imap-login Tainted: G
 L  4.4.4+4-ph #1
[184826.384775] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
BIOS rel-1.8.2-0-g33fbe13 by qemu-project.org 04/01/2014
[184826.386927] task: ffff8800ae8a4a00 ti: ffff880037940000 task.ti:
ffff880037940000
[184826.389028] RIP: 0010:[<ffffffffb407e45f>]  [<ffffffffb407e45f>]
exit_to_usermode_loop+0x35/0x95
[184826.391300] RSP: 0000:ffff880037943f18  EFLAGS: 00000286
[184826.393373] RAX: 0000000000000096 RBX: 0000000000080008 RCX:
ffffffffb4c0f4c0
[184826.395266] RDX: ffff88013fc0ca70 RSI: 0000000000080008 RDI:
ffff880037943f58
[184826.397055] RBP: ffff880037943f38 R08: ffff88013fc153f8 R09:
ffff8800ae8a4a00
[184826.398805] R10: 0000000005dd1c00 R11: 0000000000000000 R12:
ffff880037943f58
[184826.401053] R13: ffff880037940000 R14: ffff8800ae8a4a00 R15:
0000559d76dfdc18
[184826.402906] FS:  00007f7dbee94700(0000) GS:ffff88013fc00000(0000)
knlGS:0000000000000000
[184826.404987] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[184826.406973] CR2: ffffffffff600400 CR3: 00000000378e1000 CR4:
00000000001406f0
[184826.408879] Stack:
[184826.411567]  0000559d76f214b0 0000000000000003 00007f7dbea7dc50
0000000000000000
[184826.413434]  ffff880037943f48 ffffffffb400298c 0000000000000003
ffffffffb46b172a
[184826.415575]  0000559d76dfdc18 0000000000000000 00007f7dbea7dc50
0000000000000003
[184826.417425] Call Trace:
[184826.419262]  [<ffffffffb400298c>] prepare_exit_to_usermode+0x2c/0x40
[184826.423694]  [<ffffffffb46b172a>] retint_user+0x8/0x13
[184826.425828] Code: 56 65 4c 8b 34 25 80 ad 00 00 41 55 65 4c 8b 2c 25
84 28 01 00 41 54 49 81 ed 00 40 00 00 49 89 fc 53 89 f3 fb 66 0f 1f 44
00 00 <f6> c3 08 74 05 e8 e7 eb 62 00 f6 c3 04 74 08 4c 89 e7 e8 5a 6d
[184972.665760] INFO: rcu_sched detected stalls on CPUs/tasks:
[184972.669324] 	(detected by 0, t=61041 jiffies, g=6465105, c=6465104, q=0)
[184972.671231] All QSes seen, last rcu_sched kthread activity 49624
(4479640932-4479591308), jiffies_till_next_fqs=3, root ->qsmask 0x0
[184972.675288] qpsmtpd p:25 wa R  running task        0 29491   8090
0x00080008
[184972.677441]  ffffffffb4c54980 ffff88013fc03db8 ffffffffb40aeeaf
ffff88013fc15f80
[184972.679540]  ffffffffb4c54980 ffff88013fc03e38 ffffffffb40dec96
0000000000000000
[184972.681497]  ffffffffb40eb79c 0000000000000000 000000000062a651
ffff88013fc15f80
[184972.683562] Call Trace:
[184972.685581]  <IRQ>  [<ffffffffb40aeeaf>] sched_show_task+0xaf/0x110
[184972.692341]  [<ffffffffb40dec96>] rcu_check_callbacks+0x7d6/0x7e0
[184972.694446]  [<ffffffffb40eb79c>] ? update_wall_time+0x23c/0x660
[184972.696634]  [<ffffffffb40f39f0>] ? tick_nohz_handler+0xa0/0xa0
[184972.698784]  [<ffffffffb40e4978>] update_process_times+0x38/0x70
[184972.700997]  [<ffffffffb40f348e>] tick_sched_handle.isra.15+0x2e/0x70
[184972.703128]  [<ffffffffb40f3a38>] tick_sched_timer+0x48/0x80
[184972.705399]  [<ffffffffb40e51d3>] __hrtimer_run_queues+0xf3/0x260
[184972.707370]  [<ffffffffb40e59c8>] hrtimer_interrupt+0xa8/0x1a0
[184972.711724]  [<ffffffffb403da59>] local_apic_timer_interrupt+0x39/0x60
[184972.713779]  [<ffffffffb403e465>] smp_apic_timer_interrupt+0x45/0x60
[184972.716056]  [<ffffffffb46b19a7>] apic_timer_interrupt+0x87/0x90
[184972.743139]  <EOI>  [<ffffffffb407e45f>] ?
exit_to_usermode_loop+0x35/0x95
[184972.745322]  [<ffffffffb400298c>] prepare_exit_to_usermode+0x2c/0x40
[184972.751738]  [<ffffffffb46b172a>] retint_user+0x8/0x13
[184972.753678] rcu_sched kthread starved for 49624 jiffies! g6465105
c6465104 f0x2 s3 ->state=0x0
[185128.047621] INFO: rcu_sched detected stalls on CPUs/tasks:
[185128.049719] 	(detected by 0, t=85222 jiffies, g=6467929, c=6467928, q=0)
[185128.051563] All QSes seen, last rcu_sched kthread activity 85222
(4479796314-4479711092), jiffies_till_next_fqs=3, root ->qsmask 0x0
[185128.055036] mysql           R  running task        0 19050  19048
0x00080008
[185128.056631]  ffffffffb4c54980 ffff88013fc03db8 ffffffffb40aeeaf
ffff88013fc15f80
[185128.058237]  ffffffffb4c54980 ffff88013fc03e38 ffffffffb40dec96
0000000000000000
[185128.060195]  ffffffffb40eb79c 0000000000000000 000000000062b159
ffff88013fc15f80
[185128.061831] Call Trace:
[185128.063904]  <IRQ>  [<ffffffffb40aeeaf>] sched_show_task+0xaf/0x110
[185128.065776]  [<ffffffffb40dec96>] rcu_check_callbacks+0x7d6/0x7e0
[185128.067589]  [<ffffffffb40eb79c>] ? update_wall_time+0x23c/0x660
[185128.069405]  [<ffffffffb40f39f0>] ? tick_nohz_handler+0xa0/0xa0
[185128.071114]  [<ffffffffb40e4978>] update_process_times+0x38/0x70
[185128.074093]  [<ffffffffb40f348e>] tick_sched_handle.isra.15+0x2e/0x70
[185128.075843]  [<ffffffffb40f3a38>] tick_sched_timer+0x48/0x80
[185128.077920]  [<ffffffffb40e51d3>] __hrtimer_run_queues+0xf3/0x260
[185128.079691]  [<ffffffffb40e59c8>] hrtimer_interrupt+0xa8/0x1a0
[185128.081439]  [<ffffffffb403da59>] local_apic_timer_interrupt+0x39/0x60
[185128.083531]  [<ffffffffb403e465>] smp_apic_timer_interrupt+0x45/0x60
[185128.085297]  [<ffffffffb46b19a7>] apic_timer_interrupt+0x87/0x90
[185128.086948]  <EOI>  [<ffffffffb43d079a>] ? copy_page+0xa/0x10
[185128.088700]  [<ffffffffb417d5cc>] ? wp_page_copy.isra.56+0xec/0x4d0
[185128.090368]  [<ffffffffb40cac51>] ?
__raw_callee_save___pv_queued_spin_unlock+0x11/0x20
[185128.092195]  [<ffffffffb417e619>] do_wp_page+0x99/0x630
[185128.093803]  [<ffffffffb43d8958>] ? find_next_bit+0x18/0x20
[185128.095414]  [<ffffffffb4180c54>] __handle_mm_fault+0xb54/0x11f0
[185128.097168]  [<ffffffffb41813cf>] handle_mm_fault+0xdf/0x180
[185128.098605]  [<ffffffffb404f324>] __do_page_fault+0x164/0x380
[185128.100193]  [<ffffffffb404f650>] trace_do_page_fault+0x50/0x140
[185128.101897]  [<ffffffffb414ebe5>] ? __context_tracking_exit+0x15/0xc0
[185128.103613]  [<ffffffffb404b14e>] do_async_page_fault+0x1e/0xc0
[185128.105325]  [<ffffffffb400261f>] ? enter_from_user_mode+0x1f/0x50
[185128.106806]  [<ffffffffb46b2b28>] async_page_fault+0x28/0x30
[185128.108273] rcu_sched kthread starved for 85222 jiffies! g6467929
c6467928 f0x2 s3 ->state=0x0
[185726.121092] INFO: rcu_sched detected stalls on CPUs/tasks:
[185726.124251] 	1-...: (7056 GPs behind) idle=7e8/0/0 softirq=359/360
fqs=0
[185726.125772] 	(detected by 0, t=72077 jiffies, g=6481102, c=6481101, q=0)
[185726.127205] Task dump for CPU 1:
[185726.128616] authscanclient  R  running task        0  2707      1
0x00080008
[185726.130063]  ffffffffb46ac94c ffff88013abc8000 ffff8800b9f30000
000000000000db00
[185726.131523]  ffff8800b8e8c000 ffff8800b9f30000 ffff8800b8e8bd70
ffff8800b8e8bd18
[185726.192287]  ffffc9000071b480 ffff8800b8e8bc68 ffffffffb46ad089
ffff8800b8e8bd18
[185726.193938] Call Trace:
[185726.195660]  [<ffffffffb46ad089>] schedule+0x39/0x80
[185726.197354]  [<ffffffffb40f5461>] futex_wait_queue_me+0xd1/0x130
[185726.199311]  [<ffffffffb40cac51>] ?
__raw_callee_save___pv_queued_spin_unlock+0x11/0x20
[185726.201194]  [<ffffffffb40f6755>] futex_wait+0x195/0x2b0
[185726.202837]  [<ffffffffb40e4c20>] ? update_rmtp+0x70/0x70
[185726.204395]  [<ffffffffb40f543f>] ? futex_wait_queue_me+0xaf/0x130
[185726.206142]  [<ffffffffb40f8285>] do_futex+0x115/0x520
[185726.207831]  [<ffffffffb40cac51>] ?
__raw_callee_save___pv_queued_spin_unlock+0x11/0x20
[185726.209641]  [<ffffffffb40b28af>] ? vtime_account_user+0x5f/0x70
[185726.211280]  [<ffffffffb40f8728>] SyS_futex+0x98/0x1a0
[185726.212963]  [<ffffffffb400261f>] ? enter_from_user_mode+0x1f/0x50
[185726.214639]  [<ffffffffb46b0c6e>] entry_SYSCALL_64_fastpath+0x12/0x71
[185726.216332] rcu_sched kthread starved for 72077 jiffies! g6481102
c6481101 f0x0 s3 ->state=0x1
[185847.242124] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 22s!
[kworker/0:1:34]
[185847.243092] Modules linked in: netconsole ipt_REJECT nf_reject_ipv4
xt_multiport iptable_filter ip_tables x_tables i2c_piix4 i2c_core
virtio_balloon shpchp button btrfs xor raid6_pq usbhid sg ata_generic
sd_mod floppy virtio_net virtio_scsi uhci_hcd ehci_hcd ata_piix usbcore
usb_common virtio_pci
[185847.246197] CPU: 0 PID: 34 Comm: kworker/0:1 Tainted: G
L  4.4.4+4-ph #1
[185847.247198] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
BIOS rel-1.8.2-0-g33fbe13 by qemu-project.org 04/01/2014
[185847.248248] Workqueue: events nohz_kick_work_fn
[185847.249299] task: ffff8800bb97a500 ti: ffff8800bb9ac000 task.ti:
ffff8800bb9ac000
[185847.250361] RIP: 0010:[<ffffffffb40f916e>]  [<ffffffffb40f916e>]
smp_call_function_single+0x7e/0x110
[185847.251455] RSP: 0018:ffff8800bb9afd38  EFLAGS: 00000202
[185847.252538] RAX: 0000000000000001 RBX: 0000000000000001 RCX:
0000000000000000
[185847.253632] RDX: 0000000000000000 RSI: ffff88013fc16500 RDI:
0000000000000001
[185847.254723] RBP: ffff8800bb9afd78 R08: ffffffffb4d2c4e0 R09:
0000000000000000
[185847.255801] R10: 0000000000000001 R11: 0000000000000000 R12:
ffffffffb40f3410
[185847.256877] R13: 0000000000000000 R14: 0000000000000000 R15:
ffff88013b0055f8
[185847.257939] FS:  0000000000000000(0000) GS:ffff88013fc00000(0000)
knlGS:0000000000000000
[185847.259021] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[185847.260098] CR2: ffffffffff600400 CR3: 0000000078673000 CR4:
00000000001406f0
[185847.261193] Stack:
[185847.262274]  ffff8800bb9afdc8 ffff8800bb9afdc0 0000000000000000
0000000000000000
[185847.263400]  0000000000000000 0000000000000003 0000000000000000
ffffffffb40f3410
[185847.264540]  ffff8800bb9afdc8 ffffffffb40f94fb ffff880000000001
0000000000000000
[185847.265680] Call Trace:
[185847.266794]  [<ffffffffb40f3410>] ? nohz_full_kick_work_func+0x10/0x10
[185847.267930]  [<ffffffffb40f94fb>] smp_call_function_many+0x21b/0x260
[185847.269059]  [<ffffffffb40f41bb>] tick_nohz_full_kick_all+0x2b/0x40
[185847.270162]  [<ffffffffb40e82de>] nohz_kick_work_fn+0xe/0x10
[185847.271259]  [<ffffffffb409a6ad>] process_one_work+0x14d/0x3e0
[185847.272362]  [<ffffffffb409aa9a>] worker_thread+0x11a/0x440
[185847.273440]  [<ffffffffb46ac94c>] ? __schedule+0x34c/0x9a1
[185847.274518]  [<ffffffffb409a980>] ? process_scheduled_works+0x40/0x40
[185847.275587]  [<ffffffffb40a0b49>] kthread+0xc9/0xe0
[185847.276646]  [<ffffffffb40a0a80>] ? kthread_stop+0x100/0x100
[185847.277719]  [<ffffffffb46b0fcf>] ret_from_fork+0x3f/0x70
[185847.278768]  [<ffffffffb40a0a80>] ? kthread_stop+0x100/0x100
[185847.279813] Code: c0 74 0c 9c 58 0f 1f 44 00 00 f6 c4 02 74 62 85 c9
75 39 48 c7 c6 00 65 01 00 65 48 03 35 b3 0f f1 4b 8b 46 18 a8 01 74 09
f3 90 <8b> 46 18 a8 01 75 f7 83 4e 18 01 48 89 d1 89 df 4c 89 e2 e8 2a
[185875.069239] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 22s!
[kworker/0:1:34]
[185875.070388] Modules linked in: netconsole ipt_REJECT nf_reject_ipv4
xt_multiport iptable_filter ip_tables x_tables i2c_piix4 i2c_core
virtio_balloon shpchp button btrfs xor raid6_pq usbhid sg ata_generic
sd_mod floppy virtio_net virtio_scsi uhci_hcd ehci_hcd ata_piix usbcore
usb_common virtio_pci
[185875.073948] CPU: 0 PID: 34 Comm: kworker/0:1 Tainted: G
L  4.4.4+4-ph #1
[185875.075133] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
BIOS rel-1.8.2-0-g33fbe13 by qemu-project.org 04/01/2014
[185875.076353] Workqueue: events nohz_kick_work_fn
[185875.077567] task: ffff8800bb97a500 ti: ffff8800bb9ac000 task.ti:
ffff8800bb9ac000
[185875.078802] RIP: 0010:[<ffffffffc03a2b53>]  [<ffffffffc03a2b53>]
virtnet_receive+0x2c3/0x890 [virtio_net]
[185875.080078] RSP: 0018:ffff88013fc03d88  EFLAGS: 00010246
[185875.081322] RAX: ffff880093c33000 RBX: ffff880093c33005 RCX:
ffff8800b9d90000
[185875.082565] RDX: ffff8800baa517c0 RSI: 0000000000000064 RDI:
ffff8800baa52000
[185875.083780] RBP: ffff88013fc03e18 R08: 0000000000000048 R09:
0000000000000000
[185875.084963] R10: 0000000000000022 R11: 000077ff80000000 R12:
ffff8800b9c47808
[185875.086120] R13: 0000000000000040 R14: 000077ff80000000 R15:
ffff8800b9c47800
[185875.087261] FS:  0000000000000000(0000) GS:ffff88013fc00000(0000)
knlGS:0000000000000000
[185875.088385] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[185875.089487] CR2: ffffffffff600400 CR3: 0000000078673000 CR4:
00000000001406f0
[185875.090590] Stack:
[185875.091662]  0000000100000000 0000000000000000 ffff88013b005000
0000000000000000
[185875.092759]  ffff8800b9c47808 ffff880093c33000 ffff8800baa51000
0000000000000040
[185875.093859]  ffff8800baa517c0 ffff88013fc1d638 000000010b10949d
0000004800000048
[185875.094956] Call Trace:
[185875.096035]  <IRQ>
[185875.096050]  [<ffffffffc03a3148>] virtnet_poll+0x28/0x90 [virtio_net]
[185875.098206]  [<ffffffffb456d79d>] net_rx_action+0x14d/0x340
[185875.099296]  [<ffffffffc03a3707>] ? skb_recv_done+0x47/0x50 [virtio_net]
[185875.100388]  [<ffffffffb408741c>] __do_softirq+0xdc/0x2d0
[185875.101464]  [<ffffffffb40cac51>] ?
__raw_callee_save___pv_queued_spin_unlock+0x11/0x20
[185875.102546]  [<ffffffffb40878d5>] irq_exit+0x105/0x110
[185875.103615]  [<ffffffffb4007495>] do_IRQ+0x65/0xf0
[185875.104675]  [<ffffffffb40f3410>] ? nohz_full_kick_work_func+0x10/0x10
[185875.105738]  [<ffffffffb46b1707>] common_interrupt+0x87/0x87
[185875.106790]  <EOI>
[185875.106803]  [<ffffffffb40f3410>] ? nohz_full_kick_work_func+0x10/0x10
[185875.108878]  [<ffffffffb40f916e>] ? smp_call_function_single+0x7e/0x110
[185875.109931]  [<ffffffffb40f3410>] ? nohz_full_kick_work_func+0x10/0x10
[185875.110984]  [<ffffffffb40f94fb>] smp_call_function_many+0x21b/0x260
[185875.112037]  [<ffffffffb40f41bb>] tick_nohz_full_kick_all+0x2b/0x40
[185875.113090]  [<ffffffffb40e82de>] nohz_kick_work_fn+0xe/0x10
[185875.114143]  [<ffffffffb409a6ad>] process_one_work+0x14d/0x3e0
[185875.115194]  [<ffffffffb409aa9a>] worker_thread+0x11a/0x440
[185875.116242]  [<ffffffffb46ac94c>] ? __schedule+0x34c/0x9a1
[185875.117297]  [<ffffffffb409a980>] ? process_scheduled_works+0x40/0x40
[185875.118354]  [<ffffffffb40a0b49>] kthread+0xc9/0xe0
[185875.119405]  [<ffffffffb40a0a80>] ? kthread_stop+0x100/0x100
[185875.120437]  [<ffffffffb46b0fcf>] ret_from_fork+0x3f/0x70
[185877.142523]  [<ffffffffb40a0a80>] ? kthread_stop+0x100/0x100
[185877.143599] Code: 5c 41 5d 41 5e 41 5f 5d c3 44 89 c6 48 89 df 29 c6
e8 e2 93 1b f4 e9 81 fe ff ff 48 89 d8 4d 89 f3 44 89 45 cc 30 c0 48 89
45 98 <44> 0f b7 60 0a b8 00 00 00 80 48 03 45 98 4c 0f 42 1d a7 c4 86
[186553.525454] INFO: rcu_sched detected stalls on CPUs/tasks:
[186553.528512] 	1-...: (2153 GPs behind) idle=3c1/140000000000000/0
softirq=383/383 fqs=17
[186553.530296] 	(detected by 0, t=67656 jiffies, g=6494354, c=6494353, q=0)
[186553.531990] Task dump for CPU 1:
[186553.533527] php5.2          R  running task        0 21137  27635
0x00080008
[186553.575828]  ffff880139c3ad00 ffff880037547ee8 ffffffffb404f324
3b6c6d756f264c3e
[186553.590500]  0000000000000002 ffff880139c3ad68 0000005500000000
ffff8800b9eb8934
[186553.601241]  ffff880037547f58 0000000000000006 0000000005363000
0000000001cccab8
[186553.613959] Call Trace:
[186553.636746]  [<ffffffffb404f324>] ? __do_page_fault+0x164/0x380
[186553.646399]  [<ffffffffb404f650>] ? trace_do_page_fault+0x50/0x140
[186553.654689]  [<ffffffffb414ec38>] ? __context_tracking_exit+0x68/0xc0
[186553.662718]  [<ffffffffb404b14e>] ? do_async_page_fault+0x1e/0xc0
[186553.672492]  [<ffffffffb400261f>] ? enter_from_user_mode+0x1f/0x50
[186553.683275]  [<ffffffffb46b2b28>] ? async_page_fault+0x28/0x30
[186553.690594] rcu_sched kthread starved for 50945 jiffies! g6494354
c6494353 f0x0 s3 ->state=0x1
[188039.072001] INFO: rcu_sched detected stalls on CPUs/tasks:
[188039.075029] 	(detected by 0, t=90920 jiffies, g=6539663, c=6539662, q=0)
[188039.076660] All QSes seen, last rcu_sched kthread activity 89756
(4482707356-4482617600), jiffies_till_next_fqs=3, root ->qsmask 0x0
[188039.079895] mysqld          R  running task        0  7782   6301
0x00080008
[188039.082958]  ffffffffb4c54980 ffff88013fc03db8 ffffffffb40aeeaf
ffff88013fc15f80
[188039.084671]  ffffffffb4c54980 ffff88013fc03e38 ffffffffb40dec96
0000000000000000
[188039.086311]  ffffffffb40eb79c 0000000000000000 000000000063c98f
ffff88013fc15f80
[188039.088044] Call Trace:
[188039.089728]  <IRQ>  [<ffffffffb40aeeaf>] sched_show_task+0xaf/0x110
[188039.092059]  [<ffffffffb40dec96>] rcu_check_callbacks+0x7d6/0x7e0
[188039.093791]  [<ffffffffb40eb79c>] ? update_wall_time+0x23c/0x660
[188039.095400]  [<ffffffffb40f39f0>] ? tick_nohz_handler+0xa0/0xa0
[188039.097160]  [<ffffffffb40e4978>] update_process_times+0x38/0x70
[188039.098755]  [<ffffffffb40f348e>] tick_sched_handle.isra.15+0x2e/0x70
[188039.100967]  [<ffffffffb40f3a38>] tick_sched_timer+0x48/0x80
[188039.102576]  [<ffffffffb40e51d3>] __hrtimer_run_queues+0xf3/0x260
[188039.104213]  [<ffffffffb40e59c8>] hrtimer_interrupt+0xa8/0x1a0
[188039.105881]  [<ffffffffb403da59>] local_apic_timer_interrupt+0x39/0x60
[188039.107455]  [<ffffffffb403e465>] smp_apic_timer_interrupt+0x45/0x60
[188039.109586]  [<ffffffffb46b19a7>] apic_timer_interrupt+0x87/0x90
[188039.111306]  <EOI>  [<ffffffffb407e45f>] ?
exit_to_usermode_loop+0x35/0x95
[188039.112936]  [<ffffffffb400298c>] prepare_exit_to_usermode+0x2c/0x40
[188039.114591]  [<ffffffffb46b172a>] retint_user+0x8/0x13
[188039.116249] rcu_sched kthread starved for 89756 jiffies! g6539663
c6539662 f0x2 s3 ->state=0x0


Greets,
Stefan

  parent reply	other threads:[~2016-03-09  7:37 UTC|newest]

Thread overview: 5+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2016-03-01 10:58 Kernel: BUG: soft lockup - CPU#0 stuck for 22s! on many machines at the same time Stefan Priebe - Profihost AG
2016-03-06 19:24 ` Stefan Priebe
2016-03-09  7:37 ` Stefan Priebe - Profihost AG [this message]
2016-03-17 23:16   ` [Qemu-stable] high i/o waits and 100% khugepaged with 4.4.4 Michael Roth
2016-03-21 10:53     ` Stefan Priebe - Profihost AG

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to=56DFD2C1.5080907@profihost.ag \
    --to=s.priebe@profihost.ag \
    --cc=kvm@vger.kernel.org \
    --cc=qemu-stable@nongnu.org \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line before the message body.
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.