Actions
Bug #18130
closedsoft lockups in ceph.ko
% Done:
0%
Source:
Tags:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Crash signature (v1):
Crash signature (v2):
Description
While running xfstests vs. a ceph vstart cluster, I hitting softlockups in test generic/095. Looks like a we're cycling over and over again on a splice write? Unfortunately, the VM was completely frozen so I couldn't get more than the stack traces from the soft lockups. The kernel is the current ceph-client testing branch (commit b818a11fe + some d_revalidate changes, which I don't think would be related here):
[ 7579.947190] run fstests generic/094 at 2016-12-02 13:08:11 [ 7580.237678] run fstests generic/095 at 2016-12-02 13:08:11 [ 7581.157345] libceph: mon0 192.168.1.3:6789 session established [ 7581.159992] libceph: client4249 fsid ad1604e3-173c-4298-89d6-a5ed61dba811 [ 7582.529699] libceph: mon0 192.168.1.3:6789 session established [ 7582.532220] libceph: client4250 fsid ad1604e3-173c-4298-89d6-a5ed61dba811 [ 7608.369471] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 22s! [fio:16914] [ 7608.370481] Modules linked in: ceph(OE) libceph loop rpcsec_gss_krb5 nfsv4 dns_resolver nfs fscache ip6t_rpfilter ip6t_REJECT nf_reject_ipv6 xt_conntrack ip_set nfnetlink ebtable_nat ebtable_broute bridge stp llc ip6table_security ip6table_raw ip6table_mangle ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 iptable_security iptable_raw iptable_mangle iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack ebtable_filter ebtables ip6table_filter ip6_tables nfsd crct10dif_pclmul crc32_pclmul ghash_clmulni_intel acpi_cpufreq auth_rpcgss tpm_tis tpm_tis_core nfs_acl lockd tpm ppdev joydev floppy i2c_piix4 virtio_balloon pcspkr parport_pc parport qemu_fw_cfg grace sunrpc xfs libcrc32c qxl drm_kms_helper ttm drm virtio_net virtio_console virtio_blk crc32c_intel ata_generic virtio_pci pata_acpi serio_raw virtio_ring virtio [last unloaded: libceph] [ 7608.380623] CPU: 0 PID: 16914 Comm: fio Tainted: G OE 4.9.0-rc6+ #24 [ 7608.381550] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.1-1.fc24 04/01/2014 [ 7608.382606] task: ffff8b247960d880 task.stack: ffff9b3e88a1c000 [ 7608.383388] RIP: 0010:[<ffffffffac3f7ba6>] [<ffffffffac3f7ba6>] iov_iter_advance+0x36/0x380 [ 7608.384445] RSP: 0018:ffff9b3e88a1fa50 EFLAGS: 00000202 [ 7608.385161] RAX: 0000000000001000 RBX: 0000000000000000 RCX: ffff9b3e88a1fbb0 [ 7608.386062] RDX: 0000000000000005 RSI: 0000000000000000 RDI: ffff9b3e88a1fbb0 [ 7608.386961] RBP: ffff9b3e88a1faa0 R08: ffff9b3e88a1fba8 R09: 0000000000000000 [ 7608.387866] R10: ffff8b2477744d10 R11: ffffffffacc75c80 R12: 0000000000000000 [ 7608.388795] R13: ffff8b23f5687de0 R14: 0000000000000000 R15: 0000000000000001 [ 7608.389707] FS: 00007fca3ee3ba80(0000) GS:ffff8b247fc00000(0000) knlGS:0000000000000000 [ 7608.390714] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 7608.391482] CR2: 000000000046efd0 CR3: 0000000137845000 CR4: 00000000000406f0 [ 7608.392399] Stack: [ 7608.392792] ffff9b3e88a1fa60 0000000000000018 0000000000000002 0000000000000000 [ 7608.393821] 00000000137a28c7 0000000000000000 0000000000000002 ffff8b23f5687de0 [ 7608.394834] 0000000000000000 0000000000000001 ffff9b3e88a1fc10 ffffffffc09590ea [ 7608.395868] Call Trace: [ 7608.396341] [<ffffffffc09590ea>] ceph_direct_read_write+0x36a/0xc60 [ceph] [ 7608.397251] [<ffffffffc0959c94>] ceph_write_iter+0x2b4/0xbe0 [ceph] [ 7608.398104] [<ffffffffac06961b>] ? get_user_pages_fast+0x10b/0x1a0 [ 7608.398944] [<ffffffffac2505f2>] vfs_iter_write+0x92/0x110 [ 7608.399707] [<ffffffffac2842c9>] iter_file_splice_write+0x279/0x3f0 [ 7608.400554] [<ffffffffac284bb6>] SyS_splice+0x326/0x7f0 [ 7608.401291] [<ffffffffac05cf1e>] ? kvm_clock_get_cycles+0x1e/0x20 [ 7608.402121] [<ffffffffac809b77>] entry_SYSCALL_64_fastpath+0x1a/0xa9 [ 7608.402979] Code: 41 55 41 54 53 48 83 ec 28 8b 17 f6 c2 08 0f 85 21 01 00 00 48 8b 47 10 48 85 c0 74 78 48 39 c6 4c 8b 67 08 48 0f 47 f0 f6 c2 04 <49> 89 f0 75 74 83 e2 02 48 8b 77 18 0f 85 8d 02 00 00 4c 8b 4e [ 7636.370045] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 22s! [fio:16914] [ 7636.371116] Modules linked in: ceph(OE) libceph loop rpcsec_gss_krb5 nfsv4 dns_resolver nfs fscache ip6t_rpfilter ip6t_REJECT nf_reject_ipv6 xt_conntrack ip_set nfnetlink ebtable_nat ebtable_broute bridge stp llc ip6table_security ip6table_raw ip6table_mangle ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 iptable_security iptable_raw iptable_mangle iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack ebtable_filter ebtables ip6table_filter ip6_tables nfsd crct10dif_pclmul crc32_pclmul ghash_clmulni_intel acpi_cpufreq auth_rpcgss tpm_tis tpm_tis_core nfs_acl lockd tpm ppdev joydev floppy i2c_piix4 virtio_balloon pcspkr parport_pc parport qemu_fw_cfg grace sunrpc xfs libcrc32c qxl drm_kms_helper ttm drm virtio_net virtio_console virtio_blk crc32c_intel ata_generic virtio_pci pata_acpi serio_raw virtio_ring virtio [last unloaded: libceph] [ 7636.381824] CPU: 0 PID: 16914 Comm: fio Tainted: G OEL 4.9.0-rc6+ #24 [ 7636.382855] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.1-1.fc24 04/01/2014 [ 7636.384024] task: ffff8b247960d880 task.stack: ffff9b3e88a1c000 [ 7636.384883] RIP: 0010:[<ffffffffac3f7c1d>] [<ffffffffac3f7c1d>] iov_iter_advance+0xad/0x380 [ 7636.386016] RSP: 0018:ffff9b3e88a1faa0 EFLAGS: 00000286 [ 7636.386803] RAX: 0000000000001000 RBX: 0000000000000000 RCX: ffff9b3e88a1fbb0 [ 7636.387782] RDX: 0000000000000005 RSI: 0000000000000000 RDI: ffff9b3e88a1fbb0 [ 7636.388766] RBP: ffff9b3e88a1faa0 R08: 0000000000000000 R09: 0000000000000000 [ 7636.389750] R10: ffff8b2477744d10 R11: ffffffffacc75c80 R12: 0000000000000002 [ 7636.390728] R13: ffff8b23f5687de0 R14: 0000000000000000 R15: 0000000000000001 [ 7636.391693] FS: 00007fca3ee3ba80(0000) GS:ffff8b247fc00000(0000) knlGS:0000000000000000 [ 7636.392750] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 7636.393576] CR2: 000000000046efd0 CR3: 0000000137845000 CR4: 00000000000406f0 [ 7636.394541] Stack: [ 7636.394973] ffff9b3e88a1fc10 ffffffffc09590ea ffff8b2400000000 ffff8b2400000002 [ 7636.396018] ffff8b2400002201 ffff8b2400000064 ffff8b24704bdaa0 ffffffff00000001 [ 7636.397069] ffffffffffffffff ffff9b3e00000000 ffff8b246f8d6400 ffff9b3e88a1fd30 [ 7636.398114] Call Trace: [ 7636.398611] [<ffffffffc09590ea>] ceph_direct_read_write+0x36a/0xc60 [ceph] [ 7636.399556] [<ffffffffc0959c94>] ceph_write_iter+0x2b4/0xbe0 [ceph] [ 7636.400456] [<ffffffffac06961b>] ? get_user_pages_fast+0x10b/0x1a0 [ 7636.401335] [<ffffffffac2505f2>] vfs_iter_write+0x92/0x110 [ 7636.402130] [<ffffffffac2842c9>] iter_file_splice_write+0x279/0x3f0 [ 7636.403007] [<ffffffffac284bb6>] SyS_splice+0x326/0x7f0 [ 7636.403778] [<ffffffffac05cf1e>] ? kvm_clock_get_cycles+0x1e/0x20 [ 7636.404640] [<ffffffffac809b77>] entry_SYSCALL_64_fastpath+0x1a/0xa9 [ 7636.405523] Code: 00 48 89 fa 48 89 79 18 48 29 f2 48 c1 fa 04 48 29 51 20 4c 29 c0 4c 89 61 08 48 89 41 10 48 83 c4 28 5b 41 5c 41 5d 41 5e 41 5f <5d> c3 4c 8b 57 18 41 89 f5 45 31 c9 45 31 f6 49 c7 c3 80 5c c7 [ 7643.185184] INFO: rcu_sched detected stalls on CPUs/tasks: [ 7643.186125] (detected by 0, t=60002 jiffies, g=647181, c=647180, q=0) [ 7643.187046] All QSes seen, last rcu_sched kthread activity 60002 (4302310160-4302250158), jiffies_till_next_fqs=3, root ->qsmask 0x0 [ 7643.188750] fio R running task 0 16914 16897 0x00000008 [ 7643.189755] ffff8b247fc03e40 ffffffffac0cf783 ffff8b247fc1a400 fffffffface4cb00 [ 7643.190816] ffff8b247fc03ea8 ffffffffac10c6b0 0000000000000000 ffff8b247960d880 [ 7643.191878] ffff8b247fc1a400 ffffffff00000000 0000000000000000 ffff8b247960d880 [ 7643.192954] Call Trace: [ 7643.193454] <IRQ> [ 7643.193674] [<ffffffffac0cf783>] sched_show_task+0xd3/0x140 [ 7643.194507] [<ffffffffac10c6b0>] rcu_check_callbacks+0x8c0/0x8d0 [ 7643.195368] [<ffffffffac121d80>] ? tick_sched_do_timer+0x50/0x50 [ 7643.196241] [<ffffffffac111b8f>] update_process_times+0x2f/0x60 [ 7643.197091] [<ffffffffac1216d5>] tick_sched_handle.isra.17+0x25/0x60 [ 7643.197983] [<ffffffffac121dbd>] tick_sched_timer+0x3d/0x70 [ 7643.198793] [<ffffffffac11260e>] __hrtimer_run_queues+0xee/0x260 [ 7643.199631] [<ffffffffac112d9a>] hrtimer_interrupt+0x9a/0x180 [ 7643.200442] [<ffffffffac04b978>] local_apic_timer_interrupt+0x38/0x60 [ 7643.201324] [<ffffffffac80c72d>] smp_apic_timer_interrupt+0x3d/0x50 [ 7643.202182] [<ffffffffac80b8ec>] apic_timer_interrupt+0x8c/0xa0 [ 7643.203011] <EOI> [ 7643.203238] [<ffffffffac3f7b79>] ? iov_iter_advance+0x9/0x380 [ 7643.204064] [<ffffffffc09590ea>] ceph_direct_read_write+0x36a/0xc60 [ceph] [ 7643.204979] [<ffffffffc0959c94>] ceph_write_iter+0x2b4/0xbe0 [ceph] [ 7643.205840] [<ffffffffac06961b>] ? get_user_pages_fast+0x10b/0x1a0 [ 7643.206700] [<ffffffffac2505f2>] vfs_iter_write+0x92/0x110 [ 7643.207476] [<ffffffffac2842c9>] iter_file_splice_write+0x279/0x3f0 [ 7643.208337] [<ffffffffac284bb6>] SyS_splice+0x326/0x7f0 [ 7643.209083] [<ffffffffac05cf1e>] ? kvm_clock_get_cycles+0x1e/0x20 [ 7643.209903] [<ffffffffac809b77>] entry_SYSCALL_64_fastpath+0x1a/0xa9 [ 7643.210765] rcu_sched kthread starved for 60002 jiffies! g647181 c647180 f0x2 RCU_GP_WAIT_FQS(3) ->state=0x0 [ 7643.211990] rcu_sched R running task 0 7 2 0x00000000 [ 7643.212957] ffff8b246ef2da40 0000000000000000 ffff8b247abf8000 ffff8b247fc19600 [ 7643.213981] ffff8b23f5a3bb00 ffff9b3e8065fd78 ffffffffac804985 ffff8b247a400000 [ 7643.214993] 00ff8b247a400080 ffff8b247fc19600 ffff9b3e8065fdc0 ffff8b247abf8000 [ 7643.216012] Call Trace: [ 7643.216467] [<ffffffffac804985>] ? __schedule+0x225/0x6d0 [ 7643.217228] [<ffffffffac804e66>] schedule+0x36/0x80 [ 7643.217932] [<ffffffffac80823b>] schedule_timeout+0x1db/0x3f0 [ 7643.218726] [<ffffffffac110040>] ? del_timer_sync+0x50/0x50 [ 7643.219511] [<ffffffffac10a139>] rcu_gp_kthread+0x4d9/0x960 [ 7643.220285] [<ffffffffac109c60>] ? _synchronize_rcu_expedited.constprop.65+0x320/0x320 [ 7643.221288] [<ffffffffac0c1959>] kthread+0xd9/0xf0 [ 7643.221980] [<ffffffffac0c1880>] ? kthread_park+0x60/0x60 [ 7643.222745] [<ffffffffac809dd5>] ret_from_fork+0x25/0x30 [ 7668.370705] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 22s! [fio:16914] [ 7668.371756] Modules linked in: ceph(OE) libceph loop rpcsec_gss_krb5 nfsv4 dns_resolver nfs fscache ip6t_rpfilter ip6t_REJECT nf_reject_ipv6 xt_conntrack ip_set nfnetlink ebtable_nat ebtable_broute bridge stp llc ip6table_security ip6table_raw ip6table_mangle ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 iptable_security iptable_raw iptable_mangle iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack ebtable_filter ebtables ip6table_filter ip6_tables nfsd crct10dif_pclmul crc32_pclmul ghash_clmulni_intel acpi_cpufreq auth_rpcgss tpm_tis tpm_tis_core nfs_acl lockd tpm ppdev joydev floppy i2c_piix4 virtio_balloon pcspkr parport_pc parport qemu_fw_cfg grace sunrpc xfs libcrc32c qxl drm_kms_helper ttm drm virtio_net virtio_console virtio_blk crc32c_intel ata_generic virtio_pci pata_acpi serio_raw virtio_ring virtio [last unloaded: libceph] [ 7668.382576] CPU: 0 PID: 16914 Comm: fio Tainted: G OEL 4.9.0-rc6+ #24 [ 7668.383554] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.1-1.fc24 04/01/2014 [ 7668.384736] task: ffff8b247960d880 task.stack: ffff9b3e88a1c000 [ 7668.385609] RIP: 0010:[<ffffffffc09590e2>] [<ffffffffc09590e2>] ceph_direct_read_write+0x362/0xc60 [ceph] [ 7668.386939] RSP: 0018:ffff9b3e88a1fab0 EFLAGS: 00000246 [ 7668.387775] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000001 [ 7668.388793] RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffff9b3e88a1fbb0 [ 7668.389816] RBP: ffff9b3e88a1fc10 R08: ffff9b3e88a1fba8 R09: 0000000000000000 [ 7668.390842] R10: ffff8b2477744d10 R11: ffffffffacc75c80 R12: 0000000000000002 [ 7668.391875] R13: ffff8b23f5687de0 R14: 0000000000000000 R15: 0000000000000001 [ 7668.392869] FS: 00007fca3ee3ba80(0000) GS:ffff8b247fc00000(0000) knlGS:0000000000000000 [ 7668.393976] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 7668.394841] CR2: 000000000046efd0 CR3: 0000000137845000 CR4: 00000000000406f0 [ 7668.395861] Stack: [ 7668.396331] ffff8b2400000000 ffff8b2400000002 ffff8b2400002201 ffff8b2400000064 [ 7668.397375] ffff8b24704bdaa0 ffffffff00000001 ffffffffffffffff ffff9b3e00000000 [ 7668.398491] ffff8b246f8d6400 ffff9b3e88a1fd30 000000005841b88e 0000000032314610 [ 7668.399616] Call Trace: [ 7668.400155] [<ffffffffc0959c94>] ceph_write_iter+0x2b4/0xbe0 [ceph] [ 7668.401094] [<ffffffffac06961b>] ? get_user_pages_fast+0x10b/0x1a0 [ 7668.402053] [<ffffffffac2505f2>] vfs_iter_write+0x92/0x110 [ 7668.402916] [<ffffffffac2842c9>] iter_file_splice_write+0x279/0x3f0 [ 7668.403859] [<ffffffffac284bb6>] SyS_splice+0x326/0x7f0 [ 7668.404687] [<ffffffffac05cf1e>] ? kvm_clock_get_cycles+0x1e/0x20 [ 7668.405608] [<ffffffffac809b77>] entry_SYSCALL_64_fastpath+0x1a/0xa9 [ 7668.406534] Code: 85 c9 0f 8e 0d 02 00 00 45 31 ff 4c 8b ac 24 e8 00 00 00 4c 89 b4 24 a0 00 00 00 eb 36 4c 63 f0 48 8d bc 24 00 01 00 00 4c 89 f6 <4c> 29 f3 e8 86 ea a9 eb 48 8b 94 24 f8 00 00 00 49 8d 84 16 ff [ 7696.371279] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 22s! [fio:16914] [ 7696.372376] Modules linked in: ceph(OE) libceph loop rpcsec_gss_krb5 nfsv4 dns_resolver nfs fscache ip6t_rpfilter ip6t_REJECT nf_reject_ipv6 xt_conntrack ip_set nfnetlink ebtable_nat ebtable_broute bridge stp llc ip6table_security ip6table_raw ip6table_mangle ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 iptable_security iptable_raw iptable_mangle iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack ebtable_filter ebtables ip6table_filter ip6_tables nfsd crct10dif_pclmul crc32_pclmul ghash_clmulni_intel acpi_cpufreq auth_rpcgss tpm_tis tpm_tis_core nfs_acl lockd tpm ppdev joydev floppy i2c_piix4 virtio_balloon pcspkr parport_pc parport qemu_fw_cfg grace sunrpc xfs libcrc32c qxl drm_kms_helper ttm drm virtio_net virtio_console virtio_blk crc32c_intel ata_generic virtio_pci pata_acpi serio_raw virtio_ring virtio [last unloaded: libceph] [ 7696.383272] CPU: 0 PID: 16914 Comm: fio Tainted: G OEL 4.9.0-rc6+ #24 [ 7696.384342] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.1-1.fc24 04/01/2014 [ 7696.385520] task: ffff8b247960d880 task.stack: ffff9b3e88a1c000 [ 7696.386431] RIP: 0010:[<ffffffffac3fa562>] [<ffffffffac3fa562>] iov_iter_get_pages+0x102/0x340 [ 7696.387666] RSP: 0018:ffff9b3e88a1fa60 EFLAGS: 00000246 [ 7696.388536] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000001 [ 7696.389601] RDX: 0000000000000000 RSI: ffff8b23f5687de8 RDI: ffff9b3e88a1fbb0 [ 7696.390615] RBP: ffff9b3e88a1faa0 R08: ffff9b3e88a1fba8 R09: 0000000000000000 [ 7696.391585] R10: ffff8b2477744d10 R11: ffffffffacc75c80 R12: 0000000000000002 [ 7696.392542] R13: ffff8b23f5687de0 R14: 0000000000000000 R15: 0000000000000001 [ 7696.393528] FS: 00007fca3ee3ba80(0000) GS:ffff8b247fc00000(0000) knlGS:0000000000000000 [ 7696.394603] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 7696.395461] CR2: 000000000046efd0 CR3: 0000000137845000 CR4: 00000000000406f0 [ 7696.396429] Stack: [ 7696.396875] ffff9b3e88a1fbb0 0000000000000000 00000000137a28c7 0000000000000000 [ 7696.397940] 0000000000000002 ffff8b23f5687de0 0000000000000000 0000000000000001 [ 7696.399053] ffff9b3e88a1fc10 ffffffffc0959130 ffff8b2400000000 ffff8b2400000002 [ 7696.400184] Call Trace: [ 7696.400699] [<ffffffffc0959130>] ceph_direct_read_write+0x3b0/0xc60 [ceph] [ 7696.401694] [<ffffffffc0959c94>] ceph_write_iter+0x2b4/0xbe0 [ceph] [ 7696.402610] [<ffffffffac06961b>] ? get_user_pages_fast+0x10b/0x1a0 [ 7696.403529] [<ffffffffac2505f2>] vfs_iter_write+0x92/0x110 [ 7696.404356] [<ffffffffac2842c9>] iter_file_splice_write+0x279/0x3f0 [ 7696.405237] [<ffffffffac284bb6>] SyS_splice+0x326/0x7f0 [ 7696.406002] [<ffffffffac05cf1e>] ? kvm_clock_get_cycles+0x1e/0x20 [ 7696.406881] [<ffffffffac809b77>] entry_SYSCALL_64_fastpath+0x1a/0xa9 [ 7696.407789] Code: 0f 45 da 48 89 d8 49 2b 06 48 8b 75 d0 65 48 33 34 25 28 00 00 00 0f 85 43 02 00 00 48 83 c4 18 5b 41 5c 41 5d 41 5e 41 5f 5d c3 <31> c0 eb da 85 d2 74 f8 49 8b 4c 24 18 8b 41 08 29 f0 39 d0 48 [ 7724.371852] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 22s! [fio:16914] [ 7724.372945] Modules linked in: ceph(OE) libceph loop rpcsec_gss_krb5 nfsv4 dns_resolver nfs fscache ip6t_rpfilter ip6t_REJECT nf_reject_ipv6 xt_conntrack ip_set nfnetlink ebtable_nat ebtable_broute bridge stp llc ip6table_security ip6table_raw ip6table_mangle ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 iptable_security iptable_raw iptable_mangle iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack ebtable_filter ebtables ip6table_filter ip6_tables nfsd crct10dif_pclmul crc32_pclmul ghash_clmulni_intel acpi_cpufreq auth_rpcgss tpm_tis tpm_tis_core nfs_acl lockd tpm ppdev joydev floppy i2c_piix4 virtio_balloon pcspkr parport_pc parport qemu_fw_cfg grace sunrpc xfs libcrc32c qxl drm_kms_helper ttm drm virtio_net virtio_console virtio_blk crc32c_intel ata_generic virtio_pci pata_acpi serio_raw virtio_ring virtio [last unloaded: libceph] [ 7724.383794] CPU: 0 PID: 16914 Comm: fio Tainted: G OEL 4.9.0-rc6+ #24 [ 7724.384850] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.1-1.fc24 04/01/2014 [ 7724.386062] task: ffff8b247960d880 task.stack: ffff9b3e88a1c000 [ 7724.386943] RIP: 0010:[<ffffffffc09590fa>] [<ffffffffc09590fa>] ceph_direct_read_write+0x37a/0xc60 [ceph] [ 7724.388212] RSP: 0018:ffff9b3e88a1fab0 EFLAGS: 00000286 [ 7724.389019] RAX: 0000000000000fff RBX: 0000000000000000 RCX: ffff9b3e88a1fbb0 [ 7724.390003] RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffff9b3e88a1fbb0 [ 7724.390979] RBP: ffff9b3e88a1fc10 R08: 0000000000000000 R09: 0000000000000000 [ 7724.391951] R10: ffff8b2477744d10 R11: ffffffffacc75c80 R12: 0000000000000002 [ 7724.392918] R13: ffff8b23f5687de0 R14: 0000000000000000 R15: 0000000000000001 [ 7724.393892] FS: 00007fca3ee3ba80(0000) GS:ffff8b247fc00000(0000) knlGS:0000000000000000 [ 7724.394971] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 7724.395800] CR2: 000000000046efd0 CR3: 0000000137845000 CR4: 00000000000406f0 [ 7724.396768] Stack: [ 7724.397202] ffff8b2400000000 ffff8b2400000002 ffff8b2400002201 ffff8b2400000064 [ 7724.398270] ffff8b24704bdaa0 ffffffff00000001 ffffffffffffffff ffff9b3e00000000 [ 7724.399348] ffff8b246f8d6400 ffff9b3e88a1fd30 000000005841b88e 0000000032314610 [ 7724.400402] Call Trace: [ 7724.400908] [<ffffffffc0959c94>] ceph_write_iter+0x2b4/0xbe0 [ceph] [ 7724.401810] [<ffffffffac06961b>] ? get_user_pages_fast+0x10b/0x1a0 [ 7724.402715] [<ffffffffac2505f2>] vfs_iter_write+0x92/0x110 [ 7724.403548] [<ffffffffac2842c9>] iter_file_splice_write+0x279/0x3f0 [ 7724.404428] [<ffffffffac284bb6>] SyS_splice+0x326/0x7f0 [ 7724.405215] [<ffffffffac05cf1e>] ? kvm_clock_get_cycles+0x1e/0x20 [ 7724.406087] [<ffffffffac809b77>] entry_SYSCALL_64_fastpath+0x1a/0xa9 [ 7724.406981] Code: 00 00 00 eb 36 4c 63 f0 48 8d bc 24 00 01 00 00 4c 89 f6 4c 29 f3 e8 86 ea a9 eb 48 8b 94 24 f8 00 00 00 49 8d 84 16 ff 0f 00 00 <48> c1 e8 0c 41 01 c7 45 39 fc 0f 8e ba 01 00 00 49 63 c7 44 89 [ 7752.372427] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 22s! [fio:16914] [ 7752.373512] Modules linked in: ceph(OE) libceph loop rpcsec_gss_krb5 nfsv4 dns_resolver nfs fscache ip6t_rpfilter ip6t_REJECT nf_reject_ipv6 xt_conntrack ip_set nfnetlink ebtable_nat ebtable_broute bridge stp llc ip6table_security ip6table_raw ip6table_mangle ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 iptable_security iptable_raw iptable_mangle iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack ebtable_filter ebtables ip6table_filter ip6_tables nfsd crct10dif_pclmul crc32_pclmul ghash_clmulni_intel acpi_cpufreq auth_rpcgss tpm_tis tpm_tis_core nfs_acl lockd tpm ppdev joydev floppy i2c_piix4 virtio_balloon pcspkr parport_pc parport qemu_fw_cfg grace sunrpc xfs libcrc32c qxl drm_kms_helper ttm drm virtio_net virtio_console virtio_blk crc32c_intel ata_generic virtio_pci pata_acpi serio_raw virtio_ring virtio [last unloaded: libceph] [ 7752.384304] CPU: 0 PID: 16914 Comm: fio Tainted: G OEL 4.9.0-rc6+ #24 [ 7752.385330] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.1-1.fc24 04/01/2014 [ 7752.386526] task: ffff8b247960d880 task.stack: ffff9b3e88a1c000 [ 7752.387417] RIP: 0010:[<ffffffffc095911d>] [<ffffffffc095911d>] ceph_direct_read_write+0x39d/0xc60 [ceph] [ 7752.388725] RSP: 0018:ffff9b3e88a1fab0 EFLAGS: 00000202 [ 7752.389542] RAX: 0000000000000001 RBX: 0000000000000000 RCX: 0000000000000002 [ 7752.390530] RDX: 0000000000000000 RSI: ffff8b23f5687de8 RDI: ffff9b3e88a1fbb0 [ 7752.391518] RBP: ffff9b3e88a1fc10 R08: ffff9b3e88a1fba8 R09: 0000000000000000 [ 7752.392489] R10: ffff8b2477744d10 R11: ffffffffacc75c80 R12: 0000000000000002 [ 7752.393458] R13: ffff8b23f5687de0 R14: 0000000000000000 R15: 0000000000000001 [ 7752.394426] FS: 00007fca3ee3ba80(0000) GS:ffff8b247fc00000(0000) knlGS:0000000000000000 [ 7752.395499] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 7752.396323] CR2: 000000000046efd0 CR3: 0000000137845000 CR4: 00000000000406f0 [ 7752.397286] Stack: [ 7752.397721] ffff8b2400000000 ffff8b2400000002 ffff8b2400002201 ffff8b2400000064 [ 7752.398770] ffff8b24704bdaa0 ffffffff00000001 ffffffffffffffff ffff9b3e00000000 [ 7752.399827] ffff8b246f8d6400 ffff9b3e88a1fd30 000000005841b88e 0000000032314610 [ 7752.400895] Call Trace: [ 7752.401396] [<ffffffffc0959c94>] ceph_write_iter+0x2b4/0xbe0 [ceph] [ 7752.402281] [<ffffffffac06961b>] ? get_user_pages_fast+0x10b/0x1a0 [ 7752.403167] [<ffffffffac2505f2>] vfs_iter_write+0x92/0x110 [ 7752.403991] [<ffffffffac2842c9>] iter_file_splice_write+0x279/0x3f0 [ 7752.404917] [<ffffffffac284bb6>] SyS_splice+0x326/0x7f0 [ 7752.405688] [<ffffffffac05cf1e>] ? kvm_clock_get_cycles+0x1e/0x20 [ 7752.406568] [<ffffffffac809b77>] entry_SYSCALL_64_fastpath+0x1a/0xa9 [ 7752.407453] Code: 49 8d 84 16 ff 0f 00 00 48 c1 e8 0c 41 01 c7 45 39 fc 0f 8e ba 01 00 00 49 63 c7 44 89 e1 4c 8d 84 24 f8 00 00 00 49 8d 74 c5 00 <48> 8d bc 24 00 01 00 00 44 29 f9 48 89 da e8 30 13 aa eb 85 c0 [ 7780.373001] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 23s! [fio:16914] [ 7780.374091] Modules linked in: ceph(OE) libceph loop rpcsec_gss_krb5 nfsv4 dns_resolver nfs fscache ip6t_rpfilter ip6t_REJECT nf_reject_ipv6 xt_conntrack ip_set nfnetlink ebtable_nat ebtable_broute bridge stp llc ip6table_security ip6table_raw ip6table_mangle ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 iptable_security iptable_raw iptable_mangle iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack ebtable_filter ebtables ip6table_filter ip6_tables nfsd crct10dif_pclmul crc32_pclmul ghash_clmulni_intel acpi_cpufreq auth_rpcgss tpm_tis tpm_tis_core nfs_acl lockd tpm ppdev joydev floppy i2c_piix4 virtio_balloon pcspkr parport_pc parport qemu_fw_cfg grace sunrpc xfs libcrc32c qxl drm_kms_helper ttm drm virtio_net virtio_console virtio_blk crc32c_intel ata_generic virtio_pci pata_acpi serio_raw virtio_ring virtio [last unloaded: libceph] [ 7780.384722] CPU: 0 PID: 16914 Comm: fio Tainted: G OEL 4.9.0-rc6+ #24 [ 7780.385748] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.1-1.fc24 04/01/2014 [ 7780.386958] task: ffff8b247960d880 task.stack: ffff9b3e88a1c000 [ 7780.387848] RIP: 0010:[<ffffffffac3fa46c>] [<ffffffffac3fa46c>] iov_iter_get_pages+0xc/0x340 [ 7780.389035] RSP: 0018:ffff9b3e88a1fa80 EFLAGS: 00000202 [ 7780.389914] RAX: 0000000000000001 RBX: 0000000000000000 RCX: 0000000000000001 [ 7780.390948] RDX: 0000000000000000 RSI: ffff8b23f5687de8 RDI: ffff9b3e88a1fbb0 [ 7780.391969] RBP: ffff9b3e88a1faa0 R08: ffff9b3e88a1fba8 R09: 0000000000000000 [ 7780.392950] R10: ffff8b2477744d10 R11: ffffffffacc75c80 R12: 0000000000000002 [ 7780.393939] R13: ffff8b23f5687de0 R14: 0000000000000000 R15: 0000000000000001 [ 7780.394930] FS: 00007fca3ee3ba80(0000) GS:ffff8b247fc00000(0000) knlGS:0000000000000000 [ 7780.396026] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 7780.396864] CR2: 000000000046efd0 CR3: 0000000137845000 CR4: 00000000000406f0 [ 7780.397840] Stack: [ 7780.398277] 0000000000000002 ffff8b23f5687de0 0000000000000000 0000000000000001 [ 7780.399340] ffff9b3e88a1fc10 ffffffffc0959130 ffff8b2400000000 ffff8b2400000002 [ 7780.400420] ffff8b2400002201 ffff8b2400000064 ffff8b24704bdaa0 ffffffff00000001 [ 7780.401467] Call Trace: [ 7780.401971] [<ffffffffc0959130>] ceph_direct_read_write+0x3b0/0xc60 [ceph] [ 7780.402967] [<ffffffffc0959c94>] ceph_write_iter+0x2b4/0xbe0 [ceph] [ 7780.403874] [<ffffffffac06961b>] ? get_user_pages_fast+0x10b/0x1a0 [ 7780.404767] [<ffffffffac2505f2>] vfs_iter_write+0x92/0x110 [ 7780.405589] [<ffffffffac2842c9>] iter_file_splice_write+0x279/0x3f0 [ 7780.406481] [<ffffffffac284bb6>] SyS_splice+0x326/0x7f0 [ 7780.407262] [<ffffffffac05cf1e>] ? kvm_clock_get_cycles+0x1e/0x20 [ 7780.408122] [<ffffffffac809b77>] entry_SYSCALL_64_fastpath+0x1a/0xa9 [ 7780.409017] Code: 85 c0 0f 85 f6 fe ff ff 4d 85 ed 0f 84 ed fe ff ff eb c1 66 90 66 2e 0f 1f 84 00 00 00 00 00 55 48 89 e5 41 57 41 56 41 55 41 54 <53> 48 89 d3 48 83 ec 18 65 48 8b 04 25 28 00 00 00 48 89 45 d0 [ 7808.373575] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 23s! [fio:16914] [ 7808.374678] Modules linked in: ceph(OE) libceph loop rpcsec_gss_krb5 nfsv4 dns_resolver nfs fscache ip6t_rpfilter ip6t_REJECT nf_reject_ipv6 xt_conntrack ip_set nfnetlink ebtable_nat ebtable_broute bridge stp llc ip6table_security ip6table_raw ip6table_mangle ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 iptable_security iptable_raw iptable_mangle iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack ebtable_filter ebtables ip6table_filter ip6_tables nfsd crct10dif_pclmul crc32_pclmul ghash_clmulni_intel acpi_cpufreq auth_rpcgss tpm_tis tpm_tis_core nfs_acl lockd tpm ppdev joydev floppy i2c_piix4 virtio_balloon pcspkr parport_pc parport qemu_fw_cfg grace sunrpc xfs libcrc32c qxl drm_kms_helper ttm drm virtio_net virtio_console virtio_blk crc32c_intel ata_generic virtio_pci pata_acpi serio_raw virtio_ring virtio [last unloaded: libceph] [ 7808.385453] CPU: 0 PID: 16914 Comm: fio Tainted: G OEL 4.9.0-rc6+ #24 [ 7808.386521] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.1-1.fc24 04/01/2014 [ 7808.387735] task: ffff8b247960d880 task.stack: ffff9b3e88a1c000 [ 7808.388625] RIP: 0010:[<ffffffffac3f7b71>] [<ffffffffac3f7b71>] iov_iter_advance+0x1/0x380 [ 7808.389765] RSP: 0018:ffff9b3e88a1faa0 EFLAGS: 00000246 [ 7808.390560] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000001 [ 7808.391542] RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffff9b3e88a1fbb0 [ 7808.392536] RBP: ffff9b3e88a1fc10 R08: ffff9b3e88a1fba8 R09: 0000000000000000 [ 7808.393510] R10: ffff8b2477744d10 R11: ffffffffacc75c80 R12: 0000000000000002 [ 7808.394474] R13: ffff8b23f5687de0 R14: 0000000000000000 R15: 0000000000000001 [ 7808.395433] FS: 00007fca3ee3ba80(0000) GS:ffff8b247fc00000(0000) knlGS:0000000000000000 [ 7808.396488] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 7808.397309] CR2: 000000000046efd0 CR3: 0000000137845000 CR4: 00000000000406f0 [ 7808.398272] Stack: [ 7808.398710] ffff9b3e88a1fc10 ffffffffc09590ea ffff8b2400000000 ffff8b2400000002 [ 7808.399760] ffff8b2400002201 ffff8b2400000064 ffff8b24704bdaa0 ffffffff00000001 [ 7808.400821] ffffffffffffffff ffff9b3e00000000 ffff8b246f8d6400 ffff9b3e88a1fd30 [ 7808.401879] Call Trace: [ 7808.402381] [<ffffffffc09590ea>] ? ceph_direct_read_write+0x36a/0xc60 [ceph] [ 7808.403362] [<ffffffffc0959c94>] ceph_write_iter+0x2b4/0xbe0 [ceph] [ 7808.404291] [<ffffffffac06961b>] ? get_user_pages_fast+0x10b/0x1a0 [ 7808.405216] [<ffffffffac2505f2>] vfs_iter_write+0x92/0x110 [ 7808.406045] [<ffffffffac2842c9>] iter_file_splice_write+0x279/0x3f0 [ 7808.406938] [<ffffffffac284bb6>] SyS_splice+0x326/0x7f0 [ 7808.407722] [<ffffffffac05cf1e>] ? kvm_clock_get_cycles+0x1e/0x20 [ 7808.408586] [<ffffffffac809b77>] entry_SYSCALL_64_fastpath+0x1a/0xa9 [ 7808.409465] Code: ff 74 eb 48 8b 16 48 85 c0 4d 89 c1 49 0f 44 d0 48 39 f9 4c 0f 45 c9 48 09 d0 4c 09 c8 48 29 f9 0f 84 54 fe ff ff eb c6 66 90 55 <48> 89 f9 48 89 e5 41 57 41 56 41 55 41 54 53 48 83 ec 28 8b 17 [ 7823.193878] INFO: rcu_sched detected stalls on CPUs/tasks: [ 7823.194828] (detected by 0, t=240007 jiffies, g=647181, c=647180, q=0) [ 7823.195790] All QSes seen, last rcu_sched kthread activity 240007 (4302490165-4302250158), jiffies_till_next_fqs=3, root ->qsmask 0x0 [ 7823.197484] fio R running task 0 16914 16897 0x00000008 [ 7823.198486] ffff8b247fc03e40 ffffffffac0cf783 ffff8b247fc1a400 fffffffface4cb00 [ 7823.199546] ffff8b247fc03ea8 ffffffffac10c6b0 0000000000000000 ffff8b247960d880 [ 7823.200620] ffff8b247fc1a400 ffffffff00000000 0000000000000000 ffff8b247960d880 [ 7823.201698] Call Trace: [ 7823.202192] <IRQ> [ 7823.202411] [<ffffffffac0cf783>] sched_show_task+0xd3/0x140 [ 7823.203239] [<ffffffffac10c6b0>] rcu_check_callbacks+0x8c0/0x8d0 [ 7823.204097] [<ffffffffac121d80>] ? tick_sched_do_timer+0x50/0x50 [ 7823.204972] [<ffffffffac111b8f>] update_process_times+0x2f/0x60 [ 7823.205848] [<ffffffffac1216d5>] tick_sched_handle.isra.17+0x25/0x60 [ 7823.206777] [<ffffffffac121dbd>] tick_sched_timer+0x3d/0x70 [ 7823.207635] [<ffffffffac11260e>] __hrtimer_run_queues+0xee/0x260 [ 7823.208496] [<ffffffffac112d9a>] hrtimer_interrupt+0x9a/0x180 [ 7823.209314] [<ffffffffac04b978>] local_apic_timer_interrupt+0x38/0x60 [ 7823.210194] [<ffffffffac80c72d>] smp_apic_timer_interrupt+0x3d/0x50 [ 7823.211052] [<ffffffffac80b8ec>] apic_timer_interrupt+0x8c/0xa0 [ 7823.211881] <EOI> [ 7823.212115] [<ffffffffc09590d4>] ? ceph_direct_read_write+0x354/0xc60 [ceph] [ 7823.213102] [<ffffffffc0959c94>] ceph_write_iter+0x2b4/0xbe0 [ceph] [ 7823.213962] [<ffffffffac06961b>] ? get_user_pages_fast+0x10b/0x1a0 [ 7823.214824] [<ffffffffac2505f2>] vfs_iter_write+0x92/0x110 [ 7823.215602] [<ffffffffac2842c9>] iter_file_splice_write+0x279/0x3f0 [ 7823.216467] [<ffffffffac284bb6>] SyS_splice+0x326/0x7f0 [ 7823.217215] [<ffffffffac05cf1e>] ? kvm_clock_get_cycles+0x1e/0x20 [ 7823.218059] [<ffffffffac809b77>] entry_SYSCALL_64_fastpath+0x1a/0xa9 [ 7823.218919] rcu_sched kthread starved for 240007 jiffies! g647181 c647180 f0x2 RCU_GP_WAIT_FQS(3) ->state=0x0 [ 7823.220147] rcu_sched R running task 0 7 2 0x00000000 [ 7823.221117] ffff8b246ef2da40 0000000000000000 ffff8b247abf8000 ffff8b247fc19600 [ 7823.222136] ffff8b23f5a3bb00 ffff9b3e8065fd78 ffffffffac804985 ffff8b247a400000 [ 7823.223211] 00ff8b247a400080 ffff8b247fc19600 ffff9b3e8065fdc0 ffff8b247abf8000 [ 7823.224274] Call Trace: [ 7823.224758] [<ffffffffac804985>] ? __schedule+0x225/0x6d0 [ 7823.225515] [<ffffffffac804e66>] schedule+0x36/0x80 [ 7823.226220] [<ffffffffac80823b>] schedule_timeout+0x1db/0x3f0 [ 7823.227015] [<ffffffffac110040>] ? del_timer_sync+0x50/0x50 [ 7823.227784] [<ffffffffac10a139>] rcu_gp_kthread+0x4d9/0x960 [ 7823.228572] [<ffffffffac109c60>] ? _synchronize_rcu_expedited.constprop.65+0x320/0x320 [ 7823.229595] [<ffffffffac0c1959>] kthread+0xd9/0xf0 [ 7823.230300] [<ffffffffac0c1880>] ? kthread_park+0x60/0x60 [ 7823.231082] [<ffffffffac809dd5>] ret_from_fork+0x25/0x30 [ 7848.374400] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 22s! [fio:16914] [ 7848.375451] Modules linked in: ceph(OE) libceph loop rpcsec_gss_krb5 nfsv4 dns_resolver nfs fscache ip6t_rpfilter ip6t_REJECT nf_reject_ipv6 xt_conntrack ip_set nfnetlink ebtable_nat ebtable_broute bridge stp llc ip6table_security ip6table_raw ip6table_mangle ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 iptable_security iptable_raw iptable_mangle iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack ebtable_filter ebtables ip6table_filter ip6_tables nfsd crct10dif_pclmul crc32_pclmul ghash_clmulni_intel acpi_cpufreq auth_rpcgss tpm_tis tpm_tis_core nfs_acl lockd tpm ppdev joydev floppy i2c_piix4 virtio_balloon pcspkr parport_pc parport qemu_fw_cfg grace sunrpc xfs libcrc32c qxl drm_kms_helper ttm drm virtio_net virtio_console virtio_blk crc32c_intel ata_generic virtio_pci pata_acpi serio_raw virtio_ring virtio [last unloaded: libceph] [ 7848.385913] CPU: 0 PID: 16914 Comm: fio Tainted: G OEL 4.9.0-rc6+ #24 [ 7848.386910] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.1-1.fc24 04/01/2014 [ 7848.388009] task: ffff8b247960d880 task.stack: ffff9b3e88a1c000 [ 7848.388817] RIP: 0010:[<ffffffffac3fa55e>] [<ffffffffac3fa55e>] iov_iter_get_pages+0xfe/0x340 [ 7848.389919] RSP: 0018:ffff9b3e88a1fa98 EFLAGS: 00000286 [ 7848.390666] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000001 [ 7848.391598] RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffff9b3e88a1fbb0 [ 7848.392547] RBP: ffff9b3e88a1faa0 R08: ffff9b3e88a1fba8 R09: 0000000000000000 [ 7848.393470] R10: ffff8b2477744d10 R11: ffffffffacc75c80 R12: 0000000000000002 [ 7848.394401] R13: ffff8b23f5687de0 R14: 0000000000000000 R15: 0000000000000001 [ 7848.395337] FS: 00007fca3ee3ba80(0000) GS:ffff8b247fc00000(0000) knlGS:0000000000000000 [ 7848.396358] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 7848.397156] CR2: 000000000046efd0 CR3: 0000000137845000 CR4: 00000000000406f0 [ 7848.398113] Stack: [ 7848.398537] 0000000000000001 ffff9b3e88a1fc10 ffffffffc0959130 ffff8b2400000000 [ 7848.399548] ffff8b2400000002 ffff8b2400002201 ffff8b2400000064 ffff8b24704bdaa0 [ 7848.400582] ffffffff00000001 ffffffffffffffff ffff9b3e00000000 ffff8b246f8d6400 [ 7848.401636] Call Trace: [ 7848.402116] [<ffffffffc0959130>] ceph_direct_read_write+0x3b0/0xc60 [ceph] [ 7848.403067] [<ffffffffc0959c94>] ceph_write_iter+0x2b4/0xbe0 [ceph] [ 7848.403954] [<ffffffffac06961b>] ? get_user_pages_fast+0x10b/0x1a0 [ 7848.404808] [<ffffffffac2505f2>] vfs_iter_write+0x92/0x110 [ 7848.405622] [<ffffffffac2842c9>] iter_file_splice_write+0x279/0x3f0 [ 7848.406601] [<ffffffffac284bb6>] SyS_splice+0x326/0x7f0 [ 7848.407385] [<ffffffffac05cf1e>] ? kvm_clock_get_cycles+0x1e/0x20 [ 7848.408307] [<ffffffffac809b77>] entry_SYSCALL_64_fastpath+0x1a/0xa9 [ 7848.409219] Code: 44 39 f8 48 0f 45 da 48 89 d8 49 2b 06 48 8b 75 d0 65 48 33 34 25 28 00 00 00 0f 85 43 02 00 00 48 83 c4 18 5b 41 5c 41 5d 41 5e <41> 5f 5d c3 31 c0 eb da 85 d2 74 f8 49 8b 4c 24 18 8b 41 08 29
Updated by Zheng Yan over 7 years ago
looks like our code can't handle iov_iter of type ITER_PIPE
Updated by Jeff Layton over 7 years ago
I don't see where ITER_PIPE gets used in the write codepaths. Maybe ITER_BVEC needs special handling? In any case, I'll plan to instrument this code and figure out what's going on.
Updated by Jeff Layton over 7 years ago
Ok, this is proving difficult to troubleshoot as the softlockups end up bringing the box to its knees.
I think at this point that the code is continually looping in dio_get_pages_alloc. Perhaps the splice codepath is passing in something different there that causes this to happen. In any case, I'll keep going with more instrumentation here.
Updated by Jeff Layton over 7 years ago
I think I see the problem. Still looking at the fix. I converted some dout messages to printks (just for simplicity) and just before the softlockups I see this:
[ 51.695013] count=1024 size=1024 [ 51.695016] dio_get_pages_alloc: align=3072 nbytes=1024 npages=1 [ 51.695018] dio_get_pages_alloc: got 1 pages align 3072 [ 51.701890] sync_direct_read_write (write) on file ffff8ea6ad799d00 90112~8192 type=1 [ 51.703208] sync_direct_read_write (write) on file ffff8ea6ad799f00 434176~8192 type=1 [ 51.704532] sync_direct_read_write (write) on file ffff8ea6ad799500 393216~8192 type=1 [ 51.786488] count=8192 size=4096 [ 51.788031] dio_get_pages_alloc: align=512 nbytes=4096 npages=2 [ 51.867789] count=8192 size=4096 [ 51.870118] dio_get_pages_alloc: align=384 nbytes=4096 npages=2 [ 51.941070] sync_direct_read_write (write) on file ffff8ea6b56db600 449536~1024 type=1 [ 55.200810] dio_get_pages_alloc: 43535991 callbacks suppressed [ 55.202135] dio_get_pages_alloc: align=3648 ret=0 start=0 idx=1 npages=2 [ 55.202136] dio_get_pages_alloc: align=512 ret=0 start=0 idx=1 npages=2 [ 55.202138] dio_get_pages_alloc: align=512 ret=0 start=0 idx=1 npages=2 [ 55.202139] dio_get_pages_alloc: align=512 ret=0 start=0 idx=1 npages=2 [ 55.202139] dio_get_pages_alloc: align=512 ret=0 start=0 idx=1 npages=2 [ 55.202140] dio_get_pages_alloc: align=512 ret=0 start=0 idx=1 npages=2
Those printk message drops mean that we're looping there, most likely and that's inside the for loop in dio_get_pages_alloc.
The handling of idx therefore in the for loop in dio_get_pages_alloc seems like it's probably wrong or we're calling iov_iter_get_pages with the wrong args in non-aligned cases.
Updated by Jeff Layton over 7 years ago
Added a bit more info, including the tgid for the task. That allows us to tell what thread context each of these is operating. Here's one:
[ 5192.109181] sync_direct_read_write (write) on file ffff97e2757b6800 139264~8192 type=5 tgid=1731 [ 5192.109189] tgid=1731 count=8192 size=4096 [ 5192.109196] dio_get_pages_alloc: tgid=1731 align=1920 nbytes=4096 npages=2 [ 5195.619136] dio_get_pages_alloc: tgid=1731 align=1920 ret=0 start=0 idx=1 npages=2 nbytes=0
So what's happening is that we're calling iov_iter_get_pages and getting back 0 bytes, because we're passing in 0 for the "maxsize" argument after the iovec has been consumed. We have no more bytes that need to be consumed, but we still don't have all of the pages we expect.
So there seems to be a disconnect between what we get in calc_pages_for and what iov_iter_get_pages does. My money is on calc_pages_for being wrong, but I'm not quite sure yet. The new iov_iter code is really hard to follow.
Updated by Jeff Layton over 7 years ago
Ok, revamped my debugging a bit and fixed the code to error out when no progress is being made. Now I see this:
[ 605.822409] dio_get_pages_alloc: tgid=1674 align=1536 nbytes=4096 npages=2 iov_base=0xffffde118439a600 iov_offset=0 [ 605.826509] dio_get_pages_alloc: tgid=1674 align=1536 ret=4096 start=0 idx=0 npages=2 nbytes=4096 [ 605.826510] dio_get_pages_alloc: tgid=1674 align=1536 ret=0 start=0 idx=1 npages=2 nbytes=0 [ 605.826511] dio_get_pages_alloc: fail(-61)
The align and npages values make sense here -- we do need two pages for this request. We called into iov_iter_get_pages, which consumes all 4096 bytes, but then it sets the "start" parameter to 0 rather than the value for "align".
I suspect that this is a bug in iov_iter_get_pages and I'm asking Al about it now...
Actually it's even worse -- we end up only getting one page in the array instead of the expected two. Still investigating...
Updated by Jeff Layton over 7 years ago
fio jobfile that easily reproduces this:
[global] bs=8k randrepeat=1 size=1m directory=/mnt/scratch numjobs=5 iodepth=16 iodepth_batch=8 [job1] ioengine=splice direct=1 rw=randwrite filename=file1:file2
Updated by Jeff Layton over 7 years ago
Ok, I think the problem is actually here and this patch fixes it:
diff --git a/fs/ceph/file.c b/fs/ceph/file.c
index f633165f3fdc..5f47087ff84c 100644
--- a/fs/ceph/file.c
+++ b/fs/ceph/file.c
@@ -71,8 +71,7 @@ dio_get_pages_alloc(const struct iov_iter *it, size_t nbytes,
struct page **pages;
int ret = 0, idx, npages;
- align = (unsigned long)(it->iov->iov_base + it->iov_offset) &
- (PAGE_SIZE - 1);
+ align = iov_iter_alignment(it) & (PAGE_SIZE - 1);
npages = calc_pages_for(align, nbytes);
pages = kmalloc(sizeof(*pages) * npages, GFP_KERNEL);
if (!pages) {
Basically, with the change to the new iov_iter infrastructure, we can't assume that the iov_iter actually contains iovecs. It could contain kvecs or bvecs as well, and that alignment calculation will misrepresent those.
This patch seems to fix the testcases, but there is some similar breakage in dio_get_pagev_size(). That function will also need to be reworked, and that might require a new iov_iter helper.
Updated by Jeff Layton over 7 years ago
Bulding and testing a revised patch now.
iov_iter_alignment is not quite right since it takes the iov_len into account. It happened to fix this specific case, but is not generally correct. To fix that we have to add yet another iov_iter helper to find the offset into the page of the first segement for all types. I also have replaced dio_get_pagev_size with a generic iov_iter helper.
Updated by Jeff Layton over 7 years ago
New patch sent this morning that seems to fix this problem. Still waiting for feedback from Al Viro as to why ITER_BVEC handling in iov_iter_get_pages is limited to handing out single page at a time. Very odd.
Updated by Zheng Yan about 7 years ago
- Status changed from New to Resolved
relevant code has been removed. (now vfs helpers are used)
Updated by Jeff Layton about 7 years ago
- Status changed from Resolved to In Progress
No, not quite resolved yet. I have a couple of patches for this in the testing branch, but they're marked DNM for now. Al Viro is reworking this code into a iov_iter_for_each_page model. Once he does that we'll want to wire up this code to use that newer infrastructure. I think he's targeting v4.12 for it, when we last spoke.
Updated by Jeff Layton about 6 years ago
- Assignee changed from Jeff Layton to Ilya Dryomov
Reassigning to Ilya since he's working on this.
Updated by Ilya Dryomov almost 6 years ago
Here is a simpler reproducer:
$ xfs_io -f -c 'pwrite 0 4k' /mnt/srcfile $ xfs_io -f -d -c 'sendfile -i /mnt/srcfile' /mnt/tgtfile
Updated by Ilya Dryomov almost 6 years ago
- Status changed from In Progress to Fix Under Review
Updated by Ilya Dryomov almost 6 years ago
- Status changed from Fix Under Review to Resolved
Actions