Bug 35150

Summary: systemd-udev-settle зависает при LVM не на корне
Product: Sisyphus Reporter: Ivan A. Melnikov <iv>
Component: lvm2Assignee: Alexey Shabalin <shaba>
Status: ASSIGNED --- QA Contact: qa-sisyphus
Severity: normal    
Priority: P3 CC: aen, evg, lav, rider, shaba, sin, stalker, vitty
Version: unstable   
Hardware: all   
OS: Linux   

Description Ivan A. Melnikov 2018-07-13 11:47:55 MSK
Есть система: актуальный на вчера (2018-07-12) Сизиф, systemd 238. Корень и /boot на обычном разделе. На отдельном жестком диске создаётся LVMный PV, поверх котрого создаётся VG. После этого загрузка системы от нескольких секунд удлинняется до нескольких минут, и после загрузки LVM-ные разделы не всегда сразу видны.

Оказывается, systemd-udev-settle не может  и отваливается по таймауту. При этом единственное, что наблюдается в логах -- сообщение типа:

 systemd-udevd[855]: seq 3138 '/devices/pci0000:00/0000:00:17.0/ata2/host1/target1:0:0/1:0:0:0/block/sda' is taking a long time

sda -- это как раз тот самый отдельный жесткий диск, прямо на котором сделан PV.

Естественно, если убить PV, затерев пару первых секторов /dev/sda нулями, загрузка снова становится быстрой и безпроблемной.
Comment 1 Ivan A. Melnikov 2018-07-13 11:54:44 MSK
Отладка показала, что udev запускает следующую команду:

  lvm pvscan -v --background --cache --activate ay --major 8 --minor 0

Делает он это по правилу из файла /lib/udev/rules.d/69-dm-lvm-metad.rules, в самом конце.

При этом pvscan пытается общаться с lvmetad через /run/lvm/lvmetad.socket (да, я впихнул в правило strace). lvm2-lvmetad в нашем systemd поидее должен socket-актирвироваться, однако этого не происходит до тех пор, пока с systemd-udev-settle не случится timeout, и загрузка не пойдёт дальше.
Comment 2 Ivan A. Melnikov 2018-07-13 12:02:23 MSK
В том же файлике /lib/udev/rules.d/69-dm-lvm-metad.rules обнаружился следующий абзац:

# The method for invoking pvscan is selected at build time with the option
# --(enable|disable)-udev-systemd-background-jobs to "configure".
# On modern distributions with recent systemd, it's "systemd_background";
# on others, "direct_pvscan".
GOTO="direct_pvscan"

Я предположил, что Сизиф с systemd это вполне modern distribution, и закомментировал этот GOTO. И действительно, это решило проблему: загрузка системы теперь происходит быстро, все разделы на LVM видны и монтируются согласно тому, что я написал в /etc/fstab.

Видимо, с современным systemd --enable-udev-systemd-background-jobs не просто желателен, а необходим. С другой стороны, если нужно тот же udev использовать на системах с SysV init, наверное, часть этой логики надо перетаскивать из build time в runtime...

Если что, я готов что-нибудь потестировать =)
Comment 3 Evgeny Sinelnikov 2018-07-13 12:35:23 MSK
Я столкнулся с той же проблемой после обновления до сизифа и решил её довольно криво, но быстро - я отключил ожидание:
sudo systemctl mask systemd-udev-settle

Аналогично, готов потестировать, как только в сизифе появится новый udev-rules.
Comment 4 Alexey Shabalin 2018-07-13 17:49:54 MSK
(В ответ на комментарий №2)
> В том же файлике /lib/udev/rules.d/69-dm-lvm-metad.rules обнаружился следующий
> абзац:
> 
> # The method for invoking pvscan is selected at build time with the option
> # --(enable|disable)-udev-systemd-background-jobs to "configure".
> # On modern distributions with recent systemd, it's "systemd_background";
> # on others, "direct_pvscan".
> GOTO="direct_pvscan"
> 
> Я предположил, что Сизиф с systemd это вполне modern distribution, и
> закомментировал этот GOTO. И действительно, это решило проблему: загрузка
> системы теперь происходит быстро, все разделы на LVM видны и монтируются
> согласно тому, что я написал в /etc/fstab.
> 
> Видимо, с современным systemd --enable-udev-systemd-background-jobs не просто
> желателен, а необходим. С другой стороны, если нужно тот же udev использовать
> на системах с SysV init, наверное, часть этой логики надо перетаскивать из
> build time в runtime...
> 
> Если что, я готов что-нибудь потестировать =)

А можно протестировать эти же ваши действия под SysV?
У меня есть подозрение, что будет все нормально работать.
Comment 5 Alexey Shabalin 2018-07-13 18:51:25 MSK
и для информации, в master ветке lvm2 выпиливают lvmetad как ненужную сущность.
Comment 6 Ivan A. Melnikov 2018-07-14 20:51:48 MSK
(In reply to comment #4)
> А можно протестировать эти же ваши действия под SysV?
> У меня есть подозрение, что будет все нормально работать.

Попробую в понедельник.
Comment 7 Vitaly Lipatov 2018-09-26 19:04:42 MSK
В багзилле RedHat есть длительные обсуждения очень похожей проблемы, которые закончились у них не пойми чем
https://bugzilla.redhat.com/show_bug.cgi?id=989607
https://bugzilla.redhat.com/show_bug.cgi?id=1023250

но там назван способ обхода:
global/use_lvmetad = 0 in /etc/lvm/lvm.conf 

мне отлично помогло на p8, а до того было длительное ожидание, которое приводило к emergency mode (с предложением нажать Ctrl-D).
Comment 8 Alexey Shabalin 2018-11-23 19:54:34 MSK
(В ответ на комментарий №2)
> В том же файлике /lib/udev/rules.d/69-dm-lvm-metad.rules обнаружился следующий
> абзац:
> 
> # The method for invoking pvscan is selected at build time with the option
> # --(enable|disable)-udev-systemd-background-jobs to "configure".
> # On modern distributions with recent systemd, it's "systemd_background";
> # on others, "direct_pvscan".
> GOTO="direct_pvscan"
> 
> Я предположил, что Сизиф с systemd это вполне modern distribution, и
> закомментировал этот GOTO. И действительно, это решило проблему: загрузка
> системы теперь происходит быстро, все разделы на LVM видны и монтируются
> согласно тому, что я написал в /etc/fstab.
> 
> Видимо, с современным systemd --enable-udev-systemd-background-jobs не просто
> желателен, а необходим. С другой стороны, если нужно тот же udev использовать
> на системах с SysV init, наверное, часть этой логики надо перетаскивать из
> build time в runtime...
> 
> Если что, я готов что-нибудь потестировать =)

lvm2 собирается с --disable-udev-systemd-background-jobs, поэтому в rules попадает GOTO="direct_pvscan".
А собирается он с этим параметром потому, что в rules запускается systemd-run.
Надо тогда systemd-run перенести в /bin.
Comment 9 Alexey Shabalin 2018-11-23 22:30:33 MSK
А можно еще попросить, убедиться что lvm2-lvmetad.socket включен, и если нет  сделать:
systemctl enable lvm2-lvmetad.socket
и перезагрузиться.
Comment 10 Ivan A. Melnikov 2018-11-26 11:30:15 MSK
(In reply to comment #9)
> А можно еще попросить, убедиться что lvm2-lvmetad.socket включен, и если нет 
> сделать:
> systemctl enable lvm2-lvmetad.socket
> и перезагрузиться.

lvm2-lvmetad.socket был включен когда я это поймал.
Comment 11 Ivan A. Melnikov 2018-11-26 11:55:57 MSK
Сейчас перепроверил:
- обновился до сегодняшнего Сизифа
- apt-get install --reinstall lvm2
- перезагрузился

udev-settle не сумел завершиться и меня выбросило в recovery mode. В этом самом recovery mode я вернул назад комментарий в 88 строку /lib/udev/rules.d/69-dm-lvm-metad.rules:

# GOTO="direct_pvscan"

и нормально загрузился, быстро и все разделы на месте.
Comment 12 Ivan A. Melnikov 2018-11-26 12:02:21 MSK
(In reply to comment #7)
> В багзилле RedHat есть длительные обсуждения очень похожей проблемы, которые
> закончились у них не пойми чем
> https://bugzilla.redhat.com/show_bug.cgi?id=989607
> https://bugzilla.redhat.com/show_bug.cgi?id=1023250
> 
> но там назван способ обхода:
> global/use_lvmetad = 0 in /etc/lvm/lvm.conf 
> 
> мне отлично помогло на p8, а до того было длительное ожидание, которое
> приводило к emergency mode (с предложением нажать Ctrl-D).

Проверил и этот вариант, естественно вернув GOTO как было в пакете. Тоже помогло. Пока оставил так.
Comment 13 Alexey Shabalin 2018-11-26 16:53:32 MSK
Я сделал таск #216915, в котором по-умолчанию отключено использование lvmetad (global/use_lvmetad = 0).

Видимо пока мы пытаемся усидеть на двух стульях (systemd и sysv) придется делать выбор в пользу sysv.
В ветке master уже удалили lvmetad. Но я пока не решаюсь её собирать.
Comment 14 Alexey Shabalin 2018-11-27 22:52:51 MSK
(В ответ на комментарий №13)
> Я сделал таск #216915, в котором по-умолчанию отключено использование lvmetad
> (global/use_lvmetad = 0).

посылать в таком виде в сизиф? одобряете?
 
> Видимо пока мы пытаемся усидеть на двух стульях (systemd и sysv) придется
> делать выбор в пользу sysv.
> В ветке master уже удалили lvmetad. Но я пока не решаюсь её собирать.
Comment 15 Evgenii Terechkov 2018-12-01 12:57:17 MSK
У меня после обновления до lvm2-2.02.182-alt2 загрузка растянулась с 15 секунд до 4-х минут с таким результатом:

=8<======================================================================
root@thinkpad ~ #systemctl --state=failed
  UNIT                          LOAD   ACTIVE SUB    DESCRIPTION                       
● lvm2-activation-early.service loaded failed failed Activation of LVM2 logical volumes
● lvm2-activation-net.service   loaded failed failed Activation of LVM2 logical volumes
● lvm2-activation.service       loaded failed failed Activation of LVM2 logical volumes

LOAD   = Reflects whether the unit definition was properly loaded.
ACTIVE = The high-level unit activation state, i.e. generalization of SUB.
SUB    = The low-level unit activation state, values depend on unit type.

3 loaded units listed. Pass --all to see loaded but inactive units, too.
To show all installed unit files use 'systemctl list-unit-files'.
root@thinkpad ~ #systemctl --no-pager status lvm2-activation-early lvm2-activation-net lvm2-activation
● lvm2-activation-early.service - Activation of LVM2 logical volumes
   Loaded: loaded (/etc/lvm/lvm.conf; generated)
   Active: failed (Result: timeout) since Sat 2018-12-01 16:13:32 +07; 34min ago
     Docs: man:lvm2-activation-generator(8)
  Process: 1263 ExecStart=/sbin/lvm vgchange -aay --ignoreskippedcluster (code=exited, status=0/SUCCESS)
 Main PID: 1263 (code=exited, status=0/SUCCESS)

дек 01 16:12:01 thinkpad.evg-krsk.dyndns.org systemd[1]: Starting Activation of LVM2 logical volumes...
дек 01 16:12:01 thinkpad.evg-krsk.dyndns.org dmeventd[1299]: dmeventd ready for processing.
дек 01 16:12:01 thinkpad.evg-krsk.dyndns.org lvm[1299]: Monitoring thin pool nonredundant-thinpool.
дек 01 16:12:01 thinkpad.evg-krsk.dyndns.org lvm[1263]:   1 logical volume(s) in volume group "nonredundant" now active
дек 01 16:12:01 thinkpad.evg-krsk.dyndns.org lvm[1263]:   3 logical volume(s) in volume group "thinkpad" now active
дек 01 16:12:01 thinkpad.evg-krsk.dyndns.org lvm[1299]: dmeventd received break, scheduling exit.
дек 01 16:13:32 thinkpad.evg-krsk.dyndns.org systemd[1]: lvm2-activation-early.service: State 'stop-sigterm' timed out. Killing.
дек 01 16:13:32 thinkpad.evg-krsk.dyndns.org systemd[1]: lvm2-activation-early.service: Killing process 1299 (dmeventd) with signal SIGKILL.
дек 01 16:13:32 thinkpad.evg-krsk.dyndns.org systemd[1]: lvm2-activation-early.service: Failed with result 'timeout'.
дек 01 16:13:32 thinkpad.evg-krsk.dyndns.org systemd[1]: Failed to start Activation of LVM2 logical volumes.

● lvm2-activation-net.service - Activation of LVM2 logical volumes
   Loaded: loaded (/etc/lvm/lvm.conf; generated)
   Active: failed (Result: timeout) since Sat 2018-12-01 16:16:32 +07; 31min ago
     Docs: man:lvm2-activation-generator(8)
  Process: 1318 ExecStart=/sbin/lvm vgchange -aay --ignoreskippedcluster (code=exited, status=0/SUCCESS)
  Process: 1310 ExecStartPre=/sbin/udevadm settle (code=exited, status=0/SUCCESS)
 Main PID: 1318 (code=exited, status=0/SUCCESS)

дек 01 16:15:02 thinkpad.evg-krsk.dyndns.org systemd[1]: Starting Activation of LVM2 logical volumes...
дек 01 16:15:02 thinkpad.evg-krsk.dyndns.org dmeventd[1330]: dmeventd ready for processing.
дек 01 16:15:02 thinkpad.evg-krsk.dyndns.org lvm[1330]: Monitoring thin pool nonredundant-thinpool.
дек 01 16:15:02 thinkpad.evg-krsk.dyndns.org lvm[1318]:   1 logical volume(s) in volume group "nonredundant" now active
дек 01 16:15:02 thinkpad.evg-krsk.dyndns.org lvm[1318]:   3 logical volume(s) in volume group "thinkpad" now active
дек 01 16:15:02 thinkpad.evg-krsk.dyndns.org lvm[1330]: dmeventd received break, scheduling exit.
дек 01 16:16:32 thinkpad.evg-krsk.dyndns.org systemd[1]: lvm2-activation-net.service: State 'stop-sigterm' timed out. Killing.
дек 01 16:16:32 thinkpad.evg-krsk.dyndns.org systemd[1]: lvm2-activation-net.service: Killing process 1330 (dmeventd) with signal SIGKILL.
дек 01 16:16:32 thinkpad.evg-krsk.dyndns.org systemd[1]: lvm2-activation-net.service: Failed with result 'timeout'.
дек 01 16:16:32 thinkpad.evg-krsk.dyndns.org systemd[1]: Failed to start Activation of LVM2 logical volumes.

● lvm2-activation.service - Activation of LVM2 logical volumes
   Loaded: loaded (/etc/lvm/lvm.conf; generated)
   Active: failed (Result: timeout) since Sat 2018-12-01 16:15:02 +07; 33min ago
     Docs: man:lvm2-activation-generator(8)
  Process: 1305 ExecStart=/sbin/lvm vgchange -aay --ignoreskippedcluster (code=exited, status=0/SUCCESS)
 Main PID: 1305 (code=exited, status=0/SUCCESS)

дек 01 16:13:32 thinkpad.evg-krsk.dyndns.org systemd[1]: Starting Activation of LVM2 logical volumes...
дек 01 16:13:32 thinkpad.evg-krsk.dyndns.org dmeventd[1307]: dmeventd ready for processing.
дек 01 16:13:32 thinkpad.evg-krsk.dyndns.org lvm[1307]: Monitoring thin pool nonredundant-thinpool.
дек 01 16:13:32 thinkpad.evg-krsk.dyndns.org lvm[1305]:   1 logical volume(s) in volume group "nonredundant" now active
дек 01 16:13:32 thinkpad.evg-krsk.dyndns.org lvm[1305]:   3 logical volume(s) in volume group "thinkpad" now active
дек 01 16:13:32 thinkpad.evg-krsk.dyndns.org lvm[1307]: dmeventd received break, scheduling exit.
дек 01 16:15:02 thinkpad.evg-krsk.dyndns.org systemd[1]: lvm2-activation.service: State 'stop-sigterm' timed out. Killing.
дек 01 16:15:02 thinkpad.evg-krsk.dyndns.org systemd[1]: lvm2-activation.service: Killing process 1307 (dmeventd) with signal SIGKILL.
дек 01 16:15:02 thinkpad.evg-krsk.dyndns.org systemd[1]: lvm2-activation.service: Failed with result 'timeout'.
дек 01 16:15:02 thinkpad.evg-krsk.dyndns.org systemd[1]: Failed to start Activation of LVM2 logical volumes.
[1]    4898 exit 3     systemctl --no-pager status lvm2-activation-early lvm2-activation-net 
=8<======================================================================

восстановить скорость загрузки удалось лишь явно задав "use_lvmetad = 1" в /etc/lvm/lvm.conf.
Comment 16 stalker 2018-12-03 21:46:27 MSK
У меня на 2 ~ одинаковых рабочих станциях с lvm и lvmetad  поведение с точностью до наоборот. При том что "разбивка" дисков примерно одинаковая.

на домашней,если включаю use_lvmetad = 1 - то загрузка минут 4-5. Без ~2 минуты.
на рабочей с точностью до наоборот.

Единственное что бросается в глаз - на домашней станции пустой /etc/lvm/cache
На рабочей  совсем не пустой и lvm и стартует почти моментально.

P8.
Comment 17 stalker 2018-12-03 21:51:53 MSK
Собственно с рабочей:

2.893s systemd-udev-settle.service
2.198s dev-mapper-MAIN\x2dROOTFS.device

С домашней:
120.539s systemd-udev-settle.service
9.474s dev-mapper-SYSLVM\x2dROOTFS.device
Comment 18 Alexey Shabalin 2023-02-08 16:42:49 MSK
Проявляются ли у вас проблемы с lvm сейчас?
Я в rules давным-давно добавил авто-детект как запускать. Все должно было исправится.