Re: [PATCH 2/2] module: add support to avoid duplicates early on load

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



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@xxxxxxxxxx> 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@xxxxxxxxxx>

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@xxxxxxxxxx

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





[Index of Archives]     [Linux ARM Kernel]     [Linux ARM]     [Linux Omap]     [Fedora ARM]     [IETF Annouce]     [Bugtraq]     [Linux OMAP]     [Linux MIPS]     [eCos]     [Asterisk Internet PBX]     [Linux API]

  Powered by Linux