Bug 1668982 - Boot speed regression with 219-62.el7_6.2 -- udev hotplug memory rules suspected
Summary: Boot speed regression with 219-62.el7_6.2 -- udev hotplug memory rules suspected
Status: CLOSED DUPLICATE of bug 1666612
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: systemd
Version: 7.0
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: rc
: ---
Assignee: systemd-maint
QA Contact: qe-baseos-daemons
URL:
Whiteboard:
Keywords:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2019-01-24 04:03 UTC by Ian Wienand
Modified: 2019-01-24 07:26 UTC (History)
2 users (show)

(edit)
Clone Of:
(edit)
Last Closed: 2019-01-24 07:14:48 UTC


Attachments (Terms of Use)
Standard boot logs with verbose systemd logging (1.29 MB, text/plain)
2019-01-24 04:04 UTC, Ian Wienand
no flags Details
Boot logs with initramfs generated with systemd 219-62.el7_6.2 (3.72 MB, text/plain)
2019-01-24 04:06 UTC, Ian Wienand
no flags Details
View of sysfs memory directories (8.43 KB, text/plain)
2019-01-24 04:08 UTC, Ian Wienand
no flags Details


External Trackers
Tracker ID Priority Status Summary Last Updated
CentOS 15735 None None None 2019-01-24 04:03 UTC

Description Ian Wienand 2019-01-24 04:03:04 UTC
I'm trying to determine a significant boot-time regression when using an initramfs generated with 219-62.el7.  

The short version of the referenced bug is that after upgrading systemd and regenerating the initramfs, we see significantly slower boot times.

There isn't that much different between the two initramfs images; the diff is http://paste.openstack.org/show/743145/

Booting with systemd debugging turned on, I think that the hotplug rules introduced with [1] (which references #1614686) are a very likely suspect.  The slow-boot logs show a flood of stuff like 

---
...
Jan 23 23:01:14 localhost systemd-udevd[254]: PROGRAM '/bin/uname -p' /usr/lib/udev/rules.d/40-redhat.rules:8
Jan 23 23:01:14 localhost systemd-udevd[257]: seq 741 running
Jan 23 23:01:14 localhost systemd-udevd[239]: '/bin/uname -p'(out) 'x86_64'
Jan 23 23:01:14 localhost systemd-udevd[239]: '/bin/uname -p' [250] exit with return code 0
Jan 23 23:01:14 localhost systemd-udevd[239]: PROGRAM '/bin/systemd-detect-virt' /usr/lib/udev/rules.d/40-redhat.rules:11
Jan 23 23:01:14 localhost systemd-udevd[224]: seq 742 queued, 'add' 'bus'
Jan 23 23:01:14 localhost systemd-udevd[224]: maximum number (10) of children reached
Jan 23 23:01:14 localhost systemd-udevd[224]: seq 743 queued, 'add' 'bus'
Jan 23 23:01:14 localhost systemd-udevd[224]: maximum number (10) of children reached
Jan 23 23:01:14 localhost systemd-udevd[224]: maximum number (10) of children reached
...
---

grepping for the "systemd-detect-virt" invocations shows it runs *a lot* 

---
cat boot-slow-trunc.log | grep systemd-detect-virt | grep qemu | wc -l
143
---

In the "fast" boot logs, I don't see anything at all seemingly related to memory hotplug coming up.  

The rule is quite short

---
 # Memory hotadd request
-SUBSYSTEM=="memory", ACTION=="add", PROGRAM="/bin/uname -p", RESULT!="s390*", ATTR{state}=="offline", ATTR{state}="online"
+SUBSYSTEM!="memory", ACTION!="add", GOTO="memory_hotplug_end"
+PROGRAM="/bin/uname -p", RESULT=="s390*", GOTO="memory_hotplug_end"
+
+ENV{.state}="online"
+PROGRAM="/bin/systemd-detect-virt", RESULT=="none", ENV{.state}="online_movable"
+ATTR{state}=="offline", ATTR{state}="$env{.state}"
+
+LABEL="memory_hotplug_end"
---

I'm not sure I can see anything wrong with this as such, it seems like this would correctly skip any events it wasn't interested in.  Maybe there's just way more memory events than anticipated?  

This is running in a binary-translation qemu, which is essentially what is happening in the CI jobs where we noticed this.  The slower boot times started making jobs time out.




[1] https://git.centos.org/blob/rpms!systemd.git/c7/SOURCES!0659-rules-implement-new-memory-hotplug-policy.patch

Comment 2 Ian Wienand 2019-01-24 04:04 UTC
Created attachment 1522939 [details]
Standard boot logs with verbose systemd logging

Comment 3 Ian Wienand 2019-01-24 04:06 UTC
Created attachment 1522940 [details]
Boot logs with initramfs generated with systemd 219-62.el7_6.2

Comment 4 Ian Wienand 2019-01-24 04:08 UTC
Created attachment 1522941 [details]
View of sysfs memory directories

Comment 5 Jan Synacek 2019-01-24 07:14:48 UTC

*** This bug has been marked as a duplicate of bug 1666612 ***

Comment 6 Ian Wienand 2019-01-24 07:26:41 UTC
Actually, no looking at it, the rule is subtly wrong (thanks to Jens Harbott for pointing me in this direction :) -- this should not trigger on something like a block device

---
# udevadm test /block/sr0
calling: test
version 219
...
rules contain 24576 bytes tokens (2048 * 12 bytes), 12369 bytes strings
1853 strings (23179 bytes), 1230 de-duplicated (11434 bytes), 624 trie nodes used
PROGRAM '/bin/uname -p' /usr/lib/udev/rules.d/40-redhat.rules:8
starting '/bin/uname -p'
'/bin/uname -p'(out) 'x86_64'
'/bin/uname -p' [5462] exit with return code 0
PROGRAM '/bin/systemd-detect-virt' /usr/lib/udev/rules.d/40-redhat.rules:11
starting '/bin/systemd-detect-virt'
'/bin/systemd-detect-virt'(out) 'qemu'
'/bin/systemd-detect-virt' [5463] exit with return code 0
...

ACTION=add
SUBSYSTEM=block

---

The new rule is:

 SUBSYSTEM!="memory", ACTION!="add", GOTO="memory_hotplug_end"

so when "SUBSYSTEM=block, ACTION=add" we get "True, False" and don't take the GOTO ...

This explains the initial symptoms reported in [1] very well; a large regression in the boot phase where it's going through adding devices, due to the extra overheads of the forks in here.

[1] https://etherpad.openstack.org/p/dib-centos-slow


Note You need to log in before you can comment on or make changes to this bug.