| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Message-ID: <fa3f1a1f-edc6-f13b-cc84-f3264b03b0b1@redhat.com>
Date: Mon, 5 Jun 2023 13:26:00 +0200
From: David Hildenbrand <david@...hat.com>
To: Luis Chamberlain <mcgrof@...nel.org>
Cc: Linus Torvalds <torvalds@...ux-foundation.org>,
Johan Hovold <johan@...nel.org>,
Lucas De Marchi <lucas.demarchi@...el.com>,
Petr Pavlu <petr.pavlu@...e.com>, gregkh@...uxfoundation.org,
rafael@...nel.org, song@...nel.org, lucas.de.marchi@...il.com,
christophe.leroy@...roup.eu, peterz@...radead.org, rppt@...nel.org,
dave@...olabs.net, willy@...radead.org, vbabka@...e.cz,
mhocko@...e.com, dave.hansen@...ux.intel.com,
colin.i.king@...il.com, jim.cromie@...il.com,
catalin.marinas@....com, jbaron@...mai.com,
rick.p.edgecombe@...el.com, yujie.liu@...el.com,
tglx@...utronix.de, hch@....de, patches@...ts.linux.dev,
linux-modules@...r.kernel.org, linux-mm@...ck.org,
linux-kernel@...r.kernel.org, pmladek@...e.com, prarit@...hat.com,
lennart@...ttering.net
Subject: Re: [PATCH 2/2] module: add support to avoid duplicates early on load
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@...nel.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@...d ~ # 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@...nel.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
Powered by blists - more mailing lists