Re: [PATCH v2 2/2] module: Merge same-name module load requests

From: Petr Pavlu <petr.pavlu@suse.com>
To: Prarit Bhargava <prarit@redhat.com>, Petr Mladek <pmladek@suse.com>
Cc: David Hildenbrand <david@redhat.com>,
	Luis Chamberlain <mcgrof@kernel.org>,
	linux-modules@vger.kernel.org, linux-kernel@vger.kernel.org
Subject: Re: [PATCH v2 2/2] module: Merge same-name module load requests
Date: Wed, 7 Dec 2022 14:23:25 +0100	[thread overview]
Message-ID: <cb149b17-4bbf-71b0-424c-c4f3d1b96952@suse.com> (raw)
In-Reply-To: <2e8d862d-fa3d-0879-9097-215d17cb1fed@redhat.com>

On 12/6/22 13:31, Prarit Bhargava wrote:
> 
>>
>>> Could you please boot the machine with 'udev.log_level=debug' and provide me
>>> logs ('journalctl -b -o short-monotonic') from a run with the vanilla kernel
>>> and with the discussed patch?
>>
> 
> Petr, I tried to in-line the logs however the email bounced due to its size.
> 
> I know this isn't a preferred method of passing information on LKML and 
> other lists, but here are links to the logs:
> 
> https://people.redhat.com/prarit/4petr/
> 
> Both outputs were done with, as requested, 'journalctl -b -o 
> short-monotonic'.
> 
> vanilla.log is kernel booted with 'udev.log_level=debug'
> with-changeset.log is kernel + patch booted with 'udev.log_level=debug'

Thanks Prarit for re-testing the patch. Both logs in this case actually show
similar startup times.

Vanilla:
[   68.108176] intel-eaglestream-spr-15.khw3.lab.eng.bos.redhat.com systemd[1]: Startup finished in 55.874s (firmware) + 25.646s (loader) + 35.793s (kernel) + 7.845s (initrd) + 24.469s (userspace) = 2min 29.629s.

With the patch:
[   68.064826] intel-eaglestream-spr-15.khw3.lab.eng.bos.redhat.com systemd[1]: Startup finished in 54.153s (firmware) + 19.947s (loader) + 35.965s (kernel) + 9.449s (initrd) + 22.650s (userspace) = 2min 22.165s.

The system has 192 CPUs. The vanilla case shows 144x inserts of acpi_cpufreq
and 43x of pcc_cpufreq:

acpi_cpufreq (the first and last recorded insert):
[   47.485621] intel-eaglestream-spr-15.khw3.lab.eng.bos.redhat.com systemd-udevd[1871]: Inserted module 'acpi_cpufreq'
[...]
[   53.052401] intel-eaglestream-spr-15.khw3.lab.eng.bos.redhat.com systemd-udevd[1914]: Inserted module 'acpi_cpufreq'

pcc_cpufreq:
[   47.515221] intel-eaglestream-spr-15.khw3.lab.eng.bos.redhat.com systemd-udevd[1871]: Inserted module 'pcc_cpufreq'
[...]
[   53.067917] intel-eaglestream-spr-15.khw3.lab.eng.bos.redhat.com systemd-udevd[2040]: Inserted module 'pcc_cpufreq'

Processing inserts of all CPU frequency modules took at least ~5.5 seconds.
It was likely more because not all inserts are recorded in the log, udevd
messages appear to be missing from ~53.1.

With the patch, both modules are attempted to be inserted 192x:

acpi_cpufreq:
[   50.107403] intel-eaglestream-spr-15.khw3.lab.eng.bos.redhat.com systemd-udevd[1817]: Failed to insert module 'acpi_cpufreq': Device or resource busy
[...]
[   50.438755] intel-eaglestream-spr-15.khw3.lab.eng.bos.redhat.com systemd-udevd[2016]: Inserted module 'acpi_cpufreq'

pcc_cpufreq:
[   50.110731] intel-eaglestream-spr-15.khw3.lab.eng.bos.redhat.com systemd-udevd[1849]: Failed to insert module 'pcc_cpufreq': Device or resource busy
[...]
[   50.579249] intel-eaglestream-spr-15.khw3.lab.eng.bos.redhat.com systemd-udevd[2016]: Inserted module 'pcc_cpufreq'

This shows that the patch reduced the sequence to ~0.5 seconds and its logic
looks to be working as intended.

Thanks,
Petr