Re: lvm2 deadlock

Hi,

Thanks for the insight.  Please refer below.

On 2024/05/31 14:34, Zdenek Kabelac wrote:
> Dne 30. 05. 24 v 12:21 Jaco Kroon napsal(a):
>> Hi,
>>
>> Possible lvm2 command deadlock scenario:
>>
>> crowsnest [12:15:47] /run/lvm # fuser //run/lock/lvm/*
>> /run/lock/lvm/P_global: 17231
>> /run/lock/lvm/V_lvm: 16087 17231
>>
>> crowsnest [12:15:54] /run/lvm # ps axf | grep -E '16087|17231'
>> 24437 pts/1    S+     0:00  |       \_ grep --colour=auto -E 16087|17231
>> 16087 ?        S      0:00  |       |       \_ /sbin/lvcreate -kn -An 
>> -s -n fsck_cerberus /dev/lvm/backup_cerberus
>> 17231 ?        S      0:00  |           \_ /sbin/lvs --noheadings 
>> --nameprefixes
>>
>> crowsnest [12:17:40] /run/lvm # dmsetup udevcookies
>> Cookie       Semid      Value      Last semop time Last change time
>> 0xd4d2051    10         1          Thu May 30 02:34:05 2024  Thu May 
>> 30 02:32:22 2024
>>
>> This was almost 10 hours ago.
>>
>> crowsnest [12:17:44] /run/lvm # dmsetup udevcomplete 0xd4d2051
>> DM_COOKIE_COMPLETED=0xd4d2051
>> crowsnest [12:18:43] /run/lvm # ps axf | grep -E '16087|17231'
>> 27252 pts/1    S+     0:00  |       \_ grep --colour=auto -E 16087|17231
>> crowsnest [12:18:45] /run/lvm #
>>
>> Allows progress again.
>
> Hi
>
> I'm kind of missing here to see your 'deadlock' scenario from this 
> description.
Well, stuff blocks, until the cookie is released by using the dmset 
udevcomplete command, so wrong wording perhaps?
>
> Lvm2 takes the VG lock - creates LV - waits for udev till it's 
> finished with its job and confirms all the udev work with dmsetup 
> udevcomplete.

So what I understand from this is that udevcomplete ends up never 
executing?  Is there some way of confirming this?

>
> If something 'kills'  your udev worker  (which may eventually happen 
> on some 'very very very' busy system - you may need to set up longer 
> timeout for systemd to kill udev worker (I believe it's just 30seconds 
> by default).

Well, I guess upwards of 1GB/s of IO at times qualify.  No systemd, so 
more likely the udev configuration.  When this happens we see load 
averages upwards of 50 ... so based on that I'd say busy is probably a 
reasonable assessment.  Normally doesn't exceed load average values 
10-15 at most.

Even so ... event_timeout = 180 should be a VERY, VERY long time in 
terms of udev event processing.

I'm not seeing anything for udev in /var/log/messages (which is 
explicitly configured to log everything logged to syslog).  But it may 
also be a case of "not logging because LVM isn't processing any IO (/var 
is stored on it's own LV).

>
> If it happens your cookies blocks your lvm2 command - you can 
> 'unblock' them with  'dmsetup udevcomplete_all'  -  but that's a sign 
> your system is already in very bad state.
>
> It's also unclear which OS are you using - Debian, Fedora, ???

Gentoo.

> Version of your packages ?

I thought I did provide this:

Kernel version was 6.4.12 when this hapened, is now 6.9.3.

crowsnest [12:19:47] /run/lvm # udevadm --version
254

aka systemd-utils-254.10

lvm2-2.03.22

Thanks for the feedback, what you say makes perfect sense, and the 
implication is that there are only a few options:

1.  Something is resulting in the udev trigger to take longer than three 
minutes, and the dmsetup udevcomplete never being executed.
2.  Something goes horribly wrong during the udev trigger (which invokes 
dmsetup a few times) processing and the process crashes, never executing 
dmsetup udevcomplete.

This could potentially be due to extremely heavy disk IO, or LVM itself 
freezing IO.

Given the rulesets the only way I see this happening is if dmsetup 
command takes very long to load - and even in the degraded (most 
filesystems blocked) state it was fast to execute.

Or if udevd itself has problems accessing /sys - which I find extremely 
unlikely.

I don't see the default value for udev_log from the config. Explicitly 
set to debug now, but still not seeing anything logged to syslog.  
Running with udevd --debug, which logs to a ramdisk on /run.  Hopefully 
(if/when this happens again) that may shed some light.  There is 256GB 
of RAM available, so as long as the log doesn't grow too quickly should 
be fine.

Kind regards,
Jaco