[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]
[Qemu-stable] high i/o waits and 100% khugepaged with 4.4.4
From: |
Stefan Priebe - Profihost AG |
Subject: |
[Qemu-stable] high i/o waits and 100% khugepaged with 4.4.4 |
Date: |
Wed, 9 Mar 2016 08:37:37 +0100 |
User-agent: |
Mozilla/5.0 (X11; Linux x86_64; rv:38.0) Gecko/20100101 Thunderbird/38.5.1 |
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