Some operations hang on CentOS 8.5 with the latest kernel 4.18.0-348.7.1.el8_5.x86_64

[elastio]

Some operations hang on CentOS 8.5 with the latest kernel 4.18.0-348.7.1.el8_5.x86_64

[alexxxsereda]

So far it's because of kernel panic during snapshot destroy.

[alexxxsereda]

dmesg output:

[ +0.000631] elastio-snap: module init
[ +0.000000] elastio-snap: get major number
[ +0.000002] elastio-snap: allocate global device array
[ +0.000000] elastio-snap: registering proc file
[ +0.000003] elastio-snap: registering control device
[ +0.001344] elastio-snap: locating system call table
[ +0.000001] elastio-snap: failed to locate system call table, persistence disabled
[ +0.330933] loop: module loaded
[ +0.006528] loop0: detected capacity change from 0 to 268435456
[ +0.281733] EXT4-fs (loop0): mounted filesystem with ordered data mode. Opts: (null)
[ +0.007980] elastio-snap: ioctl command received: 1076379905
[ +0.000003] elastio-snap: received setup snap ioctl - 1 : /dev/loop0 : /tmp/elastio-snap_994/cow.snap
[ +0.000009] elastio-snap: allocating device struct
[ +0.000001] elastio-snap: initializing tracer
[ +0.000001] elastio-snap: finding block device
[ +0.000001] elastio-snap: checking block device is not already being traced
[ +0.000001] elastio-snap: fetching the absolute pathname for the base device
[ +0.000002] elastio-snap: calculating block device size and offset
[ +0.000000] elastio-snap: bdev size = 524288, offset = 0
[ +0.000001] elastio-snap: creating cow manager
[ +0.000000] elastio-snap: allocating cow manager, seqid = 1
[ +0.000001] elastio-snap: creating cow file
[ +0.000608] elastio-snap: allocating cow manager array (16 sections)
[ +0.000001] elastio-snap: allocating cow file (26843545 bytes)
[ +0.000046] elastio-snap: finding cow file inode
[ +0.000001] elastio-snap: getting relative pathname of cow file
[ +0.000117] elastio-snap: setting up make request function
[ +0.000000] elastio-snap: setting queue limits
[ +0.000002] elastio-snap: allocating gendisk
[ +0.000001] elastio-snap: initializing gendisk
[ +0.000001] elastio-snap: naming gendisk
[ +0.000000] elastio-snap: block device size: 524288
[ +0.000001] elastio-snap: adding disk
[ +0.000175] elastio-snap: starting mrf kernel thread
[ +0.000059] elastio-snap: creating kernel cow thread
[ +0.000603] elastio-snap: getting the base block device's make_request_fn
[ +0.000002] elastio-snap: freezing 'loop0'
[ +0.017957] elastio-snap: starting tracing
[ +0.000002] elastio-snap: thawing 'loop0'
[ +0.000692] elastio-snap: minor range = 1 - 1
[ +0.016935] elastio-snap: ioctl command received: 1074020613
[ +0.000003] elastio-snap: received transition inc ioctl - 1
[ +0.000001] elastio-snap: allocating device struct
[ +0.000001] elastio-snap: initializing tracer
[ +0.000001] elastio-snap: creating kernel cow thread
[ +0.000158] elastio-snap: getting the base block device's make_request_fn
[ +0.000010] elastio-snap: freezing 'loop0'
[ +0.025238] elastio-snap: starting tracing
[ +0.000002] elastio-snap: thawing 'loop0'
[ +0.000486] elastio-snap: stopping cow thread
[ +0.000639] elastio-snap: stopping mrf thread
[ +0.000076] elastio-snap: freeing gendisk
[ +0.000252] elastio-snap: freeing request queue
[ +0.006703] elastio-snap: minor range = 1 - 1
[ +0.008751] elastio-snap: ioctl command received: 1074020612
[ +0.000002] elastio-snap: received destroy ioctl - 1
[ +0.000000] elastio-snap: replacing make_request_fn if needed
[ +0.000007] elastio-snap: freezing 'loop0'
[ +0.025827] elastio-snap: ending tracing
[ +0.000002] elastio-snap: thawing 'loop0'
[ +0.000277] elastio-snap: stopping cow thread
[ +0.000022] elastio-snap: freeing cow path
[ +0.000001] elastio-snap: destroying cow manager. close method: 0
[ +0.000024] elastio-snap: freeing base block device path
[ +0.000001] elastio-snap: freeing base block device
[ +0.000003] elastio-snap: minor range = 23 - 0
[ +0.010368] elastio-snap: ioctl command received: -1605353208
[ +0.000003] elastio-snap: received elastio-snap info ioctl - 1
[ +0.000001] elastio-snap: device specified does not exist: -2
[ +0.000016] elastio-snap: error during reconfigure ioctl handler: -2
[ +0.000008] elastio-snap: minor range = 23 - 0
[ +0.000125] elastio-snap: ioctl command received: 1076379905
[ +0.000002] elastio-snap: received setup snap ioctl - 1 : /dev/loop0 : /tmp/elastio-snap_994/cow.snap
[ +0.000011] elastio-snap: allocating device struct
[ +0.000001] elastio-snap: initializing tracer
[ +0.000000] elastio-snap: finding block device
[ +0.000001] elastio-snap: checking block device is not already being traced
[ +0.000000] elastio-snap: fetching the absolute pathname for the base device
[ +0.000002] elastio-snap: calculating block device size and offset
[ +0.000000] elastio-snap: bdev size = 524288, offset = 0
[ +0.000001] elastio-snap: creating cow manager
[ +0.000000] elastio-snap: allocating cow manager, seqid = 1
[ +0.000000] elastio-snap: creating cow file
[ +0.000040] elastio-snap: allocating cow manager array (16 sections)
[ +0.000001] elastio-snap: allocating cow file (26843545 bytes)
[ +0.000043] elastio-snap: finding cow file inode
[ +0.000000] elastio-snap: getting relative pathname of cow file
[ +0.000114] elastio-snap: setting up make request function
[ +0.000000] elastio-snap: setting queue limits
[ +0.000001] elastio-snap: allocating gendisk
[ +0.000002] elastio-snap: initializing gendisk
[ +0.000000] elastio-snap: naming gendisk
[ +0.000001] elastio-snap: block device size: 524288
[ +0.000001] elastio-snap: adding disk
[ +0.001258] elastio-snap: starting mrf kernel thread
[ +0.000077] elastio-snap: creating kernel cow thread
[ +0.000327] elastio-snap: getting the base block device's make_request_fn
[ +0.000003] elastio-snap: freezing 'loop0'
[ +0.027657] elastio-snap: starting tracing
[ +0.000002] elastio-snap: thawing 'loop0'
[ +0.000576] elastio-snap: minor range = 1 - 1
[ +0.016755] elastio-snap: ioctl command received: 1074020612
[ +0.000002] elastio-snap: received destroy ioctl - 1
[ +0.000001] elastio-snap: replacing make_request_fn if needed
[ +0.000007] elastio-snap: freezing 'loop0'
[ +0.025581] elastio-snap: ending tracing
[ +0.000001] elastio-snap: thawing 'loop0'
[ +0.000537] elastio-snap: stopping cow thread
[ +0.000063] elastio-snap: stopping mrf thread
[ +0.000052] elastio-snap: freeing gendisk
[ +0.000284] elastio-snap: freeing request queue
[ +0.006143] elastio-snap: freeing cow path
[ +0.000001] elastio-snap: destroying cow manager. close method: 0
[ +0.000014] elastio-snap: freeing base block device path
[ +0.000000] elastio-snap: freeing base block device
[ +0.000002] elastio-snap: minor range = 23 - 0
[ +0.009282] elastio-snap: ioctl command received: -1605353208
[ +0.000002] elastio-snap: received elastio-snap info ioctl - 1
[ +0.000001] elastio-snap: device specified does not exist: -2
[ +0.000016] elastio-snap: error during reconfigure ioctl handler: -2
[ +0.000008] elastio-snap: minor range = 23 - 0
[ +0.000199] elastio-snap: ioctl command received: 1074020612
[ +0.000000] elastio-snap: received destroy ioctl - 1
[ +0.000000] elastio-snap: device specified does not exist: -2
[ +0.000009] elastio-snap: error during destroy ioctl handler: -2
[ +0.000008] elastio-snap: minor range = 23 - 0
[ +0.021288] ------------[ cut here ]------------
[ +0.000022] percpu ref (blk_queue_usage_counter_release) <= 0 (-23) after switching to atomic
[ +0.000024] WARNING: CPU: 3 PID: 0 at lib/percpu-refcount.c:161 percpu_ref_switch_to_atomic_rcu+0x131/0x140
[ +0.000001] Modules linked in: loop elastio_snap(OE) ipt_MASQUERADE nf_conntrack_netlink nft_counter xt_addrtype nft_compat br_netfilter bridge stp llc nft_masq nft_fib_inet nft_fib_ipv4 nft_fib_ipv6 nft_fib nft_reject_inet nf_reject_ipv4 nf_reject_ipv6 nft_reject nft_ct nf_tables_set nft_chain_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 ip_set overlay nf_tables libcrc32c nfnetlink intel_rapl_msr intel_rapl_common kvm_amd ccp cirrus kvm drm_kms_helper irqbypass crct10dif_pclmul syscopyarea crc32_pclmul sysfillrect sysimgblt fb_sys_fops ghash_clmulni_intel drm joydev pcspkr virtio_balloon i2c_piix4 fuse ext4 mbcache jbd2 ata_generic ata_piix libata crc32c_intel virtio_net virtio_blk serio_raw net_failover failover
[ +0.000028] CPU: 3 PID: 0 Comm: swapper/3 Kdump: loaded Tainted: G OE --------- - - 4.18.0-348.7.1.el8_5.x86_64 #1
[ +0.000001] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.13.0-1ubuntu1.1 04/01/2014
[ +0.000002] RIP: 0010:percpu_ref_switch_to_atomic_rcu+0x131/0x140
[ +0.000002] Code: 80 3d 67 78 33 01 00 0f 85 57 ff ff ff 49 8b 54 24 d8 49 8b 74 24 e8 48 c7 c7 28 64 91 94 c6 05 49 78 33 01 01 e8 e8 98 c4 ff <0f> 0b e9 33 ff ff ff 0f 1f 84 00 00 00 00 00 41 54 49 89 f4 55 53
[ +0.000002] RSP: 0018:ffffa61300d7cec8 EFLAGS: 00010282
[ +0.000001] RAX: 0000000000000000 RBX: 7fffffffffffffe8 RCX: 0000000000000000
[ +0.000001] RDX: 0000000000000001 RSI: ffffffff956dff71 RDI: 0000000000000246
[ +0.000001] RBP: 00003d8088007f80 R08: ffffffff956dff20 R09: 0000000000000051
[ +0.000000] R10: ffffffff956e0300 R11: 0000000080000003 R12: ffff889148598710
[ +0.000001] R13: ffffffff95028f00 R14: ffffffff9396cdda R15: ffff889277dab010
[ +0.000003] FS: 0000000000000000(0000) GS:ffff889277d80000(0000) knlGS:0000000000000000
[ +0.000001] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ +0.000001] CR2: 00007ffe18f2adc8 CR3: 0000000103432000 CR4: 0000000000350ee0
[ +0.000003] Call Trace:
[ +0.000002]
[ +0.000011] rcu_do_batch+0x1bf/0x410
[ +0.000002] rcu_core+0x145/0x200
[ +0.000010] __do_softirq+0xd7/0x2d6
[ +0.000012] irq_exit+0xf7/0x100
[ +0.000002] smp_apic_timer_interrupt+0x74/0x130
[ +0.000003] apic_timer_interrupt+0xf/0x20
[ +0.000001]
[ +0.000001] RIP: 0010:native_safe_halt+0xe/0x10
[ +0.000002] Code: ff ff 7f c3 65 48 8b 04 25 40 5c 01 00 f0 80 48 02 20 48 8b 00 a8 08 75 c4 eb 80 90 e9 07 00 00 00 0f 00 2d 76 9c 48 00 fb f4 90 e9 07 00 00 00 0f 00 2d 66 9c 48 00 f4 c3 90 90 0f 1f 44 00
[ +0.000001] RSP: 0018:ffffa61300cd7ea0 EFLAGS: 00000206 ORIG_RAX: ffffffffffffff13
[ +0.000001] RAX: ffffffff9417fd80 RBX: 0000000000000003 RCX: ffff889144011880
[ +0.000001] RDX: 0000000000098e0a RSI: 0000000000000000 RDI: 00000085086cd300
[ +0.000000] RBP: 0000000000000003 R08: 000000d01ae2ec17 R09: ffff8891412b3000
[ +0.000001] R10: 0000000000000004 R11: 0000000000000001 R12: ffffffffffffffff
[ +0.000001] R13: 0000000000000000 R14: 0000000000000000 R15: ffff889141232f80
[ +0.000002] ? __sched_text_end+0x7/0x7
[ +0.000002] default_idle+0xa/0x10
[ +0.000001] default_idle_call+0x40/0xf0
[ +0.000003] do_idle+0x1f4/0x260
[ +0.000003] cpu_startup_entry+0x6f/0x80
[ +0.000009] start_secondary+0x19b/0x1e0
[ +0.000003] secondary_startup_64_no_verify+0xc2/0xcb
[ +0.000002] ---[ end trace bd77160093954630 ]---

[anelson]

@e-kov do I understand right that block backup is broken on newer RHEL-like kernels because of this.

[e-kov]

@anelson yes, it is