126 ms irqsoff Latency - Possibly due to commit 190cc82489f4 ("tcp: change source port randomizarion at connect() time")

126 ms irqsoff Latency - Possibly due to commit 190cc82489f4 ("tcp: change source port randomizarion at connect() time")

[Christophe Leroy]

Hi,

With recent kernels I have a huge irqsoff latency in my boards, shortly 
after startup, from the call to net_get_random_once() in 
__inet_hash_connect().

On a non instrumented kernel, IRQs are disabled during approximately 80 
milliseconds. With the traces in goes to 126 milliseconds.

Was apparently introduced by commit 190cc82489f4 ("tcp: change source 
port randomizarion at connect() time")

Trace below.

Would there be a way to perform the call to get_random_bytes() without 
disabling IRQ ?

Thanks
Christophe

# tracer: irqsoff
#
# irqsoff latency trace v1.1.5 on 6.0.0-rc5-s3k-dev-02351-gebc95f69a7d4
# --------------------------------------------------------------------
# latency: 126337 us, #8207/8207, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0)
#    -----------------
#    | task: CORSurv-352 (uid:0 nice:0 policy:0 rt_prio:0)
#    -----------------
#  => started at: _raw_spin_lock_irqsave
#  => ended at:   _raw_spin_unlock_irqrestore
#
#
#                    _------=> CPU#
#                   / _-----=> irqs-off/BH-disabled
#                  | / _----=> need-resched
#                  || / _---=> hardirq/softirq
#                  ||| / _--=> preempt-depth
#                  |||| / _-=> migrate-disable
#                  ||||| /     delay
#  cmd     pid     |||||| time  |   caller
#     \   /        ||||||  \    |    /
  CORSurv-352       0d....    4us : _raw_spin_lock_irqsave
  CORSurv-352       0d....   13us+: preempt_count_add 
<-_raw_spin_lock_irqsave
  CORSurv-352       0d..1.   25us+: do_raw_spin_lock 
<-_raw_spin_lock_irqsave
  CORSurv-352       0d..1.   36us : get_random_bytes <-__inet_hash_connect
  CORSurv-352       0d..1.   45us : _get_random_bytes.part.0 
<-__inet_hash_connect
  CORSurv-352       0d..1.   55us : crng_make_state 
<-_get_random_bytes.part.0
  CORSurv-352       0d..1.   65us+: ktime_get_seconds <-crng_make_state
  CORSurv-352       0d..1.   77us+: crng_fast_key_erasure <-crng_make_state
  CORSurv-352       0d..1.   89us+: chacha_block_generic 
<-crng_fast_key_erasure
  CORSurv-352       0d..1.  101us+: chacha_permute <-chacha_block_generic
  CORSurv-352       0d..1.  129us : chacha_block_generic 
<-_get_random_bytes.part.0
  CORSurv-352       0d..1.  139us+: chacha_permute <-chacha_block_generic
  CORSurv-352       0d..1.  160us : chacha_block_generic 
<-_get_random_bytes.part.0
  CORSurv-352       0d..1.  170us+: chacha_permute <-chacha_block_generic
  CORSurv-352       0d..1.  191us : chacha_block_generic 
<-_get_random_bytes.part.0
  CORSurv-352       0d..1.  200us+: chacha_permute <-chacha_block_generic
  CORSurv-352       0d..1.  221us : chacha_block_generic 
<-_get_random_bytes.part.0
  CORSurv-352       0d..1.  231us+: chacha_permute <-chacha_block_generic

	8182 x the above two line

  CORSurv-352       0d..1. 126275us : chacha_block_generic 
<-_get_random_bytes.part.0
  CORSurv-352       0d..1. 126285us+: chacha_permute <-chacha_block_generic
  CORSurv-352       0d..1. 126309us : _raw_spin_unlock_irqrestore 
<-__do_once_done
  CORSurv-352       0d..1. 126318us+: do_raw_spin_unlock 
<-_raw_spin_unlock_irqrestore
  CORSurv-352       0d..1. 126330us+: _raw_spin_unlock_irqrestore
  CORSurv-352       0d..1. 126346us+: trace_hardirqs_on 
<-_raw_spin_unlock_irqrestore
  CORSurv-352       0d..1. 126387us : <stack trace>
  => tcp_v4_connect
  => __inet_stream_connect
  => inet_stream_connect
  => __sys_connect
  => system_call_exception
  => ret_from_syscall

Re: 126 ms irqsoff Latency - Possibly due to commit 190cc82489f4 ("tcp: change source port randomizarion at connect() time")

[Eric Dumazet]

On Sat, Oct 1, 2022 at 10:16 AM Christophe Leroy
<christophe.leroy@csgroup.eu> wrote:
>
> Hi,
>
> With recent kernels I have a huge irqsoff latency in my boards, shortly
> after startup, from the call to net_get_random_once() in
> __inet_hash_connect().
>
> On a non instrumented kernel, IRQs are disabled during approximately 80
> milliseconds. With the traces in goes to 126 milliseconds.
>
> Was apparently introduced by commit 190cc82489f4 ("tcp: change source
> port randomizarion at connect() time")
>
> Trace below.
>
> Would there be a way to perform the call to get_random_bytes() without
> disabling IRQ ?

This looks a question for drivers/char/random.c maintainer, because we
do not block interrupts at this point in __inet_hash_connect()




>
> Thanks
> Christophe
>
> # tracer: irqsoff
> #
> # irqsoff latency trace v1.1.5 on 6.0.0-rc5-s3k-dev-02351-gebc95f69a7d4
> # --------------------------------------------------------------------
> # latency: 126337 us, #8207/8207, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0)
> #    -----------------
> #    | task: CORSurv-352 (uid:0 nice:0 policy:0 rt_prio:0)
> #    -----------------
> #  => started at: _raw_spin_lock_irqsave
> #  => ended at:   _raw_spin_unlock_irqrestore
> #
> #
> #                    _------=> CPU#
> #                   / _-----=> irqs-off/BH-disabled
> #                  | / _----=> need-resched
> #                  || / _---=> hardirq/softirq
> #                  ||| / _--=> preempt-depth
> #                  |||| / _-=> migrate-disable
> #                  ||||| /     delay
> #  cmd     pid     |||||| time  |   caller
> #     \   /        ||||||  \    |    /
>   CORSurv-352       0d....    4us : _raw_spin_lock_irqsave
>   CORSurv-352       0d....   13us+: preempt_count_add
> <-_raw_spin_lock_irqsave
>   CORSurv-352       0d..1.   25us+: do_raw_spin_lock
> <-_raw_spin_lock_irqsave
>   CORSurv-352       0d..1.   36us : get_random_bytes <-__inet_hash_connect
>   CORSurv-352       0d..1.   45us : _get_random_bytes.part.0
> <-__inet_hash_connect
>   CORSurv-352       0d..1.   55us : crng_make_state
> <-_get_random_bytes.part.0
>   CORSurv-352       0d..1.   65us+: ktime_get_seconds <-crng_make_state
>   CORSurv-352       0d..1.   77us+: crng_fast_key_erasure <-crng_make_state
>   CORSurv-352       0d..1.   89us+: chacha_block_generic
> <-crng_fast_key_erasure
>   CORSurv-352       0d..1.  101us+: chacha_permute <-chacha_block_generic
>   CORSurv-352       0d..1.  129us : chacha_block_generic
> <-_get_random_bytes.part.0
>   CORSurv-352       0d..1.  139us+: chacha_permute <-chacha_block_generic
>   CORSurv-352       0d..1.  160us : chacha_block_generic
> <-_get_random_bytes.part.0
>   CORSurv-352       0d..1.  170us+: chacha_permute <-chacha_block_generic
>   CORSurv-352       0d..1.  191us : chacha_block_generic
> <-_get_random_bytes.part.0
>   CORSurv-352       0d..1.  200us+: chacha_permute <-chacha_block_generic
>   CORSurv-352       0d..1.  221us : chacha_block_generic
> <-_get_random_bytes.part.0
>   CORSurv-352       0d..1.  231us+: chacha_permute <-chacha_block_generic
>
>         8182 x the above two line
>

It seems hard irqs are blocked for short periods, no worries here.

But perhaps your problem is a lack of cond_resched() in a long loop
(_get_random_bytes() I guess)

Problem is : I do not think _get_random_bytes() can always schedule,
we probably would need to add
extra parameters.

>   CORSurv-352       0d..1. 126275us : chacha_block_generic
> <-_get_random_bytes.part.0
>   CORSurv-352       0d..1. 126285us+: chacha_permute <-chacha_block_generic
>   CORSurv-352       0d..1. 126309us : _raw_spin_unlock_irqrestore
> <-__do_once_done
>   CORSurv-352       0d..1. 126318us+: do_raw_spin_unlock
> <-_raw_spin_unlock_irqrestore
>   CORSurv-352       0d..1. 126330us+: _raw_spin_unlock_irqrestore
>   CORSurv-352       0d..1. 126346us+: trace_hardirqs_on
> <-_raw_spin_unlock_irqrestore
>   CORSurv-352       0d..1. 126387us : <stack trace>
>   => tcp_v4_connect
>   => __inet_stream_connect
>   => inet_stream_connect
>   => __sys_connect
>   => system_call_exception
>   => ret_from_syscall

Re: 126 ms irqsoff Latency - Possibly due to commit 190cc82489f4 ("tcp: change source port randomizarion at connect() time")

[Eric Dumazet]

On Sat, Oct 1, 2022 at 10:43 AM Eric Dumazet <edumazet@google.com> wrote:
>
> On Sat, Oct 1, 2022 at 10:16 AM Christophe Leroy
> <christophe.leroy@csgroup.eu> wrote:
> >
> > Hi,
> >
> > With recent kernels I have a huge irqsoff latency in my boards, shortly
> > after startup, from the call to net_get_random_once() in
> > __inet_hash_connect().
> >
> > On a non instrumented kernel, IRQs are disabled during approximately 80
> > milliseconds. With the traces in goes to 126 milliseconds.
> >
> > Was apparently introduced by commit 190cc82489f4 ("tcp: change source
> > port randomizarion at connect() time")
> >
> > Trace below.
> >
> > Would there be a way to perform the call to get_random_bytes() without
> > disabling IRQ ?
>
> This looks a question for drivers/char/random.c maintainer, because we
> do not block interrupts at this point in __inet_hash_connect()

Oh well, this is probably coming from __do_once_start() / __do_once_done()

We need something better for process contexts...


>
>
>
>
> >
> > Thanks
> > Christophe
> >
> > # tracer: irqsoff
> > #
> > # irqsoff latency trace v1.1.5 on 6.0.0-rc5-s3k-dev-02351-gebc95f69a7d4
> > # --------------------------------------------------------------------
> > # latency: 126337 us, #8207/8207, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0)
> > #    -----------------
> > #    | task: CORSurv-352 (uid:0 nice:0 policy:0 rt_prio:0)
> > #    -----------------
> > #  => started at: _raw_spin_lock_irqsave
> > #  => ended at:   _raw_spin_unlock_irqrestore
> > #
> > #
> > #                    _------=> CPU#
> > #                   / _-----=> irqs-off/BH-disabled
> > #                  | / _----=> need-resched
> > #                  || / _---=> hardirq/softirq
> > #                  ||| / _--=> preempt-depth
> > #                  |||| / _-=> migrate-disable
> > #                  ||||| /     delay
> > #  cmd     pid     |||||| time  |   caller
> > #     \   /        ||||||  \    |    /
> >   CORSurv-352       0d....    4us : _raw_spin_lock_irqsave
> >   CORSurv-352       0d....   13us+: preempt_count_add
> > <-_raw_spin_lock_irqsave
> >   CORSurv-352       0d..1.   25us+: do_raw_spin_lock
> > <-_raw_spin_lock_irqsave
> >   CORSurv-352       0d..1.   36us : get_random_bytes <-__inet_hash_connect
> >   CORSurv-352       0d..1.   45us : _get_random_bytes.part.0
> > <-__inet_hash_connect
> >   CORSurv-352       0d..1.   55us : crng_make_state
> > <-_get_random_bytes.part.0
> >   CORSurv-352       0d..1.   65us+: ktime_get_seconds <-crng_make_state
> >   CORSurv-352       0d..1.   77us+: crng_fast_key_erasure <-crng_make_state
> >   CORSurv-352       0d..1.   89us+: chacha_block_generic
> > <-crng_fast_key_erasure
> >   CORSurv-352       0d..1.  101us+: chacha_permute <-chacha_block_generic
> >   CORSurv-352       0d..1.  129us : chacha_block_generic
> > <-_get_random_bytes.part.0
> >   CORSurv-352       0d..1.  139us+: chacha_permute <-chacha_block_generic
> >   CORSurv-352       0d..1.  160us : chacha_block_generic
> > <-_get_random_bytes.part.0
> >   CORSurv-352       0d..1.  170us+: chacha_permute <-chacha_block_generic
> >   CORSurv-352       0d..1.  191us : chacha_block_generic
> > <-_get_random_bytes.part.0
> >   CORSurv-352       0d..1.  200us+: chacha_permute <-chacha_block_generic
> >   CORSurv-352       0d..1.  221us : chacha_block_generic
> > <-_get_random_bytes.part.0
> >   CORSurv-352       0d..1.  231us+: chacha_permute <-chacha_block_generic
> >
> >         8182 x the above two line
> >
>
> It seems hard irqs are blocked for short periods, no worries here.
>
> But perhaps your problem is a lack of cond_resched() in a long loop
> (_get_random_bytes() I guess)
>
> Problem is : I do not think _get_random_bytes() can always schedule,
> we probably would need to add
> extra parameters.
>
> >   CORSurv-352       0d..1. 126275us : chacha_block_generic
> > <-_get_random_bytes.part.0
> >   CORSurv-352       0d..1. 126285us+: chacha_permute <-chacha_block_generic
> >   CORSurv-352       0d..1. 126309us : _raw_spin_unlock_irqrestore
> > <-__do_once_done
> >   CORSurv-352       0d..1. 126318us+: do_raw_spin_unlock
> > <-_raw_spin_unlock_irqrestore
> >   CORSurv-352       0d..1. 126330us+: _raw_spin_unlock_irqrestore
> >   CORSurv-352       0d..1. 126346us+: trace_hardirqs_on
> > <-_raw_spin_unlock_irqrestore
> >   CORSurv-352       0d..1. 126387us : <stack trace>
> >   => tcp_v4_connect
> >   => __inet_stream_connect
> >   => inet_stream_connect
> >   => __sys_connect
> >   => system_call_exception
> >   => ret_from_syscall

Re: 126 ms irqsoff Latency - Possibly due to commit 190cc82489f4 ("tcp: change source port randomizarion at connect() time")

[Jason A. Donenfeld]

(CC+Sebastian)

Hi Eric, Christophe,

I'm trying to understand the context of this and whether/why there's a
problem. Some overview on how get_random_bytes() works:

Most of the time, get_random_bytes() is completely lockless and operates
over per-CPU data structures. get_random_bytes() calls
_get_random_bytes(), which calls crng_make_state(), and then operates
over stack data to churn out some random bytes. crng_make_state() is
where all the meat happens.

In crng_make_state(), there are three unlikely conditionals where locks
are taken. The first is:

    if (!crng_ready()) {
        ... do some expensive things involving locks ...
	... but only during early boot before the rng is initialized ...
    }

The second one is:

    if (unlikely(time_is_before_jiffies(READ_ONCE(base_crng.birth) + crng_reseed_interval()))) {
        ... do something less expensive involving locks ...
	... which happens approximately once per minute ...
    }

The third one is:

    if (unlikely(crng->generation != READ_ONCE(base_crng.generation))) {
        ... do something even less expensive involving locks ...
	... which happens when after a different cpu hit the above ...
    }

So all three of these conditions are pretty darn unlikely, with the
exception of the first one that happens all the time during early boot
before the RNG is initialized, after which it is static-branched out and
never triggers again. So as far as /locks/ are concerned, things should
be good here.

However, in order to operate on per-cpu data, and therefore be lockless
most of the time, it does take a "local lock", which is basically just
disabling interrupts on non-RT to do a short operation:

    local_lock_irqsave(&crngs.lock, flags);
    crng = raw_cpu_ptr(&crngs);
    crng_fast_key_erasure(...);
    local_unlock_irqrestore(&crngs.lock, flags);

crng_fast_key_erasure(), in turn, computes a single block of chacha20,
which should be relatively fast. So the critical section is very short
there.

The reason that's local_lock_irqsave() rather than local_lock() (which
would only disable preemption, I believe), is because IRQ handlers are
supposed to be able to have access to random bytes too. It seems like it
wouldn't be a super nice thing to remove that capability.

It might be possible to double the amount of per-cpu data and have a
separate state for IRQ than for non-IRQ, but that seems kind of wasteful
and complex/hairy to implement.

So that leads me to wonder more about the context: why does this matter?
It looks like you're hitting this from a DO_ONCE() thing, which are
usually only hit, as the name says, once, and then incur the overhead of
firing off a worker to change the once-static-branch, which means
DO_ONCE()es aren't very fast anyway? Or does that not accurately reflect
what's happening?

I'll also CC Sebastian here, who worked with me on that local lock and
might have some insights on IRQ latency as well.

Regards,
Jason

Re: 126 ms irqsoff Latency - Possibly due to commit 190cc82489f4 ("tcp: change source port randomizarion at connect() time")

[Eric Dumazet]

On Sat, Oct 1, 2022 at 3:16 PM Jason A. Donenfeld <Jason@zx2c4.com> wrote:
>
> (CC+Sebastian)
>
> Hi Eric, Christophe,
>
> I'm trying to understand the context of this and whether/why there's a
> problem. Some overview on how get_random_bytes() works:
>
> Most of the time, get_random_bytes() is completely lockless and operates
> over per-CPU data structures. get_random_bytes() calls
> _get_random_bytes(), which calls crng_make_state(), and then operates
> over stack data to churn out some random bytes. crng_make_state() is
> where all the meat happens.
>
> In crng_make_state(), there are three unlikely conditionals where locks
> are taken. The first is:
>
>     if (!crng_ready()) {
>         ... do some expensive things involving locks ...
>         ... but only during early boot before the rng is initialized ...
>     }
>
> The second one is:
>
>     if (unlikely(time_is_before_jiffies(READ_ONCE(base_crng.birth) + crng_reseed_interval()))) {
>         ... do something less expensive involving locks ...
>         ... which happens approximately once per minute ...
>     }
>
> The third one is:
>
>     if (unlikely(crng->generation != READ_ONCE(base_crng.generation))) {
>         ... do something even less expensive involving locks ...
>         ... which happens when after a different cpu hit the above ...
>     }
>
> So all three of these conditions are pretty darn unlikely, with the
> exception of the first one that happens all the time during early boot
> before the RNG is initialized, after which it is static-branched out and
> never triggers again. So as far as /locks/ are concerned, things should
> be good here.
>
> However, in order to operate on per-cpu data, and therefore be lockless
> most of the time, it does take a "local lock", which is basically just
> disabling interrupts on non-RT to do a short operation:
>
>     local_lock_irqsave(&crngs.lock, flags);
>     crng = raw_cpu_ptr(&crngs);
>     crng_fast_key_erasure(...);
>     local_unlock_irqrestore(&crngs.lock, flags);
>
> crng_fast_key_erasure(), in turn, computes a single block of chacha20,
> which should be relatively fast. So the critical section is very short
> there.
>
> The reason that's local_lock_irqsave() rather than local_lock() (which
> would only disable preemption, I believe), is because IRQ handlers are
> supposed to be able to have access to random bytes too. It seems like it
> wouldn't be a super nice thing to remove that capability.
>
> It might be possible to double the amount of per-cpu data and have a
> separate state for IRQ than for non-IRQ, but that seems kind of wasteful
> and complex/hairy to implement.
>
> So that leads me to wonder more about the context: why does this matter?
> It looks like you're hitting this from a DO_ONCE() thing, which are
> usually only hit, as the name says, once, and then incur the overhead of
> firing off a worker to change the once-static-branch, which means
> DO_ONCE()es aren't very fast anyway? Or does that not accurately reflect
> what's happening?
>
> I'll also CC Sebastian here, who worked with me on that local lock and
> might have some insights on IRQ latency as well.

Sorry Jason, it seems I forgot to CC you on the tentative patch I sent
earlier today

https://patchwork.kernel.org/project/netdevbpf/patch/20221001205102.2319658-1-eric.dumazet@gmail.com/

Re: 126 ms irqsoff Latency - Possibly due to commit 190cc82489f4 ("tcp: change source port randomizarion at connect() time")

[Jason A. Donenfeld]

Hi Eric,

On Sun, Oct 2, 2022 at 12:31 AM Eric Dumazet <edumazet@google.com> wrote:
> Sorry Jason, it seems I forgot to CC you on the tentative patch I sent
> earlier today
>
> https://patchwork.kernel.org/project/netdevbpf/patch/20221001205102.2319658-1-eric.dumazet@gmail.com/

Oh, pfiew! I just came to basically the same conclusion as you were
typing that to me:
https://lore.kernel.org/netdev/YzjAfdip8giWBF4+@zx2c4.com/

Your patch seems like a good approach.

Jason

Re: 126 ms irqsoff Latency - Possibly due to commit 190cc82489f4 ("tcp: change source port randomizarion at connect() time")

[Jason A. Donenfeld]

Hi again,

Actually, ignore everything I said before. I looked more closely at the
trace, and this seems like a bogus report. Let me explain:

The part of the trace that concerns my last email is tiny:

  CORSurv-352       0d..1.   36us : get_random_bytes <-__inet_hash_connect
  CORSurv-352       0d..1.   45us : _get_random_bytes.part.0 <-__inet_hash_connect
  CORSurv-352       0d..1.   55us : crng_make_state <-_get_random_bytes.part.0
  CORSurv-352       0d..1.   65us+: ktime_get_seconds <-crng_make_state
  CORSurv-352       0d..1.   77us+: crng_fast_key_erasure <-crng_make_state
  CORSurv-352       0d..1.   89us+: chacha_block_generic <-crng_fast_key_erasure
  CORSurv-352       0d..1.  101us+: chacha_permute <-chacha_block_generic

After those lines, crng_make_state() returns back into
_get_random_bytes(), where _get_random_bytes() proceeds to call chacha20
totally unlocked, having released all interrupts:

  CORSurv-352       0d..1.  129us : chacha_block_generic <-_get_random_bytes.part.0
  CORSurv-352       0d..1.  139us+: chacha_permute <-chacha_block_generic
  ...
  CORSurv-352       0d..1. 126275us : chacha_block_generic <-_get_random_bytes.part.0
  CORSurv-352       0d..1. 126285us+: chacha_permute <-chacha_block_generic

I guess it's generating a lot of blocks, and this is a slow board?
Either way, no interrupts are held here, and no locks either.

But then let's zoom out to see if we can figure out what is disabling
IRQs. This time, pasting from the top and the bottom of the stack trace,
rather than from the middle:

  CORSurv-352       0d....    4us : _raw_spin_lock_irqsave
  ...
  CORSurv-352       0d..1. 126309us : _raw_spin_unlock_irqrestore <-__do_once_done
  CORSurv-352       0d..1. 126318us+: do_raw_spin_unlock <-_raw_spin_unlock_irqrestore
  CORSurv-352       0d..1. 126330us+: _raw_spin_unlock_irqrestore
  CORSurv-352       0d..1. 126346us+: trace_hardirqs_on <-_raw_spin_unlock_irqrestore

Oh, hello hello __do_once_done(). Let's have a look at you:

  bool __do_once_start(bool *done, unsigned long *flags)
      __acquires(once_lock)
  {
      spin_lock_irqsave(&once_lock, *flags);
      if (*done) {
          spin_unlock_irqrestore(&once_lock, *flags);
          /* Keep sparse happy by restoring an even lock count on
           * this lock. In case we return here, we don't call into
           * __do_once_done but return early in the DO_ONCE() macro.
           */
          __acquire(once_lock);
          return false;
      }
  
      return true;
  }
  EXPORT_SYMBOL(__do_once_start);
  
  void __do_once_done(bool *done, struct static_key_true *once_key,
              unsigned long *flags, struct module *mod)
      __releases(once_lock)
  {
      *done = true;
      spin_unlock_irqrestore(&once_lock, *flags);
      once_disable_jump(once_key, mod);
  }
  EXPORT_SYMBOL(__do_once_done);

Well then! It looks like DO_ONCE() takes an irqsave spinlock. So, as far
as get_random_bytes() is concerned, interrupts are not being held
abnormally long. This is something having to do with the code that's
calling into it. So... doesn't seem like an RNG issue?

Jason

Re: 126 ms irqsoff Latency - Possibly due to commit 190cc82489f4 ("tcp: change source port randomizarion at connect() time")

[Eric Dumazet]

On Sat, Oct 1, 2022 at 3:34 PM Jason A. Donenfeld <Jason@zx2c4.com> wrote:
>
> Hi again,
>
> Actually, ignore everything I said before. I looked more closely at the
> trace, and this seems like a bogus report. Let me explain:
>
> The part of the trace that concerns my last email is tiny:
>
>   CORSurv-352       0d..1.   36us : get_random_bytes <-__inet_hash_connect
>   CORSurv-352       0d..1.   45us : _get_random_bytes.part.0 <-__inet_hash_connect
>   CORSurv-352       0d..1.   55us : crng_make_state <-_get_random_bytes.part.0
>   CORSurv-352       0d..1.   65us+: ktime_get_seconds <-crng_make_state
>   CORSurv-352       0d..1.   77us+: crng_fast_key_erasure <-crng_make_state
>   CORSurv-352       0d..1.   89us+: chacha_block_generic <-crng_fast_key_erasure
>   CORSurv-352       0d..1.  101us+: chacha_permute <-chacha_block_generic
>
> After those lines, crng_make_state() returns back into
> _get_random_bytes(), where _get_random_bytes() proceeds to call chacha20
> totally unlocked, having released all interrupts:
>
>   CORSurv-352       0d..1.  129us : chacha_block_generic <-_get_random_bytes.part.0
>   CORSurv-352       0d..1.  139us+: chacha_permute <-chacha_block_generic
>   ...
>   CORSurv-352       0d..1. 126275us : chacha_block_generic <-_get_random_bytes.part.0
>   CORSurv-352       0d..1. 126285us+: chacha_permute <-chacha_block_generic
>
> I guess it's generating a lot of blocks, and this is a slow board?
> Either way, no interrupts are held here, and no locks either.
>
> But then let's zoom out to see if we can figure out what is disabling
> IRQs. This time, pasting from the top and the bottom of the stack trace,
> rather than from the middle:
>
>   CORSurv-352       0d....    4us : _raw_spin_lock_irqsave
>   ...
>   CORSurv-352       0d..1. 126309us : _raw_spin_unlock_irqrestore <-__do_once_done
>   CORSurv-352       0d..1. 126318us+: do_raw_spin_unlock <-_raw_spin_unlock_irqrestore
>   CORSurv-352       0d..1. 126330us+: _raw_spin_unlock_irqrestore
>   CORSurv-352       0d..1. 126346us+: trace_hardirqs_on <-_raw_spin_unlock_irqrestore
>
> Oh, hello hello __do_once_done(). Let's have a look at you:
>
>   bool __do_once_start(bool *done, unsigned long *flags)
>       __acquires(once_lock)
>   {
>       spin_lock_irqsave(&once_lock, *flags);
>       if (*done) {
>           spin_unlock_irqrestore(&once_lock, *flags);
>           /* Keep sparse happy by restoring an even lock count on
>            * this lock. In case we return here, we don't call into
>            * __do_once_done but return early in the DO_ONCE() macro.
>            */
>           __acquire(once_lock);
>           return false;
>       }
>
>       return true;
>   }
>   EXPORT_SYMBOL(__do_once_start);
>
>   void __do_once_done(bool *done, struct static_key_true *once_key,
>               unsigned long *flags, struct module *mod)
>       __releases(once_lock)
>   {
>       *done = true;
>       spin_unlock_irqrestore(&once_lock, *flags);
>       once_disable_jump(once_key, mod);
>   }
>   EXPORT_SYMBOL(__do_once_done);
>
> Well then! It looks like DO_ONCE() takes an irqsave spinlock. So, as far
> as get_random_bytes() is concerned, interrupts are not being held
> abnormally long. This is something having to do with the code that's
> calling into it. So... doesn't seem like an RNG issue?

I guess you did not read my prior email sent hours ago :)

https://lore.kernel.org/netdev/CANn89iLAEYBaoYajy0Y9UmGFff5GPxDUoG-ErVB2jDdRNQ5Tug@mail.gmail.com/T/#m43fa0bac40dfda59c2b72cb3e844b41f3cdb949d