iscsi issues with ceph (Nautilus) + tcmu-runner
So, we've been running with iscsi enabled (tcmu-runner) on our Nautilus ceph cluster for a couple of weeks, and started using it with our vsphere cluster. Things looked good so we put it in production, but yesterday morning we experienced a freeze of all iSCSO I/O one of the ESXi nodes, and the only way to recover was a reboot of the client node (and the VMs with it). At first I thought this was a glitch on the VMware side, as we saw lots of warnings, but after digging in the kernel logs on the ceph side, we saw quite a few of the messages below, leading up to the freeze. We've got two iscsi gateways enabled, and have set things up as per https://docs.ceph.com/docs/mimic/rbd/iscsi-initiators/ Kernel is 4.19 / Debian 10. This is single 10G link for the ESXi nodes, with separate vlan and dedicated vmkernel nic on the storage vlan to talk to the iscsi gateways on the ceph side. Ceph is 10 nodes with a mix of HDD and SSD. The affected pool is replication on HDD w/NVMe block db in front. No overrun / errors on the interfaces, and no mtu mismatch - not that I believe this is connected to the error below. No errors/warnings on the ceph side. Anyone seen this before ? Can provide more details/logs as required. If this happens again, we'll be moving the VMs to an NFS backed vm store (even if iscsi is probably preferred) until we can find a solution to go into full prod. Cheers, Phil [Tue May 12 05:15:45 2020] WARNING: CPU: 8 PID: 2448784 at kernel/workqueue.c:2917 __flush_work.cold.54+0x1f/0x29 [Tue May 12 05:15:45 2020] Modules linked in: fuse cbc ceph libceph libcrc32c crc32c_generic fscache target_core_pscsi target_core_file target_core_iblock iscsi_target_mod target_core_user uio target_core_mod configfs binfmt_misc 8021q garp stp mrp llc bonding intel_rapl sb_edac x86_pkg_temp_thermal intel_powerclamp coretemp kvm irqbypass crct10dif_pclmul crc32_pclmul ghash_clmulni_intel ast cryptd ipmi_ssif ttm intel_cstate drm_kms_helper intel_uncore mei_me iTCO_wdt drm pcc_cpufreq intel_rapl_perf joydev pcspkr sg iTCO_vendor_support mei ioatdma ipmi_si ipmi_devintf ipmi_msghandler acpi_pad acpi_power_meter evdev dm_mod sunrpc ip_tables x_tables autofs4 squashfs zstd_decompress xxhash loop overlay hid_generic usbhid hid sd_mod ahci xhci_pci ehci_pci libahci ehci_hcd xhci_hcd libata ixgbe igb nvme mxm_wmi lpc_ich [Tue May 12 05:15:45 2020] dca usbcore i2c_i801 scsi_mod mfd_core mdio usb_common nvme_core crc32c_intel i2c_algo_bit wmi button [Tue May 12 05:15:45 2020] CPU: 8 PID: 2448784 Comm: kworker/u32:0 Tainted: G W 4.19.0-8-amd64 #1 Debian 4.19.98-1 [Tue May 12 05:15:45 2020] Hardware name: Supermicro SYS-6018R-TD8/X10DDW-i, BIOS 3.2 12/16/2019 [Tue May 12 05:15:45 2020] Workqueue: tmr-user target_tmr_work [target_core_mod] [Tue May 12 05:15:45 2020] RIP: 0010:__flush_work.cold.54+0x1f/0x29 [Tue May 12 05:15:45 2020] Code: 69 2c 04 00 0f 0b e9 4a d3 ff ff 48 c7 c7 d8 f9 83 be e8 56 2c 04 00 0f 0b e9 41 d6 ff ff 48 c7 c7 d8 f9 83 be e8 43 2c 04 00 <0f> 0b 45 31 ed e9 2b d6 ff ff 49 8d b4 24 b0 00 00 00 48 c7 c7 b8 [Tue May 12 05:15:45 2020] RSP: 0018:ffffa0180b537d38 EFLAGS: 00010246 [Tue May 12 05:15:45 2020] RAX: 0000000000000024 RBX: ffff94f619c3fad0 RCX: 0000000000000006 [Tue May 12 05:15:45 2020] RDX: 0000000000000000 RSI: 0000000000000082 RDI: ffff94f77fa166b0 [Tue May 12 05:15:45 2020] RBP: ffff94f619c3fad0 R08: 00000000000013ea R09: 0000000000aaaaaa [Tue May 12 05:15:45 2020] R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000000000 [Tue May 12 05:15:45 2020] R13: 0000000000000001 R14: ffffffffbda98400 R15: ffff94f5a3ecc088 [Tue May 12 05:15:45 2020] FS: 0000000000000000(0000) GS:ffff94f77fa00000(0000) knlGS:0000000000000000 [Tue May 12 05:15:45 2020] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [Tue May 12 05:15:45 2020] CR2: 0000555d72f0f000 CR3: 000000048240a005 CR4: 00000000003606e0 [Tue May 12 05:15:45 2020] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 [Tue May 12 05:15:45 2020] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 [Tue May 12 05:15:45 2020] Call Trace: [Tue May 12 05:15:45 2020] ? __irq_work_queue_local+0x50/0x60 [Tue May 12 05:15:45 2020] ? irq_work_queue+0x46/0x50 [Tue May 12 05:15:45 2020] ? wake_up_klogd+0x30/0x40 [Tue May 12 05:15:45 2020] ? vprintk_emit+0x215/0x270 [Tue May 12 05:15:45 2020] ? get_work_pool+0x40/0x40 [Tue May 12 05:15:45 2020] __cancel_work_timer+0x10a/0x190 [Tue May 12 05:15:45 2020] ? printk+0x58/0x6f [Tue May 12 05:15:45 2020] core_tmr_abort_task+0xd6/0x130 [target_core_mod] [Tue May 12 05:15:45 2020] target_tmr_work+0xc4/0x140 [target_core_mod] [Tue May 12 05:15:45 2020] process_one_work+0x1a7/0x3a0 [Tue May 12 05:15:45 2020] worker_thread+0x30/0x390 [Tue May 12 05:15:45 2020] ? create_worker+0x1a0/0x1a0 [Tue May 12 05:15:45 2020] kthread+0x112/0x130 [Tue May 12 05:15:45 2020] ? kthread_bind+0x30/0x30 [Tue May 12 05:15:45 2020] ret_from_fork+0x1f/0x40 [Tue May 12 05:15:45 2020] ---[ end trace 3835b5fe0aa99038 ]--- [Tue May 12 05:15:45 2020] ABORT_TASK: Sending TMR_FUNCTION_COMPLETE for ref_tag: 94585265 [Tue May 12 05:15:45 2020] ABORT_TASK: Found referenced iSCSI task_tag: 94585266 [Tue May 12 05:15:45 2020] ------------[ cut here ]------------
On 5/13/20 3:21 AM, Phil Regnauld wrote:
So, we've been running with iscsi enabled (tcmu-runner) on our Nautilus ceph cluster for a couple of weeks, and started using it with our vsphere cluster. Things looked good so we put it in production, but yesterday morning we experienced a freeze of all iSCSO I/O one of the ESXi nodes, and the only way to recover was a reboot of the client node (and the VMs with it).
At first I thought this was a glitch on the VMware side, as we saw lots of warnings, but after digging in the kernel logs on the ceph side, we saw quite a few of the messages below, leading up to the freeze.
I've never seen this kernel crash before. It might be helpful to send more of the log before the kernel warning below. From the bit of log you sent, it looks like commands might have started to timeout on the vmware side. That then kicked off the target layer's error handler which we then barf in. You used the ceph-iscsi tools to set this up right? You didn't use targetcli with tcmu-runner directly?
We've got two iscsi gateways enabled, and have set things up as per https://docs.ceph.com/docs/mimic/rbd/iscsi-initiators/
Kernel is 4.19 / Debian 10. This is single 10G link for the ESXi nodes, with separate vlan and dedicated vmkernel nic on the storage vlan to talk to the iscsi gateways on the ceph side. Ceph is 10 nodes with a mix of HDD and SSD. The affected pool is replication on HDD w/NVMe block db in front.
No overrun / errors on the interfaces, and no mtu mismatch - not that I believe this is connected to the error below. No errors/warnings on the ceph side.
Just to double check you didn't see old/slow requests like described here: https://docs.ceph.com/docs/master/rados/troubleshooting/troubleshooting-osd/ right? When see the "ABORT_TASK" messages in the log it means vmware timed out the command. We see that when disks start to die, a heavier than normal workload starts and commands take longer than normal, connection issues, sometimes when operations like scrubs are running.
Anyone seen this before ? Can provide more details/logs as required. If this happens again, we'll be moving the VMs to an NFS backed vm store (even if iscsi is probably preferred) until we can find a solution to go into full prod.
Cheers, Phil
[Tue May 12 05:15:45 2020] WARNING: CPU: 8 PID: 2448784 at kernel/workqueue.c:2917 __flush_work.cold.54+0x1f/0x29 [Tue May 12 05:15:45 2020] Modules linked in: fuse cbc ceph libceph libcrc32c crc32c_generic fscache target_core_pscsi target_core_file target_core_iblock iscsi_target_mod target_core_user uio target_core_mod configfs binfmt_misc 8021q garp stp mrp llc bonding intel_rapl sb_edac x86_pkg_temp_thermal intel_powerclamp coretemp kvm irqbypass crct10dif_pclmul crc32_pclmul ghash_clmulni_intel ast cryptd ipmi_ssif ttm intel_cstate drm_kms_helper intel_uncore mei_me iTCO_wdt drm pcc_cpufreq intel_rapl_perf joydev pcspkr sg iTCO_vendor_support mei ioatdma ipmi_si ipmi_devintf ipmi_msghandler acpi_pad acpi_power_meter evdev dm_mod sunrpc ip_tables x_tables autofs4 squashfs zstd_decompress xxhash loop overlay hid_generic usbhid hid sd_mod ahci xhci_pci ehci_pci libahci ehci_hcd xhci_hcd libata ixgbe igb nvme mxm_wmi lpc_ich [Tue May 12 05:15:45 2020] dca usbcore i2c_i801 scsi_mod mfd_core mdio usb_common nvme_core crc32c_intel i2c_algo_bit wmi button [Tue May 12 05:15:45 2020] CPU: 8 PID: 2448784 Comm: kworker/u32:0 Tainted: G W 4.19.0-8-amd64 #1 Debian 4.19.98-1 [Tue May 12 05:15:45 2020] Hardware name: Supermicro SYS-6018R-TD8/X10DDW-i, BIOS 3.2 12/16/2019 [Tue May 12 05:15:45 2020] Workqueue: tmr-user target_tmr_work [target_core_mod] [Tue May 12 05:15:45 2020] RIP: 0010:__flush_work.cold.54+0x1f/0x29 [Tue May 12 05:15:45 2020] Code: 69 2c 04 00 0f 0b e9 4a d3 ff ff 48 c7 c7 d8 f9 83 be e8 56 2c 04 00 0f 0b e9 41 d6 ff ff 48 c7 c7 d8 f9 83 be e8 43 2c 04 00 <0f> 0b 45 31 ed e9 2b d6 ff ff 49 8d b4 24 b0 00 00 00 48 c7 c7 b8 [Tue May 12 05:15:45 2020] RSP: 0018:ffffa0180b537d38 EFLAGS: 00010246 [Tue May 12 05:15:45 2020] RAX: 0000000000000024 RBX: ffff94f619c3fad0 RCX: 0000000000000006 [Tue May 12 05:15:45 2020] RDX: 0000000000000000 RSI: 0000000000000082 RDI: ffff94f77fa166b0 [Tue May 12 05:15:45 2020] RBP: ffff94f619c3fad0 R08: 00000000000013ea R09: 0000000000aaaaaa [Tue May 12 05:15:45 2020] R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000000000 [Tue May 12 05:15:45 2020] R13: 0000000000000001 R14: ffffffffbda98400 R15: ffff94f5a3ecc088 [Tue May 12 05:15:45 2020] FS: 0000000000000000(0000) GS:ffff94f77fa00000(0000) knlGS:0000000000000000 [Tue May 12 05:15:45 2020] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [Tue May 12 05:15:45 2020] CR2: 0000555d72f0f000 CR3: 000000048240a005 CR4: 00000000003606e0 [Tue May 12 05:15:45 2020] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 [Tue May 12 05:15:45 2020] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 [Tue May 12 05:15:45 2020] Call Trace: [Tue May 12 05:15:45 2020] ? __irq_work_queue_local+0x50/0x60 [Tue May 12 05:15:45 2020] ? irq_work_queue+0x46/0x50 [Tue May 12 05:15:45 2020] ? wake_up_klogd+0x30/0x40 [Tue May 12 05:15:45 2020] ? vprintk_emit+0x215/0x270 [Tue May 12 05:15:45 2020] ? get_work_pool+0x40/0x40 [Tue May 12 05:15:45 2020] __cancel_work_timer+0x10a/0x190 [Tue May 12 05:15:45 2020] ? printk+0x58/0x6f [Tue May 12 05:15:45 2020] core_tmr_abort_task+0xd6/0x130 [target_core_mod] [Tue May 12 05:15:45 2020] target_tmr_work+0xc4/0x140 [target_core_mod] [Tue May 12 05:15:45 2020] process_one_work+0x1a7/0x3a0 [Tue May 12 05:15:45 2020] worker_thread+0x30/0x390 [Tue May 12 05:15:45 2020] ? create_worker+0x1a0/0x1a0 [Tue May 12 05:15:45 2020] kthread+0x112/0x130 [Tue May 12 05:15:45 2020] ? kthread_bind+0x30/0x30 [Tue May 12 05:15:45 2020] ret_from_fork+0x1f/0x40 [Tue May 12 05:15:45 2020] ---[ end trace 3835b5fe0aa99038 ]--- [Tue May 12 05:15:45 2020] ABORT_TASK: Sending TMR_FUNCTION_COMPLETE for ref_tag: 94585265 [Tue May 12 05:15:45 2020] ABORT_TASK: Found referenced iSCSI task_tag: 94585266 [Tue May 12 05:15:45 2020] ------------[ cut here ]------------ _______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
Mike Christie (mchristi) writes:
I've never seen this kernel crash before. It might be helpful to send more of the log before the kernel warning below.
These are the messages leading up to the warning (pretty much the same, with the occasional notice about an ongoing deep scrub (2 active+clean+scrubbing+deep+repair), and at 05:09:34, the first ABORT_TASK shows up. I don't know how busy the cluster was, but we normally have no backups at that time (but veeam might have been taking snapshots). May 12 05:09:32 ceph4 ceph-mon[485955]: 2020-05-12 05:09:32.727 7f80cb9c4700 0 mon.ceph4@3(peon) e13 handle_command mon_command({"prefix": "status", "format": "json"} v 0) v1 May 12 05:09:33 ceph8 ceph-mon[256815]: 2020-05-12 05:09:33.431 7f2082335700 0 log_channel(audit) log [DBG] : from='client.61723502 10.254.212.60:0/72439561' entity='client.admin' cmd=[{"prefix": "osd lspools", "format": "json"}]: dispatch May 12 05:09:33 ceph8 ceph-mon[256815]: 2020-05-12 05:09:33.431 7f2082335700 0 mon.ceph8@2(peon) e13 handle_command mon_command({"prefix": "osd lspools", "format": "json"} v 0) v1 May 12 05:09:34 ceph10 ceph-mgr[242781]: 2020-05-12 05:09:34.547 7f2813721700 0 log_channel(cluster) log [DBG] : pgmap v848512: 896 pgs: 2 active+clean+scrubbing+deep+repair, 894 active+clean; 10 TiB data, 32 TiB used, 87 TiB / 120 TiB avail; 3.3 MiB/s rd, 4.8 MiB/s wr, 313 op/s May 12 05:09:34 ceph1 kernel: ABORT_TASK: Found referenced iSCSI task_tag: 94555972 May 12 05:09:34 ceph1 kernel: Call Trace: May 12 05:09:34 ceph1 kernel: __cancel_work_timer+0x10a/0x190 May 12 05:09:34 ceph1 kernel: Code: 69 2c 04 00 0f 0b e9 4a d3 ff ff 48 c7 c7 d8 f9 83 be e8 56 2c 04 00 0f 0b e9 41 d6 ff ff 48 c7 c7 d8 f9 83 be e8 43 2c 04 00 <0f> 0b 45 31 ed e9 2b d6 ff ff 49 8d b4 24 b0 00 00 00 48 c7 c7 b8 May 12 05:09:34 ceph1 kernel: core_tmr_abort_task+0xd6/0x130 [target_core_mod] May 12 05:09:34 ceph1 kernel: CPU: 11 PID: 2448784 Comm: kworker/u32:0 Tainted: G W 4.19.0-8-amd64 #1 Debian 4.19.98-1 May 12 05:09:34 ceph1 kernel: CR2: 0000555de2e07000 CR3: 000000048240a005 CR4: 00000000003606e0 May 12 05:09:34 ceph1 kernel: ? create_worker+0x1a0/0x1a0 May 12 05:09:34 ceph1 kernel: CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 May 12 05:09:34 ceph1 kernel: ------------[ cut here ]------------ May 12 05:09:34 ceph1 kernel: dca usbcore i2c_i801 scsi_mod mfd_core mdio usb_common nvme_core crc32c_intel i2c_algo_bit wmi button May 12 05:09:34 ceph1 kernel: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 May 12 05:09:34 ceph1 kernel: DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 May 12 05:09:34 ceph1 kernel: ---[ end trace 3835b5fe0aa98ff0 ]--- May 12 05:09:34 ceph1 kernel: FS: 0000000000000000(0000) GS:ffff94f77fac0000(0000) knlGS:0000000000000000 May 12 05:09:34 ceph1 kernel: ? get_work_pool+0x40/0x40 May 12 05:09:34 ceph1 kernel: Hardware name: Supermicro SYS-6018R-TD8/X10DDW-i, BIOS 3.2 12/16/2019 May 12 05:09:34 ceph1 kernel: ? irq_work_queue+0x46/0x50 May 12 05:09:34 ceph1 kernel: ? __irq_work_queue_local+0x50/0x60 May 12 05:09:34 ceph1 kernel: kthread+0x112/0x130 May 12 05:09:34 ceph1 kernel: ? kthread_bind+0x30/0x30 May 12 05:09:34 ceph1 kernel: Modules linked in: fuse cbc ceph libceph libcrc32c crc32c_generic fscache target_core_pscsi target_core_file target_core_iblock iscsi_target_mod target_core_user uio target_core_mod configfs binfmt_misc 8021q garp stp mrp llc bonding intel_rapl sb_edac x86_pkg_temp_thermal intel_powerclamp coretemp kvm irqbypass crct10dif_pclmul crc32_pclmul ghash_clmulni_intel ast cryptd ipmi_ssif ttm intel_cstate drm_kms_helper intel_uncore mei_me iTCO_wdt drm pcc_cpufreq intel_rapl_perf joydev pcspkr sg iTCO_vendor_support mei ioatdma ipmi_si ipmi_devintf ipmi_msghandler acpi_pad acpi_power_meter evdev dm_mod sunrpc ip_tables x_tables autofs4 squashfs zstd_decompress xxhash loop overlay hid_generic usbhid hid sd_mod ahci xhci_pci ehci_pci libahci ehci_hcd xhci_hcd libata ixgbe igb nvme mxm_wmi lpc_ich May 12 05:09:34 ceph1 kernel: ? printk+0x58/0x6f May 12 05:09:34 ceph1 kernel: process_one_work+0x1a7/0x3a0 [...]
From the bit of log you sent, it looks like commands might have started to timeout on the vmware side. That then kicked off the target layer's error handler which we then barf in.
You used the ceph-iscsi tools to set this up right? You didn't use targetcli with tcmu-runner directly?
Actually this bit is managed by croit.io, so I'm not 100% sure (we're using their software as we didn't want to deal with iscsi setup, among other things). They said they hadn't seen this particular error before, which is why I'm asking here (and totally ok if that means we're on our own). I've got the option of trying a 5.x kernel, if it helps.
Just to double check you didn't see old/slow requests like described here:
https://docs.ceph.com/docs/master/rados/troubleshooting/troubleshooting-osd/
right?
Absolutely none in the logs (going back 2 weeks).
When see the "ABORT_TASK" messages in the log it means vmware timed out the command. We see that when disks start to die, a heavier than normal workload starts and commands take longer than normal, connection issues, sometimes when operations like scrubs are running.
Apart from the 2 pgs scrubbing, no significant activity that I could see. There are only 4 VMs using iscsi at this point, with veeam doing regular snapshots in the background. Wrt. LUN provisioning, would it make improve performance or spread the workload more efficiently to allocate multiple RBDs vs one large RBD for all VMs ? (If that could be the issue) Cheers, Phil
participants (2)
-
Mike Christie
-
Phil Regnauld