runtime
runtime copied to clipboard
Published
20 hours ago •
clearcontainers
clearcontainers
Kernel errors after running test suite for around 2 hrs in a loop
Description of problem
After executing docker integration tests from https://github.com/clearcontainers/tests for around 2 hours on a Fedora 26 VM, I got kernel errors and the VM seems to be hanged, although the same errors (which appear below) keep being posted on the console.
Expected result
There shouldn't be any kernel error. The VM should not hang.
Actual result
There are some errors related to ksm and qemu-lite
Logs from cc-collect-data.sh
collected_data.log
[ 9064.191703] NMI watchdog: BUG: soft lockup - CPU#3 stuck for 22s! [ksmd:45]
[ 9064.193702] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 22s! [qemu-lite-syste:15705]
[ 9064.193703] Modules linked in: xt_nat vhost_net vhost tap tun veth ipt_MASQUERADE nf_nat_masquerade_ipv4 nf_conntrack_netlink nfnetlink iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 xt_addrtype xt_
conntrack nf_nat nf_conntrack libcrc32c br_netfilter bridge stp llc overlay nls_utf8 isofs sb_edac kvm_intel qxl kvm ttm ppdev drm_kms_helper irqbypass parport_pc drm parport tpm_tis tpm_tis_core tpm joydev virt
io_net i2c_piix4 virtio_balloon virtio_blk crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel virtio_pci virtio_ring serio_raw virtio ata_generic pata_acpi
[ 9064.193730] CPU: 0 PID: 15705 Comm: qemu-lite-syste Tainted: G L 4.12.14-300.fc26.x86_64 #1
[ 9064.193731] Hardware name: Red Hat KVM, BIOS 0.5.1 01/01/2011
[ 9064.193732] task: ffff97ccb3cf0000 task.stack: ffffbb6a11d64000
[ 9064.193738] RIP: 0010:smp_call_function_many+0x212/0x240
[ 9064.193739] RSP: 0018:ffffbb6a11d67778 EFLAGS: 00000202 ORIG_RAX: ffffffffffffff10
[ 9064.193739] RAX: ffff97cdbfc9e478 RBX: ffff97cdbfc1b3c0 RCX: 0000000000000001
[ 9064.193740] RDX: 0000000000000001 RSI: 0000000000000000 RDI: ffff97cdb70213b8
[ 9064.193740] RBP: ffffbb6a11d677b0 R08: ffffffffffffffff R09: 0000000000000006
[ 9064.193741] R10: ffffdd41c890da00 R11: ffff97cdb7003c80 R12: 0000000000000004
[ 9064.193741] R13: 000000000001b380 R14: ffffffff9c06c310 R15: ffffbb6a11d677c8
[ 9064.193742] FS: 00007effd3fff700(0000) GS:ffff97cdbfc00000(0000) knlGS:0000000000000000
[ 9064.193743] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 9064.193743] CR2: 00000000ffffffff CR3: 00000001ada2f000 CR4: 00000000001426f0
[ 9064.193747] Call Trace:
[ 9064.193752] native_flush_tlb_others+0x124/0x190
[ 9064.193754] flush_tlb_page+0x5a/0x90
[ 9064.193757] ptep_clear_flush+0x4e/0x60
[ 9064.193759] wp_page_copy+0x283/0x6b0
[ 9064.193760] do_wp_page+0x98/0x590
[ 9064.193761] __handle_mm_fault+0xa83/0x1030
[ 9064.193762] handle_mm_fault+0xb1/0x250
[ 9064.193763] __get_user_pages+0x19b/0x690
[ 9064.193765] get_user_pages+0x42/0x50
[ 9064.193793] __gfn_to_pfn_memslot+0x11d/0x410 [kvm]
[ 9064.193804] try_async_pf+0x66/0x1f0 [kvm]
[ 9064.193825] tdp_page_fault+0x138/0x280 [kvm]
[ 9064.193835] kvm_mmu_page_fault+0x61/0x130 [kvm]
[ 9064.193838] handle_ept_violation+0x99/0x130 [kvm_intel]
[ 9064.193840] vmx_handle_exit+0xad/0x13c0 [kvm_intel]
[ 9064.193849] kvm_arch_vcpu_ioctl_run+0x672/0x1640 [kvm]
[ 9064.193867] kvm_vcpu_ioctl+0x2a6/0x620 [kvm]
[ 9064.193886] ? kvm_vcpu_ioctl+0x2a6/0x620 [kvm]
[ 9064.193889] ? do_sigtimedwait+0xc7/0x220
[ 9064.193891] do_vfs_ioctl+0xa5/0x600
[ 9064.193893] SyS_ioctl+0x79/0x90
[ 9064.193896] entry_SYSCALL_64_fastpath+0x1a/0xa5
[ 9064.193897] RIP: 0033:0x7effe7bfb5e7
[ 9064.193897] RSP: 002b:00007effd3ffeaa8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[ 9064.193898] RAX: ffffffffffffffda RBX: 0000000000000001 RCX: 00007effe7bfb5e7
[ 9064.193898] RDX: 0000000000000000 RSI: 000000000000ae80 RDI: 0000000000000017
[ 9064.193899] RBP: 0000000000000402 R08: 00005616c462d330 R09: 00005616c4bca940
[ 9064.193899] R10: 0000000000000000 R11: 0000000000000246 R12: 00007effe9ad1000
[ 9064.193900] R13: 0000000000000001 R14: 0000000000000000 R15: 00005616c5e2a5f0
[ 9064.193901] Code: 52 30 00 39 05 64 d2 f2 00 89 c1 0f 8e 75 fe ff ff 48 98 48 8b 13 48 03 14 c5 e0 f3 d2 9c 48 89 d0 8b 52 18 83 e2 01 74 0a f3 90 <8b> 50 18 83 e2 01 75 f6 eb b9 48 c7 c2 80 9d 05 9d 4c 89 e6 89
[ 9064.232520] Modules linked in: xt_nat vhost_net vhost tap tun veth ipt_MASQUERADE nf_nat_masquerade_ipv4 nf_conntrack_netlink nfnetlink iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 xt_addrtype xt_conntrack nf_nat nf_conntrack libcrc32c br_netfilter bridge stp llc overlay nls_utf8 isofs sb_edac kvm_intel qxl kvm ttm ppdev drm_kms_helper irqbypass parport_pc drm parport tpm_tis tpm_tis_core tpm joydev virtio_net i2c_piix4 virtio_balloon virtio_blk crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel virtio_pci virtio_ring serio_raw virtio ata_generic pata_acpi
[ 9064.237939] CPU: 3 PID: 45 Comm: ksmd Tainted: G L 4.12.14-300.fc26.x86_64 #1
[ 9064.238858] Hardware name: Red Hat KVM, BIOS 0.5.1 01/01/2011
[ 9064.239559] task: ffff97cdb5c40000 task.stack: ffffbb6a00dd8000
[ 9064.240280] RIP: 0010:queued_spin_lock_slowpath+0x25/0x1a0
[ 9064.240975] RSP: 0018:ffffbb6a00ddbd90 EFLAGS: 00000202 ORIG_RAX: ffffffffffffff10
[ 9064.241837] RAX: 0000000000000001 RBX: ffff97cd10ae2000 RCX: 0000000000000004
[ 9064.242664] RDX: 0000000000000001 RSI: 0000000000000001 RDI: ffffdd41c642b8b0
[ 9064.243489] RBP: ffffbb6a00ddbd90 R08: ffff97cd5d1c0ff8 R09: ffff97cda4134018
[ 9064.244639] R10: 0000000000000001 R11: 0000000000000000 R12: ffffdd41c642b880
[ 9064.245462] R13: 0000000000000004 R14: ffff97cda4134018 R15: ffff97ccb43b4840
[ 9064.246289] FS: 0000000000000000(0000) GS:ffff97cdbfd80000(0000) knlGS:0000000000000000
[ 9064.247200] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 9064.247905] CR2: 00000000ffffffff CR3: 0000000129e09000 CR4: 00000000001426e0
[ 9064.248742] Call Trace:
[ 9064.249171] _raw_spin_lock+0x21/0x30
[ 9064.249699] follow_page_pte+0xd1/0x5c0
[ 9064.250244] follow_page_mask+0x1d1/0x520
[ 9064.250806] ksm_scan_thread+0xd2e/0x1380
[ 9064.251368] ? finish_wait+0x80/0x80
[ 9064.251888] kthread+0x125/0x140
[ 9064.252380] ? try_to_merge_with_ksm_page+0xa0/0xa0
[ 9064.253020] ? kthread_park+0x60/0x60
[ 9064.253546] ret_from_fork+0x25/0x30
[ 9064.254065] Code: 1f 80 00 00 00 00 0f 1f 44 00 00 55 48 89 e5 0f 1f 44 00 00 ba 01 00 00 00 8b 07 85 c0 75 0a f0 0f b1 17 85 c0 75 f2 5d c3 f3 90 <eb> ec 81 fe 00 01 00 00 0f 84 92 00 00 00 41 b8 01 01 00 00 b9
Recent errors on cc-proxy journal log:
Oct 02 10:58:52 fedora26-obs-cc3.localdomain cc-proxy[994]: time="2017-10-02T10:58:52Z" level=debug msg="{"level":"error","msg":"Wait for process 1 failed: wait: no child processes","time":"2017-10-02T10:58:51.873350537Z"}" source=qemu vm=c936c38d8889e68d8b5d56c20ac30c3e06e50951c659cd9b0303a36f39863972
Oct 02 10:58:57 fedora26-obs-cc3.localdomain cc-proxy[994]: time="2017-10-02T10:58:57Z" level=debug msg="[ 2.299345] EXT4-fs (pmem0p1): mounted filesystem with ordered data mode. Opts: dax,data=ordered,errors=remount-ro" source=qemu vm=f039e981f73372ea3c23750bae24c8e575bbfd737e247c4e56363dfd3080a05c
Oct 02 10:59:01 fedora26-obs-cc3.localdomain cc-proxy[994]: time="2017-10-02T10:59:01Z" level=debug msg="{"level":"error","msg":"Wait for process 5 failed: exit status 42","time":"2017-10-02T10:59:01.586540409Z"}" source=qemu vm=f039e981f73372ea3c23750bae24c8e575bbfd737e247c4e56363dfd3080a05c
Oct 02 10:59:01 fedora26-obs-cc3.localdomain cc-proxy[994]: time="2017-10-02T10:59:01Z" level=error msg="error serving client: write unix /var/run/clear-containers/proxy.sock->@: use of closed network connection" client=2703 source=proxy
Oct 02 10:59:01 fedora26-obs-cc3.localdomain cc-proxy[994]: time="2017-10-02T10:59:01Z" level=error msg="error serving client: write unix /var/run/clear-containers/proxy.sock->@: write: broken pipe" client=2699 source=proxy
Oct 02 10:59:01 fedora26-obs-cc3.localdomain cc-proxy[994]: time="2017-10-02T10:59:01Z" level=debug msg="{"level":"info","msg":"Stream 3 has been closed: read /dev/ptmx: input/output error","time":"2017-10-02T10:59:01.656914318Z"}" source=qemu vm=f039e981f73372ea3c23750bae24c8e575bbfd737e247c4e56363dfd3080a05c
Oct 02 10:59:01 fedora26-obs-cc3.localdomain cc-proxy[994]: time="2017-10-02T10:59:01Z" level=debug msg="{"level":"error","msg":"Wait for process 3 failed: waitid: no child processes","time":"2017-10-02T10:59:01.66039789Z"}" source=qemu vm=f039e981f73372ea3c23750bae24c8e575bbfd737e247c4e56363dfd3080a05c
Oct 02 10:59:01 fedora26-obs-cc3.localdomain cc-proxy[994]: time="2017-10-02T10:59:01Z" level=error msg="error writing I/O data to client: write unix /var/run/clear-containers/proxy.sock->@: use of closed network connection" section=io source=proxy vm=f039e981f73372ea3c23750bae24c8e575bbfd737e247c4e56363dfd3080a05c
Oct 02 10:59:02 fedora26-obs-cc3.localdomain cc-proxy[994]: time="2017-10-02T10:59:02Z" level=debug msg="{"level":"error","msg":"Wait for process 1 failed: signal: killed","time":"2017-10-02T10:59:02.002540413Z"}" source=qemu vm=f039e981f73372ea3c23750bae24c8e575bbfd737e247c4e56363dfd3080a05c
Oct 02 10:59:07 fedora26-obs-cc3.localdomain cc-proxy[994]: time="2017-10-02T10:59:07Z" level=debug msg="[ 2.417756] EXT4-fs (pmem0p1): mounted filesystem with ordered data mode. Opts: dax,data=ordered,errors=remount-ro" source=qemu vm=649597ed015af862ff35dc47e44d030c81db9a28fc88c04c10f254563aff1f02
Oct 02 10:59:12 fedora26-obs-cc3.localdomain cc-proxy[994]: time="2017-10-02T10:59:12Z" level=error msg="error serving client: write unix /var/run/clear-containers/proxy.sock->@: use of closed network connection" client=2712 source=proxy
Oct 02 10:59:12 fedora26-obs-cc3.localdomain cc-proxy[994]: time="2017-10-02T10:59:12Z" level=error msg="error serving client: write unix /var/run/clear-containers/proxy.sock->@: write: broken pipe" client=2708 source=proxy
Oct 02 10:59:12 fedora26-obs-cc3.localdomain cc-proxy[994]: time="2017-10-02T10:59:12Z" level=debug msg="{"level":"info","msg":"Stream 3 has been closed: read /dev/ptmx: input/output error","time":"2017-10-02T10:59:12.111573287Z"}" source=qemu vm=649597ed015af862ff35dc47e44d030c81db9a28fc88c04c10f254563aff1f02
Oct 02 10:59:12 fedora26-obs-cc3.localdomain cc-proxy[994]: time="2017-10-02T10:59:12Z" level=debug msg="{"level":"error","msg":"Wait for process 3 failed: signal: killed","time":"2017-10-02T10:59:12.113804941Z"}" source=qemu vm=649597ed015af862ff35dc47e44d030c81db9a28fc88c04c10f254563aff1f02
Oct 02 10:59:12 fedora26-obs-cc3.localdomain cc-proxy[994]: time="2017-10-02T10:59:12Z" level=error msg="error writing I/O data to client: write unix /var/run/clear-containers/proxy.sock->@: use of closed network connection" section=io source=proxy vm=649597ed015af862ff35dc47e44d030c81db9a28fc88c04c10f254563aff1f02
Oct 02 10:59:12 fedora26-obs-cc3.localdomain cc-proxy[994]: time="2017-10-02T10:59:12Z" level=debug msg="{"level":"error","msg":"Wait for process 1 failed: signal: killed","time":"2017-10-02T10:59:12.420353092Z"}" source=qemu vm=649597ed015af862ff35dc47e44d030c81db9a28fc88c04c10f254563aff1f02
Oct 02 10:59:17 fedora26-obs-cc3.localdomain cc-proxy[994]: time="2017-10-02T10:59:17Z" level=debug msg="[ 2.250359] EXT4-fs (pmem0p1): mounted filesystem with ordered data mode. Opts: dax,data=ordered,errors=remount-ro" source=qemu vm=841fe24e720d36e299c4613a9d35acb462142f63151d54c91d8d391aa16b29f5
Oct 02 10:59:21 fedora26-obs-cc3.localdomain cc-proxy[994]: time="2017-10-02T10:59:21Z" level=debug msg="{"level":"error","msg":"Wait for process 5 failed: exit status 1","time":"2017-10-02T10:59:21.87216785Z"}" source=qemu vm=841fe24e720d36e299c4613a9d35acb462142f63151d54c91d8d391aa16b29f5
Oct 02 10:59:21 fedora26-obs-cc3.localdomain cc-proxy[994]: time="2017-10-02T10:59:21Z" level=error msg="error serving client: write unix /var/run/clear-containers/proxy.sock->@: use of closed network connection" client=2721 source=proxy
Oct 02 10:59:22 fedora26-obs-cc3.localdomain cc-proxy[994]: time="2017-10-02T10:59:22Z" level=error msg="error serving client: write unix /var/run/clear-containers/proxy.sock->@: write: broken pipe" client=2717 source=proxy
Oct 02 10:59:22 fedora26-obs-cc3.localdomain cc-proxy[994]: time="2017-10-02T10:59:22Z" level=debug msg="{"level":"info","msg":"Stream 3 has been closed: read /dev/ptmx: input/output error","time":"2017-10-02T10:59:21.939476023Z"}" source=qemu vm=841fe24e720d36e299c4613a9d35acb462142f63151d54c91d8d391aa16b29f5
Oct 02 10:59:22 fedora26-obs-cc3.localdomain cc-proxy[994]: time="2017-10-02T10:59:22Z" level=debug msg="{"level":"error","msg":"Wait for process 3 failed: signal: killed","time":"2017-10-02T10:59:21.951196248Z"}" source=qemu vm=841fe24e720d36e299c4613a9d35acb462142f63151d54c91d8d391aa16b29f5
Oct 02 10:59:22 fedora26-obs-cc3.localdomain cc-proxy[994]: time="2017-10-02T10:59:22Z" level=error msg="error writing I/O data to client: write unix /var/run/clear-containers/proxy.sock->@: use of closed network connection" section=io source=proxy vm=841fe24e720d36e299c4613a9d35acb462142f63151d54c91d8d391aa16b29f5
Oct 02 10:59:22 fedora26-obs-cc3.localdomain cc-proxy[994]: time="2017-10-02T10:59:22Z" level=debug msg="{"level":"error","msg":"Wait for process 1 failed: waitid: no child processes","time":"2017-10-02T10:59:22.188273838Z"}" source=qemu vm=841fe24e720d36e299c4613a9d35acb462142f63151d54c91d8d391aa16b29f5
Oct 02 10:59:37 fedora26-obs-cc3.localdomain cc-proxy[994]: time="2017-10-02T10:59:37Z" level=debug msg="[ 2.257955] EXT4-fs (pmem0p1): mounted filesystem with ordered data mode. Opts: dax,data=ordered,errors=remount-ro" source=qemu vm=eabdd65b87cdb70717c38652818378bf2ca1c0686a762a9e64f9dce5f703271d
I can reproduce this issue in Clear Linux as well using kernel linux-kvm-4.13.1. The vm hangs until you do hit enter by serial console.
[ 8243.712008] INFO: rcu_sched self-detected stall on CPU
[ 8243.714006] INFO: rcu_sched detected stalls on CPUs/tasks:
[ 8243.714012] 2-...: (1 GPs behind) idle=e1e/140000000000000/0 softirq=416776/416777 fqs=27
[ 8243.714015] 3-...: (59999 ticks this GP) idle=fb6/140000000000001/0 softirq=365003/365003 fqs=27
[ 8243.714015] (detected by 0, t=60002 jiffies, g=198525, c=198524, q=13)
[ 8243.714020] Sending NMI from CPU 0 to CPUs 2:
[ 8243.714171] NMI backtrace for cpu 2
[ 8243.714175] CPU: 2 PID: 23292 Comm: qemu-lite-syste Not tainted 4.13.1-246.kvm #2
[ 8243.714176] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
[ 8243.714177] task: ffffa3882ff87180 task.stack: ffffa60684398000
[ 8243.714185] RIP: 0010:vmx_vcpu_run+0x1f9/0x420
[ 8243.714186] RSP: 0018:ffffa6068439bcf8 EFLAGS: 00000002
[ 8243.714187] RAX: 0000000000000001 RBX: 0000000000000246 RCX: 0000000000000000
[ 8243.714188] RDX: 0000000000000001 RSI: 0000000000000001 RDI: ffff88007c8c8168
[ 8243.714189] RBP: ffff88007cbbbdf8 R08: ffff88007fc152a8 R09: 0000000000000000
[ 8243.714190] R10: 0000000000000000 R11: 0000000000000000 R12: ffff88007c860280
[ 8243.714191] R13: ffffffff81854610 R14: ffffffff81989828 R15: ffff88007c8c8000
[ 8243.714192] FS: 00007f635b111700(0000) GS:ffffa38839d00000(0000) knlGS:0000000000000000
[ 8243.714193] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 8243.714194] CR2: 00007f0596337e90 CR3: 00000001aeb70000 CR4: 00000000001426a0
[ 8243.714199] Call Trace:
[ 8243.714206] ? vcpu_enter_guest+0x4d2/0x1090
[ 8243.714212] ? __schedule+0x255/0x7a0
[ 8243.714214] ? vmx_deliver_posted_interrupt+0xe7/0x100
[ 8243.714217] ? kvm_arch_vcpu_ioctl_run+0xe9/0x3f0
[ 8243.714220] ? kvm_vcpu_ioctl+0x2a7/0x4f0
[ 8243.714225] ? do_futex+0x2e9/0x4b0
[ 8243.714229] ? do_vfs_ioctl+0x8d/0x5b0
[ 8243.714231] ? kvm_on_user_return+0x6a/0xa0
[ 8243.714233] ? SyS_ioctl+0x74/0x80
[ 8243.714236] ? entry_SYSCALL_64_fastpath+0x1a/0xa5
[ 8243.714237] Code: a1 a0 02 00 00 4c 8b a9 a8 02 00 00 4c 8b b1 b0 02 00 00 4c 8b b9 b8 02 00 00 48 8b 89 48 02 00 00 75 05 0f 01 c2 eb 03 0f 01 c3 <48> 89 4c 24 08 59 48 89 81 40 02 00 00 48 89 99 58 02 00 00 8f
[ 8243.715029] Sending NMI from CPU 0 to CPUs 3:
[ 8243.716035] NMI backtrace for cpu 3
[ 8243.716036] CPU: 3 PID: 32 Comm: ksmd Not tainted 4.13.1-246.kvm #2
[ 8243.716037] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
[ 8243.716038] task: ffffa388309d50c0 task.stack: ffffa60680118000
[ 8243.716038] RIP: 0010:io_serial_out+0x11/0x20
[ 8243.716039] RSP: 0018:ffffa38839d83c70 EFLAGS: 00000002
[ 8243.716040] RAX: 0000000000000034 RBX: ffffffffb1df4d00 RCX: 0000000000000000
[ 8243.716041] RDX: 00000000000003f8 RSI: 0000000000000000 RDI: ffffffffb1df4d00
[ 8243.716041] RBP: ffffa38839d83c88 R08: 00000000000ae516 R09: 0000000000000004
[ 8243.716042] R10: 0000000000000000 R11: ffffffffb1da190d R12: 0000000000000034
[ 8243.716042] R13: ffffffffb1da193e R14: ffffffffb1da1905 R15: ffffffffb1df4d00
[ 8243.716043] FS: 0000000000000000(0000) GS:ffffa38839d80000(0000) knlGS:0000000000000000
[ 8243.716043] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 8243.716044] CR2: 00007f91e7adb490 CR3: 0000000107ca5000 CR4: 00000000001426a0
[ 8243.716044] Call Trace:
[ 8243.716045] <IRQ>
[ 8243.716045] ? serial8250_console_putchar+0x22/0x30
[ 8243.716046] ? wait_for_xmitr+0x90/0x90
[ 8243.716046] uart_console_write+0x43/0x60
[ 8243.716046] serial8250_console_write+0xeb/0x260
[ 8243.716047] ? msg_print_text+0x76/0x100
[ 8243.716047] univ8250_console_write+0x23/0x30
[ 8243.716048] console_unlock+0x2f0/0x450
[ 8243.716048] vprintk_emit+0x2f5/0x350
[ 8243.716048] vprintk_default+0x1a/0x20
[ 8243.716049] vprintk_func+0x22/0x60
[ 8243.716049] printk+0x43/0x45
[ 8243.716050] rcu_check_callbacks+0x466/0x840
[ 8243.716050] ? account_system_index_time+0x5e/0x70
[ 8243.716050] ? account_system_time+0x4b/0x60
[ 8243.716051] update_process_times+0x2a/0x50
[ 8243.716051] tick_sched_handle.isra.5+0x30/0x40
[ 8243.716052] tick_sched_timer+0x39/0x80
[ 8243.716052] __hrtimer_run_queues+0xaf/0x110
[ 8243.716052] hrtimer_interrupt+0x9b/0x1c0
[ 8243.716053] smp_apic_timer_interrupt+0x5e/0x90
[ 8243.716053] apic_timer_interrupt+0x8e/0xa0
[ 8243.716054] RIP: 0010:queued_spin_lock_slowpath+0x1b/0x190
[ 8243.716054] RSP: 0018:ffffa6068011bcd0 EFLAGS: 00000202 ORIG_RAX: ffffffffffffff10
[ 8243.716055] RAX: 0000000000000001 RBX: ffffa38707c190f0 RCX: 0000000000000000
[ 8243.716056] RDX: 0000000000000001 RSI: 0000000000000001 RDI: ffffa38707c10000
[ 8243.716056] RBP: ffffa6068011bcd8 R08: 0000000000000000 R09: ffffa38727953010
[ 8243.716057] R10: 0000000000000001 R11: 0000000000000000 R12: ffffa38707c10000
[ 8243.716057] R13: ffffa38707c19140 R14: 0000000000000000 R15: 00007f63404b9000
[ 8243.716058] </IRQ>
[ 8243.716058] ? _raw_spin_lock+0x1b/0x20
[ 8243.716058] kvm_mmu_notifier_invalidate_range_start+0x39/0x80
[ 8243.716059] __mmu_notifier_invalidate_range_start+0x50/0x80
[ 8243.716059] try_to_merge_one_page+0x53f/0x750
[ 8243.716060] ? uncharge_list+0x10f/0x120
[ 8243.716060] try_to_merge_with_ksm_page+0x49/0x90
[ 8243.716061] ksm_do_scan+0x673/0xe10
[ 8243.716061] ksm_scan_thread+0x196/0x1d0
[ 8243.716062] ? wait_woken+0x80/0x80
[ 8243.716062] kthread+0x11a/0x130
[ 8243.716062] ? ksm_do_scan+0xe10/0xe10
[ 8243.716063] ? kthread_create_on_node+0x40/0x40
[ 8243.716064] ret_from_fork+0x25/0x30
[ 8243.716064] Code: 00 8b 57 08 d3 e6 01 f2 ec 0f b6 c0 c3 0f 1f 00 66 2e 0f 1f 84 00 00 00 00 00 0f b6 8f a1 00 00 00 89 d0 8b 57 08 d3 e6 01 f2 ee <c3> 0f 1f 40 00 66 2e 0f 1f 84 00 00 00 00 00 0f b6 87 a2 00 00
[ 8243.716078] rcu_sched kthread starved for 59846 jiffies! g198525 c198524 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x0
[ 8243.716080] rcu_sched R running task 0 8 2 0x00000000
[ 8243.716082] Call Trace:
[ 8243.716090] __schedule+0x24d/0x7a0
[ 8243.716093] schedule+0x31/0x80
[ 8243.716095] schedule_timeout+0x14e/0x290
[ 8243.716098] ? del_timer_sync+0x40/0x40
[ 8243.716100] rcu_gp_kthread+0x52c/0x8d0
[ 8243.716104] kthread+0x11a/0x130
[ 8243.716106] ? note_gp_changes+0xa0/0xa0
[ 8243.716109] ? kthread_create_on_node+0x40/0x40
[ 8243.716111] ret_from_fork+0x25/0x30
[ 8243.726944] 3-...: (59999 ticks this GP) idle=fb6/140000000000001/0 softirq=365003/365003 fqs=28
[ 8243.728575] (t=60016 jiffies g=198525 c=198524 q=705)
[ 8243.729534] NMI backtrace for cpu 3
[ 8243.729538] CPU: 3 PID: 32 Comm: ksmd Not tainted 4.13.1-246.kvm #2
[ 8243.729540] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
[ 8243.729541] Call Trace:
[ 8243.729543] <IRQ>
[ 8243.729550] dump_stack+0x63/0x82
[ 8243.729554] nmi_cpu_backtrace+0xbe/0xc0
[ 8243.729571] ? irq_force_complete_move+0xe0/0xe0
[ 8243.729574] nmi_trigger_cpumask_backtrace+0x91/0xc0
[ 8243.729577] arch_trigger_cpumask_backtrace+0x14/0x20
[ 8243.729581] rcu_dump_cpu_stacks+0x9f/0xd8
[ 8243.729583] rcu_check_callbacks+0x6ed/0x840
[ 8243.729588] ? account_system_index_time+0x5e/0x70
[ 8243.729590] ? account_system_time+0x4b/0x60
[ 8243.729594] update_process_times+0x2a/0x50
[ 8243.729598] tick_sched_handle.isra.5+0x30/0x40
[ 8243.729600] tick_sched_timer+0x39/0x80
[ 8243.729604] __hrtimer_run_queues+0xaf/0x110
[ 8243.729607] hrtimer_interrupt+0x9b/0x1c0
[ 8243.729612] smp_apic_timer_interrupt+0x5e/0x90
[ 8243.729616] apic_timer_interrupt+0x8e/0xa0
[ 8243.729621] RIP: 0010:queued_spin_lock_slowpath+0x1b/0x190
[ 8243.729623] RSP: 0018:ffffa6068011bcd0 EFLAGS: 00000202 ORIG_RAX: ffffffffffffff10
[ 8243.729625] RAX: 0000000000000001 RBX: ffffa38707c190f0 RCX: 0000000000000000
[ 8243.729627] RDX: 0000000000000001 RSI: 0000000000000001 RDI: ffffa38707c10000
[ 8243.729628] RBP: ffffa6068011bcd8 R08: 0000000000000000 R09: ffffa38727953010
[ 8243.729629] R10: 0000000000000001 R11: 0000000000000000 R12: ffffa38707c10000
[ 8243.729630] R13: ffffa38707c19140 R14: 0000000000000000 R15: 00007f63404b9000
[ 8243.729632] </IRQ>
[ 8243.729635] ? _raw_spin_lock+0x1b/0x20
[ 8243.729640] kvm_mmu_notifier_invalidate_range_start+0x39/0x80
[ 8243.729646] __mmu_notifier_invalidate_range_start+0x50/0x80
[ 8243.729648] try_to_merge_one_page+0x53f/0x750
[ 8243.729652] ? uncharge_list+0x10f/0x120
[ 8243.729654] try_to_merge_with_ksm_page+0x49/0x90
[ 8243.729656] ksm_do_scan+0x673/0xe10
[ 8243.729658] ksm_scan_thread+0x196/0x1d0
[ 8243.729662] ? wait_woken+0x80/0x80
[ 8243.729668] kthread+0x11a/0x130
[ 8243.729670] ? ksm_do_scan+0xe10/0xe10
[ 8243.729673] ? kthread_create_on_node+0x40/0x40
[ 8243.729676] ret_from_fork+0x25/0x30
@chavafg @jcvenegas next time that happens can you also do the following
echo 1 >/sys/kernel/debug/tracing/events/kvm/enable
cat /sys/kernel/debug/tracing/trace_pipe
dump the pipe a few times
Also dump dmesg on the host
I will let the tests running again during the night with ksm off, will let you know what happens.
Ran the tests with ksm off in a loop 100 times and the issue was not reproducible.
Also, seems like this only happens on a nested virtualization environment. I ran the tests also in Baremetal and couldn't reproduce even with ksm enabled.