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

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [day] [month] [year] [list]

Message-ID: <cb149b17-4bbf-71b0-424c-c4f3d1b96952@suse.com>
Date:   Wed, 7 Dec 2022 14:23:25 +0100
From:   Petr Pavlu <petr.pavlu@...e.com>
To:     Prarit Bhargava <prarit@...hat.com>, Petr Mladek <pmladek@...e.com>
Cc:     David Hildenbrand <david@...hat.com>,
        Luis Chamberlain <mcgrof@...nel.org>,
        linux-modules@...r.kernel.org, linux-kernel@...r.kernel.org
Subject: Re: [PATCH v2 2/2] module: Merge same-name module load requests

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