Mailing List Archive

On 5/24/23 23:36, Luis Chamberlain wrote:
> Add support to use the new kread_uniq_fd() to avoid duplicate kernel
> reads on modules. At the cost of about ~945 bytes to your kernel size,
> enabling this on a 255 CPU x86_64 qemu guest this saves about ~1.8 GiB
> of memory during boot which would otherwise be free'd, and reduces boot
> time by about ~11 seconds.
>
> Userspace loads modules through finit_module(), this in turn will
> use vmalloc space up to 3 times:
>
> a) The kernel_read_file() call
> b) Optional module decompression
> c) Our final copy of the module
>
> Commit 064f4536d139 ("module: avoid allocation if module is already
> present and ready") shows a graph of the amount of vmalloc space
> observed allocated but freed for duplicate module request which end
> up in the trash bin. Since there is a linear relationship with the
> number of CPUs eventually this will bite us and you end up not being
> able to boot. That commit put a stop gap for c) but to avoid the
> vmalloc() space wasted on a) and b) we need to detect duplicates
> earlier.
>
> We could just have userspace fix this, but as reviewed at LSFMM 2023
> this year in Vancouver, fixing this in userspace can be complex and we
> also can't know when userpace is fixed. Fixing this in kernel turned
> out to be easy with the inode and with a simple kconfig option we can
> let users / distros decide if this full stop gap is worthy to enable.

kmod normally uses finit_module() only if a module is not compressed,
otherwise it decompresses it first and then invokes init_module().

Looking at Fedora and openSUSE Tumbleweed, they compress kernel modules
with xz and zstd, respectively. They also have their kernels built
without any CONFIG_MODULE_COMPRESS_{GZIP,XZ,ZSTD} options.

It means that these and similarly organized distributions end up using
init_module(), and adding complexity to optimize finit_module() wouldn't
actually help in their case.

-- Petr

On Thu, May 25, 2023 at 4:40?AM Petr Pavlu <petr.pavlu@suse.com> wrote:
>
> kmod normally uses finit_module() only if a module is not compressed,
> otherwise it decompresses it first and then invokes init_module().

Note that it would probably be good to teach Fedora and SuSE to use
the kernel-side decompression, if only because we have it and would
like to try to avoid using the old "load contents from user memory".

Mainly because it allows security modules to actively check for
tampering (ie things like verity etc). Long-term, it would be good to
just deprecate the old init_module() entirely.

But yes:

> It means that these and similarly organized distributions end up using
> init_module(), and adding complexity to optimize finit_module() wouldn't
> actually help in their case.

Yeah, I think the real bug is absolutely in udev, and trying to load
the same module hundreds of times is very very wrong. So I think the
"mitigate it in the kernel" is at most a quick hack to fix user-space
brokenness.

And I don't think 1/2 is acceptable as that "quick hack". Not at all.
It also seems fundamentally buggy, as it uses purely the inode number
as the file identity, which means that it does bad things across
filesystem limits.

That said, I posted an alternate patch that I think _is_ valid as that
quick hack. I don't love it, but it sure is simpler (and avoids the
i_ino bug):

https://lore.kernel.org/lkml/CAHk-=wgKu=tJf1bm_dtme4Hde4zTB=_7EdgR8avsDRK4_jD+uA@mail.gmail.com/

that patch hasn't seen any testing, and for all I know it won't even
boot because of some thinko, but I think it would be acceptable as a
workaround if it does work.

But no, it's not some kind of "fix" for the bug, and yes, using
init_module() rather than finit_module() will circumvent the quick
hack. The true fix would be for udev to do proper handling of its data
structures instead of randomly spraying duplicate module loading
events.

I don't know why udev does what it does. From what Luis told me,
apparently it's just forking stuff and keeping all its data structures
in memory, and has no actual consistency or locking or memory of what
it has done. Luis pointed me at

https://lore.kernel.org/all/23bd0ce6-ef78-1cd8-1f21-0e706a00424a@suse.com/T/#u

for some udev background.

It's been about a decade since I looked at udev sources, and none of
this encourages me to take a second look, so all of the above may be
me misunderstanding just exactly what the udev problem is. But for
that 'finit' case, we *could* try that simple hack of mine.

I say "hack", but the patch really is pretty simple, and the concept
of "exclusive special access" certainly is not some hack in itself.
It's just not anything we've ever done before. So the hackishness from
that exclusive_deny_write_access() thing in my patch is mainly that it
shouldn't be needed at all (and that the exclusivity should probably
be set some other way).

Comments welcome.

Linus

On Thu, May 25, 2023 at 09:07:23AM -0700, Linus Torvalds wrote:
> > It means that these and similarly organized distributions end up using
> > init_module(), and adding complexity to optimize finit_module() wouldn't
> > actually help in their case.
>
> Yeah, I think the real bug is absolutely in udev, and trying to load
> the same module hundreds of times is very very wrong. So I think the
> "mitigate it in the kernel" is at most a quick hack to fix user-space
> brokenness.

I totally agree. I also agree that this doesn't really seem to be any
sort of "bug" in that no memory leaks, and when userspace calms down,
all goes back to normal. So hacks in the vfs layer for this is not
good, let's not paper over userspace code that we have control over with
kernel changes.

Luis, I asked last time what modules are being asked by the kernel to be
loaded thousands of times at boot and can't seem to find an answer
anywhere, did I miss that? This should be very easy to handle in
userspace if systems need it, so that begs the questions, what types of
systems need this? We have handled booting with tens of thousands of
devices attached for decades now with no reports of boot/udev/kmod
issues before, what has recently changed to cause issues?

thanks,

greg k-h

On Thu, May 25, 2023 at 01:40:32PM +0200, Petr Pavlu wrote:
>On 5/24/23 23:36, Luis Chamberlain wrote:
>> Add support to use the new kread_uniq_fd() to avoid duplicate kernel
>> reads on modules. At the cost of about ~945 bytes to your kernel size,
>> enabling this on a 255 CPU x86_64 qemu guest this saves about ~1.8 GiB
>> of memory during boot which would otherwise be free'd, and reduces boot
>> time by about ~11 seconds.
>>
>> Userspace loads modules through finit_module(), this in turn will
>> use vmalloc space up to 3 times:
>>
>> a) The kernel_read_file() call
>> b) Optional module decompression
>> c) Our final copy of the module
>>
>> Commit 064f4536d139 ("module: avoid allocation if module is already
>> present and ready") shows a graph of the amount of vmalloc space
>> observed allocated but freed for duplicate module request which end
>> up in the trash bin. Since there is a linear relationship with the
>> number of CPUs eventually this will bite us and you end up not being
>> able to boot. That commit put a stop gap for c) but to avoid the
>> vmalloc() space wasted on a) and b) we need to detect duplicates
>> earlier.
>>
>> We could just have userspace fix this, but as reviewed at LSFMM 2023
>> this year in Vancouver, fixing this in userspace can be complex and we
>> also can't know when userpace is fixed. Fixing this in kernel turned
>> out to be easy with the inode and with a simple kconfig option we can
>> let users / distros decide if this full stop gap is worthy to enable.
>
>kmod normally uses finit_module() only if a module is not compressed,
>otherwise it decompresses it first and then invokes init_module().

that is for historical reasons, because the kernel didn't support to
uncompress the module by itself.

>
>Looking at Fedora and openSUSE Tumbleweed, they compress kernel modules
>with xz and zstd, respectively. They also have their kernels built
>without any CONFIG_MODULE_COMPRESS_{GZIP,XZ,ZSTD} options.
>
>It means that these and similarly organized distributions end up using
>init_module(), and adding complexity to optimize finit_module() wouldn't
>actually help in their case.

true, but the change in kmod should be trivial now that the kernel has
the proper support in place and the algorithms support match the ones
kmod has. I will take a look at switching the logic around to just pass
the fd to the kernel so it can also deduplicate the requests.

thanks for the reminder,

Lucas De Marchi

>
>-- Petr

On Thu, May 25, 2023 at 9:07?AM Linus Torvalds
<torvalds@linux-foundation.org> wrote:
>
> That said, I posted an alternate patch that I think _is_ valid as that
> quick hack. I don't love it, but it sure is simpler (and avoids the
> i_ino bug):
>
> https://lore.kernel.org/lkml/CAHk-=wgKu=tJf1bm_dtme4Hde4zTB=_7EdgR8avsDRK4_jD+uA@mail.gmail.com/
>
> that patch hasn't seen any testing, and for all I know it won't even
> boot because of some thinko, but I think it would be acceptable as a
> workaround if it does work.

Well, it boots here, so it must be perfect.

That said, I didn't add any debugging code, and I didn't test it on
any odd setups, and I've never had any problems before. So I don't
actually know if the patch *does* anything.

But it did boot..

Linus

On Thu, May 25, 2023 at 05:42:10PM +0100, Greg KH wrote:
> Luis, I asked last time what modules are being asked by the kernel to be
> loaded thousands of times at boot and can't seem to find an answer
> anywhere, did I miss that?

Yes you missed it, I had explained it:

https://lore.kernel.org/all/ZEGopJ8VAYnE7LQ2@bombadil.infradead.org/

"My best assessment of the situation is that each CPU in udev ends up
triggering a load of duplicate set of modules, not just one, but *a
lot*. Not sure what heuristics udev uses to load a set of modules per
CPU."

Petr Pavlu then finishes the assessment:

https://lore.kernel.org/all/23bd0ce6-ef78-1cd8-1f21-0e706a00424a@suse.com/

But let me quote it, so it is not missed:

"My understanding is that udev workers are forked. An initial kmod
context is created by the main udevd process but no sharing happens
after the fork. It means that the mentioned memory pool logic doesn't
really kick in.

Multiple parallel load requests come from multiple udev workers, for
instance, each handling an udev event for one CPU device and making the
exactly same requests as all others are doing at the same time.

The optimization idea would be to recognize these duplicate requests at
the udevd/kmod level and converge them."

> This should be very easy to handle in
> userspace if systems need it, so that begs the questions, what types of
> systems need this?

I had explained, this has existed for a long time.

> We have handled booting with tens of thousands of
> devices attached for decades now with no reports of boot/udev/kmod
> issues before, what has recently changed to cause issues?

Doesn't mean this didn't happen before, just because memory is freed due
to duplicates does not mean that the memory pressure induced by them is
not stupid. It is stupid, but hasn't come up as a possible real issue
nowadays where systems require more vmalloc space used during boot with
new features. I had explained also the context where this came from.
David Hildenbrand had reported failure to boot on many CPUs. If you
induce more vmap memory pressure on boot with multiple CPUs eventually
you can't boot. Enabling KASAN will make this worse today.

Luis

On Thu, May 25, 2023 at 09:07:23AM -0700, Linus Torvalds wrote:
>On Thu, May 25, 2023 at 4:40?AM Petr Pavlu <petr.pavlu@suse.com> wrote:
>>
>> kmod normally uses finit_module() only if a module is not compressed,
>> otherwise it decompresses it first and then invokes init_module().
>
>Note that it would probably be good to teach Fedora and SuSE to use
>the kernel-side decompression, if only because we have it and would
>like to try to avoid using the old "load contents from user memory".
>
>Mainly because it allows security modules to actively check for
>tampering (ie things like verity etc). Long-term, it would be good to
>just deprecate the old init_module() entirely.

Right... I was trying to remember why that wasn't done yet since I
thought it was. The in-kernel decompression is much more recent than
the finit_module. Commit b1ae6dc41eaa ("module: add in-kernel support for decompressing")
was actually the one allowing to decompress on the kernel side
and commit 169a58ad824d ("module/decompress: Support zstd in-kernel decompression")
brought the algo support on the kernel and userspace side to parity.

I will teach kmod to take the proper path considering the in-kernel
decompression availability.

>
>But yes:
>
>> It means that these and similarly organized distributions end up using
>> init_module(), and adding complexity to optimize finit_module() wouldn't
>> actually help in their case.
>
>Yeah, I think the real bug is absolutely in udev, and trying to load
>the same module hundreds of times is very very wrong. So I think the
>"mitigate it in the kernel" is at most a quick hack to fix user-space
>brokenness.
>
>And I don't think 1/2 is acceptable as that "quick hack". Not at all.
>It also seems fundamentally buggy, as it uses purely the inode number
>as the file identity, which means that it does bad things across
>filesystem limits.
>
>That said, I posted an alternate patch that I think _is_ valid as that
>quick hack. I don't love it, but it sure is simpler (and avoids the
>i_ino bug):
>
> https://lore.kernel.org/lkml/CAHk-=wgKu=tJf1bm_dtme4Hde4zTB=_7EdgR8avsDRK4_jD+uA@mail.gmail.com/
>
>that patch hasn't seen any testing, and for all I know it won't even
>boot because of some thinko, but I think it would be acceptable as a
>workaround if it does work.
>
>But no, it's not some kind of "fix" for the bug, and yes, using
>init_module() rather than finit_module() will circumvent the quick
>hack. The true fix would be for udev to do proper handling of its data
>structures instead of randomly spraying duplicate module loading
>events.
>
>I don't know why udev does what it does. From what Luis told me,
>apparently it's just forking stuff and keeping all its data structures
>in memory, and has no actual consistency or locking or memory of what
>it has done. Luis pointed me at

It's a long time I don't touch that udev code, but my understanding
is that it first creates the kmod context and then starts to fork workers
(up to a limit) as the events arrive and there are no idle workers available.
At this point each of them have a separate kmod context derived from the
initial context. I was told the workers are needed because
a) they must be resilient to crashing without catastrophic consequences and
b) the kernel floods udev with thousands of netlink events during boot.
c) unrelated netlink events can't wait a module to be loaded, for example.

If the above is true (need confirmation from udev devs), then what could
be done on the userspace side would be:

1) do the modalias lookup first, before delegating the module load part
to the workers. That will translate the modalias to the module name,
2) hand over to the worker the module loading part by name, not by alias,
iff there isn't one being done for that already by other workers -
workers need to share some state with the main process.

With this the dedup can happen based on the *module name*. I was told
a dedup based on the aliases is not effective as there are slight
changes on the modaliases being sent on boot leading to the same module.


> https://lore.kernel.org/all/23bd0ce6-ef78-1cd8-1f21-0e706a00424a@suse.com/T/#u
>
>for some udev background.

the synchronization point in the kernel side rather than on userspace
used to be cheap and the race window smaller. About the race: libkmod
already checks if there's a module being loaded before actually loading
it, however there is a race between the initstate file being created by
the kernel side and new requests arriving to load the same module.

>
>It's been about a decade since I looked at udev sources, and none of
>this encourages me to take a second look, so all of the above may be
>me misunderstanding just exactly what the udev problem is. But for
>that 'finit' case, we *could* try that simple hack of mine.
>
>I say "hack", but the patch really is pretty simple, and the concept
>of "exclusive special access" certainly is not some hack in itself.
>It's just not anything we've ever done before. So the hackishness from
>that exclusive_deny_write_access() thing in my patch is mainly that it
>shouldn't be needed at all (and that the exclusivity should probably
>be set some other way).
>
>Comments welcome.

Thinking only on the finit_module case and given libkmod will be
changed to prefer that path, it's not clear if it's preferred
to dedup on module name (userspace) or inode (kernel). Also worth
mentioning that both of them only protect against the window of calling
finit_module() and having a initstate file created by the kernel: if the
file exists in the coming or live states, libkmod will already do the
shortcut.

Are you willig to merge (a possibly improved version of) your patch
or the userspace change is still something that
would be desired? Doing that on the kernel has the small advantage
that it also synchronizes requests from sources other than udev,
but I don't think we would have many to justify.

Lucas De Marchi

>
> Linus

On Thu, May 25, 2023 at 11:45?AM Lucas De Marchi
<lucas.demarchi@intel.com> wrote:
>
> Are you willig to merge (a possibly improved version of) your patch
> or the userspace change is still something that would be desired?

I think a user space change should still be something that people
should look at, particularly as the kernel side patch I'm willing to
accept doesn't catch the "completely serial" cases, only the "trying
to load at the same time that the same module is literally busy being
loaded".

But I've cleaned up my patch a bit, and while the cleaned-up version
is rather larger as a patch (mainly because of just also re-organizing
the finit_module() code to do all the 'struct file' prep), I'm
actually pretty happy with this attached patch conceptually.

In this form, it actually "makes sense" to me, rather than being just
clearly a workaround. Also, unlike the previous patch, this doesn't
actually make any changes to the basic kernel_read_file() set of
functions, it's all done by the module loading code itself.

Luis, would you mind testing this version on your load? It still won't
actually handle the purely serial case, so there *will* be those
spurious double module reads from different CPU's just doing the
things serially, but the exclusive file access region has been
extended to not just cover the actual file content reading, but to
cover the whole "turn it into a a real module" part too.

Also, this does *not* update some of the comments in the module
loading. I changed finit_module to use "kernel_read_file()" instead of
"kernel_read_file_from_fd()", since it actually now has to look up the
file descriptor anyway. But the comments still talk about that
"from_fd" thing.

Anyway, this is back to "ENTIRELY UNTESTED" territory, in that I've
compiled this, but haven't booted it. The changes look obvious, but
hey, mistakes happen.

And the commit message is just a place-holder. Obviously. I won't sign
off on this or write more of a commit message until it has had some
real testing.

Linus

On Thu, May 25, 2023 at 02:12:49PM -0700, Linus Torvalds wrote:
> On Thu, May 25, 2023 at 11:45?AM Lucas De Marchi
> <lucas.demarchi@intel.com> wrote:
> >
> > Are you willig to merge (a possibly improved version of) your patch
> > or the userspace change is still something that would be desired?
>
> I think a user space change should still be something that people
> should look at, particularly as the kernel side patch I'm willing to
> accept doesn't catch the "completely serial" cases, only the "trying
> to load at the same time that the same module is literally busy being
> loaded".
>
> But I've cleaned up my patch a bit, and while the cleaned-up version
> is rather larger as a patch (mainly because of just also re-organizing
> the finit_module() code to do all the 'struct file' prep), I'm
> actually pretty happy with this attached patch conceptually.
>
> In this form, it actually "makes sense" to me, rather than being just
> clearly a workaround. Also, unlike the previous patch, this doesn't
> actually make any changes to the basic kernel_read_file() set of
> functions, it's all done by the module loading code itself.
>
> Luis, would you mind testing this version on your load? It still won't
> actually handle the purely serial case, so there *will* be those
> spurious double module reads from different CPU's just doing the
> things serially, but the exclusive file access region has been
> extended to not just cover the actual file content reading, but to
> cover the whole "turn it into a a real module" part too.
>
> Also, this does *not* update some of the comments in the module
> loading. I changed finit_module to use "kernel_read_file()" instead of
> "kernel_read_file_from_fd()", since it actually now has to look up the
> file descriptor anyway. But the comments still talk about that
> "from_fd" thing.
>
> Anyway, this is back to "ENTIRELY UNTESTED" territory, in that I've
> compiled this, but haven't booted it. The changes look obvious, but
> hey, mistakes happen.
>
> And the commit message is just a place-holder. Obviously. I won't sign
> off on this or write more of a commit message until it has had some
> real testing.

With 255 vcpus:

Before:

vagrant@kmod ~ $ sudo systemd-analyze
Startup finished in 41.653s (kernel) + 44.305s (userspace) = 1min 25.958s
graphical.target reached after 44.178s in userspace.

root@kmod ~ # grep "Virtual mem wasted bytes"
/sys/kernel/debug/modules/stats
Virtual mem wasted bytes 1949006968

So ~1.8 GiB.

After:

root@kmod ~ # systemd-analyze
Startup finished in 35.872s (kernel) + 41.715s (userspace) = 1min 17.588s
graphical.target reached after 41.594s in userspace.

root@kmod ~ # cat /sys/kernel/debug/modules/stats
Mods ever loaded 66
Mods failed on kread 0
Mods failed on decompress 0
Mods failed on becoming 1
Mods failed on load 0
Total module size 11268096
Total mod text size 4149248
Failed kread bytes 0
Failed decompress bytes 0
Failed becoming bytes 474688
Failed kmod bytes 0
Virtual mem wasted bytes 474688
Average mod size 170729
Average mod text size 62868
Avg fail becoming bytes 474688
Duplicate failed modules:
Module-name How-many-times Reason
cryptd 1 Becoming

root@kmod ~ # du -b /lib/modules/6.3.0-next-20230505+/kernel/crypto/cryptd.ko
475409 /lib/modules/6.3.0-next-20230505+/kernel/crypto/cryptd.ko

So yeah definitely a pretty good improvement. Sometimes the system boots
without any duplicates at all, for some reason Vs the previous attempt.

Tested-by: Luis Chamberlain <mcgrof@kernel.org>

Luis

On Thu, May 25, 2023 at 3:02?PM Luis Chamberlain <mcgrof@kernel.org> wrote:
>
> So yeah definitely a pretty good improvement. Sometimes the system boots
> without any duplicates at all, for some reason Vs the previous attempt.
>
> Tested-by: Luis Chamberlain <mcgrof@kernel.org>

Ok, I decided to just move it from my experimental tree to my main tree.

I think I used about three times the time and effort (and lines of
text) on writing the commit message compared to what I did on the
patch itself.

I tried to lay out the background and the implications of the change -
it may be pretty darn simple, but it does have some subtle issues.

Anyway: I've committed it to my tree. This is not necessarily the best
time to do that, but let's get this behind us, and in particular,
let's get it out and into wider testing asap.

If it causes any problems what-so-ever, I'll just revert it very
aggressively (unless the problem is trivially and obviously fixable).
It is, after all, not a fix for a _kernel_ bug per se, and whil eI
think the patch is very benign, it does change user-visible behavior.
Very intentionally so, but still..

Linus

On Thu, May 25, 2023 at 06:39:52PM -0700, Linus Torvalds wrote:

> Ok, I decided to just move it from my experimental tree to my main tree.
>
> I think I used about three times the time and effort (and lines of
> text) on writing the commit message compared to what I did on the
> patch itself.
>
> I tried to lay out the background and the implications of the change -
> it may be pretty darn simple, but it does have some subtle issues.
>
> Anyway: I've committed it to my tree. This is not necessarily the best
> time to do that, but let's get this behind us, and in particular,
> let's get it out and into wider testing asap.
>
> If it causes any problems what-so-ever, I'll just revert it very
> aggressively (unless the problem is trivially and obviously fixable).
> It is, after all, not a fix for a _kernel_ bug per se, and whil eI
> think the patch is very benign, it does change user-visible behavior.
> Very intentionally so, but still..

This change breaks module loading during boot on the Lenovo Thinkpad
X13s (aarch64).

Specifically it results in indefinite probe deferral of the display and
USB (ethernet) which makes it a pain to debug. Typing in the dark to
acquire some logs reveals that other modules are missing as well.

Fortunately commit 9828ed3f695a ("module: error out early on concurrent
load of the same module file") stood out when skimming the changes that
went into -rc4, and reverting it make all the expected modules be loaded
again.

I have not tried to figure out exactly why things break, but it does
seem like this one should be reverted.

Johan

On Mon, May 29, 2023 at 4:58?AM Johan Hovold <johan@kernel.org> wrote:
>
> I have not tried to figure out exactly why things break, but it does
> seem like this one should be reverted.

Yes, I have done so.

However, can I ask you to just verify that it was purely the exclusive
open part, and it wasn't that I messed up something else. IOW, can you
replace the

return exclusive_deny_write_access(file);

in prepare_file_for_module_load() with just a "return 0", and remove the

allow_write_access(f.file);

line in finit_module()?

That's obviously _instead_ of the revert that I already pushed out,
just to verify that "yup, it's that part, not something silly
elsewhere"

I do wonder what it is that is different in your setup, and maybe you
could also enable the

pr_debug("finit_module: fd=%d, uargs=%p, flags=%i\n", fd, uargs, flags);

in finit_module() while you are at it? Since you'd be editing that
file anyway for the test, just change the pr_debug() to a printk() and
then do

dmesg | grep finit_module

to see what it all results in (on a working kernel, of course).

Linus

On Mon, May 29, 2023 at 07:00:05AM -0400, Linus Torvalds wrote:

> However, can I ask you to just verify that it was purely the exclusive
> open part, and it wasn't that I messed up something else. IOW, can you
> replace the
>
> return exclusive_deny_write_access(file);
>
> in prepare_file_for_module_load() with just a "return 0", and remove the
>
> allow_write_access(f.file);
>
> line in finit_module()?
>
> That's obviously _instead_ of the revert that I already pushed out,
> just to verify that "yup, it's that part, not something silly
> elsewhere"

Yes, those two changes are enough to make the problem go away.

> I do wonder what it is that is different in your setup, and maybe you
> could also enable the
>
> pr_debug("finit_module: fd=%d, uargs=%p, flags=%i\n", fd, uargs, flags);

Below is the corresponding output with a working kernel: 174 requests
for the 131 modules that end up being loaded (without the revert there
is only around 110 modules loaded).

There is some probe deferral and async probing going on during normal
boot which may be part of the explanation.

Johan

[ 0.669112] finit_module: fd=3, uargs=00000000b461506c, flags=0
[ 0.674144] finit_module: fd=4, uargs=00000000b461506c, flags=0
[ 0.676783] finit_module: fd=5, uargs=00000000b461506c, flags=0
[ 0.678920] finit_module: fd=3, uargs=00000000b461506c, flags=0
[ 0.837967] finit_module: fd=5, uargs=0000000000157d9f, flags=0
[ 0.839414] finit_module: fd=3, uargs=00000000b461506c, flags=0
[ 0.844129] finit_module: fd=4, uargs=00000000b461506c, flags=0
[ 0.845016] finit_module: fd=3, uargs=00000000b461506c, flags=0
[ 0.849132] finit_module: fd=3, uargs=00000000b461506c, flags=0
[ 0.849460] finit_module: fd=4, uargs=00000000b461506c, flags=0
[ 3.345004] finit_module: fd=4, uargs=00000000e3e6c6d2, flags=0
[ 3.364302] finit_module: fd=4, uargs=0000000095136ea7, flags=0
[ 3.371928] finit_module: fd=5, uargs=0000000095136ea7, flags=0
[ 4.099183] finit_module: fd=3, uargs=00000000ce2d6f3e, flags=0
[ 4.103156] finit_module: fd=3, uargs=000000004e3e14c2, flags=0
[ 4.713558] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.715608] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.717620] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.717910] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.719517] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.725862] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.726730] finit_module: fd=13, uargs=00000000262da138, flags=0
[ 4.727018] finit_module: fd=14, uargs=00000000262da138, flags=0
[ 4.730525] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.749602] finit_module: fd=15, uargs=00000000262da138, flags=0
[ 4.749675] finit_module: fd=15, uargs=00000000262da138, flags=0
[ 4.749678] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.774117] finit_module: fd=13, uargs=00000000262da138, flags=0
[ 4.795307] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.797327] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.798405] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.799140] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.800850] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.807306] finit_module: fd=13, uargs=00000000262da138, flags=0
[ 4.807313] finit_module: fd=13, uargs=00000000262da138, flags=0
[ 4.807321] finit_module: fd=16, uargs=00000000262da138, flags=0
[ 4.807394] finit_module: fd=13, uargs=00000000262da138, flags=0
[ 4.807463] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.807525] finit_module: fd=13, uargs=00000000262da138, flags=0
[ 4.807530] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.807590] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.811469] finit_module: fd=0, uargs=0000000080fab15b, flags=0
[ 4.845851] finit_module: fd=15, uargs=00000000262da138, flags=0
[ 4.845875] finit_module: fd=13, uargs=00000000262da138, flags=0
[ 4.846282] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.846363] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.846363] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.846669] finit_module: fd=13, uargs=00000000262da138, flags=0
[ 4.846994] finit_module: fd=13, uargs=00000000262da138, flags=0
[ 4.847005] finit_module: fd=13, uargs=00000000262da138, flags=0
[ 4.847194] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.847356] finit_module: fd=15, uargs=00000000262da138, flags=0
[ 4.847448] finit_module: fd=17, uargs=00000000262da138, flags=0
[ 4.847556] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.847651] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.848175] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.850005] finit_module: fd=15, uargs=00000000262da138, flags=0
[ 4.850485] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.866031] finit_module: fd=15, uargs=00000000262da138, flags=0
[ 4.866032] finit_module: fd=16, uargs=00000000262da138, flags=0
[ 4.866381] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.866711] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.867757] finit_module: fd=13, uargs=00000000262da138, flags=0
[ 4.868360] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.886043] finit_module: fd=16, uargs=00000000262da138, flags=0
[ 4.886046] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.886046] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.886060] finit_module: fd=17, uargs=00000000262da138, flags=0
[ 4.886114] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.886140] finit_module: fd=13, uargs=00000000262da138, flags=0
[ 4.886326] finit_module: fd=15, uargs=00000000262da138, flags=0
[ 4.886716] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.887210] finit_module: fd=16, uargs=00000000262da138, flags=0
[ 4.887451] finit_module: fd=13, uargs=00000000262da138, flags=0
[ 4.887811] finit_module: fd=13, uargs=00000000262da138, flags=0
[ 4.887963] finit_module: fd=15, uargs=00000000262da138, flags=0
[ 4.892066] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.896048] finit_module: fd=13, uargs=00000000262da138, flags=0
[ 4.896070] finit_module: fd=13, uargs=00000000262da138, flags=0
[ 4.896092] finit_module: fd=15, uargs=00000000262da138, flags=0
[ 4.896157] finit_module: fd=18, uargs=00000000262da138, flags=0
[ 4.896193] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.896211] finit_module: fd=18, uargs=00000000262da138, flags=0
[ 4.896737] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.896751] finit_module: fd=15, uargs=00000000262da138, flags=0
[ 4.897174] finit_module: fd=15, uargs=00000000262da138, flags=0
[ 4.897343] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.897388] finit_module: fd=19, uargs=00000000262da138, flags=0
[ 4.897555] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.897592] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.899657] finit_module: fd=16, uargs=00000000262da138, flags=0
[ 4.899973] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 4.900316] finit_module: fd=17, uargs=00000000262da138, flags=0
[ 4.901188] finit_module: fd=13, uargs=00000000262da138, flags=0
[ 4.901668] finit_module: fd=13, uargs=00000000262da138, flags=0
[ 4.901708] finit_module: fd=13, uargs=00000000262da138, flags=0
[ 4.902030] finit_module: fd=15, uargs=00000000262da138, flags=0
[ 4.903964] finit_module: fd=14, uargs=00000000262da138, flags=0
[ 4.905243] finit_module: fd=13, uargs=00000000262da138, flags=0
[ 4.907083] finit_module: fd=17, uargs=00000000262da138, flags=0
[ 4.907480] finit_module: fd=16, uargs=00000000262da138, flags=0
[ 4.907519] finit_module: fd=16, uargs=00000000262da138, flags=0
[ 4.909481] finit_module: fd=13, uargs=00000000262da138, flags=0
[ 4.911705] finit_module: fd=15, uargs=00000000262da138, flags=0
[ 4.912056] finit_module: fd=18, uargs=00000000262da138, flags=0
[ 4.912079] finit_module: fd=15, uargs=00000000262da138, flags=0
[ 4.915340] finit_module: fd=19, uargs=00000000262da138, flags=0
[ 4.933199] finit_module: fd=16, uargs=00000000262da138, flags=0
[ 4.933585] finit_module: fd=18, uargs=00000000262da138, flags=0
[ 4.935169] finit_module: fd=20, uargs=00000000262da138, flags=0
[ 4.956021] finit_module: fd=19, uargs=00000000262da138, flags=0
[ 4.956797] finit_module: fd=16, uargs=00000000262da138, flags=0
[ 4.959865] finit_module: fd=17, uargs=00000000262da138, flags=0
[ 4.964171] finit_module: fd=17, uargs=00000000262da138, flags=0
[ 4.977073] finit_module: fd=18, uargs=00000000262da138, flags=0
[ 4.980167] finit_module: fd=18, uargs=00000000262da138, flags=0
[ 5.043379] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 5.053709] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 5.131232] finit_module: fd=15, uargs=00000000262da138, flags=0
[ 5.140785] finit_module: fd=19, uargs=00000000262da138, flags=0
[ 5.186244] finit_module: fd=18, uargs=00000000262da138, flags=0
[ 5.186247] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 5.186252] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 5.186451] finit_module: fd=15, uargs=00000000262da138, flags=0
[ 5.186507] finit_module: fd=13, uargs=00000000262da138, flags=0
[ 5.187345] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 5.190282] finit_module: fd=15, uargs=00000000262da138, flags=0
[ 5.195744] finit_module: fd=13, uargs=00000000262da138, flags=0
[ 5.198242] finit_module: fd=16, uargs=00000000262da138, flags=0
[ 5.198271] finit_module: fd=20, uargs=00000000262da138, flags=0
[ 5.222394] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 5.222395] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 5.222407] finit_module: fd=16, uargs=00000000262da138, flags=0
[ 5.222430] finit_module: fd=21, uargs=00000000262da138, flags=0
[ 5.222432] finit_module: fd=16, uargs=00000000262da138, flags=0
[ 5.222443] finit_module: fd=15, uargs=00000000262da138, flags=0
[ 5.229650] finit_module: fd=22, uargs=00000000262da138, flags=0
[ 5.257981] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 5.313560] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 6.144316] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 6.178956] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 6.178961] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 6.182057] finit_module: fd=13, uargs=00000000262da138, flags=0
[ 6.182067] finit_module: fd=13, uargs=00000000262da138, flags=0
[ 6.243708] finit_module: fd=0, uargs=00000000f9e4f67e, flags=0
[ 6.249397] finit_module: fd=0, uargs=000000001b26db10, flags=0
[ 6.249904] finit_module: fd=1, uargs=000000001b26db10, flags=0
[ 6.250626] finit_module: fd=2, uargs=000000001b26db10, flags=0
[ 6.251515] finit_module: fd=3, uargs=000000001b26db10, flags=0
[ 6.254112] finit_module: fd=4, uargs=000000001b26db10, flags=0
[ 6.255129] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 6.255504] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 6.259256] finit_module: fd=0, uargs=00000000e1b6cfe4, flags=0
[ 6.264136] finit_module: fd=0, uargs=000000004070418f, flags=0
[ 6.265227] finit_module: fd=1, uargs=000000004070418f, flags=0
[ 6.270175] finit_module: fd=0, uargs=0000000092757077, flags=0
[ 6.271230] finit_module: fd=1, uargs=0000000092757077, flags=0
[ 6.322960] finit_module: fd=3, uargs=00000000fb904223, flags=0
[ 6.373125] finit_module: fd=0, uargs=00000000e2cdc73f, flags=0
[ 6.380061] finit_module: fd=0, uargs=000000000591e4e9, flags=0
[ 6.392296] finit_module: fd=0, uargs=0000000088d2796a, flags=0
[ 6.464595] finit_module: fd=0, uargs=000000001aa8b42e, flags=0
[ 6.479839] finit_module: fd=0, uargs=00000000de50a030, flags=0
[ 6.488790] finit_module: fd=0, uargs=00000000cbcb6a65, flags=0
[ 6.492573] finit_module: fd=1, uargs=00000000cbcb6a65, flags=0
[ 6.514903] finit_module: fd=0, uargs=000000006f393376, flags=0
[ 7.989970] finit_module: fd=0, uargs=00000000c4594f52, flags=0
[ 11.492886] finit_module: fd=13, uargs=00000000262da138, flags=0
[ 11.639532] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 11.640048] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 11.640997] finit_module: fd=15, uargs=00000000262da138, flags=0
[ 11.641049] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 11.775051] finit_module: fd=6, uargs=00000000262da138, flags=0
[ 11.776806] finit_module: fd=6, uargs=00000000262da138, flags=0

> On Mon, May 29, 2023 at 07:00:05AM -0400, Linus Torvalds wrote:
> > I do wonder what it is that is different in your setup

I took a closer look at some of the modules that failed to load and
noticed a pattern in that they have dependencies that are needed by more
than one device.

If attempts to load the drivers for two such devices are made in
parallel, only one of them may be successful in loading the shared
dependency which means that module loading is now aborted for the other.

I took a quick look at the kmod code

https://git.kernel.org/pub/scm/utils/kernel/kmod/kmod.git/tree/libkmod/libkmod-module.c#n1305

and it does seem like this could happen if we start returning errors
when a module is already in the process of being loaded.

Johan

On Mon, May 29, 2023 at 8:44?AM Johan Hovold <johan@kernel.org> wrote:
>
> Yes, those two changes are enough to make the problem go away.

Ok, good. Expected, but just verifying that it wasn't some silly
incidental thinko.

> > I do wonder what it is that is different in your setup, and maybe you
> > could also enable the
> >
> > pr_debug("finit_module: fd=%d, uargs=%p, flags=%i\n", fd, uargs, flags);
>
> Below is the corresponding output with a working kernel: 174 requests
> for the 131 modules that end up being loaded (without the revert there
> is only around 110 modules loaded).

Ok, your setup doesn't sound *too* different from mine. I have 176
kernel modules on my laptop right now, and that exclusive open
obviously worked fine for me.

But it could easily be some random small difference just from
different hardware, so...

And yeah, that dmesg output is useless, I didn't think of the fact
that it only prints out the file descriptor, not the actual path to
the file. In fact, without that change in place, the module code never
actually looks at the file and leaves it all to
kernel_read_file_from_fd().

With my change, it woul dhave been trivial to use "%pD" and point it
at the file pointer instead, and get the dentry name that way, but
never mind. I think you're entirely right that it's probably due to a
shared dependency module, and I just didn't happen to trigger that
case.

Sadly, the whole idea was to figure out the exclusion so early that we
don't have the module data structures lookup up yet, so there's no
really obvious thing to serialize the load on.

I'll have to think about this more. Serializing on a per-inode lock
would seem to be the simplest thing, but they are all for IO, and we
can't just take them over the read.

Linus

On Mon, May 29, 2023 at 11:18?AM Johan Hovold <johan@kernel.org> wrote:
>
> I took a closer look at some of the modules that failed to load and
> noticed a pattern in that they have dependencies that are needed by more
> than one device.

Ok, this is a "maybe something like this" RFC series of two patches -
one trivial one to re-organize things a bit so that we can then do the
real one which uses a filter based on the inode pointer to return an
"idempotent return value" for module loads that share the same inode.

It's entirely untested, and since I'm on the road I'm going to not
really be able to test it. It compiles for me, and the code looks
fairly straightforward, but it's probably buggy.

It's very loosely based on Luis' attempt, but it
(a) is internal to module loading
(b) uses a reliable cookie
(c) doesn't leave the cookie around randomly for later
(d) has seen absolutely no testing

Put another way: if somebody wants to play with this, please treat it
as a starting point, not the final thing. You might need to debug
things, and fix silly mistakes.

The idea is to just have a simple hash list of currently executing
module loads, protected by a trivial spinlock. Every module loader
adds itself to the right hash list, and if they were the *first* one
(ie no other pending module loads for that inode), will actually do
the module load.

Everybody who *isn't* the first one will just wait for completion and
return the same error code that the first one returned.

This is technically bogus. The first one might fail due to arguments.
So the cookie shouldn't be just the inode, it should be the inode and
a hash of the arguments or something like that. But it is what it is,
and apart from possible show-stopper bugs this is no worse than the
failed "exclusive write deny" attempt. IOW - maybe worth trying?

And if *that* didn't sell people on this patch series, I don't know
what will. I should be in marketing! Two drink minimums, here I come!

Linus

On Mon, May 29, 2023 at 09:55:15PM -0400, Linus Torvalds wrote:
> On Mon, May 29, 2023 at 11:18?AM Johan Hovold <johan@kernel.org> wrote:
> >
> > I took a closer look at some of the modules that failed to load and
> > noticed a pattern in that they have dependencies that are needed by more
> > than one device.
>
> Ok, this is a "maybe something like this" RFC series of two patches -
> one trivial one to re-organize things a bit so that we can then do the
> real one which uses a filter based on the inode pointer to return an
> "idempotent return value" for module loads that share the same inode.
>
> It's entirely untested, and since I'm on the road I'm going to not
> really be able to test it. It compiles for me, and the code looks
> fairly straightforward, but it's probably buggy.
>
> It's very loosely based on Luis' attempt, but it
> (a) is internal to module loading
> (b) uses a reliable cookie
> (c) doesn't leave the cookie around randomly for later
> (d) has seen absolutely no testing
>
> Put another way: if somebody wants to play with this, please treat it
> as a starting point, not the final thing. You might need to debug
> things, and fix silly mistakes.

With the missing spinlock initialisation fixed:

-static struct spinlock idem_lock;
+static DEFINE_SPINLOCK(idem_lock);

this passes basic smoke testing and allows the X13s to boot.

It does not seem to have any significant impact on boot time, but it
avoids some of the unnecessary load attempts as intended:

Before:

Mods ever loaded 131
Mods failed on kread 0
Mods failed on decompress 0
Mods failed on becoming 24
Mods failed on load 14
Total module size 12587008
Total mod text size 5058560
Failed kread bytes 0
Failed decompress bytes 0
Failed becoming bytes 2437992
Failed kmod bytes 1858992
Virtual mem wasted bytes 4296984
Average mod size 96085
Average mod text size 38615
Avg fail becoming bytes 101583
Average fail load bytes 132786

After:

Mods ever loaded 131
Mods failed on kread 0
Mods failed on decompress 0
Mods failed on becoming 4
Mods failed on load 0
Total module size 12587008
Total mod text size 5058560
Failed kread bytes 0
Failed decompress bytes 0
Failed becoming bytes 109776
Failed kmod bytes 0
Virtual mem wasted bytes 109776
Average mod size 96085
Average mod text size 38615
Avg fail becoming bytes 27444

Johan

On Mon, May 29, 2023 at 01:47:28PM -0400, Linus Torvalds wrote:
> On Mon, May 29, 2023 at 8:44?AM Johan Hovold <johan@kernel.org> wrote:

> > > I do wonder what it is that is different in your setup, and maybe you
> > > could also enable the
> > >
> > > pr_debug("finit_module: fd=%d, uargs=%p, flags=%i\n", fd, uargs, flags);
> >
> > Below is the corresponding output with a working kernel: 174 requests
> > for the 131 modules that end up being loaded (without the revert there
> > is only around 110 modules loaded).

> And yeah, that dmesg output is useless, I didn't think of the fact
> that it only prints out the file descriptor, not the actual path to
> the file. In fact, without that change in place, the module code never
> actually looks at the file and leaves it all to
> kernel_read_file_from_fd().

Yeah, I added a printk with the module name to load_module() to make
some sense of it.

> With my change, it woul dhave been trivial to use "%pD" and point it
> at the file pointer instead, and get the dentry name that way, but
> never mind. I think you're entirely right that it's probably due to a
> shared dependency module, and I just didn't happen to trigger that
> case.

For completeness, here's a corresponding log from when running with your
RFC. Those duplicate requests that now wait for loading to complete
would have failed, and that explains why some modules like
qcom-spmi-adc5 and qcom-spmi-adc-tm5 that both depend on
qcom-vadc-common would in turn fail to load.

Johan

[ 0.633127] init_module_from_file - i2c-core.ko
[ 0.638320] init_module_from_file - i2c-hid.ko
[ 0.640654] init_module_from_file - i2c-hid-of.ko
[ 0.642572] init_module_from_file - i2c-qcom-geni.ko
[ 0.826911] init_module_from_file - hid-multitouch.ko
[ 0.827861] init_module_from_file - nvme-core.ko
[ 0.833011] init_module_from_file - nvme.ko
[ 0.835558] init_module_from_file - phy-qcom-qmp-pcie.ko
[ 0.841050] init_module_from_file - crc8.ko
[ 0.841371] init_module_from_file - pcie-qcom.ko
[ 3.390182] init_module_from_file - ipv6.ko
[ 3.402261] init_module_from_file - x_tables.ko
[ 3.406573] init_module_from_file - ip_tables.ko
[ 4.180345] init_module_from_file - dm-mod.ko
[ 4.186611] init_module_from_file - drm.ko
[ 4.793481] init_module_from_file - pwm_bl.ko
[ 4.798935] init_module_from_file - soundwire-bus.ko
[ 4.802551] init_module_from_file - qmi_helpers.ko
[ 4.805664] init_module_from_file - socinfo.ko
[ 4.814729] init_module_from_file - pdr_interface.ko
[ 4.830809] init_module_from_file - soundcore.ko
[ 4.832227] init_module_from_file - qcom-wdt.ko
[ 4.832242] init_module_from_file - qcom-rng.ko
[ 4.832311] init_module_from_file - icc-osm-l3.ko
[ 4.867903] init_module_from_file - pmic_glink.ko
[ 4.867904] init_module_from_file - snd.ko
[ 4.868045] init_module_from_file - mdt_loader.ko
[ 4.890274] init_module_from_file - snd.ko
[ 4.893962] init_module_from_file - snd.ko
[ 4.894620] init_module_from_file - snd.ko
[ 4.896162] init_module_from_file - snd.ko
[ 4.896797] init_module_from_file - snd.ko
[ 4.896907] init_module_from_file - snd.ko
[ 4.898087] init_module_from_file - snd.ko
[ 4.907548] init_module_from_file - qcom_sysmon.ko
[ 4.907560] init_module_from_file - qcom_sysmon.ko
[ 4.918690] init_module_from_file - snd.ko - waited, ret = 0
[ 4.918692] init_module_from_file - snd.ko - waited, ret = 0
[ 4.918694] init_module_from_file - snd.ko - waited, ret = 0
[ 4.918695] init_module_from_file - snd.ko - waited, ret = 0
[ 4.918699] init_module_from_file - snd.ko - waited, ret = 0
[ 4.918700] init_module_from_file - snd.ko - waited, ret = 0
[ 4.920849] init_module_from_file - snd.ko - waited, ret = 0
[ 4.937139] init_module_from_file - qrtr.ko
[ 4.937163] init_module_from_file - icc-bwmon.ko
[ 4.937185] init_module_from_file - icc-bwmon.ko
[ 4.938603] init_module_from_file - qcom_sysmon.ko - waited, ret = 0
[ 4.939866] init_module_from_file - snd-timer.ko
[ 4.939877] init_module_from_file - snd-timer.ko
[ 4.939885] init_module_from_file - snd-timer.ko
[ 4.939897] init_module_from_file - snd-timer.ko
[ 4.939905] init_module_from_file - snd-timer.ko
[ 4.939914] init_module_from_file - snd-timer.ko
[ 4.939982] init_module_from_file - snd-timer.ko
[ 4.940050] init_module_from_file - snd-timer.ko
[ 4.943465] init_module_from_file - pinctrl-lpass-lpi.ko
[ 4.943493] init_module_from_file - phy-qcom-snps-femto-v2.ko
[ 4.943512] init_module_from_file - phy-qcom-snps-femto-v2.ko
[ 4.944176] init_module_from_file - qcom_q6v5.ko
[ 4.944362] init_module_from_file - qcom_q6v5.ko
[ 4.946140] init_module_from_file - qcom_q6v5.ko - waited, ret = 0
[ 4.946758] init_module_from_file - snd-timer.ko - waited, ret = 0
[ 4.946762] init_module_from_file - snd-timer.ko - waited, ret = 0
[ 4.946919] init_module_from_file - snd-timer.ko - waited, ret = 0
[ 4.947484] init_module_from_file - snd-timer.ko - waited, ret = 0
[ 4.947827] init_module_from_file - snd-timer.ko - waited, ret = 0
[ 4.948101] init_module_from_file - snd-timer.ko - waited, ret = 0
[ 4.948163] init_module_from_file - snd-timer.ko - waited, ret = 0
[ 4.948483] init_module_from_file - phy-qcom-snps-femto-v2.ko - waited, ret = 0
[ 4.950639] init_module_from_file - icc-bwmon.ko - waited, ret = 0
[ 4.951178] init_module_from_file - snd-pcm.ko
[ 4.951279] init_module_from_file - snd-pcm.ko
[ 4.951616] init_module_from_file - qcom_glink_smem.ko
[ 4.952049] init_module_from_file - snd-pcm.ko
[ 4.952122] init_module_from_file - snd-pcm.ko
[ 4.952132] init_module_from_file - snd-pcm.ko
[ 4.952185] init_module_from_file - snd-pcm.ko
[ 4.952231] init_module_from_file - pinctrl-sc8280xp-lpass-lpi.ko
[ 4.952238] init_module_from_file - snd-pcm.ko
[ 4.952326] init_module_from_file - qcom_glink_smem.ko
[ 4.957870] init_module_from_file - snd-pcm.ko
[ 4.971513] init_module_from_file - typec.ko
[ 4.971529] init_module_from_file - typec.ko
[ 4.971544] init_module_from_file - phy-qcom-edp.ko
[ 4.971619] init_module_from_file - typec.ko
[ 4.971806] init_module_from_file - snd-pcm.ko
[ 4.971961] init_module_from_file - qcom_common.ko
[ 4.972583] init_module_from_file - qcom_common.ko
[ 4.972676] init_module_from_file - rfkill.ko
[ 4.972898] init_module_from_file - qcom_stats.ko
[ 4.973031] init_module_from_file - typec.ko
[ 4.973917] init_module_from_file - snd-pcm.ko - waited, ret = 0
[ 4.974024] init_module_from_file - snd-pcm.ko - waited, ret = 0
[ 4.974090] init_module_from_file - qcom_common.ko - waited, ret = 0
[ 4.974134] init_module_from_file - snd-pcm.ko - waited, ret = 0
[ 4.974205] init_module_from_file - snd-pcm.ko - waited, ret = 0
[ 4.974265] init_module_from_file - snd-pcm.ko - waited, ret = 0
[ 4.974307] init_module_from_file - snd-pcm.ko - waited, ret = 0
[ 4.974385] init_module_from_file - snd-pcm.ko - waited, ret = 0
[ 4.974436] init_module_from_file - snd-pcm.ko - waited, ret = 0
[ 4.979168] init_module_from_file - qcom_pil_info.ko
[ 4.979352] init_module_from_file - snd-compress.ko
[ 4.979399] init_module_from_file - qcom_pil_info.ko
[ 4.979668] init_module_from_file - snd-compress.ko
[ 4.979912] init_module_from_file - snd-compress.ko
[ 4.980022] init_module_from_file - rtc-pm8xxx.ko
[ 4.980107] init_module_from_file - snd-compress.ko
[ 4.980216] init_module_from_file - sysimgblt.ko
[ 4.980490] init_module_from_file - nvmem_qcom-spmi-sdam.ko
[ 4.980593] init_module_from_file - snd-compress.ko
[ 4.981109] init_module_from_file - snd-compress.ko
[ 4.981136] init_module_from_file - qcom_pil_info.ko - waited, ret = 0
[ 4.981285] init_module_from_file - snd-compress.ko
[ 4.981378] init_module_from_file - typec.ko - waited, ret = 0
[ 4.981382] init_module_from_file - typec.ko - waited, ret = 0
[ 4.981402] init_module_from_file - snd-compress.ko - waited, ret = 0
[ 4.981404] init_module_from_file - snd-compress.ko - waited, ret = 0
[ 4.981412] init_module_from_file - typec.ko - waited, ret = 0
[ 4.981453] init_module_from_file - snd-compress.ko - waited, ret = 0
[ 4.981482] init_module_from_file - snd-compress.ko - waited, ret = 0
[ 4.981516] init_module_from_file - snd-compress.ko - waited, ret = 0
[ 4.981620] init_module_from_file - snd-compress.ko
[ 4.982970] init_module_from_file - snd-compress.ko
[ 4.985063] init_module_from_file - qcom_q6v5_pas.ko
[ 4.985132] init_module_from_file - qcom_q6v5_pas.ko
[ 4.985200] init_module_from_file - snd-soc-core.ko
[ 4.985222] init_module_from_file - qcom-vadc-common.ko
[ 4.985254] init_module_from_file - sysfillrect.ko
[ 4.985654] init_module_from_file - snd-soc-core.ko
[ 4.985697] init_module_from_file - sysfillrect.ko
[ 4.985862] init_module_from_file - snd-soc-core.ko
[ 4.985883] init_module_from_file - ecc.ko
[ 4.985950] init_module_from_file - reboot-mode.ko
[ 4.985982] init_module_from_file - snd-soc-core.ko
[ 4.986159] init_module_from_file - snd-soc-core.ko
[ 4.986304] init_module_from_file - snd-soc-core.ko
[ 4.986829] init_module_from_file - qcom-vadc-common.ko
[ 4.987106] init_module_from_file - snd-soc-core.ko
[ 4.987546] init_module_from_file - qcom-vadc-common.ko - waited, ret = 0
[ 4.987889] init_module_from_file - snd-soc-core.ko
[ 4.988198] init_module_from_file - snd-soc-core.ko
[ 4.989151] init_module_from_file - industrialio.ko
[ 4.989220] init_module_from_file - industrialio.ko
[ 4.989588] init_module_from_file - gpio-sbu-mux.ko
[ 4.989651] init_module_from_file - gpio-sbu-mux.ko
[ 4.990037] init_module_from_file - qcom-pon.ko
[ 4.991354] init_module_from_file - mhi.ko
[ 4.992889] init_module_from_file - industrialio.ko - waited, ret = 0
[ 4.993473] init_module_from_file - cfg80211.ko
[ 4.994053] init_module_from_file - snd-soc-core.ko - waited, ret = 0
[ 4.994073] init_module_from_file - snd-soc-core.ko - waited, ret = 0
[ 4.994103] init_module_from_file - snd-soc-core.ko - waited, ret = 0
[ 4.994107] init_module_from_file - snd-soc-core.ko - waited, ret = 0
[ 4.994129] init_module_from_file - snd-soc-core.ko - waited, ret = 0
[ 4.994147] init_module_from_file - snd-soc-core.ko - waited, ret = 0
[ 4.994166] init_module_from_file - sysfillrect.ko
[ 4.994176] init_module_from_file - snd-soc-core.ko - waited, ret = 0
[ 4.994206] init_module_from_file - snd-soc-core.ko - waited, ret = 0
[ 4.994319] init_module_from_file - qcom-spmi-adc5.ko
[ 4.994621] init_module_from_file - ecdh_generic.ko
[ 4.994975] init_module_from_file - snd-soc-lpass-macro-common.ko
[ 4.994999] init_module_from_file - qcom-spmi-adc-tm5.ko
[ 4.996797] init_module_from_file - gpio-sbu-mux.ko - waited, ret = 0
[ 4.997487] init_module_from_file - snd-soc-qcom-sdw.ko
[ 4.997511] init_module_from_file - snd-soc-lpass-macro-common.ko
[ 4.997546] init_module_from_file - snd-soc-wcd-mbhc.ko
[ 4.997573] init_module_from_file - sysfillrect.ko - waited, ret = 0
[ 4.997754] init_module_from_file - syscopyarea.ko
[ 4.997762] init_module_from_file - syscopyarea.ko
[ 4.999053] init_module_from_file - sysfillrect.ko - waited, ret = 0
[ 4.999247] init_module_from_file - snd-soc-lpass-macro-common.ko
[ 4.999482] init_module_from_file - snd-soc-lpass-wsa-macro.ko
[ 4.999587] init_module_from_file - soundwire-qcom.ko
[ 5.000338] init_module_from_file - soundwire-qcom.ko
[ 5.000745] init_module_from_file - soundwire-qcom.ko
[ 5.001008] init_module_from_file - syscopyarea.ko
[ 5.015734] init_module_from_file - bluetooth.ko
[ 5.016020] init_module_from_file - regmap-sdw.ko
[ 5.016434] init_module_from_file - snd-soc-qcom-common.ko
[ 5.017416] init_module_from_file - syscopyarea.ko - waited, ret = 0
[ 5.018912] init_module_from_file - snd-soc-lpass-macro-common.ko - waited, ret = 0
[ 5.018952] init_module_from_file - syscopyarea.ko - waited, ret = 0
[ 5.019196] init_module_from_file - snd-soc-lpass-macro-common.ko - waited, ret = 0
[ 5.020220] init_module_from_file - drm_kms_helper.ko
[ 5.020230] init_module_from_file - snd-soc-lpass-rx-macro.ko
[ 5.023262] init_module_from_file - drm_kms_helper.ko
[ 5.023366] init_module_from_file - snd-soc-wcd938x-sdw.ko
[ 5.023705] init_module_from_file - snd-soc-lpass-va-macro.ko
[ 5.024133] init_module_from_file - drm_kms_helper.ko
[ 5.024223] init_module_from_file - snd-soc-sc8280xp.ko
[ 5.024814] init_module_from_file - snd-soc-lpass-tx-macro.ko
[ 5.027886] init_module_from_file - drm_kms_helper.ko - waited, ret = 0
[ 5.027937] init_module_from_file - drm_kms_helper.ko - waited, ret = 0
[ 5.028550] init_module_from_file - phy-qcom-qmp-combo.ko
[ 5.028828] init_module_from_file - snd-soc-wcd938x.ko
[ 5.029106] init_module_from_file - drm_dp_aux_bus.ko
[ 5.030265] init_module_from_file - phy-qcom-qmp-combo.ko
[ 5.037773] init_module_from_file - qcom_q6v5_pas.ko - waited, ret = 0
[ 5.038034] init_module_from_file - soundwire-qcom.ko - waited, ret = 0
[ 5.038548] init_module_from_file - libarc4.ko
[ 5.038551] init_module_from_file - soundwire-qcom.ko - waited, ret = 0
[ 5.042176] init_module_from_file - btqca.ko
[ 5.044433] init_module_from_file - mac80211.ko
[ 5.044480] init_module_from_file - drm_display_helper.ko
[ 5.046672] init_module_from_file - qcom-spmi-temp-alarm.ko
[ 5.048163] init_module_from_file - hci_uart.ko
[ 5.056843] init_module_from_file - gpu-sched.ko
[ 5.073356] init_module_from_file - led-class-multicolor.ko
[ 5.087906] init_module_from_file - qcom-spmi-temp-alarm.ko
[ 5.106010] init_module_from_file - ath11k.ko
[ 5.106084] init_module_from_file - msm.ko
[ 5.125345] init_module_from_file - leds-qcom-lpg.ko
[ 5.150715] init_module_from_file - ath11k_pci.ko
[ 5.157163] init_module_from_file - qcom-spmi-temp-alarm.ko - waited, ret = 0
[ 5.157894] init_module_from_file - qcom_battmgr.ko
[ 5.158102] init_module_from_file - phy-qcom-qmp-combo.ko - waited, ret = 0
[ 5.159204] init_module_from_file - pmic_glink_altmode.ko
[ 5.258217] init_module_from_file - qrtr-smd.ko
[ 5.258238] init_module_from_file - qrtr-smd.ko
[ 5.258294] init_module_from_file - rpmsg_char.ko
[ 5.259157] init_module_from_file - apr.ko
[ 5.259160] init_module_from_file - rpmsg_char.ko
[ 5.276634] init_module_from_file - qrtr-smd.ko - waited, ret = 0
[ 5.277698] init_module_from_file - fastrpc.ko
[ 5.278293] init_module_from_file - rpmsg_char.ko - waited, ret = 0
[ 5.278926] init_module_from_file - rpmsg_ctrl.ko
[ 5.279642] init_module_from_file - rpmsg_ctrl.ko
[ 5.281399] init_module_from_file - rpmsg_ctrl.ko - waited, ret = 0
[ 5.330747] init_module_from_file - snd-soc-hdmi-codec.ko
[ 5.330826] init_module_from_file - snd-soc-hdmi-codec.ko
[ 5.333130] init_module_from_file - snd-soc-hdmi-codec.ko
[ 5.333201] init_module_from_file - snd-soc-hdmi-codec.ko - waited, ret = 0
[ 5.333214] init_module_from_file - snd-soc-hdmi-codec.ko - waited, ret = 0
[ 5.396803] init_module_from_file - panel-edp.ko
[ 6.101509] init_module_from_file - qrtr-mhi.ko
[ 6.196359] init_module_from_file - iptable_filter.ko
[ 6.203333] init_module_from_file - nf_defrag_ipv4.ko
[ 6.203903] init_module_from_file - nf_defrag_ipv6.ko
[ 6.204628] init_module_from_file - libcrc32c.ko
[ 6.204727] init_module_from_file - snd-q6apm.ko
[ 6.204985] init_module_from_file - snd-q6apm.ko
[ 6.205007] init_module_from_file - nf_conntrack.ko
[ 6.207137] init_module_from_file - xt_conntrack.ko
[ 6.211214] init_module_from_file - xt_tcpudp.ko
[ 6.215535] init_module_from_file - nf_reject_ipv4.ko
[ 6.216071] init_module_from_file - ipt_REJECT.ko
[ 6.222201] init_module_from_file - nf_log_syslog.ko
[ 6.223050] init_module_from_file - xt_LOG.ko
[ 6.241544] init_module_from_file - ip6_tables.ko
[ 6.286511] init_module_from_file - af_alg.ko
[ 6.293272] init_module_from_file - algif_hash.ko
[ 6.304773] init_module_from_file - md5.ko
[ 6.333540] init_module_from_file - mii.ko
[ 6.333550] init_module_from_file - mii.ko
[ 6.334785] init_module_from_file - mii.ko - waited, ret = 0
[ 6.335170] init_module_from_file - r8152.ko
[ 6.335282] init_module_from_file - r8152.ko
[ 6.370285] init_module_from_file - algif_skcipher.ko
[ 6.384424] init_module_from_file - ecb.ko
[ 6.392643] init_module_from_file - libdes.ko
[ 6.397046] init_module_from_file - des_generic.ko
[ 6.416039] init_module_from_file - cbc.ko
[ 6.643702] init_module_from_file - r8152.ko - waited, ret = 0
[ 7.940666] init_module_from_file - michael_mic.ko
[ 11.233648] init_module_from_file - snd-q6apm.ko - waited, ret = 0
[ 11.234264] init_module_from_file - q6prm.ko
[ 11.303802] init_module_from_file - q6apm-dai.ko
[ 11.304498] init_module_from_file - snd-q6dsp-common.ko
[ 11.305476] init_module_from_file - q6apm-lpass-dais.ko
[ 11.309858] init_module_from_file - q6prm-clocks.ko
[ 11.446919] init_module_from_file - snd-soc-wsa883x.ko
[ 11.446953] init_module_from_file - snd-soc-wsa883x.ko
[ 11.456469] init_module_from_file - snd-soc-wsa883x.ko - waited, ret = 0

On Mon, May 29, 2023 at 09:55:15PM -0400, Linus Torvalds wrote:
> On Mon, May 29, 2023 at 11:18?AM Johan Hovold <johan@kernel.org> wrote:
> >
> > I took a closer look at some of the modules that failed to load and
> > noticed a pattern in that they have dependencies that are needed by more
> > than one device.
>
> Ok, this is a "maybe something like this" RFC series of two patches -
> one trivial one to re-organize things a bit so that we can then do the
> real one which uses a filter based on the inode pointer to return an
> "idempotent return value" for module loads that share the same inode.
>
> It's entirely untested, and since I'm on the road I'm going to not
> really be able to test it. It compiles for me, and the code looks
> fairly straightforward, but it's probably buggy.
>
> It's very loosely based on Luis' attempt, but it
> (a) is internal to module loading
> (b) uses a reliable cookie
> (c) doesn't leave the cookie around randomly for later
> (d) has seen absolutely no testing
>
> Put another way: if somebody wants to play with this, please treat it
> as a starting point, not the final thing. You might need to debug
> things, and fix silly mistakes.
>
> The idea is to just have a simple hash list of currently executing
> module loads, protected by a trivial spinlock. Every module loader
> adds itself to the right hash list, and if they were the *first* one
> (ie no other pending module loads for that inode), will actually do
> the module load.
>
> Everybody who *isn't* the first one will just wait for completion and
> return the same error code that the first one returned.

That's also a hell much more snazzier MODULE_DEBUG_AUTOLOAD_DUPS if we
ever wanted to do something similar there if we wanted to also
join request_module() calls, instead of it hiding under debug.

> This is technically bogus. The first one might fail due to arguments.

For boot it's fine, as I can't think of boot wanting to support trying
to load a module with different arguments but who knows. But I can't
see it sensible to issue concurrent multiple requests for modules
with different arguments without waiting in userspace for the first
to fail.

Even post-boot, doing that sounds rather insane, but it would certainly
be a compromise and should probably be clearly documented. I think just
a comment acknolwedging that corner case seems sensible.

Because we won't be able to get the arguments until we process the
module, so it would be too late for this optimization on kread. So it is
why I had also stuck to the original feature being in kread, as then it
provides a uniq kread call and the caller is aware of it. But indeed I
had not considered the effects of arguments.

Lucas, any thoughts from modules kmod userspace perspective into
supporting anyone likely issuing concurrent modules requests with
differing arguments?

> So the cookie shouldn't be just the inode, it should be the inode and
> a hash of the arguments or something like that.

Personally I think it's a fine optimization without the arguments.

> But it is what it is,
> and apart from possible show-stopper bugs this is no worse than the
> failed "exclusive write deny" attempt. IOW - maybe worth trying?

The only thing I can think of is allowing threads other than the
first one to complete before the one that actually loaded the
module. I thought about this race for module auto-loading, see
the comment in kmod_dup_request_announce(), so that just
further delays the completion to other thread with a stupid
queue_work(). That seems more important for module auto-loading
duplicates than for boot finit_module() duplicates. But not sure
if odering matters in the end due to a preemtible kernel and maybe
that concern is hysteria.

> And if *that* didn't sell people on this patch series, I don't know
> what will. I should be in marketing! Two drink minimums, here I come!

Sold:

on 255 vcpus 0 duplicates found with this setup:

root@kmod ~ # cat /sys/kernel/debug/modules/stats
Mods ever loaded 66
Mods failed on kread 0
Mods failed on decompress 0
Mods failed on becoming 0
Mods failed on load 0
Total module size 11268096
Total mod text size 4149248
Failed kread bytes 0
Failed decompress bytes 0
Failed becoming bytes 0
Failed kmod bytes 0
Virtual mem wasted bytes 0
Average mod size 170729
Average mod text size 62868

So:

Tested-by: Luis Chamberlain <mcgrof@kernel.org>

In terms of bootup timing:

Before:
Startup finished in 41.653s (kernel) + 44.305s (userspace) = 1min 25.958s
graphical.target reached after 44.178s in userspace.

After:
Startup finished in 23.995s (kernel) + 40.350s (userspace) = 1min 4.345s
graphical.target reached after 40.226s in userspace.

So other than the brain farts above, I think this is pretty sexy.

Luis

On Tue, May 30, 2023 at 09:22:14AM -0700, Luis Chamberlain wrote:
>On Mon, May 29, 2023 at 09:55:15PM -0400, Linus Torvalds wrote:
>> On Mon, May 29, 2023 at 11:18?AM Johan Hovold <johan@kernel.org> wrote:
>> >
>> > I took a closer look at some of the modules that failed to load and
>> > noticed a pattern in that they have dependencies that are needed by more
>> > than one device.
>>
>> Ok, this is a "maybe something like this" RFC series of two patches -
>> one trivial one to re-organize things a bit so that we can then do the
>> real one which uses a filter based on the inode pointer to return an
>> "idempotent return value" for module loads that share the same inode.
>>
>> It's entirely untested, and since I'm on the road I'm going to not
>> really be able to test it. It compiles for me, and the code looks
>> fairly straightforward, but it's probably buggy.
>>
>> It's very loosely based on Luis' attempt, but it
>> (a) is internal to module loading
>> (b) uses a reliable cookie
>> (c) doesn't leave the cookie around randomly for later
>> (d) has seen absolutely no testing
>>
>> Put another way: if somebody wants to play with this, please treat it
>> as a starting point, not the final thing. You might need to debug
>> things, and fix silly mistakes.
>>
>> The idea is to just have a simple hash list of currently executing
>> module loads, protected by a trivial spinlock. Every module loader
>> adds itself to the right hash list, and if they were the *first* one
>> (ie no other pending module loads for that inode), will actually do
>> the module load.
>>
>> Everybody who *isn't* the first one will just wait for completion and
>> return the same error code that the first one returned.
>
>That's also a hell much more snazzier MODULE_DEBUG_AUTOLOAD_DUPS if we
>ever wanted to do something similar there if we wanted to also
>join request_module() calls, instead of it hiding under debug.
>
>> This is technically bogus. The first one might fail due to arguments.
>
>For boot it's fine, as I can't think of boot wanting to support trying
>to load a module with different arguments but who knows. But I can't
>see it sensible to issue concurrent multiple requests for modules
>with different arguments without waiting in userspace for the first
>to fail.
>
>Even post-boot, doing that sounds rather insane, but it would certainly
>be a compromise and should probably be clearly documented. I think just
>a comment acknolwedging that corner case seems sensible.
>
>Because we won't be able to get the arguments until we process the
>module, so it would be too late for this optimization on kread. So it is
>why I had also stuck to the original feature being in kread, as then it
>provides a uniq kread call and the caller is aware of it. But indeed I
>had not considered the effects of arguments.
>
>Lucas, any thoughts from modules kmod userspace perspective into
>supporting anyone likely issuing concurrent modules requests with
>differing arguments?

Changing module params like that without first explicitly removing the
module was never supported by kmod or module-init-tools (I'm not digging
the history before 2.6 kernel)

During boot, note there is already a shortcut
if we have the sysfs node already in the "live" state or if the module is
built-in. In that case we will return success or -EEXIST (if the
KMOD_PROBE_IGNORE_LOADED flag was passed). To be 100% equivalent when
covering the window between the first finit_module() and the sysfs node
being created, then we could add a similar flag to finit_module() and
return -EEXIST. Note however that likbmod will already clear the error
when no flag is passed, which is the normal case during boot.

The only scenario I can think of during boot in which the module params
could change would be when a buggy initrd is created, i.e.
/etc/modprobed.d/*.conf is in the rootfs but absent from initrd.

So returning the same error code seems good to me.

thanks
Lucas De Marchi

>
>> So the cookie shouldn't be just the inode, it should be the inode and
>> a hash of the arguments or something like that.
>
>Personally I think it's a fine optimization without the arguments.
>
>> But it is what it is,
>> and apart from possible show-stopper bugs this is no worse than the
>> failed "exclusive write deny" attempt. IOW - maybe worth trying?
>
>The only thing I can think of is allowing threads other than the
>first one to complete before the one that actually loaded the
>module. I thought about this race for module auto-loading, see
>the comment in kmod_dup_request_announce(), so that just
>further delays the completion to other thread with a stupid
>queue_work(). That seems more important for module auto-loading
>duplicates than for boot finit_module() duplicates. But not sure
>if odering matters in the end due to a preemtible kernel and maybe
>that concern is hysteria.
>
>> And if *that* didn't sell people on this patch series, I don't know
>> what will. I should be in marketing! Two drink minimums, here I come!
>
>Sold:
>
>on 255 vcpus 0 duplicates found with this setup:
>
>root@kmod ~ # cat /sys/kernel/debug/modules/stats
> Mods ever loaded 66
> Mods failed on kread 0
>Mods failed on decompress 0
> Mods failed on becoming 0
> Mods failed on load 0
> Total module size 11268096
> Total mod text size 4149248
> Failed kread bytes 0
> Failed decompress bytes 0
> Failed becoming bytes 0
> Failed kmod bytes 0
> Virtual mem wasted bytes 0
> Average mod size 170729
> Average mod text size 62868
>
>So:
>
>Tested-by: Luis Chamberlain <mcgrof@kernel.org>
>
>In terms of bootup timing:
>
>Before:
>Startup finished in 41.653s (kernel) + 44.305s (userspace) = 1min 25.958s
>graphical.target reached after 44.178s in userspace.
>
>After:
>Startup finished in 23.995s (kernel) + 40.350s (userspace) = 1min 4.345s
>graphical.target reached after 40.226s in userspace.
>
>So other than the brain farts above, I think this is pretty sexy.
>
> Luis

On Tue, May 30, 2023 at 10:16:22AM -0700, Lucas De Marchi wrote:
> On Tue, May 30, 2023 at 09:22:14AM -0700, Luis Chamberlain wrote:
> > Lucas, any thoughts from modules kmod userspace perspective into
> > supporting anyone likely issuing concurrent modules requests with
> > differing arguments?
>
> Changing module params like that without first explicitly removing the
> module was never supported by kmod or module-init-tools (I'm not digging
> the history before 2.6 kernel)

That's good enough.

> During boot, note there is already a shortcut
> if we have the sysfs node already in the "live" state or if the module is
> built-in. In that case we will return success or -EEXIST (if the
> KMOD_PROBE_IGNORE_LOADED flag was passed).

Linus' code would make duplicates wait and share the same return value,
ie, no new odd error code is returned. Or are you suggesting -EEXIST
should be returned to duplicates if the module succeeded to load
instead of 0 ?

> The only scenario I can think of during boot in which the module params
> could change would be when a buggy initrd is created, i.e.
> /etc/modprobed.d/*.conf is in the rootfs but absent from initrd.

This helps thanks.

> So returning the same error code seems good to me.

OK thanks! So just to confirm, it seems fine to return the same error
code if duplicates wait, or do you prefer for some reason for there to
be an exception and return -EEXIST if the module did succeed in the
duplicate case?

Luis

On Tue, May 30, 2023 at 3:41?PM Luis Chamberlain <mcgrof@kernel.org> wrote:
>
> OK thanks! So just to confirm, it seems fine to return the same error
> code if duplicates wait, or do you prefer for some reason for there to
> be an exception and return -EEXIST if the module did succeed in the
> duplicate case?

I think either should be fine, since either was possible before.

By definition, these are module loads being done in parallel, and so
any of them "could" have been the first, and returned success before.

And by extension, any of them could have been not first, and returned
-EEXIST if somebody else loaded the same module first.

So that "somebody else did a load" code:

if (idempotent(&idem, file_inode(f))) {
wait_for_completion(&idem.complete);
return idem.ret;
}

could certainly have made the return value be something like

return idem.ret ? : -EEXIST;

instead of that "return idem.ret".

But it does seem simpler - and more in line with the conceptual
"loading the same module is an idempotent operation" of the patch -
to just always return the success value to all of them.

After all, they all did in some sense succeed to get that module
loaded, even if it was a communal effort, and some threads did more
than others...

As mentioned, I don't think it can matter either way, since any of the
callers might as well have been the successful one, and they would
basically have to act the same way regardless (ie "somebody else
succeeded" and "you succeeded" are basically equivalent return
values). If the module was a prerequisite for another module being
loaded, either -EEXIST or 0 _is_ a success case.

Linus

Linus Torvalds wrote:
> On Mon, May 29, 2023 at 11:18?AM Johan Hovold <johan@kernel.org> wrote:
> >
> > I took a closer look at some of the modules that failed to load and
> > noticed a pattern in that they have dependencies that are needed by more
> > than one device.
>
> Ok, this is a "maybe something like this" RFC series of two patches -
> one trivial one to re-organize things a bit so that we can then do the
> real one which uses a filter based on the inode pointer to return an
> "idempotent return value" for module loads that share the same inode.
>
> It's entirely untested, and since I'm on the road I'm going to not
> really be able to test it. It compiles for me, and the code looks
> fairly straightforward, but it's probably buggy.

At least for me, these 2 patches, plus Johan's spinlock fixup, are:

Tested-by: Dan Williams <dan.j.williams@intel.com>

...on the test that was previously broken on plain v6.4-rc4. I have
these cherry picked on top of v6.4-rc4:

Revert "module: error out early on concurrent load of the same module file"
module: split up 'finit_module()' into init_module_from_file() helper
modules: catch concurrent module loads, take two

On Tue, May 30, 2023 at 09:22:14AM -0700, Luis Chamberlain wrote:
> The only thing I can think of is allowing threads other than the
> first one to complete before the one that actually loaded the
> module. I thought about this race for module auto-loading, see
> the comment in kmod_dup_request_announce(), so that just
> further delays the completion to other thread with a stupid
> queue_work(). That seems more important for module auto-loading
> duplicates than for boot finit_module() duplicates. But not sure
> if odering matters in the end due to a preemtible kernel and maybe
> that concern is hysteria.

I think I'm OK to accept this ordering concern as hysteria for now.

Luis

On Tue, May 30, 2023 at 06:17:11PM -0400, Linus Torvalds wrote:
>On Tue, May 30, 2023 at 3:41?PM Luis Chamberlain <mcgrof@kernel.org> wrote:
>>
>> OK thanks! So just to confirm, it seems fine to return the same error
>> code if duplicates wait, or do you prefer for some reason for there to
>> be an exception and return -EEXIST if the module did succeed in the
>> duplicate case?
>
>I think either should be fine, since either was possible before.
>
>By definition, these are module loads being done in parallel, and so
>any of them "could" have been the first, and returned success before.
>
>And by extension, any of them could have been not first, and returned
>-EEXIST if somebody else loaded the same module first.
>
>So that "somebody else did a load" code:
>
> if (idempotent(&idem, file_inode(f))) {
> wait_for_completion(&idem.complete);
> return idem.ret;
> }
>
>could certainly have made the return value be something like
>
> return idem.ret ? : -EEXIST;

yes, this is what I had in mind.

>
>instead of that "return idem.ret".
>
>But it does seem simpler - and more in line with the conceptual
>"loading the same module is an idempotent operation" of the patch -
>to just always return the success value to all of them.
>
>After all, they all did in some sense succeed to get that module
>loaded, even if it was a communal effort, and some threads did more
>than others...
>
>As mentioned, I don't think it can matter either way, since any of the
>callers might as well have been the successful one, and they would
>basically have to act the same way regardless (ie "somebody else
>succeeded" and "you succeeded" are basically equivalent return

agreed, it will just be a slightly different behavior if finit_module()
is called twice and the first call is already in the process of
initializing the module, i.e. complete_formation() was already called,
putting the module in the MODULE_STATE_COMING state, as per
kernel/module/main.c:add_unformed_module():

/*
* We are here only when the same module was being loaded. Do
* not try to load it again right now. It prevents long delays
* caused by serialized module load failures. It might happen
* when more devices of the same type trigger load of
* a particular module.
*/
if (old && old->state == MODULE_STATE_LIVE)
err = -EEXIST;
else
err = -EBUSY;
goto out;

in userspace we already deal with that in a special way and should be
compatible with returning 0 for all practical purposes.

thanks
Lucas De Marchi

>values). If the module was a prerequisite for another module being
>loaded, either -EEXIST or 0 _is_ a success case.
>
> Linus

On 30.05.23 18:22, Luis Chamberlain wrote:
> On Mon, May 29, 2023 at 09:55:15PM -0400, Linus Torvalds wrote:
>> On Mon, May 29, 2023 at 11:18?AM Johan Hovold <johan@kernel.org> wrote:
>>>
>>> I took a closer look at some of the modules that failed to load and
>>> noticed a pattern in that they have dependencies that are needed by more
>>> than one device.
>>
>> Ok, this is a "maybe something like this" RFC series of two patches -
>> one trivial one to re-organize things a bit so that we can then do the
>> real one which uses a filter based on the inode pointer to return an
>> "idempotent return value" for module loads that share the same inode.
>>
>> It's entirely untested, and since I'm on the road I'm going to not
>> really be able to test it. It compiles for me, and the code looks
>> fairly straightforward, but it's probably buggy.
>>
>> It's very loosely based on Luis' attempt, but it
>> (a) is internal to module loading
>> (b) uses a reliable cookie
>> (c) doesn't leave the cookie around randomly for later
>> (d) has seen absolutely no testing
>>
>> Put another way: if somebody wants to play with this, please treat it
>> as a starting point, not the final thing. You might need to debug
>> things, and fix silly mistakes.
>>
>> The idea is to just have a simple hash list of currently executing
>> module loads, protected by a trivial spinlock. Every module loader
>> adds itself to the right hash list, and if they were the *first* one
>> (ie no other pending module loads for that inode), will actually do
>> the module load.
>>
>> Everybody who *isn't* the first one will just wait for completion and
>> return the same error code that the first one returned.
>
> That's also a hell much more snazzier MODULE_DEBUG_AUTOLOAD_DUPS if we
> ever wanted to do something similar there if we wanted to also
> join request_module() calls, instead of it hiding under debug.
>
>> This is technically bogus. The first one might fail due to arguments.
>
> For boot it's fine, as I can't think of boot wanting to support trying
> to load a module with different arguments but who knows. But I can't
> see it sensible to issue concurrent multiple requests for modules
> with different arguments without waiting in userspace for the first
> to fail.
>
> Even post-boot, doing that sounds rather insane, but it would certainly
> be a compromise and should probably be clearly documented. I think just
> a comment acknolwedging that corner case seems sensible.
>
> Because we won't be able to get the arguments until we process the
> module, so it would be too late for this optimization on kread. So it is
> why I had also stuck to the original feature being in kread, as then it
> provides a uniq kread call and the caller is aware of it. But indeed I
> had not considered the effects of arguments.
>
> Lucas, any thoughts from modules kmod userspace perspective into
> supporting anyone likely issuing concurrent modules requests with
> differing arguments?
>
>> So the cookie shouldn't be just the inode, it should be the inode and
>> a hash of the arguments or something like that.
>
> Personally I think it's a fine optimization without the arguments.
>
>> But it is what it is,
>> and apart from possible show-stopper bugs this is no worse than the
>> failed "exclusive write deny" attempt. IOW - maybe worth trying?
>
> The only thing I can think of is allowing threads other than the
> first one to complete before the one that actually loaded the
> module. I thought about this race for module auto-loading, see
> the comment in kmod_dup_request_announce(), so that just
> further delays the completion to other thread with a stupid
> queue_work(). That seems more important for module auto-loading
> duplicates than for boot finit_module() duplicates. But not sure
> if odering matters in the end due to a preemtible kernel and maybe
> that concern is hysteria.
>
>> And if *that* didn't sell people on this patch series, I don't know
>> what will. I should be in marketing! Two drink minimums, here I come!
>
> Sold:
>
> on 255 vcpus 0 duplicates found with this setup:
>
> root@kmod ~ # cat /sys/kernel/debug/modules/stats
> Mods ever loaded 66
> Mods failed on kread 0
> Mods failed on decompress 0
> Mods failed on becoming 0
> Mods failed on load 0
> Total module size 11268096
> Total mod text size 4149248
> Failed kread bytes 0
> Failed decompress bytes 0
> Failed becoming bytes 0
> Failed kmod bytes 0
> Virtual mem wasted bytes 0
> Average mod size 170729
> Average mod text size 62868
>
> So:
>
> Tested-by: Luis Chamberlain <mcgrof@kernel.org>
>
> In terms of bootup timing:
>
> Before:
> Startup finished in 41.653s (kernel) + 44.305s (userspace) = 1min 25.958s
> graphical.target reached after 44.178s in userspace.
>
> After:
> Startup finished in 23.995s (kernel) + 40.350s (userspace) = 1min 4.345s
> graphical.target reached after 40.226s in userspace.

I'll try grabbing the system where we saw the KASAN-related issues [1]
and give it a churn with and without the two patches. Might take a bit
(~1 day), unfortunately.

[1] https://lkml.kernel.org/r/20221013180518.217405-1-david@redhat.com

--
Thanks,

David / dhildenb

On Wed, May 31, 2023 at 09:51:41AM +0200, David Hildenbrand wrote:
> On 30.05.23 18:22, Luis Chamberlain wrote:
> > On Mon, May 29, 2023 at 09:55:15PM -0400, Linus Torvalds wrote:
> > > On Mon, May 29, 2023 at 11:18?AM Johan Hovold <johan@kernel.org> wrote:
> > > >
> > > > I took a closer look at some of the modules that failed to load and
> > > > noticed a pattern in that they have dependencies that are needed by more
> > > > than one device.
> > >
> > > Ok, this is a "maybe something like this" RFC series of two patches -
> > > one trivial one to re-organize things a bit so that we can then do the
> > > real one which uses a filter based on the inode pointer to return an
> > > "idempotent return value" for module loads that share the same inode.
> > >
> > > It's entirely untested, and since I'm on the road I'm going to not
> > > really be able to test it. It compiles for me, and the code looks
> > > fairly straightforward, but it's probably buggy.
> > >
> > > It's very loosely based on Luis' attempt, but it
> > > (a) is internal to module loading
> > > (b) uses a reliable cookie
> > > (c) doesn't leave the cookie around randomly for later
> > > (d) has seen absolutely no testing
> > >
> > > Put another way: if somebody wants to play with this, please treat it
> > > as a starting point, not the final thing. You might need to debug
> > > things, and fix silly mistakes.
> > >
> > > The idea is to just have a simple hash list of currently executing
> > > module loads, protected by a trivial spinlock. Every module loader
> > > adds itself to the right hash list, and if they were the *first* one
> > > (ie no other pending module loads for that inode), will actually do
> > > the module load.
> > >
> > > Everybody who *isn't* the first one will just wait for completion and
> > > return the same error code that the first one returned.
> >
> > That's also a hell much more snazzier MODULE_DEBUG_AUTOLOAD_DUPS if we
> > ever wanted to do something similar there if we wanted to also
> > join request_module() calls, instead of it hiding under debug.
> >
> > > This is technically bogus. The first one might fail due to arguments.
> >
> > For boot it's fine, as I can't think of boot wanting to support trying
> > to load a module with different arguments but who knows. But I can't
> > see it sensible to issue concurrent multiple requests for modules
> > with different arguments without waiting in userspace for the first
> > to fail.
> >
> > Even post-boot, doing that sounds rather insane, but it would certainly
> > be a compromise and should probably be clearly documented. I think just
> > a comment acknolwedging that corner case seems sensible.
> >
> > Because we won't be able to get the arguments until we process the
> > module, so it would be too late for this optimization on kread. So it is
> > why I had also stuck to the original feature being in kread, as then it
> > provides a uniq kread call and the caller is aware of it. But indeed I
> > had not considered the effects of arguments.
> >
> > Lucas, any thoughts from modules kmod userspace perspective into
> > supporting anyone likely issuing concurrent modules requests with
> > differing arguments?
> >
> > > So the cookie shouldn't be just the inode, it should be the inode and
> > > a hash of the arguments or something like that.
> >
> > Personally I think it's a fine optimization without the arguments.
> >
> > > But it is what it is,
> > > and apart from possible show-stopper bugs this is no worse than the
> > > failed "exclusive write deny" attempt. IOW - maybe worth trying?
> >
> > The only thing I can think of is allowing threads other than the
> > first one to complete before the one that actually loaded the
> > module. I thought about this race for module auto-loading, see
> > the comment in kmod_dup_request_announce(), so that just
> > further delays the completion to other thread with a stupid
> > queue_work(). That seems more important for module auto-loading
> > duplicates than for boot finit_module() duplicates. But not sure
> > if odering matters in the end due to a preemtible kernel and maybe
> > that concern is hysteria.
> >
> > > And if *that* didn't sell people on this patch series, I don't know
> > > what will. I should be in marketing! Two drink minimums, here I come!
> >
> > Sold:
> >
> > on 255 vcpus 0 duplicates found with this setup:
> >
> > root@kmod ~ # cat /sys/kernel/debug/modules/stats
> > Mods ever loaded 66
> > Mods failed on kread 0
> > Mods failed on decompress 0
> > Mods failed on becoming 0
> > Mods failed on load 0
> > Total module size 11268096
> > Total mod text size 4149248
> > Failed kread bytes 0
> > Failed decompress bytes 0
> > Failed becoming bytes 0
> > Failed kmod bytes 0
> > Virtual mem wasted bytes 0
> > Average mod size 170729
> > Average mod text size 62868
> >
> > So:
> >
> > Tested-by: Luis Chamberlain <mcgrof@kernel.org>
> >
> > In terms of bootup timing:
> >
> > Before:
> > Startup finished in 41.653s (kernel) + 44.305s (userspace) = 1min 25.958s
> > graphical.target reached after 44.178s in userspace.
> > After:
> > Startup finished in 23.995s (kernel) + 40.350s (userspace) = 1min 4.345s
> > graphical.target reached after 40.226s in userspace.
>
> I'll try grabbing the system where we saw the KASAN-related issues [1] and
> give it a churn with and without the two patches. Might take a bit (~1 day),
> unfortunately.
>
> [1] https://lkml.kernel.org/r/20221013180518.217405-1-david@redhat.com

Great, don't forget:

diff --git a/kernel/module/main.c b/kernel/module/main.c
index 82b0dcc1fe77..222015093eeb 100644
--- a/kernel/module/main.c
+++ b/kernel/module/main.c
@@ -3066,7 +3066,7 @@ struct idempotent {

#define IDEM_HASH_BITS 8
static struct hlist_head idem_hash[1 << IDEM_HASH_BITS];
-static struct spinlock idem_lock;
+static DEFINE_SPINLOCK(idem_lock);

static bool idempotent(struct idempotent *u, const void *cookie)
{

On 31.05.23 18:57, Luis Chamberlain wrote:
> On Wed, May 31, 2023 at 09:51:41AM +0200, David Hildenbrand wrote:
>> On 30.05.23 18:22, Luis Chamberlain wrote:
>>> On Mon, May 29, 2023 at 09:55:15PM -0400, Linus Torvalds wrote:
>>>> On Mon, May 29, 2023 at 11:18?AM Johan Hovold <johan@kernel.org> wrote:
>>>>>
>>>>> I took a closer look at some of the modules that failed to load and
>>>>> noticed a pattern in that they have dependencies that are needed by more
>>>>> than one device.
>>>>
>>>> Ok, this is a "maybe something like this" RFC series of two patches -
>>>> one trivial one to re-organize things a bit so that we can then do the
>>>> real one which uses a filter based on the inode pointer to return an
>>>> "idempotent return value" for module loads that share the same inode.
>>>>
>>>> It's entirely untested, and since I'm on the road I'm going to not
>>>> really be able to test it. It compiles for me, and the code looks
>>>> fairly straightforward, but it's probably buggy.
>>>>
>>>> It's very loosely based on Luis' attempt, but it
>>>> (a) is internal to module loading
>>>> (b) uses a reliable cookie
>>>> (c) doesn't leave the cookie around randomly for later
>>>> (d) has seen absolutely no testing
>>>>
>>>> Put another way: if somebody wants to play with this, please treat it
>>>> as a starting point, not the final thing. You might need to debug
>>>> things, and fix silly mistakes.
>>>>
>>>> The idea is to just have a simple hash list of currently executing
>>>> module loads, protected by a trivial spinlock. Every module loader
>>>> adds itself to the right hash list, and if they were the *first* one
>>>> (ie no other pending module loads for that inode), will actually do
>>>> the module load.
>>>>
>>>> Everybody who *isn't* the first one will just wait for completion and
>>>> return the same error code that the first one returned.
>>>
>>> That's also a hell much more snazzier MODULE_DEBUG_AUTOLOAD_DUPS if we
>>> ever wanted to do something similar there if we wanted to also
>>> join request_module() calls, instead of it hiding under debug.
>>>
>>>> This is technically bogus. The first one might fail due to arguments.
>>>
>>> For boot it's fine, as I can't think of boot wanting to support trying
>>> to load a module with different arguments but who knows. But I can't
>>> see it sensible to issue concurrent multiple requests for modules
>>> with different arguments without waiting in userspace for the first
>>> to fail.
>>>
>>> Even post-boot, doing that sounds rather insane, but it would certainly
>>> be a compromise and should probably be clearly documented. I think just
>>> a comment acknolwedging that corner case seems sensible.
>>>
>>> Because we won't be able to get the arguments until we process the
>>> module, so it would be too late for this optimization on kread. So it is
>>> why I had also stuck to the original feature being in kread, as then it
>>> provides a uniq kread call and the caller is aware of it. But indeed I
>>> had not considered the effects of arguments.
>>>
>>> Lucas, any thoughts from modules kmod userspace perspective into
>>> supporting anyone likely issuing concurrent modules requests with
>>> differing arguments?
>>>
>>>> So the cookie shouldn't be just the inode, it should be the inode and
>>>> a hash of the arguments or something like that.
>>>
>>> Personally I think it's a fine optimization without the arguments.
>>>
>>>> But it is what it is,
>>>> and apart from possible show-stopper bugs this is no worse than the
>>>> failed "exclusive write deny" attempt. IOW - maybe worth trying?
>>>
>>> The only thing I can think of is allowing threads other than the
>>> first one to complete before the one that actually loaded the
>>> module. I thought about this race for module auto-loading, see
>>> the comment in kmod_dup_request_announce(), so that just
>>> further delays the completion to other thread with a stupid
>>> queue_work(). That seems more important for module auto-loading
>>> duplicates than for boot finit_module() duplicates. But not sure
>>> if odering matters in the end due to a preemtible kernel and maybe
>>> that concern is hysteria.
>>>
>>>> And if *that* didn't sell people on this patch series, I don't know
>>>> what will. I should be in marketing! Two drink minimums, here I come!
>>>
>>> Sold:
>>>
>>> on 255 vcpus 0 duplicates found with this setup:
>>>
>>> root@kmod ~ # cat /sys/kernel/debug/modules/stats
>>> Mods ever loaded 66
>>> Mods failed on kread 0
>>> Mods failed on decompress 0
>>> Mods failed on becoming 0
>>> Mods failed on load 0
>>> Total module size 11268096
>>> Total mod text size 4149248
>>> Failed kread bytes 0
>>> Failed decompress bytes 0
>>> Failed becoming bytes 0
>>> Failed kmod bytes 0
>>> Virtual mem wasted bytes 0
>>> Average mod size 170729
>>> Average mod text size 62868
>>>
>>> So:
>>>
>>> Tested-by: Luis Chamberlain <mcgrof@kernel.org>
>>>
>>> In terms of bootup timing:
>>>
>>> Before:
>>> Startup finished in 41.653s (kernel) + 44.305s (userspace) = 1min 25.958s
>>> graphical.target reached after 44.178s in userspace.
>>> After:
>>> Startup finished in 23.995s (kernel) + 40.350s (userspace) = 1min 4.345s
>>> graphical.target reached after 40.226s in userspace.
>>
>> I'll try grabbing the system where we saw the KASAN-related issues [1] and
>> give it a churn with and without the two patches. Might take a bit (~1 day),
>> unfortunately.
>>
>> [1] https://lkml.kernel.org/r/20221013180518.217405-1-david@redhat.com
>
> Great, don't forget:
>
> diff --git a/kernel/module/main.c b/kernel/module/main.c
> index 82b0dcc1fe77..222015093eeb 100644
> --- a/kernel/module/main.c
> +++ b/kernel/module/main.c
> @@ -3066,7 +3066,7 @@ struct idempotent {
>
> #define IDEM_HASH_BITS 8
> static struct hlist_head idem_hash[1 << IDEM_HASH_BITS];
> -static struct spinlock idem_lock;
> +static DEFINE_SPINLOCK(idem_lock);
>
> static bool idempotent(struct idempotent *u, const void *cookie)
> {
>

Finally was able to run it on that ThinkSystem SR950 with 8 populated
sockets -> 224 cores and 448 logical CPUs.

The KASAN vmap issues on that system were already no longer reproducible with your
(Luis) previous work that's already in master.

I tested a !debug and debug config (both based on corresponding RHEL9 configs), comparing
929ed21dfdb6 ("master") with 929ed21dfdb6 + Linus' patches ("patched").


Unfortunately, boot times vary a lot, and I did not figure out how to reduce
the noise. I captured the "systemd-analyze blame" output as well.


1) !debug config (not enabling KASAN)

a) master

Startup finished in 32.225s (kernel) + 7.399s (initrd) + 20.378s (userspace) = 1min 3ms
multi-user.target reached after 20.352s in userspace.
Startup finished in 43.734s (kernel) + 7.288s (initrd) + 19.827s (userspace) = 1min 10.851s
multi-user.target reached after 19.800s in userspace.
Startup finished in 50.514s (kernel) + 7.171s (initrd) + 24.757s (userspace) = 1min 22.443s
multi-user.target reached after 24.734s in userspace.
Startup finished in 26.722s (kernel) + 7.249s (initrd) + 23.923s (userspace) = 57.895s
multi-user.target reached after 23.892s in userspace.

b) patched

Startup finished in 36.318s (kernel) + 7.177s (initrd) + 21.383s (userspace) = 1min 4.879s
multi-user.target reached after 21.355s in userspace.
Startup finished in 36.318s (kernel) + 7.177s (initrd) + 21.383s (userspace) = 1min 4.879s
multi-user.target reached after 21.355s in userspace.
Startup finished in 1min 34.678s (kernel) + 7.239s (initrd) + 24.066s (userspace) = 2min 5.985s
multi-user.target reached after 24.040s in userspace.
Startup finished in 25.879s (kernel) + 7.144s (initrd) + 29.665s (userspace) = 1min 2.689s
multi-user.target reached after 29.637s in userspace.



2) debug config (enabling KASAN)

a) master

Startup finished in 2min 12.695s (kernel) + 25.058s (initrd) + 1min 13.012s (userspace) = 3min 50.765s
multi-user.target reached after 1min 12.903s in userspace.
Startup finished in 1min 45.400s (kernel) + 24.294s (initrd) + 1min 8.910s (userspace) = 3min 18.606s
multi-user.target reached after 1min 8.786s in userspace.
Startup finished in 2min 4.857s (kernel) + 24.715s (initrd) + 1min 5.088s (userspace) = 3min 34.660s
multi-user.target reached after 1min 4.967s in userspace.
Startup finished in 3min 20.400s (kernel) + 24.703s (initrd) + 1min 5.469s (userspace) = 4min 50.573s
multi-user.target reached after 1min 5.344s in userspace.

b) patched

Startup finished in 2min 5.250s (kernel) + 25.049s (initrd) + 1min 1.961s (userspace) = 3min 32.262s
multi-user.target reached after 1min 1.844s in userspace.
Startup finished in 1min 52.524s (kernel) + 24.897s (initrd) + 1min 5.062s (userspace) = 3min 22.484s
multi-user.target reached after 1min 4.916s in userspace.
Startup finished in 9min 36.817s (kernel) + 24.859s (initrd) + 1min 18.657s (userspace) = 11min 20.335s
multi-user.target reached after 1min 18.455s in userspace.
Startup finished in 30min 20.715s (kernel) + 24.722s (initrd) + 1min 7.039s (userspace) = 31min 52.476s
multi-user.target reached after 1min 6.907s in userspace.


What concerns me a bit, is that on the patched kernel we seem to hit more cases where
boot takes much longer (in both kernel configs).

I'll do some more runs/investigation to see if this is reproducible or just some system oddity.

Staring just at the udev settle time (systemd-analyze blame), it's very similar between both kernel
versions.

--
Cheers,

David / dhildenb

On Fri, Jun 02, 2023 at 05:19:58PM +0200, David Hildenbrand wrote:
> On 31.05.23 18:57, Luis Chamberlain wrote:
> > On Wed, May 31, 2023 at 09:51:41AM +0200, David Hildenbrand wrote:
> > > On 30.05.23 18:22, Luis Chamberlain wrote:
> > > > On Mon, May 29, 2023 at 09:55:15PM -0400, Linus Torvalds wrote:
> > > > > On Mon, May 29, 2023 at 11:18?AM Johan Hovold <johan@kernel.org> wrote:
> > > > > >
> > > > > > I took a closer look at some of the modules that failed to load and
> > > > > > noticed a pattern in that they have dependencies that are needed by more
> > > > > > than one device.
> > > > >
> > > > > Ok, this is a "maybe something like this" RFC series of two patches -
> > > > > one trivial one to re-organize things a bit so that we can then do the
> > > > > real one which uses a filter based on the inode pointer to return an
> > > > > "idempotent return value" for module loads that share the same inode.
> > > > >
> > > > > It's entirely untested, and since I'm on the road I'm going to not
> > > > > really be able to test it. It compiles for me, and the code looks
> > > > > fairly straightforward, but it's probably buggy.
> > > > >
> > > > > It's very loosely based on Luis' attempt, but it
> > > > > (a) is internal to module loading
> > > > > (b) uses a reliable cookie
> > > > > (c) doesn't leave the cookie around randomly for later
> > > > > (d) has seen absolutely no testing
> > > > >
> > > > > Put another way: if somebody wants to play with this, please treat it
> > > > > as a starting point, not the final thing. You might need to debug
> > > > > things, and fix silly mistakes.
> > > > >
> > > > > The idea is to just have a simple hash list of currently executing
> > > > > module loads, protected by a trivial spinlock. Every module loader
> > > > > adds itself to the right hash list, and if they were the *first* one
> > > > > (ie no other pending module loads for that inode), will actually do
> > > > > the module load.
> > > > >
> > > > > Everybody who *isn't* the first one will just wait for completion and
> > > > > return the same error code that the first one returned.
> > > >
> > > > That's also a hell much more snazzier MODULE_DEBUG_AUTOLOAD_DUPS if we
> > > > ever wanted to do something similar there if we wanted to also
> > > > join request_module() calls, instead of it hiding under debug.
> > > >
> > > > > This is technically bogus. The first one might fail due to arguments.
> > > >
> > > > For boot it's fine, as I can't think of boot wanting to support trying
> > > > to load a module with different arguments but who knows. But I can't
> > > > see it sensible to issue concurrent multiple requests for modules
> > > > with different arguments without waiting in userspace for the first
> > > > to fail.
> > > >
> > > > Even post-boot, doing that sounds rather insane, but it would certainly
> > > > be a compromise and should probably be clearly documented. I think just
> > > > a comment acknolwedging that corner case seems sensible.
> > > >
> > > > Because we won't be able to get the arguments until we process the
> > > > module, so it would be too late for this optimization on kread. So it is
> > > > why I had also stuck to the original feature being in kread, as then it
> > > > provides a uniq kread call and the caller is aware of it. But indeed I
> > > > had not considered the effects of arguments.
> > > >
> > > > Lucas, any thoughts from modules kmod userspace perspective into
> > > > supporting anyone likely issuing concurrent modules requests with
> > > > differing arguments?
> > > >
> > > > > So the cookie shouldn't be just the inode, it should be the inode and
> > > > > a hash of the arguments or something like that.
> > > >
> > > > Personally I think it's a fine optimization without the arguments.
> > > >
> > > > > But it is what it is,
> > > > > and apart from possible show-stopper bugs this is no worse than the
> > > > > failed "exclusive write deny" attempt. IOW - maybe worth trying?
> > > >
> > > > The only thing I can think of is allowing threads other than the
> > > > first one to complete before the one that actually loaded the
> > > > module. I thought about this race for module auto-loading, see
> > > > the comment in kmod_dup_request_announce(), so that just
> > > > further delays the completion to other thread with a stupid
> > > > queue_work(). That seems more important for module auto-loading
> > > > duplicates than for boot finit_module() duplicates. But not sure
> > > > if odering matters in the end due to a preemtible kernel and maybe
> > > > that concern is hysteria.
> > > >
> > > > > And if *that* didn't sell people on this patch series, I don't know
> > > > > what will. I should be in marketing! Two drink minimums, here I come!
> > > >
> > > > Sold:
> > > >
> > > > on 255 vcpus 0 duplicates found with this setup:
> > > >
> > > > root@kmod ~ # cat /sys/kernel/debug/modules/stats
> > > > Mods ever loaded 66
> > > > Mods failed on kread 0
> > > > Mods failed on decompress 0
> > > > Mods failed on becoming 0
> > > > Mods failed on load 0
> > > > Total module size 11268096
> > > > Total mod text size 4149248
> > > > Failed kread bytes 0
> > > > Failed decompress bytes 0
> > > > Failed becoming bytes 0
> > > > Failed kmod bytes 0
> > > > Virtual mem wasted bytes 0
> > > > Average mod size 170729
> > > > Average mod text size 62868
> > > >
> > > > So:
> > > >
> > > > Tested-by: Luis Chamberlain <mcgrof@kernel.org>
> > > >
> > > > In terms of bootup timing:
> > > >
> > > > Before:
> > > > Startup finished in 41.653s (kernel) + 44.305s (userspace) = 1min 25.958s
> > > > graphical.target reached after 44.178s in userspace.
> > > > After:
> > > > Startup finished in 23.995s (kernel) + 40.350s (userspace) = 1min 4.345s
> > > > graphical.target reached after 40.226s in userspace.
> > >
> > > I'll try grabbing the system where we saw the KASAN-related issues [1] and
> > > give it a churn with and without the two patches. Might take a bit (~1 day),
> > > unfortunately.
> > >
> > > [1] https://lkml.kernel.org/r/20221013180518.217405-1-david@redhat.com
> >
> > Great, don't forget:
> >
> > diff --git a/kernel/module/main.c b/kernel/module/main.c
> > index 82b0dcc1fe77..222015093eeb 100644
> > --- a/kernel/module/main.c
> > +++ b/kernel/module/main.c
> > @@ -3066,7 +3066,7 @@ struct idempotent {
> > #define IDEM_HASH_BITS 8
> > static struct hlist_head idem_hash[1 << IDEM_HASH_BITS];
> > -static struct spinlock idem_lock;
> > +static DEFINE_SPINLOCK(idem_lock);
> > static bool idempotent(struct idempotent *u, const void *cookie)
> > {
> >
>
> Finally was able to run it on that ThinkSystem SR950 with 8 populated
> sockets -> 224 cores and 448 logical CPUs.
>
> The KASAN vmap issues on that system were already no longer reproducible with your
> (Luis) previous work that's already in master.
>
> I tested a !debug and debug config (both based on corresponding RHEL9 configs), comparing
> 929ed21dfdb6 ("master") with 929ed21dfdb6 + Linus' patches ("patched").
>
>
> Unfortunately, boot times vary a lot, and I did not figure out how to reduce
> the noise. I captured the "systemd-analyze blame" output as well.
>
>
> 1) !debug config (not enabling KASAN)
>
> a) master
>
> Startup finished in 32.225s (kernel) + 7.399s (initrd) + 20.378s (userspace) = 1min 3ms
> multi-user.target reached after 20.352s in userspace.
> Startup finished in 43.734s (kernel) + 7.288s (initrd) + 19.827s (userspace) = 1min 10.851s
> multi-user.target reached after 19.800s in userspace.
> Startup finished in 50.514s (kernel) + 7.171s (initrd) + 24.757s (userspace) = 1min 22.443s
> multi-user.target reached after 24.734s in userspace.
> Startup finished in 26.722s (kernel) + 7.249s (initrd) + 23.923s (userspace) = 57.895s
> multi-user.target reached after 23.892s in userspace.
>
> b) patched
>
> Startup finished in 36.318s (kernel) + 7.177s (initrd) + 21.383s (userspace) = 1min 4.879s
> multi-user.target reached after 21.355s in userspace.
> Startup finished in 36.318s (kernel) + 7.177s (initrd) + 21.383s (userspace) = 1min 4.879s
> multi-user.target reached after 21.355s in userspace.
> Startup finished in 1min 34.678s (kernel) + 7.239s (initrd) + 24.066s (userspace) = 2min 5.985s
> multi-user.target reached after 24.040s in userspace.
> Startup finished in 25.879s (kernel) + 7.144s (initrd) + 29.665s (userspace) = 1min 2.689s
> multi-user.target reached after 29.637s in userspace.
>
>
>
> 2) debug config (enabling KASAN)
>
> a) master
>
> Startup finished in 2min 12.695s (kernel) + 25.058s (initrd) + 1min 13.012s (userspace) = 3min 50.765s
> multi-user.target reached after 1min 12.903s in userspace.
> Startup finished in 1min 45.400s (kernel) + 24.294s (initrd) + 1min 8.910s (userspace) = 3min 18.606s
> multi-user.target reached after 1min 8.786s in userspace.
> Startup finished in 2min 4.857s (kernel) + 24.715s (initrd) + 1min 5.088s (userspace) = 3min 34.660s
> multi-user.target reached after 1min 4.967s in userspace.
> Startup finished in 3min 20.400s (kernel) + 24.703s (initrd) + 1min 5.469s (userspace) = 4min 50.573s
> multi-user.target reached after 1min 5.344s in userspace.
>
> b) patched
>
> Startup finished in 2min 5.250s (kernel) + 25.049s (initrd) + 1min 1.961s (userspace) = 3min 32.262s
> multi-user.target reached after 1min 1.844s in userspace.
> Startup finished in 1min 52.524s (kernel) + 24.897s (initrd) + 1min 5.062s (userspace) = 3min 22.484s
> multi-user.target reached after 1min 4.916s in userspace.
> Startup finished in 9min 36.817s (kernel) + 24.859s (initrd) + 1min 18.657s (userspace) = 11min 20.335s
> multi-user.target reached after 1min 18.455s in userspace.
> Startup finished in 30min 20.715s (kernel) + 24.722s (initrd) + 1min 7.039s (userspace) = 31min 52.476s
> multi-user.target reached after 1min 6.907s in userspace.
>
>
> What concerns me a bit, is that on the patched kernel we seem to hit more cases where
> boot takes much longer (in both kernel configs).
>
> I'll do some more runs/investigation to see if this is reproducible or just some system oddity.
>
> Staring just at the udev settle time (systemd-analyze blame), it's very similar between both kernel
> versions.

Thanks for these tests, having MODULE_STATS enabled +

cat /sys/kernel/debug/modules/stats

would be of huge value, both on master and + patched.

Luis

On Fri, Jun 2, 2023 at 11:20?AM David Hildenbrand <david@redhat.com> wrote:
>
> What concerns me a bit, is that on the patched kernel we seem to hit more cases where
> boot takes much longer (in both kernel configs).

So it potentially serializes the loads to the same file more, but in
the process uses much less memory (since the ones waiting will not
have done any of the "load file contents and uncompress them"). So
it's a bit of a trade-off.

We could complicate things a bit, and let other callers return -EEXIST
a bit earlier, but I'm not convinced it really matters.

Honestly, taking too long because user space does something stupid and
wrong is not a kernel bug. Not booting because we use too much memory
- that's problematic. But booting slowly because udev does several
thousand unnecessary module loads is entirely on udev.

Linus

On 02.06.23 18:06, Linus Torvalds wrote:
> On Fri, Jun 2, 2023 at 11:20?AM David Hildenbrand <david@redhat.com> wrote:
>>
>> What concerns me a bit, is that on the patched kernel we seem to hit more cases where
>> boot takes much longer (in both kernel configs).
>
> So it potentially serializes the loads to the same file more, but in
> the process uses much less memory (since the ones waiting will not
> have done any of the "load file contents and uncompress them"). So
> it's a bit of a trade-off.

I have the feeling that -- on this system -- it's some inaccurate
accounting of firmware+loader times to the kernel startup time. Combined
with some other noise. Especially the firmware loading time seems to be
fairly randomized.

I guess what we care about regarding module loading is the
initrd+userspace loading times, and they are fairly stable. But we
mostly care about udev.

So let's look only at "systemd-udev" services:

1) !debug

a) master

5.672s systemd-udev-settle.service
505ms systemd-udev-trigger.service
272ms systemd-udevd.service
5.418s systemd-udev-settle.service
487ms systemd-udev-trigger.service
258ms systemd-udevd.service
5.707s systemd-udev-settle.service
527ms systemd-udev-trigger.service
273ms systemd-udevd.service
6.250s systemd-udev-settle.service
455ms systemd-udev-trigger.service
283ms systemd-udevd.service


b) patched

4.652s systemd-udev-settle.service
461ms systemd-udev-trigger.service
302ms systemd-udevd.service
4.652s systemd-udev-settle.service
461ms systemd-udev-trigger.service
302ms systemd-udevd.service
4.634s systemd-udev-settle.service
444ms systemd-udev-trigger.service
296ms systemd-udevd.service
4.745s systemd-udev-settle.service
444ms systemd-udev-trigger.service
273ms systemd-udevd.service


2) debug

a) master

32.806s systemd-udev-settle.service
9.584s systemd-udev-trigger.service
471ms systemd-udevd.service
29.901s systemd-udev-settle.service
8.914s systemd-udev-trigger.service
400ms systemd-udevd.service
28.640s systemd-udev-settle.service
9.260s systemd-udev-trigger.service
477ms systemd-udevd.service
29.498s systemd-udev-settle.service
9.073s systemd-udev-trigger.service
444ms systemd-udevd.service


b) patched

28.765s systemd-udev-settle.service
8.898s systemd-udev-trigger.service
400ms systemd-udevd.service
28.292s systemd-udev-settle.service
8.903s systemd-udev-trigger.service
401ms systemd-udevd.service
34.588s systemd-udev-settle.service
8.959s systemd-udev-trigger.service
455ms systemd-udevd.service
28.641s systemd-udev-settle.service
8.953s systemd-udev-trigger.service
389ms systemd-udevd.service



So except some noise, in the general case the patched version seems to
be faster just looking at systemd-udev.

>
> We could complicate things a bit, and let other callers return -EEXIST
> a bit earlier, but I'm not convinced it really matters.

Looking at the numbers, agreed.

>
> Honestly, taking too long because user space does something stupid and
> wrong is not a kernel bug. Not booting because we use too much memory
> - that's problematic. But booting slowly because udev does several
> thousand unnecessary module loads is entirely on udev.

Yes.


I'll do some more experiments, but from what I can tell

Tested-by: David Hildenbrand <david@redhat.com>

--
Cheers,

David / dhildenb

On Mon, May 29, 2023 at 09:55:15PM -0400, Linus Torvalds wrote:
> On Mon, May 29, 2023 at 11:18?AM Johan Hovold <johan@kernel.org> wrote:
> >
> > I took a closer look at some of the modules that failed to load and
> > noticed a pattern in that they have dependencies that are needed by more
> > than one device.
>
> Ok, this is a "maybe something like this" RFC series of two patches -
> one trivial one to re-organize things a bit so that we can then do the
> real one which uses a filter based on the inode pointer to return an
> "idempotent return value" for module loads that share the same inode.
>
> It's entirely untested, and since I'm on the road I'm going to not
> really be able to test it. It compiles for me, and the code looks
> fairly straightforward, but it's probably buggy.

The updated patches fix the issue experienced with 6.4-rc4 where the Intel
NUC12 booted fine, but on media playback resulted in the video stuttering,
then freezing - and that audio was not coming though.

# diff modules-rc4 modules-rc4-patched
< snd_hda_codec_hdmi 77824 0
< snd_hda_codec_realtek 159744 0
---
> snd_hda_codec_hdmi 77824 1
> snd_hda_codec_realtek 159744 1

Revert "module: error out early on concurrent load of the same module file"
module: split up 'finit_module()' into init_module_from_file() helper
modules: catch concurrent module loads, take two
Johan's fix:
-static struct spinlock idem_lock;
+static DEFINE_SPINLOCK(idem_lock);

Tested-by: Rudi Heitbaum <rudi@heitbaum..com>

On 02.06.23 18:04, Luis Chamberlain wrote:
> On Fri, Jun 02, 2023 at 05:19:58PM +0200, David Hildenbrand wrote:
>> On 31.05.23 18:57, Luis Chamberlain wrote:
>>> On Wed, May 31, 2023 at 09:51:41AM +0200, David Hildenbrand wrote:
>>>> On 30.05.23 18:22, Luis Chamberlain wrote:
>>>>> On Mon, May 29, 2023 at 09:55:15PM -0400, Linus Torvalds wrote:
>>>>>> On Mon, May 29, 2023 at 11:18?AM Johan Hovold <johan@kernel.org> wrote:
>>>>>>>
>>>>>>> I took a closer look at some of the modules that failed to load and
>>>>>>> noticed a pattern in that they have dependencies that are needed by more
>>>>>>> than one device.
>>>>>>
>>>>>> Ok, this is a "maybe something like this" RFC series of two patches -
>>>>>> one trivial one to re-organize things a bit so that we can then do the
>>>>>> real one which uses a filter based on the inode pointer to return an
>>>>>> "idempotent return value" for module loads that share the same inode.
>>>>>>
>>>>>> It's entirely untested, and since I'm on the road I'm going to not
>>>>>> really be able to test it. It compiles for me, and the code looks
>>>>>> fairly straightforward, but it's probably buggy.
>>>>>>
>>>>>> It's very loosely based on Luis' attempt, but it
>>>>>> (a) is internal to module loading
>>>>>> (b) uses a reliable cookie
>>>>>> (c) doesn't leave the cookie around randomly for later
>>>>>> (d) has seen absolutely no testing
>>>>>>
>>>>>> Put another way: if somebody wants to play with this, please treat it
>>>>>> as a starting point, not the final thing. You might need to debug
>>>>>> things, and fix silly mistakes.
>>>>>>
>>>>>> The idea is to just have a simple hash list of currently executing
>>>>>> module loads, protected by a trivial spinlock. Every module loader
>>>>>> adds itself to the right hash list, and if they were the *first* one
>>>>>> (ie no other pending module loads for that inode), will actually do
>>>>>> the module load.
>>>>>>
>>>>>> Everybody who *isn't* the first one will just wait for completion and
>>>>>> return the same error code that the first one returned.
>>>>>
>>>>> That's also a hell much more snazzier MODULE_DEBUG_AUTOLOAD_DUPS if we
>>>>> ever wanted to do something similar there if we wanted to also
>>>>> join request_module() calls, instead of it hiding under debug.
>>>>>
>>>>>> This is technically bogus. The first one might fail due to arguments.
>>>>>
>>>>> For boot it's fine, as I can't think of boot wanting to support trying
>>>>> to load a module with different arguments but who knows. But I can't
>>>>> see it sensible to issue concurrent multiple requests for modules
>>>>> with different arguments without waiting in userspace for the first
>>>>> to fail.
>>>>>
>>>>> Even post-boot, doing that sounds rather insane, but it would certainly
>>>>> be a compromise and should probably be clearly documented. I think just
>>>>> a comment acknolwedging that corner case seems sensible.
>>>>>
>>>>> Because we won't be able to get the arguments until we process the
>>>>> module, so it would be too late for this optimization on kread. So it is
>>>>> why I had also stuck to the original feature being in kread, as then it
>>>>> provides a uniq kread call and the caller is aware of it. But indeed I
>>>>> had not considered the effects of arguments.
>>>>>
>>>>> Lucas, any thoughts from modules kmod userspace perspective into
>>>>> supporting anyone likely issuing concurrent modules requests with
>>>>> differing arguments?
>>>>>
>>>>>> So the cookie shouldn't be just the inode, it should be the inode and
>>>>>> a hash of the arguments or something like that.
>>>>>
>>>>> Personally I think it's a fine optimization without the arguments.
>>>>>
>>>>>> But it is what it is,
>>>>>> and apart from possible show-stopper bugs this is no worse than the
>>>>>> failed "exclusive write deny" attempt. IOW - maybe worth trying?
>>>>>
>>>>> The only thing I can think of is allowing threads other than the
>>>>> first one to complete before the one that actually loaded the
>>>>> module. I thought about this race for module auto-loading, see
>>>>> the comment in kmod_dup_request_announce(), so that just
>>>>> further delays the completion to other thread with a stupid
>>>>> queue_work(). That seems more important for module auto-loading
>>>>> duplicates than for boot finit_module() duplicates. But not sure
>>>>> if odering matters in the end due to a preemtible kernel and maybe
>>>>> that concern is hysteria.
>>>>>
>>>>>> And if *that* didn't sell people on this patch series, I don't know
>>>>>> what will. I should be in marketing! Two drink minimums, here I come!
>>>>>
>>>>> Sold:
>>>>>
>>>>> on 255 vcpus 0 duplicates found with this setup:
>>>>>
>>>>> root@kmod ~ # cat /sys/kernel/debug/modules/stats
>>>>> Mods ever loaded 66
>>>>> Mods failed on kread 0
>>>>> Mods failed on decompress 0
>>>>> Mods failed on becoming 0
>>>>> Mods failed on load 0
>>>>> Total module size 11268096
>>>>> Total mod text size 4149248
>>>>> Failed kread bytes 0
>>>>> Failed decompress bytes 0
>>>>> Failed becoming bytes 0
>>>>> Failed kmod bytes 0
>>>>> Virtual mem wasted bytes 0
>>>>> Average mod size 170729
>>>>> Average mod text size 62868
>>>>>
>>>>> So:
>>>>>
>>>>> Tested-by: Luis Chamberlain <mcgrof@kernel.org>
>>>>>
>>>>> In terms of bootup timing:
>>>>>
>>>>> Before:
>>>>> Startup finished in 41.653s (kernel) + 44.305s (userspace) = 1min 25.958s
>>>>> graphical.target reached after 44.178s in userspace.
>>>>> After:
>>>>> Startup finished in 23.995s (kernel) + 40.350s (userspace) = 1min 4.345s
>>>>> graphical.target reached after 40.226s in userspace.
>>>>
>>>> I'll try grabbing the system where we saw the KASAN-related issues [1] and
>>>> give it a churn with and without the two patches. Might take a bit (~1 day),
>>>> unfortunately.
>>>>
>>>> [1] https://lkml.kernel.org/r/20221013180518.217405-1-david@redhat.com
>>>
>>> Great, don't forget:
>>>
>>> diff --git a/kernel/module/main.c b/kernel/module/main.c
>>> index 82b0dcc1fe77..222015093eeb 100644
>>> --- a/kernel/module/main.c
>>> +++ b/kernel/module/main.c
>>> @@ -3066,7 +3066,7 @@ struct idempotent {
>>> #define IDEM_HASH_BITS 8
>>> static struct hlist_head idem_hash[1 << IDEM_HASH_BITS];
>>> -static struct spinlock idem_lock;
>>> +static DEFINE_SPINLOCK(idem_lock);
>>> static bool idempotent(struct idempotent *u, const void *cookie)
>>> {
>>>
>>
>> Finally was able to run it on that ThinkSystem SR950 with 8 populated
>> sockets -> 224 cores and 448 logical CPUs.
>>
>> The KASAN vmap issues on that system were already no longer reproducible with your
>> (Luis) previous work that's already in master.
>>
>> I tested a !debug and debug config (both based on corresponding RHEL9 configs), comparing
>> 929ed21dfdb6 ("master") with 929ed21dfdb6 + Linus' patches ("patched").
>>
>>
>> Unfortunately, boot times vary a lot, and I did not figure out how to reduce
>> the noise. I captured the "systemd-analyze blame" output as well.
>>
>>
>> 1) !debug config (not enabling KASAN)
>>
>> a) master
>>
>> Startup finished in 32.225s (kernel) + 7.399s (initrd) + 20.378s (userspace) = 1min 3ms
>> multi-user.target reached after 20.352s in userspace.
>> Startup finished in 43.734s (kernel) + 7.288s (initrd) + 19.827s (userspace) = 1min 10.851s
>> multi-user.target reached after 19.800s in userspace.
>> Startup finished in 50.514s (kernel) + 7.171s (initrd) + 24.757s (userspace) = 1min 22.443s
>> multi-user.target reached after 24.734s in userspace.
>> Startup finished in 26.722s (kernel) + 7.249s (initrd) + 23.923s (userspace) = 57.895s
>> multi-user.target reached after 23.892s in userspace.
>>
>> b) patched
>>
>> Startup finished in 36.318s (kernel) + 7.177s (initrd) + 21.383s (userspace) = 1min 4.879s
>> multi-user.target reached after 21.355s in userspace.
>> Startup finished in 36.318s (kernel) + 7.177s (initrd) + 21.383s (userspace) = 1min 4.879s
>> multi-user.target reached after 21.355s in userspace.
>> Startup finished in 1min 34.678s (kernel) + 7.239s (initrd) + 24.066s (userspace) = 2min 5.985s
>> multi-user.target reached after 24.040s in userspace.
>> Startup finished in 25.879s (kernel) + 7.144s (initrd) + 29.665s (userspace) = 1min 2.689s
>> multi-user.target reached after 29.637s in userspace.
>>
>>
>>
>> 2) debug config (enabling KASAN)
>>
>> a) master
>>
>> Startup finished in 2min 12.695s (kernel) + 25.058s (initrd) + 1min 13.012s (userspace) = 3min 50.765s
>> multi-user.target reached after 1min 12.903s in userspace.
>> Startup finished in 1min 45.400s (kernel) + 24.294s (initrd) + 1min 8.910s (userspace) = 3min 18.606s
>> multi-user.target reached after 1min 8.786s in userspace.
>> Startup finished in 2min 4.857s (kernel) + 24.715s (initrd) + 1min 5.088s (userspace) = 3min 34.660s
>> multi-user.target reached after 1min 4.967s in userspace.
>> Startup finished in 3min 20.400s (kernel) + 24.703s (initrd) + 1min 5.469s (userspace) = 4min 50.573s
>> multi-user.target reached after 1min 5.344s in userspace.
>>
>> b) patched
>>
>> Startup finished in 2min 5.250s (kernel) + 25.049s (initrd) + 1min 1.961s (userspace) = 3min 32.262s
>> multi-user.target reached after 1min 1.844s in userspace.
>> Startup finished in 1min 52.524s (kernel) + 24.897s (initrd) + 1min 5.062s (userspace) = 3min 22.484s
>> multi-user.target reached after 1min 4.916s in userspace.
>> Startup finished in 9min 36.817s (kernel) + 24.859s (initrd) + 1min 18.657s (userspace) = 11min 20.335s
>> multi-user.target reached after 1min 18.455s in userspace.
>> Startup finished in 30min 20.715s (kernel) + 24.722s (initrd) + 1min 7.039s (userspace) = 31min 52.476s
>> multi-user.target reached after 1min 6.907s in userspace.
>>
>>
>> What concerns me a bit, is that on the patched kernel we seem to hit more cases where
>> boot takes much longer (in both kernel configs).
>>
>> I'll do some more runs/investigation to see if this is reproducible or just some system oddity.
>>
>> Staring just at the udev settle time (systemd-analyze blame), it's very similar between both kernel
>> versions.
>
> Thanks for these tests, having MODULE_STATS enabled +
>
> cat /sys/kernel/debug/modules/stats
>
> would be of huge value, both on master and + patched.

Sure! Sorry for the slight delay, had to recompile the kernels.

I only did a single run on each kernel, should be good enough for the purpose here.


1) !debug config (not enabling KASAN)

a) master

# cat /sys/kernel/debug/modules/stats
Mods ever loaded 75
Mods failed on kread 0
Mods failed on decompress 0
Mods failed on becoming 8052
Mods failed on load 531
Total module size 16343040
Total mod text size 4767744
Failed kread bytes 0
Failed decompress bytes 0
Failed becoming bytes 19185958488
Failed kmod bytes 1172591936
Virtual mem wasted bytes 20358550424
Average mod size 217908
Average mod text size 63570
Avg fail becoming bytes 2382757
Average fail load bytes 2208272
Duplicate failed modules:
Module-name How-many-times Reason
intel_rapl_common 447 Becoming
intel_uncore_frequency 447 Becoming
intel_uncore_frequency_common 445 Becoming & Load
isst_if_mbox_msr 447 Becoming
isst_if_common 447 Becoming & Load
skx_edac 447 Becoming & Load
nfit 447 Becoming
libnvdimm 447 Becoming
x86_pkg_temp_thermal 447 Becoming
intel_powerclamp 447 Becoming
coretemp 447 Becoming & Load
kvm_intel 447 Becoming
kvm 447 Becoming & Load
irdma 3 Load
ice 3 Becoming
irqbypass 447 Becoming & Load
rapl 393 Becoming & Load
gnss 2 Becoming & Load
ioatdma 63 Becoming & Load
ib_uverbs 3 Becoming & Load
intel_cstate 447 Becoming & Load
ipmi_si 1 Load
intel_uncore 447 Becoming & Load
ib_core 3 Becoming & Load
ipmi_devintf 1 Load
ipmi_msghandler 1 Becoming
dca 63 Becoming
ahci 1 Becoming
i40e 3 Becoming
libahci 1 Becoming
crct10dif_pclmul 195 Becoming
crc32_pclmul 262 Becoming
crc32c_intel 126 Becoming & Load
libata 1 Load
ghash_clmulni_intel 297 Becoming & Load
fjes 11 Becoming


b) patched

# cat /sys/kernel/debug/modules/stats
Mods ever loaded 75
Mods failed on kread 0
Mods failed on decompress 0
Mods failed on becoming 0
Mods failed on load 0
Total module size 16343040
Total mod text size 4767744
Failed kread bytes 0
Failed decompress bytes 0
Failed becoming bytes 0
Failed kmod bytes 0
Virtual mem wasted bytes 0
Average mod size 217908
Average mod text size 63570



2) debug config (enabling KASAN)

a) master

# cat /sys/kernel/debug/modules/stats
Mods ever loaded 75
Mods failed on kread 0
Mods failed on decompress 0
Mods failed on becoming 3173
Mods failed on load 923
Total module size 32288768
Total mod text size 14819328
Failed kread bytes 0
Failed decompress bytes 0
Failed becoming bytes 4279728952
Failed kmod bytes 2174133088
Virtual mem wasted bytes 6453862040
Average mod size 430517
Average mod text size 197592
Avg fail becoming bytes 1348796
Average fail load bytes 2355508
Duplicate failed modules:
Module-name How-many-times Reason
ioatdma 63 Becoming & Load
intel_rapl_common 313 Becoming
intel_uncore_frequency 136 Becoming & Load
intel_uncore_frequency_common 38 Becoming
isst_if_mbox_msr 443 Becoming & Load
isst_if_common 210 Becoming & Load
skx_edac 257 Becoming & Load
nfit 180 Becoming & Load
libnvdimm 294 Becoming & Load
x86_pkg_temp_thermal 321 Becoming & Load
intel_powerclamp 247 Becoming & Load
coretemp 55 Becoming & Load
kvm_intel 2 Becoming
kvm 3 Becoming & Load
irqbypass 3 Becoming
rapl 1 Becoming
intel_cstate 444 Load
intel_uncore 447 Becoming & Load
ib_uverbs 1 Load
ib_core 3 Becoming & Load
ipmi_si 1 Becoming
dca 20 Becoming & Load
sg 1 Becoming
i40e 3 Becoming & Load
ahci 1 Becoming
crct10dif_pclmul 160 Becoming & Load
crc32_pclmul 151 Becoming & Load
crc32c_intel 146 Becoming & Load
ghash_clmulni_intel 140 Becoming
libata 1 Load
fjes 11 Becoming & Load



b) patched

# cat /sys/kernel/debug/modules/stats
Mods ever loaded 75
Mods failed on kread 0
Mods failed on decompress 0
Mods failed on becoming 19
Mods failed on load 0
Total module size 32288768
Total mod text size 14819328
Failed kread bytes 0
Failed decompress bytes 0
Failed becoming bytes 6441296
Failed kmod bytes 0
Virtual mem wasted bytes 6441296
Average mod size 430517
Average mod text size 197592
Avg fail becoming bytes 339016
Duplicate failed modules:
Module-name How-many-times Reason
intel_rapl_common 2 Becoming
intel_uncore_frequency_common 5 Becoming
isst_if_common 3 Becoming
intel_powerclamp 2 Becoming
irqbypass 5 Becoming
crct10dif_pclmul 1 Becoming
crc32c_intel 1 Becoming



So, with these (helpful) stats, the improvement is obvious (and explains the ~1s
improvement I saw staring at the startup times of the udev services).

There are still some failed module loads with the debug config (only in the
becoming state), I did not dive deeply into the actual code changes (-EBUSY),
just spelling it out so we can decide if this is to be expected or some corner
case that shouldn't be happening.


Thanks!

--
Cheers,

David / dhildenb

On Tue, May 30, 2023 at 11:40:35AM +0200, Johan Hovold wrote:
> On Mon, May 29, 2023 at 09:55:15PM -0400, Linus Torvalds wrote:
> > On Mon, May 29, 2023 at 11:18?AM Johan Hovold <johan@kernel.org> wrote:
> > >
> > > I took a closer look at some of the modules that failed to load and
> > > noticed a pattern in that they have dependencies that are needed by more
> > > than one device.
> >
> > Ok, this is a "maybe something like this" RFC series of two patches -
> > one trivial one to re-organize things a bit so that we can then do the
> > real one which uses a filter based on the inode pointer to return an
> > "idempotent return value" for module loads that share the same inode.
> >
> > It's entirely untested, and since I'm on the road I'm going to not
> > really be able to test it. It compiles for me, and the code looks
> > fairly straightforward, but it's probably buggy.
> >
> > It's very loosely based on Luis' attempt, but it
> > (a) is internal to module loading
> > (b) uses a reliable cookie
> > (c) doesn't leave the cookie around randomly for later
> > (d) has seen absolutely no testing
> >
> > Put another way: if somebody wants to play with this, please treat it
> > as a starting point, not the final thing. You might need to debug
> > things, and fix silly mistakes.
>
> With the missing spinlock initialisation fixed:
>
> -static struct spinlock idem_lock;
> +static DEFINE_SPINLOCK(idem_lock);
>
> this passes basic smoke testing and allows the X13s to boot.
>
> It does not seem to have any significant impact on boot time, but it
> avoids some of the unnecessary load attempts as intended:

Took another look at code which modulo some nits like missing spaces
around a + operator and an "ourselfs" typo looks good to me. So with the
spinlock initialisation fixed:

Reviewed-by: Johan Hovold <johan@kernel.org>
Tested-by: Johan Hovold <johan@kernel.org>

Johan

On Mon, Jun 05, 2023 at 01:26:00PM +0200, David Hildenbrand wrote:
> I only did a single run on each kernel, should be good enough for the purpose here.
>
>
> 1) !debug config (not enabling KASAN)
>
> a) master
>
> # cat /sys/kernel/debug/modules/stats
> Virtual mem wasted bytes 20358550424
18 GiB

> Average mod size 217908
212 KiB

> Average mod text size 63570
62 KiB

> b) patched
>
> # cat /sys/kernel/debug/modules/stats
> Virtual mem wasted bytes 0

> 2) debug config (enabling KASAN)
>
> a) master
>
> # cat /sys/kernel/debug/modules/stats
> Virtual mem wasted bytes 6453862040
6 GiB

> Average mod size 430517
420 KiB, so ballpark kasan pretty much doubles module size.

> Average mod text size 197592
192 KiB, and is reflected on module .text too, in fact .text more than doubles.

It would have otherwise been difficult to get some of these stats, so
thanks! I make note of .text just because of the recent development work
going on for a new module_alloc(). About 14 MiB required to house a big
iron kasan enabled module .text, whereas about half is required for !kasan.

> b) patched
>
> # cat /sys/kernel/debug/modules/stats
> Virtual mem wasted bytes 6441296

We've gone down from ~6 GiB to ~6 MiB.

> So, with these (helpful) stats,

Extremely useful, yes thanks.

> the improvement is obvious (and explains the ~1s
> improvement I saw staring at the startup times of the udev services).
>
> There are still some failed module loads with the debug config (only in the
> becoming state), I did not dive deeply into the actual code changes (-EBUSY),

That's fine, Linus' patch does not keep the lock for the entire life
of the module, it releases it right away after we're done with the
kernel_read(), and because of this, there is a small race in between
a thread the kernel_read() finishing and the module then being processed
into the modules linked list. During that time, if a new module with the
same name comes in, we'll have to allow it since the lock was released.
Those extra modules end up lingering to wait for the first one that made
it to the modules linked list.

I don't think we need to worry about 6 MiB, this patch alone should
suffice for a long time until userspace gets its act together and fixes
this properly. Fixing userspace should reduce some latencies as well on
bootup so someone who cares about bootup speeds on high end systems
could likely be encouraged to fix that.

> just spelling it out so we can decide if this is to be expected or some corner
> case that shouldn't be happening.

It is expected, in fact the fact that the heuristic works so well,
without keeping the lock forever, and therefore keeping the code changes
to a minimum is quite an amazing.

Luis

On Mon, Jun 05, 2023 at 08:17:42AM -0700, Luis Chamberlain wrote:
> We've gone down from ~6 GiB to ~6 MiB.

And just to also highlight, that was just for for the KASAN enabled case, and
for !KASAN we went from ~18 GiB to 0.

Luis

On Mon, Jun 05, 2023 at 08:28:41AM -0700, Luis Chamberlain wrote:
> On Mon, Jun 05, 2023 at 08:17:42AM -0700, Luis Chamberlain wrote:
> > We've gone down from ~6 GiB to ~6 MiB.
>
> And just to also highlight, that was just for for the KASAN enabled case, and
> for !KASAN we went from ~18 GiB to 0.

Linus, were you thinking of including these patches in for v6.5-rc1?

Luis

On Wed, 28 Jun 2023 at 11:52, Luis Chamberlain <mcgrof@kernel.org> wrote:
>
> Linus, were you thinking of including these patches in for v6.5-rc1?

Heh, I don't even have them in my tree any more, I was assuming that
if they were good they'd be sent back to me...

I guess I can go fish them out from my old emails, but I actually was
expecting to just get them from you.

I do actually maintain my own branches for *some* things, and merge
them myself, but they tend to be for areas that I feel I'm
co-maintaining (ie notably vfs and mm that I still feel I'm involved
in).

In other areas, I may send out patches, but I don't feel like I'm a
maintainer, so I then think that "the real maintainer can decide if
these patches are good or not".

And I would very much hope that people don't take said patches _just_
because they come from me. They should be judged on their own merits,
and then occasionally people can mutter "Christ, what drugs is Linus
on _today_?" and just throw my patches in the garbage.

Linus

On Wed, 28 Jun 2023 at 13:14, Linus Torvalds
<torvalds@linux-foundation.org> wrote:
>
> In other areas, I may send out patches, but I don't feel like I'm a
> maintainer, so I then think that "the real maintainer can decide if
> these patches are good or not".

Anyway, since I clearly didn't communicate clearly that I was throwing
the patch over to you, let me go and find it and just apply it myself.

Linus

On Wed, 28 Jun 2023 at 15:07, Linus Torvalds
<torvalds@linux-foundation.org> wrote:
>
> Anyway, since I clearly didn't communicate clearly that I was throwing
> the patch over to you, let me go and find it and just apply it myself.

Ok, I spent some time writing a better commit message for that change,
tried to make sure I got everybody's comments and Tested-by's sorted
out etc, and committed the end result.

I also did the actual module pull and your sysctl pull.

Can you please check that it all looks like you expected?

Linus

On Wed, Jun 28, 2023 at 04:17:10PM -0700, Linus Torvalds wrote:
> On Wed, 28 Jun 2023 at 15:07, Linus Torvalds
> <torvalds@linux-foundation.org> wrote:
> >
> > Anyway, since I clearly didn't communicate clearly that I was throwing
> > the patch over to you, let me go and find it and just apply it myself.
>
> Ok, I spent some time writing a better commit message for that change,
> tried to make sure I got everybody's comments and Tested-by's sorted
> out etc, and committed the end result.
>
> I also did the actual module pull and your sysctl pull.
>
> Can you please check that it all looks like you expected?

Looks good to me, thanks for doing that. It certainly was not clear
to me that you had expected me to merge your patch just because you
had previously merged your own and later reverted it. But now I know
in the future I may just pick up your patches, instead of expecting
you to shortcut it, thanks!

Luis