| Summary: | Snapshot merge may block further dm usage | ||||||
|---|---|---|---|---|---|---|---|
| Product: | [Fedora] Fedora | Reporter: | Zdenek Kabelac <zkabelac> | ||||
| Component: | kernel | Assignee: | Mike Snitzer <msnitzer> | ||||
| Status: | CLOSED WORKSFORME | QA Contact: | Fedora Extras Quality Assurance <extras-qa> | ||||
| Severity: | unspecified | Docs Contact: | |||||
| Priority: | unspecified | ||||||
| Version: | rawhide | CC: | agk, gansalmon, itamar, jonathan, kernel-maint, madhu.chinakonda, mchehab | ||||
| Target Milestone: | --- | ||||||
| Target Release: | --- | ||||||
| Hardware: | Unspecified | ||||||
| OS: | Unspecified | ||||||
| Whiteboard: | |||||||
| Fixed In Version: | Doc Type: | Bug Fix | |||||
| Doc Text: | Story Points: | --- | |||||
| Clone Of: | Environment: | ||||||
| Last Closed: | 2016-05-06 19:32:12 UTC | Type: | Bug | ||||
| Regression: | --- | Mount Type: | --- | ||||
| Documentation: | --- | CRM: | |||||
| Verified Versions: | Category: | --- | |||||
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |||||
| Cloudforms Team: | --- | Target Upstream Version: | |||||
| Attachments: |
|
||||||
|
Description
Zdenek Kabelac
2016-04-08 20:40:12 UTC
Update: Upgrading rawhide BB machine to kernel: 4.6.0-0.rc2.git3.2.fc25.x86_64 makes the test pass many iterations. Rebooting with kernel 4.6.0-0.rc0.git17.2.fc25.x86_64 needs just at most few minutes to hit the issue. So it could be possible the bug is now already fixed. (Or the race is much harder to hit.) Update 2: It's always good idea to wait just one a few more minutes, I guess 'send-button' was needed to trigger it ;) So the race and block is still there with 4.6.0-0.rc2.git3.2.fc25.x86_64 The test case should be 'decrypted' so it's more easily testable... So there was discovered a 'race' case in suspend / resume case when snapshot-merge is going to be started. This likely may have resulted in wrong routing of I/O in running dm targets. So while the original problem in kernel likely is still there, the fixed lvm2 logic for old snapshot merge code does seem to avoid hitting this race. Related lvm2 commit: https://www.redhat.com/archives/lvm-devel/2016-April/msg00058.html I'm seeing a ton of these warnings but the test passes (with a very old lvm2 tree, head being commit 192a83de): [ 4187.833562] ------------[ cut here ]------------ [ 4187.838727] WARNING: CPU: 6 PID: 5725 at lib/list_debug.c:36 __list_add+0x8a/0xc0 [ 4187.847104] list_add double add: new=ffff8803161efb68, prev=ffff8803191a8380, next=ffff8803161efb68. [ 4187.857300] Modules linked in: ext4 jbd2 mbcache dm_snapshot(O) dm_bufio(O) loop iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi coretemp kvm_intel kvm irqbypass crct10dif_pclmul crc32_pclmul ghash_clmulni_intel iTCO_wdt iomemory_vsl(POE) aesni_intel iTCO_vendor_support i7core_edac sg glue_helper ipmi_si lrw gf128mul edac_core ablk_helper ipmi_msghandler i2c_i801 lpc_ich cryptd shpchp pcspkr acpi_power_meter mfd_core acpi_cpufreq ip_tables xfs libcrc32c sr_mod sd_mod cdrom mgag200 drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops ttm ata_generic pata_acpi ixgbe igb ata_piix mdio drm ptp i2c_algo_bit libata megaraid_sas crc32c_intel pps_core i2c_core skd dca dm_mod [ 4187.925340] CPU: 6 PID: 5725 Comm: lvm Tainted: P W IOE 4.6.0-rc6.snitm+ #162 [ 4187.934176] Hardware name: FUJITSU PRIMERGY RX300 S6 /D2619, BIOS 6.00 Rev. 1.10.2619.N1 05/24/2011 [ 4187.948829] 0000000000000286 00000000ca7738aa ffff880311333b68 ffffffff8133020f [ 4187.957119] ffff880311333bb8 0000000000000000 ffff880311333ba8 ffffffff81080ba1 [ 4187.965412] 00000024b9c43820 ffff8803161efb68 ffff8803161efb68 ffff8803191a8380 [ 4187.973705] Call Trace: [ 4187.976435] [<ffffffff8133020f>] dump_stack+0x63/0x84 [ 4187.982170] [<ffffffff81080ba1>] __warn+0xd1/0xf0 [ 4187.987515] [<ffffffff81080c1f>] warn_slowpath_fmt+0x5f/0x80 [ 4187.993929] [<ffffffff81242a30>] ? bdev_test+0x20/0x20 [ 4187.999760] [<ffffffff8134c79a>] __list_add+0x8a/0xc0 [ 4188.005494] [<ffffffff81243d18>] bd_acquire+0xc8/0xd0 [ 4188.011228] [<ffffffff81244b99>] blkdev_open+0x39/0x70 [ 4188.017060] [<ffffffff81205d97>] do_dentry_open+0x227/0x320 [ 4188.023375] [<ffffffff81244b60>] ? blkdev_get_by_dev+0x50/0x50 [ 4188.029981] [<ffffffff812071c7>] vfs_open+0x57/0x60 [ 4188.035521] [<ffffffff81216b6a>] path_openat+0x1ba/0x1340 [ 4188.041641] [<ffffffff81218113>] ? putname+0x53/0x60 [ 4188.047278] [<ffffffff812185af>] ? filename_lookup+0xef/0x190 [ 4188.053786] [<ffffffff81219161>] do_filp_open+0x91/0x100 [ 4188.059812] [<ffffffff8122fce0>] ? simple_attr_release+0x20/0x20 [ 4188.066613] [<ffffffff81226996>] ? __alloc_fd+0x46/0x180 [ 4188.072638] [<ffffffff81207524>] do_sys_open+0x124/0x210 [ 4188.078665] [<ffffffff81124c1b>] ? __audit_syscall_exit+0x1db/0x260 [ 4188.085756] [<ffffffff8120762e>] SyS_open+0x1e/0x20 [ 4188.091297] [<ffffffff81003c12>] do_syscall_64+0x62/0x110 [ 4188.097420] [<ffffffff816955a1>] entry_SYSCALL64_slow_path+0x25/0x25 [ 4188.104617] ---[ end trace 2e19a3f81f712942 ]--- I'll retry with latest lvm2. I checked out lvm2.git commit 6954de22e2281876506c0db1c98972242de977fb^ and successfully ran the test 30 times in a loop against linux-dm.git's 'dm-4.7' branch (which is based on 4.6-rc6) and cannot hit any hangs like were reported in comment#0. Closing WORKSFORME, if this rears its ugly head again please reopen. (In reply to Mike Snitzer from comment #5) > I checked out lvm2.git commit 6954de22e2281876506c0db1c98972242de977fb^ and > successfully ran the test 30 times in a loop against linux-dm.git's 'dm-4.7' > branch (which is based on 4.6-rc6) and cannot hit any hangs like were > reported in comment#0. Because we changed lvm2 to avoid this issue. The question is whether a version prior to that fix still crashes with the latest kernels. (The summary in the lvm2 commit was in effect that the race has been narrowed substantially but not entirely eliminated.) (In reply to Alasdair Kergon from comment #6) > (In reply to Mike Snitzer from comment #5) > > I checked out lvm2.git commit 6954de22e2281876506c0db1c98972242de977fb^ and > > successfully ran the test 30 times in a loop against linux-dm.git's 'dm-4.7' > > branch (which is based on 4.6-rc6) and cannot hit any hangs like were > > reported in comment#0. > > Because we changed lvm2 to avoid this issue. > > The question is whether a version prior to that fix still crashes with the > latest kernels. I checked out and tested lvm2 that did _not_ have the fix. The "^" at the end of the commit id means the commit just prior to 6954de22e2281876506c0db1c98972242de977fb (which is the commit comment#3 referred to). So I've played for some time with this: With 4.6-rc6 I'm not able to hit this issue: The best I've seen were these 2 kernel messages: device-mapper: snapshots: Cancelling snapshot handover. device-mapper: snapshots: Snapshot is invalid: can't merge ---- With these kernels: 4.6.0-0.rc6.git2.1.fc25.x86_64+debug 4.6.0-0.rc4.git0.1.fc25.x86_64+debug I've not seen any 'lockdep' errors - but neither been able to trigger the fault as report originally. However I've been able to hit weird 'ptrace' issue with non-debug 4.6.0-0.rc6.git2.1. just running in the loop in one terminal: lvcreate -s -n snap -l60%FREE $vg/$lv1 mkfs.ext3 "$DM_DEV_DIR/$vg/$lv1" lvconvert --merge $vg/snap and in other window: strace -f -p pidof systemd-udevd After some while - udev stopped responding and ptraced process was not recoverable. This of course lead to non-respoding 'cookie' processing, so lvm2 stopped - but there was not 'freeze' - since 'dmsetup udevcomplete_all' simply finished command processing. Yet udevd remained 'dead' (Full log attached in case someone fill see something more there) systemd-udevd t ffff880074e1fd98 0 473 1 0x00000083 ffff880074e1fd98 00ff880036e89ff8 ffff8800770e1d40 ffff8800749cba80 ffff880074e20000 ffff8800749cba80 ffff8800749cba80 0000000000000000 ffff8800749cba80 ffff880074e1fdb0 ffffffff817d93b5 ffff8800749cba80 Call Trace: [<ffffffff817d93b5>] schedule+0x35/0x80 [<ffffffff810b5517>] ptrace_stop+0x167/0x2a0 [<ffffffff810b56e8>] ptrace_do_notify+0x98/0xc0 [<ffffffff810b6b4b>] ptrace_notify+0x5b/0x80 [<ffffffff81003a91>] syscall_trace_enter_phase2+0x81/0x1d0 [<ffffffff81003c35>] syscall_trace_enter+0x55/0x60 [<ffffffff81003e23>] do_syscall_64+0xf3/0x110 [<ffffffff817dd521>] entry_SYSCALL64_slow_path+0x25/0x25 dmsetup t ffff88007518fd20 0 29100 29099 0x00000003 ffff88007518fd20 00ff88007518fd40 ffff880074a18000 ffff8800367e8000 ffff880075190000 ffff8800367e8000 ffff8800367e8000 0000000000000000 ffff8800367e8000 ffff88007518fd38 ffffffff817d93b5 ffff8800367e8000 Call Trace: [<ffffffff817d93b5>] schedule+0x35/0x80 [<ffffffff810b5517>] ptrace_stop+0x167/0x2a0 [<ffffffff810b56e8>] ptrace_do_notify+0x98/0xc0 [<ffffffff810b6b4b>] ptrace_notify+0x5b/0x80 [<ffffffff81003595>] tracehook_report_syscall_exit+0x45/0xd0 [<ffffffff8124f044>] ? SYSC_newfstat+0x34/0x60 [<ffffffff81003674>] syscall_slow_exit_work+0x54/0xd0 [<ffffffff81003dfb>] do_syscall_64+0xcb/0x110 [<ffffffff817dd521>] entry_SYSCALL64_slow_path+0x25/0x25 dmsetup t ffff88007565fd20 0 29101 29097 0x00000003 ffff88007565fd20 00ff88007565fda0 ffff880074a18000 ffff880074b83a80 ffff880075660000 ffff880074b83a80 ffff880074b83a80 0000000000000000 ffff880074b83a80 ffff88007565fd38 ffffffff817d93b5 ffff880074b83a80 Call Trace: [<ffffffff817d93b5>] schedule+0x35/0x80 [<ffffffff810b5517>] ptrace_stop+0x167/0x2a0 [<ffffffff810b56e8>] ptrace_do_notify+0x98/0xc0 [<ffffffff810b6b4b>] ptrace_notify+0x5b/0x80 [<ffffffff81003595>] tracehook_report_syscall_exit+0x45/0xd0 [<ffffffff81267e6f>] ? __alloc_fd+0x3f/0x170 [<ffffffff81259a24>] ? putname+0x54/0x60 [<ffffffff81248635>] ? do_sys_open+0x1a5/0x220 [<ffffffff81003674>] syscall_slow_exit_work+0x54/0xd0 [<ffffffff81003dfb>] do_syscall_64+0xcb/0x110 [<ffffffff817dd521>] entry_SYSCALL64_slow_path+0x25/0x25 systemd-udevd t ffff880075893d20 0 29102 473 0x00000003 ffff880075893d20 00ff880075893d40 ffff880076a4ba80 ffff880074a18000 ffff880075894000 ffff880074a18000 ffff880074a18000 0000000000000000 ffff880074a18000 ffff880075893d38 ffffffff817d93b5 ffff880074a18000 Call Trace: [<ffffffff817d93b5>] schedule+0x35/0x80 [<ffffffff810b5517>] ptrace_stop+0x167/0x2a0 [<ffffffff810b56e8>] ptrace_do_notify+0x98/0xc0 [<ffffffff810b6b4b>] ptrace_notify+0x5b/0x80 [<ffffffff81003595>] tracehook_report_syscall_exit+0x45/0xd0 [<ffffffff8124bd5b>] ? alloc_file+0x1b/0xa0 [<ffffffff81268013>] ? __fd_install+0x33/0xe0 [<ffffffff81293bb9>] ? anon_inode_getfile+0xd9/0x160 [<ffffffff81267e6f>] ? __alloc_fd+0x3f/0x170 [<ffffffff81003674>] syscall_slow_exit_work+0x54/0xd0 [<ffffffff81003dfb>] do_syscall_64+0xcb/0x110 [<ffffffff817dd521>] entry_SYSCALL64_slow_path+0x25/0x25 systemd-udevd t ffff88006a633d20 0 29103 29102 0x00000003 ffff88006a633d20 00ff88006a633d40 ffff880077110000 ffff880076a4ba80 ffff88006a634000 ffff880076a4ba80 ffff880076a4ba80 0000000000000000 ffff880076a4ba80 ffff88006a633d38 ffffffff817d93b5 ffff880076a4ba80 Call Trace: [<ffffffff817d93b5>] schedule+0x35/0x80 [<ffffffff810b5517>] ptrace_stop+0x167/0x2a0 [<ffffffff810b56e8>] ptrace_do_notify+0x98/0xc0 [<ffffffff810b6b4b>] ptrace_notify+0x5b/0x80 [<ffffffff81003595>] tracehook_report_syscall_exit+0x45/0xd0 [<ffffffff810b6b4b>] ? ptrace_notify+0x5b/0x80 [<ffffffff812468a6>] ? filp_close+0x56/0x80 [<ffffffff81003674>] syscall_slow_exit_work+0x54/0xd0 [<ffffffff81003dfb>] do_syscall_64+0xcb/0x110 [<ffffffff817dd521>] entry_SYSCALL64_slow_path+0x25/0x25 Created attachment 1155630 [details]
process list with frozen 'ptraced' udev
|