panic in udp_init() when using FORCE_NR_CPUS

panic in udp_init() when using FORCE_NR_CPUS

[Ricardo Nabinger Sanchez]

Hello,

I have hit again an old panic that, in the past, I could not check in
more depth.  But today I was able to pinpoint to a single config knob:

$ diff -u /mnt/tmp/Kernel/linux-6.4-rc6/.config{.old,}
--- /mnt/tmp/Kernel/linux-6.4-rc6/.config.old	2023-06-13
10:34:11.881004307 -0300 +++
/mnt/tmp/Kernel/linux-6.4-rc6/.config	2023-06-13
13:42:46.396967635 -0300 @@ -4996,7 +4996,7 @@ CONFIG_SGL_ALLOC=y
 CONFIG_CHECK_SIGNATURE=y
 CONFIG_CPUMASK_OFFSTACK=y
-CONFIG_FORCE_NR_CPUS=y
+# CONFIG_FORCE_NR_CPUS is not set
 CONFIG_CPU_RMAP=y
 CONFIG_DQL=y
 CONFIG_GLOB=y

Today's build is 6.4-rc6 tarball from kernel.org and, if I enable
FORCE_NR_CPUS, it panic()s after doing kmalloc(), with

	"UDP: failed to alloc udp_busylocks"

Backtrace leads to:

void __init udp_init(void)
{
        unsigned long limit;
        unsigned int i;

        udp_table_init(&udp_table, "UDP");
        limit = nr_free_buffer_pages() / 8; 
        limit = max(limit, 128UL);
        sysctl_udp_mem[0] = limit / 4 * 3; 
        sysctl_udp_mem[1] = limit;
        sysctl_udp_mem[2] = sysctl_udp_mem[0] * 2; 

        /* 16 spinlocks per cpu */
        udp_busylocks_log = ilog2(nr_cpu_ids) + 4; 
        udp_busylocks = kmalloc(sizeof(spinlock_t) << udp_busylocks_log,
                                GFP_KERNEL);
        if (!udp_busylocks)
                panic("UDP: failed to alloc udp_busylocks\n");
        for (i = 0; i < (1U << udp_busylocks_log); i++) 
                spin_lock_init(udp_busylocks + i);

        if (register_pernet_subsys(&udp_sysctl_ops))
                panic("UDP: failed to init sysctl parameters.\n");

#if defined(CONFIG_BPF_SYSCALL) && defined(CONFIG_PROC_FS)
        bpf_iter_register();
#endif
}

For your convenience, this panic() is from the following commit:

commit 4b272750dbe6f92a8d39a0ee1c7bd50d6cc1a2c8
Author: Eric Dumazet <edumazet@google.com>
Date:   Thu Dec 8 11:41:54 2016 -0800

    udp: add busylocks in RX path
    
    Idea of busylocks is to let producers grab an extra spinlock
    to relieve pressure on the receive_queue spinlock shared by
    consumer. 
    This behavior is requested only once socket receive queue is above
    half occupancy.
    
    Under flood, this means that only one producer can be in line
    trying to acquire the receive_queue spinlock.
    
    These busylock can be allocated on a per cpu manner, instead of a
    per socket one (that would consume a cache line per socket)
    
    This patch considerably improves UDP behavior under stress,
    depending on number of NIC RX queues and/or RPS spread.

This is very early in the boot process so I don't have textual output
to paste, and the screen is pretty much on 80x25.  Let me know if you
really need the backtrace/dump.

It should reproduce on as early as 6.1-rc5 (which was the first time I
tried to enable FORCE_NR_CPUS, as far as I can tell), but most likely
any version since the mentioned commit went upstream.

For reference, I'll leave the full .config.old in this Github gist:

	https://gist.github.com/rnsanchez/fd60d25625a0459b4ee10b653fc11f93

If you need to know which CPU I'm using:

Architecture:            x86_64
  CPU op-mode(s):        32-bit, 64-bit
  Address sizes:         39 bits physical, 48 bits virtual
  Byte Order:            Little Endian
CPU(s):                  12
  On-line CPU(s) list:   0-11
Vendor ID:               GenuineIntel
  Model name:            Intel(R) Core(TM) i7-8700 CPU @ 3.20GHz
    CPU family:          6
    Model:               158
    Thread(s) per core:  2
    Core(s) per socket:  6
    Socket(s):           1
    Stepping:            10
    CPU(s) scaling MHz:  93%
    CPU max MHz:         4600.0000
    CPU min MHz:         800.0000
    BogoMIPS:            6399.96

Let me know if you need any more information.

Please keep me in Cc:.

Best regards,

-- 
Ricardo Nabinger Sanchez

    Dedique-se a melhorar seus esforços.
    Todas as suas conquistas evolutivas não foram resultado dos
    deuses, das outras consciências, ou do acaso, mas unicamente
    da sua transpiração. ---Waldo Vieira, Léxico de Ortopensatas

Re: panic in udp_init() when using FORCE_NR_CPUS

[Eric Dumazet]

On Tue, Jun 13, 2023 at 9:56 PM Ricardo Nabinger Sanchez
<rnsanchez@gmail.com> wrote:
>
> Hello,
>
> I have hit again an old panic that, in the past, I could not check in
> more depth.  But today I was able to pinpoint to a single config knob:
>
> $ diff -u /mnt/tmp/Kernel/linux-6.4-rc6/.config{.old,}
> --- /mnt/tmp/Kernel/linux-6.4-rc6/.config.old   2023-06-13
> 10:34:11.881004307 -0300 +++
> /mnt/tmp/Kernel/linux-6.4-rc6/.config   2023-06-13
> 13:42:46.396967635 -0300 @@ -4996,7 +4996,7 @@ CONFIG_SGL_ALLOC=y
>  CONFIG_CHECK_SIGNATURE=y
>  CONFIG_CPUMASK_OFFSTACK=y
> -CONFIG_FORCE_NR_CPUS=y
> +# CONFIG_FORCE_NR_CPUS is not set
>  CONFIG_CPU_RMAP=y
>  CONFIG_DQL=y
>  CONFIG_GLOB=y
>

Sure, but you did not give NR_CPUS value ?

Also posting the stack trace might be useful.

> Today's build is 6.4-rc6 tarball from kernel.org and, if I enable
> FORCE_NR_CPUS, it panic()s after doing kmalloc(), with
>
>         "UDP: failed to alloc udp_busylocks"
>
> Backtrace leads to:
>
> void __init udp_init(void)
> {
>         unsigned long limit;
>         unsigned int i;
>
>         udp_table_init(&udp_table, "UDP");
>         limit = nr_free_buffer_pages() / 8;
>         limit = max(limit, 128UL);
>         sysctl_udp_mem[0] = limit / 4 * 3;
>         sysctl_udp_mem[1] = limit;
>         sysctl_udp_mem[2] = sysctl_udp_mem[0] * 2;
>
>         /* 16 spinlocks per cpu */
>         udp_busylocks_log = ilog2(nr_cpu_ids) + 4;
>         udp_busylocks = kmalloc(sizeof(spinlock_t) << udp_busylocks_log,
>                                 GFP_KERNEL);
>         if (!udp_busylocks)
>                 panic("UDP: failed to alloc udp_busylocks\n");
>         for (i = 0; i < (1U << udp_busylocks_log); i++)
>                 spin_lock_init(udp_busylocks + i);
>
>         if (register_pernet_subsys(&udp_sysctl_ops))
>                 panic("UDP: failed to init sysctl parameters.\n");
>
> #if defined(CONFIG_BPF_SYSCALL) && defined(CONFIG_PROC_FS)
>         bpf_iter_register();
> #endif
> }
>
> For your convenience, this panic() is from the following commit:
>
> commit 4b272750dbe6f92a8d39a0ee1c7bd50d6cc1a2c8
> Author: Eric Dumazet <edumazet@google.com>
> Date:   Thu Dec 8 11:41:54 2016 -0800
>
>     udp: add busylocks in RX path
>
>     Idea of busylocks is to let producers grab an extra spinlock
>     to relieve pressure on the receive_queue spinlock shared by
>     consumer.
>     This behavior is requested only once socket receive queue is above
>     half occupancy.
>
>     Under flood, this means that only one producer can be in line
>     trying to acquire the receive_queue spinlock.
>
>     These busylock can be allocated on a per cpu manner, instead of a
>     per socket one (that would consume a cache line per socket)
>
>     This patch considerably improves UDP behavior under stress,
>     depending on number of NIC RX queues and/or RPS spread.
>
> This is very early in the boot process so I don't have textual output
> to paste, and the screen is pretty much on 80x25.  Let me know if you
> really need the backtrace/dump.
>
> It should reproduce on as early as 6.1-rc5 (which was the first time I
> tried to enable FORCE_NR_CPUS, as far as I can tell), but most likely
> any version since the mentioned commit went upstream.
>
> For reference, I'll leave the full .config.old in this Github gist:
>
>         https://gist.github.com/rnsanchez/fd60d25625a0459b4ee10b653fc11f93
>
> If you need to know which CPU I'm using:
>
> Architecture:            x86_64
>   CPU op-mode(s):        32-bit, 64-bit
>   Address sizes:         39 bits physical, 48 bits virtual
>   Byte Order:            Little Endian
> CPU(s):                  12
>   On-line CPU(s) list:   0-11
> Vendor ID:               GenuineIntel
>   Model name:            Intel(R) Core(TM) i7-8700 CPU @ 3.20GHz
>     CPU family:          6
>     Model:               158
>     Thread(s) per core:  2
>     Core(s) per socket:  6
>     Socket(s):           1
>     Stepping:            10
>     CPU(s) scaling MHz:  93%
>     CPU max MHz:         4600.0000
>     CPU min MHz:         800.0000
>     BogoMIPS:            6399.96
>
> Let me know if you need any more information.
>
> Please keep me in Cc:.
>
> Best regards,
>
> --
> Ricardo Nabinger Sanchez
>
>     Dedique-se a melhorar seus esforços.
>     Todas as suas conquistas evolutivas não foram resultado dos
>     deuses, das outras consciências, ou do acaso, mas unicamente
>     da sua transpiração. ---Waldo Vieira, Léxico de Ortopensatas

Re: panic in udp_init() when using FORCE_NR_CPUS

[Eric Dumazet]

On Tue, Jun 13, 2023 at 10:19 PM Eric Dumazet <edumazet@google.com> wrote:
>
> On Tue, Jun 13, 2023 at 9:56 PM Ricardo Nabinger Sanchez
> <rnsanchez@gmail.com> wrote:
> >
> > Hello,
> >
> > I have hit again an old panic that, in the past, I could not check in
> > more depth.  But today I was able to pinpoint to a single config knob:
> >
> > $ diff -u /mnt/tmp/Kernel/linux-6.4-rc6/.config{.old,}
> > --- /mnt/tmp/Kernel/linux-6.4-rc6/.config.old   2023-06-13
> > 10:34:11.881004307 -0300 +++
> > /mnt/tmp/Kernel/linux-6.4-rc6/.config   2023-06-13
> > 13:42:46.396967635 -0300 @@ -4996,7 +4996,7 @@ CONFIG_SGL_ALLOC=y
> >  CONFIG_CHECK_SIGNATURE=y
> >  CONFIG_CPUMASK_OFFSTACK=y
> > -CONFIG_FORCE_NR_CPUS=y
> > +# CONFIG_FORCE_NR_CPUS is not set
> >  CONFIG_CPU_RMAP=y
> >  CONFIG_DQL=y
> >  CONFIG_GLOB=y
> >
>
> Sure, but you did not give NR_CPUS value ?

I suspect you run with LOCKDEP enabled (CONFIG_PROVE_LOCKING=y)
and a very big NR_CPUS ?

LOCKDEP makes spinlock_t 16 times bigger :/

If so, please try the following fix.

diff --git a/net/ipv4/udp.c b/net/ipv4/udp.c
index 9482def1f310379efde1a1a8c86999b4b826cf17..ad19a37a49e78715c813b17a1097226dd1450671
100644
--- a/net/ipv4/udp.c
+++ b/net/ipv4/udp.c
@@ -3481,8 +3481,13 @@ void __init udp_init(void)

        /* 16 spinlocks per cpu */
        udp_busylocks_log = ilog2(nr_cpu_ids) + 4;
-       udp_busylocks = kmalloc(sizeof(spinlock_t) << udp_busylocks_log,
-                               GFP_KERNEL);
+       while (udp_busylocks_log >= 4) {
+               udp_busylocks = kmalloc(sizeof(spinlock_t) << udp_busylocks_log,
+                                       GFP_KERNEL | __GFP_NOWARN);
+               if (udp_busylocks)
+                       break;
+               udp_busylocks_log--;
+       }
        if (!udp_busylocks)
                panic("UDP: failed to alloc udp_busylocks\n");
        for (i = 0; i < (1U << udp_busylocks_log); i++)

Re: panic in udp_init() when using FORCE_NR_CPUS

[Ricardo Nabinger Sanchez]

Hi Eric,

On Tue, 13 Jun 2023 22:19:33 +0200
Eric Dumazet <edumazet@google.com> wrote:

> Sure, but you did not give NR_CPUS value ?
> 
> Also posting the stack trace might be useful.

That's puzzling.  From menuconfig (which I always use), it is a bool:

[*] Set number of CPUs at compile time 

CONFIG_FORCE_NR_CPUS:

Say Yes if you have NR_CPUS set to an actual number of possible
CPUs in your system, not to a default value. This forces the core
code to rely on compile-time value and optimize kernel routines
better.

Symbol: FORCE_NR_CPUS [=y]
Type  : bool
Defined at lib/Kconfig:540
  Prompt: Set number of CPUs at compile time
  Depends on: SMP [=y] && EXPERT [=y] && !COMPILE_TEST [=n]
  Location:
    -> Library routines
      -> Set number of CPUs at compile time (FORCE_NR_CPUS [=y])



So I took another look into how I was setting these, and since I had
not realized I would need to disable MAXSMP and only then be able to
set NR_CPUS.  I must have misunderstood the help sections; the wording
suggests me that one of those knobs would trigger some automatic
enumeration.

Here is the diff on my resulting .config:

--- .config.old	2023-06-13 17:33:41.152720907 -0300
+++ .config	2023-06-13 17:46:48.515676191 -0300
@@ -388,11 +388,11 @@
 CONFIG_HPET_EMULATE_RTC=y
 CONFIG_DMI=y
 CONFIG_BOOT_VESA_SUPPORT=y
-CONFIG_MAXSMP=y
-CONFIG_NR_CPUS_RANGE_BEGIN=8192
-CONFIG_NR_CPUS_RANGE_END=8192
-CONFIG_NR_CPUS_DEFAULT=8192
-CONFIG_NR_CPUS=8192
+# CONFIG_MAXSMP is not set
+CONFIG_NR_CPUS_RANGE_BEGIN=2
+CONFIG_NR_CPUS_RANGE_END=512
+CONFIG_NR_CPUS_DEFAULT=64
+CONFIG_NR_CPUS=12
 CONFIG_SCHED_CLUSTER=y
 CONFIG_SCHED_SMT=y
 CONFIG_SCHED_MC=y
@@ -430,7 +430,7 @@
 # CONFIG_AMD_NUMA is not set
 CONFIG_X86_64_ACPI_NUMA=y
 # CONFIG_NUMA_EMU is not set
-CONFIG_NODES_SHIFT=10
+CONFIG_NODES_SHIFT=6
 CONFIG_ARCH_SPARSEMEM_ENABLE=y
 CONFIG_ARCH_SPARSEMEM_DEFAULT=y
 CONFIG_ARCH_PROC_KCORE_TEXT=y
@@ -4995,8 +4995,7 @@
 # CONFIG_DMA_MAP_BENCHMARK is not set
 CONFIG_SGL_ALLOC=y
 CONFIG_CHECK_SIGNATURE=y
-CONFIG_CPUMASK_OFFSTACK=y
-# CONFIG_FORCE_NR_CPUS is not set
+CONFIG_FORCE_NR_CPUS=y
 CONFIG_CPU_RMAP=y
 CONFIG_DQL=y
 CONFIG_GLOB=y
@@ -5150,6 +5149,8 @@
 # CONFIG_DEBUG_VIRTUAL is not set
 CONFIG_DEBUG_MEMORY_INIT=y
 # CONFIG_DEBUG_PER_CPU_MAPS is not set
+CONFIG_ARCH_SUPPORTS_KMAP_LOCAL_FORCE_MAP=y
+# CONFIG_DEBUG_KMAP_LOCAL_FORCE_MAP is not set
 CONFIG_HAVE_ARCH_KASAN=y
 CONFIG_HAVE_ARCH_KASAN_VMALLOC=y
 CONFIG_CC_HAS_KASAN_GENERIC=y


And I'm reporting from a freshly-rebuilt kernel, which succeeded in
booting.  So this was totally on me, I did not know about these
conflicts in my configuration.

Apologies on making noise about this panic.

Best regards,

-- 
Ricardo Nabinger Sanchez

    Dedique-se a melhorar seus esforços.
    Todas as suas conquistas evolutivas não foram resultado dos
    deuses, das outras consciências, ou do acaso, mas unicamente
    da sua transpiração. ---Waldo Vieira, Léxico de Ortopensatas

Re: panic in udp_init() when using FORCE_NR_CPUS

[Ricardo Nabinger Sanchez]

On Tue, 13 Jun 2023 23:05:34 +0200
Eric Dumazet <edumazet@google.com> wrote:

> I suspect you run with LOCKDEP enabled (CONFIG_PROVE_LOCKING=y)
> and a very big NR_CPUS ?
> 
> LOCKDEP makes spinlock_t 16 times bigger :/
> 
> If so, please try the following fix.

CONFIG_LOCKDEP_SUPPORT=y

Now I'm using only 12 CPUs, per my other message where I disabled MAXSMP
and really set NR_CPUS, resulting in a successful boot.

It may be true that earlier it was architectures's max (8192).  Maybe
that was the real issue, then?

Best regards,

-- 
Ricardo Nabinger Sanchez

    Dedique-se a melhorar seus esforços.
    Todas as suas conquistas evolutivas não foram resultado dos
    deuses, das outras consciências, ou do acaso, mas unicamente
    da sua transpiração. ---Waldo Vieira, Léxico de Ortopensatas