Re: 10% regression in qperf tcp latency after introducing commit "4a61bf7f9b18 random: defer fast pool mixing to worker"

Re: 10% regression in qperf tcp latency after introducing commit "4a61bf7f9b18 random: defer fast pool mixing to worker"

[Jason A. Donenfeld]

Hi Sherry (and Sebastian and Netdev and Tejun and whomever),

I'm top-replying so that I can provide an overview of what's up to other
readers, and then I'll leave your email below for additional context.

random.c used to have a hard IRQ handler that did something like this:

    do_some_stuff()
    spin_lock()
    do_some_other_stuff()
    spin_lock()

That worked fine, but Sebastian pointed out that having spinlocks in a
hard IRQ handler was a big no-no for RT. Not wanting to make those into
raw spinlocks, he suggested we hoist things into a workqueue. So that's
what we did together, and now that function reads:

    do_some_stuff()
    queue_work_on(raw_smp_processor_id(), other_stuff_worker);

That seemed reasonable to me -- it's a pattern practiced a million times
all over the kernel -- and is currently how random.c's
add_interrupt_randomness() functions.

Sherry, however, has reported a ~10% performance regression using qperf
with TCP over some heavy duty infiniband cards. According to Sherry's
tests, removing the call to queue_work_on() makes the performance
regression go away.

That leads me to suspect that queue_work_on() might actually not be as
cheap as I assumed? If so, is that surprising to anybody else? And what
should we do about this?

Unfortunately, as you'll see from reading below, I'm hopeless in trying
to recreate Sherry's test rig, and even Sherry was unable to reproduce
it on different hardware. Nonetheless, a 10% regression on fancy 40gbps
hardware seems like something worthy of wider concern.

What are our options? Investigate queue_work_on() bottlenecks? Move back
to the original pattern, but use raw spinlocks? Some thing else?

Sherry -- are you able to do a bit of profiling to see which
instructions or which area of a function is the hottest or creating that
bottleneck? I think we probably need more information to do something
with this.

Also, because I still have no idea how I can reproduce this myself, you
might need to take the reigns with helping to develop and test a patch,
since I'm kind of stabbing in the dark here.

Anyway, because this might be rather involved, I figure it's best to
move this conversation on list in case other folks have insights.

Regards,
Jason

On Wed, Sep 21, 2022 at 06:09:27PM +0000, Sherry Yang wrote:
> > On Sep 20, 2022, at 7:44 AM, Jason A. Donenfeld <Jason@zx2c4.com> wrote:
> > 
> > Anyway, a few questions:
> > 1) Does the regression disappear if you change this line:
> > - queue_work_on(raw_smp_processor_id(), system_highpri_wq, &fast_pool->mix);
> > + schedule_work_on(raw_smp_processor_id(), &fast_pool->mix);
> 
> After applying this change, we still see performance regression there on linux-stable v5.15
> 
> > 
> > 2) Does the regression disappear if you remove this line:
> > - queue_work_on(raw_smp_processor_id(), system_highpri_wq, &fast_pool->mix);
> > + //queue_work_on(raw_smp_processor_id(), system_highpri_wq, &fast_pool->mix);
> 
> After applying this change, we see performance get recovered on linux-stable v5.15.
> 
> > 
> >> We could see performance regression there.
> > 
> > Can you give me some detailed instructions on how I can reproduce
> > this? Can it be reproduced inside of a single VM using network
> > namespaces, for example? Something like that would greatly help me
> > nail this down. For example, if you can give me a bash script that
> > does everything entirely on a single host?
> We are dong qperf tcp latency test there. All test results above are collected from X7 server with Mellanox Technologies 
> MT27500 Family [ConnectX-3] cards: 
> Infiniband device 'mlx4_0' port 1 status: 
> default gid: fe80:0000:0000:0000:0010:e000:0178:9eb1 
> base lid: 0x6 
> sm lid: 0x1 
> state: 4: ACTIVE 
> phys state: 5: LinkUp 
> rate: 40 Gb/sec (4X QDR) 
> link_layer: InfiniBand 
> 
> Cards are configured with IP addresses on private subnet for IPoIB 
> performance testing. 
> Regression identified in this bug is in TCP latency in this stack as reported 
> by qperf tcp_lat metric: 
> 
> We have one system listen as a qperf server:
> [root@yourQperfServer ~]# qperf
> 
> Have the other system connect to qperf server as a client (in this case, it’s X7 server with Mellanox card):
> [root@yourQperfClient ~]# numactl -m0 -N0 qperf 20.20.20.101 -v -uu -ub --time 60 --wait_server 20 -oo msg_size:4K:1024K:*2 tcp_lat
> 
> However, our test team ran other experiments yesterday.
> * Ran benchmark on X5-2 system over ixgbe interface 
> * Ran 8 processes of the benchmark on the original system over the Mellanox card 
> Both these experiments failed to reproduce the regression. This highlights that the regression is not seen over ethernet network devices 
> and is only seen when running a single instance of the qperf benchmark.

Re: 10% regression in qperf tcp latency after introducing commit "4a61bf7f9b18 random: defer fast pool mixing to worker"

[Jason A. Donenfeld]

Hey again Sherry,

On Thu, Sep 22, 2022 at 12:32:49AM +0200, Jason A. Donenfeld wrote:
> That leads me to suspect that queue_work_on() might actually not be as
> cheap as I assumed? If so, is that surprising to anybody else? And what
> should we do about this?

Sultan (CC'd) suggested I look at the much less expensive softirq
tasklet for this, which matches the use case pretty much entirely as
well. Can you try out this patch below and see if it resolves the
performance regression?

Thanks,
Jason

diff --git a/drivers/char/random.c b/drivers/char/random.c
index 520a385c7dab..ad17b36cf977 100644
--- a/drivers/char/random.c
+++ b/drivers/char/random.c
@@ -918,13 +918,16 @@ EXPORT_SYMBOL_GPL(unregister_random_vmfork_notifier);
 #endif

 struct fast_pool {
-	struct work_struct mix;
+	struct tasklet_struct mix;
 	unsigned long pool[4];
 	unsigned long last;
 	unsigned int count;
 };

+static void mix_interrupt_randomness(struct tasklet_struct *work);
+
 static DEFINE_PER_CPU(struct fast_pool, irq_randomness) = {
+	.mix = { .use_callback = true, .callback = mix_interrupt_randomness },
 #ifdef CONFIG_64BIT
 #define FASTMIX_PERM SIPHASH_PERMUTATION
 	.pool = { SIPHASH_CONST_0, SIPHASH_CONST_1, SIPHASH_CONST_2, SIPHASH_CONST_3 }
@@ -973,7 +976,7 @@ int __cold random_online_cpu(unsigned int cpu)
 }
 #endif

-static void mix_interrupt_randomness(struct work_struct *work)
+static void mix_interrupt_randomness(struct tasklet_struct *work)
 {
 	struct fast_pool *fast_pool = container_of(work, struct fast_pool, mix);
 	/*
@@ -1027,10 +1030,8 @@ void add_interrupt_randomness(int irq)
 	if (new_count < 1024 && !time_is_before_jiffies(fast_pool->last + HZ))
 		return;

-	if (unlikely(!fast_pool->mix.func))
-		INIT_WORK(&fast_pool->mix, mix_interrupt_randomness);
 	fast_pool->count |= MIX_INFLIGHT;
-	queue_work_on(raw_smp_processor_id(), system_highpri_wq, &fast_pool->mix);
+	tasklet_hi_schedule(&fast_pool->mix);
 }
 EXPORT_SYMBOL_GPL(add_interrupt_randomness);

Re: 10% regression in qperf tcp latency after introducing commit "4a61bf7f9b18 random: defer fast pool mixing to worker"

[Tejun Heo]

Hello,

On Thu, Sep 22, 2022 at 12:32:49AM +0200, Jason A. Donenfeld wrote:
> What are our options? Investigate queue_work_on() bottlenecks? Move back
> to the original pattern, but use raw spinlocks? Some thing else?

I doubt it's queue_work_on() itself if it's called at very high frequency as
the duplicate calls would just fail to claim the PENDING bit and return but
if it's being called at a high frequency, it'd be waking up a kthread over
and over again, which can get pretty expensive. Maybe that ends competing
with softirqd which is handling net rx or sth?

So, yeah, I'd try something which doesn't always involve scheduling and a
context switch whether that's softirq, tasklet, or irq work. I probably am
mistaken but I thought RT kernel pushes irq handling to threads so that
these things can be handled sanely. Is this some special case?

Thanks.

-- 
tejun

Re: 10% regression in qperf tcp latency after introducing commit "4a61bf7f9b18 random: defer fast pool mixing to worker"

[Jason A. Donenfeld]

Hi Tejun,

On Wed, Sep 21, 2022 at 01:54:43PM -1000, Tejun Heo wrote:
> Hello,
> 
> On Thu, Sep 22, 2022 at 12:32:49AM +0200, Jason A. Donenfeld wrote:
> > What are our options? Investigate queue_work_on() bottlenecks? Move back
> > to the original pattern, but use raw spinlocks? Some thing else?
> 
> I doubt it's queue_work_on() itself if it's called at very high frequency as
> the duplicate calls would just fail to claim the PENDING bit and return but
> if it's being called at a high frequency, it'd be waking up a kthread over
> and over again, which can get pretty expensive. Maybe that ends competing
> with softirqd which is handling net rx or sth?

Huh, yea, interesting theory. Orrr, the one time that it _does_ pass the
test_and_set_bit check, the extra overhead here is enough to screw up
the latency? Both theories sound at least plausible.

> So, yeah, I'd try something which doesn't always involve scheduling and a
> context switch whether that's softirq, tasklet, or irq work.

Alright, I'll do that. I posted a diff for Sherry to try, and I'll make
that into a real patch and wait for her test.

> I probably am
> mistaken but I thought RT kernel pushes irq handling to threads so that
> these things can be handled sanely. Is this some special case?

It does mostly. But there's still a hard IRQ handler, somewhere, because
IRQs gotta IRQ, and the RNG benefits from getting a timestamp exactly
when that happens. So here we are.

Jason

Re: 10% regression in qperf tcp latency after introducing commit "4a61bf7f9b18 random: defer fast pool mixing to worker"

[Sebastian Siewior]

On 2022-09-21 13:54:43 [-1000], Tejun Heo wrote:
> Hello,
Hi,

> On Thu, Sep 22, 2022 at 12:32:49AM +0200, Jason A. Donenfeld wrote:
> > What are our options? Investigate queue_work_on() bottlenecks? Move back
> > to the original pattern, but use raw spinlocks? Some thing else?
> 
> I doubt it's queue_work_on() itself if it's called at very high frequency as
> the duplicate calls would just fail to claim the PENDING bit and return but
> if it's being called at a high frequency, it'd be waking up a kthread over
> and over again, which can get pretty expensive. Maybe that ends competing
> with softirqd which is handling net rx or sth?

There is this (simplified):
|         if (new_count & MIX_INFLIGHT)
|                 return;
| 
|         if (new_count < 1024 && !time_is_before_jiffies(fast_pool->last + HZ))
|                 return;
| 
|         fast_pool->count |= MIX_INFLIGHT;
|         queue_work_on(raw_smp_processor_id(), system_highpri_wq, &fast_pool->mix);

at least 1k interrupts are needed and a second must pass before a worker
will be scheduled. Oh wait. We need only one of both. So how many
interrupts do we get per second?
Is the regression coming from more than 1k interrupts in less then a
second or a context switch each second? Because if it is a context
switch every second then I am surprised to see a 10% performance drop in
this case since should happen for other reasons, too unless the CPU is
isolated.

[ There isn't a massive claims of the PENDING bit or wakeups because
fast_pool is per-CPU and due to the MIX_INFLIGHT bit. ]

> So, yeah, I'd try something which doesn't always involve scheduling and a
> context switch whether that's softirq, tasklet, or irq work. I probably am
> mistaken but I thought RT kernel pushes irq handling to threads so that
> these things can be handled sanely. Is this some special case?

As Jason explained this part is invoked in the non-threaded part.

> Thanks.

Sebastian