zperf TX loopback performance regression

[krish2718]

Describe the bug

I am running Zperf loopback test (TX only: drop at loopback driver) https://github.com/zephyrproject-rtos/zephyr/blob/main/samples/net/zperf/overlay-loopback.conf#L6 and see a dip in performance on nRF5340 from 90-->78Mbps.

Triaged to e337b7b, building with CONFIG_TIMESLICE_SIZE=0 fixes the problem, i.e., gives 90M

Regression

• This is a regression.

Steps to reproduce

Steps to repro on nRF5340DK

1. Modify samples/net/zperf/overlay-loopback.conf as below

   # Enable for testing TX only 
   CONFIG_NET_LOOPBACK_SIMULATE_PACKET_DROP=y 
   CONFIG_NET_ZPERF_UDP_REPORT_RETANSMISSION_COUNT=0

2. Build using: west build -p -b nrf7002dk/nrf5340/cpuapp samples/net/zperf/ -d samples/net/zperf/build_53dk -- -DEXTRA_CONF_FILE="overlay-loopback.conf" -DCONFIG_PICOLIBC_USE_MODULE=y
3. west flash -d samples/net/zperf/build_53dk
4. Run zperf loopback test

    zperf udp download 5001
    zperf udp upload 127.0.0.1 5001 10 1K 300M

~78Mbps would be the result which is a regression from 90M, now build with CONFIG_TIMESLICE_SIZE=0 and you will see 90M.

Relevant log output

Impact

Functional Limitation – Some features not working as expected, but system usable.

Environment

Zephyr main e22ca6b1328.

Additional Context

In our regular resting on nRF7002DK too we had seen weird behaviour when running Zperf esp. async, the driver Q is getting full easily which wasn't the case earlier, this could be the issue, I will try with the revert and see if that restores old beheaviour.

[andyross]

So, the proximate cause here (i.e. why it bisected to that commit) is that the sample builds with CONFIG_TIMESLICING=y, when it doesn't need or want timeslicing. This used to be hidden by the fact that the default was "disabled", but the default is now "timeslicing works" and not "timeslicing doesn't work" (IMHO correctly). But enabling timeslicing by default is wrong, and presumbly being set somewhere in the board/soc layer? We should fix that as optional features shouldn't be defaults.

The deeper problem is the scale of the performance regression. We just shouldn't see a 13% performance loss from turning on 20-tick timeslice interrupts. My wild-ish guess is that somewhere in this sample or the network layer are 2+ spinning threads contending for the CPU. It used to be that the important one "won" by running first and was allowed to run to completion, but now it's being preempted by its slicing partners and things are slower.

Someone with more background in the network code should look at this first, I think. I'm like 80% sure this isn't a kernel bug per se, because we surely would have noticed.

[krish2718]

So, the proximate cause here (i.e. why it bisected to that commit) is that the sample builds with CONFIG_TIMESLICING=y, when it doesn't need or want timeslicing. This used to be hidden by the fact that the default was "disabled", but the default is now "timeslicing works" and not "timeslicing doesn't work" (IMHO correctly). But enabling timeslicing by default is wrong, and presumbly being set somewhere in the board/soc layer? We should fix that as optional features shouldn't be defaults.

Looking at https://github.com/zephyrproject-rtos/zephyr/blob/main/kernel/Kconfig#L662 it is enabled by default if SYS_CLOCK_EXISTS && (NUM_PREEMPT_PRIORITIES != 0) and SYS_CLOCK_EXISTS is enabled by default unconditionally and NUM_PREEMPT_PRIORITIES is set to 15 as the default for MULTITHREADING (which is also default enabled). So, TIMESLICING was always enabled for most (at least on nRF platforms).

My wild-ish guess is that somewhere in this sample or the network layer are 2+ spinning threads contending for the CPU. It used to be that the important one "won" by running first and was allowed to run to completion, but now it's being preempted by its slicing partners and things are slower.

As this is TX only you can even drop: zperf udp download 5001 and when you run zperf udp upload 127.0.0.1 5001 10 1K 300M shell thread is running, and as we enable CONFIG_NET_TC_TX_COUNT=1 the TC thread is also running, this is the contention that you are referring to. And I have tried with CONFIG_NET_TC_TX_COUNT=0 (this disables the second thread) and now I see the throughput has actually improved to 99.5M, so you were spot on.

Configuration	Throughput
default	78 Mbps
default + timeslice_size=0	90 Mbps
default + CONFIG_NET_TC_TX_COUNT=0	99.5 Mbps

note: For the 3rd case timeslice_size doesn't matter as there is only one active thread running.

But I do still see this as a regression as nothing has changed except for the timeslice size, WDYT?

+NW maintainers (@jukkar and @rlubos )

[andyross]

Hm... I swear there was discussion in that bug that we needed to swap the sense of CONFIG_TIMESLICING to prevent exactly this surprise (i.e. it used to default off even when support was compiled in, so is now being enabled for apps that didn't see it before). But the counter argument would be that doing setting CONFIG_TIMESLICING=n by default (IMHO the best choice in theory) would have the effect of turning it off for existing apps that need it, which is maybe a worse surprise.

I don't know that we can win here and I fear the resulting bikeshed if we try. But in theory this should have been noise, so we should at least start by fixing the spinning threads if that's possible.

[krish2718]

@henrikbrixandersen Shouldn't the area be kernel? Network stack is just using two threads as it always was, the change in kernel is the regression.

[henrikbrixandersen]

@henrikbrixandersen Shouldn't the area be kernel? Network stack is just using two threads as it always was, the change in kernel is the regression.

I may have misinterpreted the response from @andyross, but I understood that the cause was spinning threads in the zperf network implementation?

[krish2718]

Not really, IIUC, CONFIG_TIMESLICING=y was always there (9 years ago). Only the timeslize size modification affected the way any two threads would work, they just happened to be networking threads, but may be there are other scenarios out there?

[andyross]

There's a kernel argument here, but it's a bikeshed about "Should CONFIG_TIMESLICING" be =y or =n by default? It's traditionally been =y, but with a default timeslice value of zero ("disabled"). Now it defaults to "enabled", so apps are seeing different behavior. Is that a regression or a bug fix? :)

FWIW, my personal opinion is that what we should have done is set it =n by default, preserving behavior for apps that didn't use time slicing (the vast majority). But if we do it that way it will have the effect of turning it off even for apps that do use time slicing, so someone will hate it.

But really this isn't very interesting. Any affected app can recover the old behavior they expect with at most two kconfig lines. The performance impact is the interesting part, and that seems to be in network.

[krish2718]

Any affected app can recover the old behavior they expect with at most two kconfig lines.
The performance impact is the interesting part, and that seems to be in network.

Sure, if the impact is only for Zperf we can certainly do that (add Kconfig), but I was thinking it might be wider? Hence the discussion about default.