* Performance regression between 4.13 and 4.14
@ 2018-05-08 16:44 Ben Greear
2018-05-08 17:10 ` Eric Dumazet
0 siblings, 1 reply; 6+ messages in thread
From: Ben Greear @ 2018-05-08 16:44 UTC (permalink / raw)
To: netdev
Hello,
I am trying to track down a performance regression that appears to be between 4.13
and 4.14.
I first saw the problem with a hacked version of pktgen on some ixgbe NICs. 4.13 can do
right at 10G bi-directional on two ports, and 4.14 and later can do only about 6Gbps.
I also tried with user-space UDP traffic on a stock kernel, and I can get about 3.2Gbps combined tx+rx
on 4.14 and about 4.4Gbps on 4.13.
Attempting to bisect seems to be triggering a weirdness in git, and also lots of commits
crash or do not bring up networking, which makes the bisect difficult.
Looking at perf top, it would appear that some lock is probably to blame.
Any ideas what might have been introduced during this interval that
would cause this?
Anyone else seen similar?
I'm going to attempt some more manual steps to try to find the commit that
introduces this...
Thanks,
Ben
--
Ben Greear <greearb@candelatech.com>
Candela Technologies Inc http://www.candelatech.com
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Performance regression between 4.13 and 4.14
2018-05-08 16:44 Performance regression between 4.13 and 4.14 Ben Greear
@ 2018-05-08 17:10 ` Eric Dumazet
2018-05-09 18:43 ` Ben Greear
0 siblings, 1 reply; 6+ messages in thread
From: Eric Dumazet @ 2018-05-08 17:10 UTC (permalink / raw)
To: Ben Greear, netdev
On 05/08/2018 09:44 AM, Ben Greear wrote:
> Hello,
>
> I am trying to track down a performance regression that appears to be between 4.13
> and 4.14.
>
> I first saw the problem with a hacked version of pktgen on some ixgbe NICs. 4.13 can do
> right at 10G bi-directional on two ports, and 4.14 and later can do only about 6Gbps.
>
> I also tried with user-space UDP traffic on a stock kernel, and I can get about 3.2Gbps combined tx+rx
> on 4.14 and about 4.4Gbps on 4.13.
>
> Attempting to bisect seems to be triggering a weirdness in git, and also lots of commits
> crash or do not bring up networking, which makes the bisect difficult.
>
> Looking at perf top, it would appear that some lock is probably to blame.
perf record -a -g -e cycles:pp sleep 5
perf report
Then you'll be able to tell us which lock (or call graph) is killing your perf.
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Performance regression between 4.13 and 4.14
2018-05-08 17:10 ` Eric Dumazet
@ 2018-05-09 18:43 ` Ben Greear
2018-05-09 18:48 ` Eric Dumazet
0 siblings, 1 reply; 6+ messages in thread
From: Ben Greear @ 2018-05-09 18:43 UTC (permalink / raw)
To: Eric Dumazet, netdev
On 05/08/2018 10:10 AM, Eric Dumazet wrote:
>
>
> On 05/08/2018 09:44 AM, Ben Greear wrote:
>> Hello,
>>
>> I am trying to track down a performance regression that appears to be between 4.13
>> and 4.14.
>>
>> I first saw the problem with a hacked version of pktgen on some ixgbe NICs. 4.13 can do
>> right at 10G bi-directional on two ports, and 4.14 and later can do only about 6Gbps.
>>
>> I also tried with user-space UDP traffic on a stock kernel, and I can get about 3.2Gbps combined tx+rx
>> on 4.14 and about 4.4Gbps on 4.13.
>>
>> Attempting to bisect seems to be triggering a weirdness in git, and also lots of commits
>> crash or do not bring up networking, which makes the bisect difficult.
>>
>> Looking at perf top, it would appear that some lock is probably to blame.
>
>
> perf record -a -g -e cycles:pp sleep 5
> perf report
>
> Then you'll be able to tell us which lock (or call graph) is killing your perf.
>
I seem to be chasing multiple issues. For 4.13, at least part of my problem was that LOCKDEP was enabled,
during my bisect, though it does NOT appear enabled in 4.16. I think maybe CONFIG_LOCKDEP moved to CONFIG_PROVE_LOCKING
in 4.16, or something like that? My 4.16 .config does have CONFIG_LOCKDEP_SUPPORT enabled, and I see no option to disable it:
[greearb@ben-dt3 linux-4.16.x64]$ grep LOCKDEP .config
CONFIG_LOCKDEP_SUPPORT=y
For 4.16, I am disabling RETRAMPOLINE...are there any other such things I need
to disable to keep from getting a performance hit from the spectre-related bug
fixes? At this point, I do not care about the security implications.
greearb@ben-dt3 linux-4.16.x64]$ grep RETPO .config
# CONFIG_RETPOLINE is not set
Thanks,
Ben
--
Ben Greear <greearb@candelatech.com>
Candela Technologies Inc http://www.candelatech.com
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Performance regression between 4.13 and 4.14
2018-05-09 18:43 ` Ben Greear
@ 2018-05-09 18:48 ` Eric Dumazet
2018-05-09 19:02 ` Ben Greear
0 siblings, 1 reply; 6+ messages in thread
From: Eric Dumazet @ 2018-05-09 18:48 UTC (permalink / raw)
To: Ben Greear, Eric Dumazet, netdev
On 05/09/2018 11:43 AM, Ben Greear wrote:
> On 05/08/2018 10:10 AM, Eric Dumazet wrote:
>>
>>
>> On 05/08/2018 09:44 AM, Ben Greear wrote:
>>> Hello,
>>>
>>> I am trying to track down a performance regression that appears to be between 4.13
>>> and 4.14.
>>>
>>> I first saw the problem with a hacked version of pktgen on some ixgbe NICs. 4.13 can do
>>> right at 10G bi-directional on two ports, and 4.14 and later can do only about 6Gbps.
>>>
>>> I also tried with user-space UDP traffic on a stock kernel, and I can get about 3.2Gbps combined tx+rx
>>> on 4.14 and about 4.4Gbps on 4.13.
>>>
>>> Attempting to bisect seems to be triggering a weirdness in git, and also lots of commits
>>> crash or do not bring up networking, which makes the bisect difficult.
>>>
>>> Looking at perf top, it would appear that some lock is probably to blame.
>>
>>
>> perf record -a -g -e cycles:pp sleep 5
>> perf report
>>
>> Then you'll be able to tell us which lock (or call graph) is killing your perf.
>>
>
> I seem to be chasing multiple issues. For 4.13, at least part of my problem was that LOCKDEP was enabled,
> during my bisect, though it does NOT appear enabled in 4.16. I think maybe CONFIG_LOCKDEP moved to CONFIG_PROVE_LOCKING
> in 4.16, or something like that? My 4.16 .config does have CONFIG_LOCKDEP_SUPPORT enabled, and I see no option to disable it:
>
> [greearb@ben-dt3 linux-4.16.x64]$ grep LOCKDEP .config
> CONFIG_LOCKDEP_SUPPORT=y
>
>
> For 4.16, I am disabling RETRAMPOLINE...are there any other such things I need
> to disable to keep from getting a performance hit from the spectre-related bug
> fixes? At this point, I do not care about the security implications.
>
> greearb@ben-dt3 linux-4.16.x64]$ grep RETPO .config
> # CONFIG_RETPOLINE is not set
>
>
> Thanks,
> Ben
>
No idea really, you mention a 4.13 -> 4.14 regression and jump then to 4.16 :/
Before doing a (painful) dissection, the perf output would immediately tell you if
something is really wrong on your .config.
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Performance regression between 4.13 and 4.14
2018-05-09 18:48 ` Eric Dumazet
@ 2018-05-09 19:02 ` Ben Greear
2018-05-09 20:55 ` Ben Greear
0 siblings, 1 reply; 6+ messages in thread
From: Ben Greear @ 2018-05-09 19:02 UTC (permalink / raw)
To: Eric Dumazet, netdev
On 05/09/2018 11:48 AM, Eric Dumazet wrote:
>
>
> On 05/09/2018 11:43 AM, Ben Greear wrote:
>> On 05/08/2018 10:10 AM, Eric Dumazet wrote:
>>>
>>>
>>> On 05/08/2018 09:44 AM, Ben Greear wrote:
>>>> Hello,
>>>>
>>>> I am trying to track down a performance regression that appears to be between 4.13
>>>> and 4.14.
>>>>
>>>> I first saw the problem with a hacked version of pktgen on some ixgbe NICs. 4.13 can do
>>>> right at 10G bi-directional on two ports, and 4.14 and later can do only about 6Gbps.
>>>>
>>>> I also tried with user-space UDP traffic on a stock kernel, and I can get about 3.2Gbps combined tx+rx
>>>> on 4.14 and about 4.4Gbps on 4.13.
>>>>
>>>> Attempting to bisect seems to be triggering a weirdness in git, and also lots of commits
>>>> crash or do not bring up networking, which makes the bisect difficult.
>>>>
>>>> Looking at perf top, it would appear that some lock is probably to blame.
>>>
>>>
>>> perf record -a -g -e cycles:pp sleep 5
>>> perf report
>>>
>>> Then you'll be able to tell us which lock (or call graph) is killing your perf.
>>>
>>
>> I seem to be chasing multiple issues. For 4.13, at least part of my problem was that LOCKDEP was enabled,
>> during my bisect, though it does NOT appear enabled in 4.16. I think maybe CONFIG_LOCKDEP moved to CONFIG_PROVE_LOCKING
>> in 4.16, or something like that? My 4.16 .config does have CONFIG_LOCKDEP_SUPPORT enabled, and I see no option to disable it:
>>
>> [greearb@ben-dt3 linux-4.16.x64]$ grep LOCKDEP .config
>> CONFIG_LOCKDEP_SUPPORT=y
>>
>>
>> For 4.16, I am disabling RETRAMPOLINE...are there any other such things I need
>> to disable to keep from getting a performance hit from the spectre-related bug
>> fixes? At this point, I do not care about the security implications.
>>
>> greearb@ben-dt3 linux-4.16.x64]$ grep RETPO .config
>> # CONFIG_RETPOLINE is not set
>>
>>
>> Thanks,
>> Ben
>>
>
> No idea really, you mention a 4.13 -> 4.14 regression and jump then to 4.16 :/
I initially saw the problem in 4.16, then bisected, and 4.14 still showed the
issue.
4.13 works, but only when I use a .config I originally built for 4.13, not the 4.16 .config
that I ended up using with the bisect (make oldconfig, accept all defaults). I originally
configured 4.16 with a .config that had lockdep enabled, then manually tried to disable it
through 'make xconfig'. I think that must leave "CONFIG_LOCKDEP=y" in the .config, which
screws up older builds during bisect, perhaps?
> Before doing a (painful) dissection, the perf output would immediately tell you if
> something is really wrong on your .config.
I didn't realize lockdep might be an issue at the time, but here is a 'bad' run from
a 4.13+ (plus pktgen hacks). I guess lockdep is why this runs slowly, but I see no obvious
proof of that in the output:
4.13+, patched pktgen, 6Gbps throughput, on commit 906dde0f355bd97c080c215811ae7db1137c4af8
Samples: 26K of event 'cycles:pp', Event count (approx.): 20119166736
Children Self Command Shared Object Symbol
+ 87.97% 0.00% kpktgend_1 [kernel.kallsyms] [k] ret_from_fork
+ 87.97% 0.00% kpktgend_1 [kernel.kallsyms] [k] kthread
+ 86.89% 5.42% kpktgend_1 [kernel.kallsyms] [k] pktgen_thread_worker
+ 33.75% 0.18% kpktgend_1 [kernel.kallsyms] [k] getnstimeofday64
+ 32.77% 4.47% kpktgend_1 [kernel.kallsyms] [k] __getnstimeofday64
+ 24.60% 10.91% kpktgend_1 [kernel.kallsyms] [k] lock_acquire
+ 23.59% 0.03% kpktgend_1 [kernel.kallsyms] [k] __do_softirq
+ 23.55% 0.07% kpktgend_1 [kernel.kallsyms] [k] net_rx_action
+ 22.29% 0.47% kpktgend_1 [kernel.kallsyms] [k] getRelativeCurNs
+ 21.33% 1.71% kpktgend_1 [kernel.kallsyms] [k] ixgbe_poll
+ 15.79% 0.02% kpktgend_1 [kernel.kallsyms] [k] ret_from_intr
+ 15.78% 0.01% kpktgend_1 [kernel.kallsyms] [k] do_IRQ
+ 15.34% 0.01% kpktgend_1 [kernel.kallsyms] [k] irq_exit
+ 13.95% 10.00% kpktgend_1 [kernel.kallsyms] [k] ip_send_check
+ 13.80% 13.80% kpktgend_1 [kernel.kallsyms] [k] __lock_acquire.isra.31
+ 12.98% 0.53% kpktgend_1 [kernel.kallsyms] [k] pktgen_finalize_skb
+ 12.31% 0.20% kpktgend_1 [kernel.kallsyms] [k] timestamp_skb.isra.24
+ 11.68% 0.13% kpktgend_1 [kernel.kallsyms] [k] napi_gro_receive
+ 11.36% 0.25% kpktgend_1 [kernel.kallsyms] [k] netif_receive_skb_internal
+ 10.93% 0.00% swapper [kernel.kallsyms] [k] verify_cpu
+ 10.93% 0.00% swapper [kernel.kallsyms] [k] cpu_startup_entry
+ 10.92% 0.02% swapper [kernel.kallsyms] [k] do_idle
+ 10.71% 0.00% swapper [kernel.kallsyms] [k] cpuidle_enter
+ 10.71% 0.00% swapper [kernel.kallsyms] [k] call_cpuidle
+ 10.66% 0.06% swapper [kernel.kallsyms] [k] cpuidle_enter_state
+ 9.78% 0.00% swapper [kernel.kallsyms] [k] x86_64_start_kernel
+ 9.78% 0.00% swapper [kernel.kallsyms] [k] x86_64_start_reservations
+ 9.78% 0.00% swapper [kernel.kallsyms] [k] start_kernel
+ 9.78% 0.00% swapper [kernel.kallsyms] [k] rest_init
+ 9.25% 0.00% swapper [kernel.kallsyms] [k] ret_from_intr
+ 9.25% 0.00% swapper [kernel.kallsyms] [k] do_IRQ
+ 9.24% 0.30% kpktgend_1 [kernel.kallsyms] [k] pktgen_alloc_skb
+ 9.14% 0.00% swapper [kernel.kallsyms] [k] irq_exit
+ 8.89% 0.00% swapper [kernel.kallsyms] [k] __do_softirq
+ 8.82% 0.01% swapper [kernel.kallsyms] [k] net_rx_action
+ 8.80% 0.47% kpktgend_1 [kernel.kallsyms] [k] __local_bh_enable_ip
+ 8.67% 6.87% kpktgend_1 [kernel.kallsyms] [k] lock_release
+ 8.57% 1.10% kpktgend_1 [kernel.kallsyms] [k] __netdev_alloc_skb
+ 8.28% 0.00% kpktgend_1 [kernel.kallsyms] [k] do_softirq.part.17
+ 8.28% 0.00% kpktgend_1 [kernel.kallsyms] [k] do_softirq_own_stack
+ 8.01% 0.74% swapper [kernel.kallsyms] [k] ixgbe_poll
+ 6.85% 2.28% kpktgend_1 [kernel.kallsyms] [k] __build_skb
+ 4.89% 0.07% kpktgend_1 [kernel.kallsyms] [k] __netif_receive_skb
+ 4.87% 0.75% kpktgend_1 [kernel.kallsyms] [k] __netif_receive_skb_core
+ 4.66% 0.16% kpktgend_1 [kernel.kallsyms] [k] _raw_spin_lock
+ 4.37% 0.06% swapper [kernel.kallsyms] [k] napi_gro_receive
+ 4.23% 0.10% swapper [kernel.kallsyms] [k] netif_receive_skb_internal
Here is a 'bad' run of 4.16.0 + my full out-of-tree patches, including my normal pktgen changes
(pktgen code should be nearly identical between the run above and the run here)
Samples: 26K of event 'cycles:pp', Event count (approx.): 19888249841
Children Self Command Shared Object Symbol
+ 74.24% 5.38% kpktgend_1 [kernel.kallsyms] [k] pktgen_thread_worker
+ 73.89% 0.00% kpktgend_1 [kernel.kallsyms] [k] ret_from_fork
+ 73.89% 0.00% kpktgend_1 [kernel.kallsyms] [k] kthread
+ 27.31% 0.25% kpktgend_1 [kernel.kallsyms] [k] getnstimeofday64
+ 26.15% 4.24% kpktgend_1 [kernel.kallsyms] [k] __getnstimeofday64
+ 22.64% 0.02% kpktgend_1 [kernel.kallsyms] [k] __softirqentry_text_s
+ 22.62% 0.06% kpktgend_1 [kernel.kallsyms] [k] net_rx_action
+ 22.59% 2.04% kpktgend_1 [kernel.kallsyms] [k] ixgbe_poll
+ 21.49% 7.92% kpktgend_1 [kernel.kallsyms] [k] lock_acquire
+ 17.78% 17.78% kpktgend_1 [kernel.kallsyms] [k] __lock_acquire.isra.3
+ 15.95% 0.39% kpktgend_1 [kernel.kallsyms] [k] getRelativeCurNs
+ 14.49% 0.02% kpktgend_1 [kernel.kallsyms] [k] ret_from_intr
+ 14.48% 0.00% kpktgend_1 [kernel.kallsyms] [k] do_IRQ
+ 14.35% 0.01% kpktgend_1 [kernel.kallsyms] [k] irq_exit
+ 13.46% 9.90% kpktgend_1 [kernel.kallsyms] [k] ip_send_check
+ 11.36% 0.18% kpktgend_1 [kernel.kallsyms] [k] napi_gro_receive
+ 11.25% 0.17% kpktgend_1 [kernel.kallsyms] [k] netif_receive_skb_int
+ 10.37% 0.16% kpktgend_1 [kernel.kallsyms] [k] timestamp_skb.isra.25
+ 8.85% 0.45% kpktgend_1 [kernel.kallsyms] [k] __local_bh_enable_ip
+ 8.61% 0.02% swapper [kernel.kallsyms] [k] do_idle
+ 8.60% 0.00% swapper [kernel.kallsyms] [k] secondary_startup_64
+ 8.60% 0.00% swapper [kernel.kallsyms] [k] cpu_startup_entry
+ 8.37% 0.05% swapper [kernel.kallsyms] [k] cpuidle_enter_state
+ 8.35% 7.57% kpktgend_1 [kernel.kallsyms] [k] lock_release
+ 8.32% 0.00% kpktgend_1 [kernel.kallsyms] [k] do_softirq.part.16
+ 8.31% 0.00% kpktgend_1 [kernel.kallsyms] [k] do_softirq_own_stack
+ 7.16% 0.36% kpktgend_1 [kernel.kallsyms] [k] pktgen_alloc_skb
+ 7.09% 1.14% kpktgend_1 [kernel.kallsyms] [k] __netdev_alloc_skb
+ 6.87% 0.00% swapper [kernel.kallsyms] [k] start_kernel
+ 6.55% 0.00% swapper [kernel.kallsyms] [k] ret_from_intr
+ 6.55% 0.01% swapper [kernel.kallsyms] [k] do_IRQ
+ 6.51% 0.01% swapper [kernel.kallsyms] [k] irq_exit
+ 6.34% 0.02% swapper [kernel.kallsyms] [k] __softirqentry_text_s
+ 6.25% 0.01% swapper [kernel.kallsyms] [k] net_rx_action
+ 6.06% 0.45% swapper [kernel.kallsyms] [k] ixgbe_poll
+ 5.35% 2.11% kpktgend_1 [kernel.kallsyms] [k] __build_skb
I tried testing with stock kernels and UDP user-space traffic, but results varied widely
from run to run, so it was useless for bisecting.
I have irqbalance disabled on this system in order to pin pktgen process and ixgbe IRQs
to be efficient, so maybe that is why user-space UDP traffic works so unreliably. My hacked pktgen
reliably shows good on my good 4.13 kernel and reliably bad on higher kernels I have compiled
so far, so I decided it was the only useful way to bisect this problem.
I will now try 4.14 and higher again with lockdep definitely disabled.
Thanks,
Ben
--
Ben Greear <greearb@candelatech.com>
Candela Technologies Inc http://www.candelatech.com
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Performance regression between 4.13 and 4.14
2018-05-09 19:02 ` Ben Greear
@ 2018-05-09 20:55 ` Ben Greear
0 siblings, 0 replies; 6+ messages in thread
From: Ben Greear @ 2018-05-09 20:55 UTC (permalink / raw)
To: Eric Dumazet, netdev
On 05/09/2018 12:02 PM, Ben Greear wrote:
> On 05/09/2018 11:48 AM, Eric Dumazet wrote:
>>
>>
>> On 05/09/2018 11:43 AM, Ben Greear wrote:
>>> On 05/08/2018 10:10 AM, Eric Dumazet wrote:
>>>>
>>>>
>>>> On 05/08/2018 09:44 AM, Ben Greear wrote:
>>>>> Hello,
>>>>>
>>>>> I am trying to track down a performance regression that appears to be between 4.13
>>>>> and 4.14.
>>>>>
>>>>> I first saw the problem with a hacked version of pktgen on some ixgbe NICs. 4.13 can do
>>>>> right at 10G bi-directional on two ports, and 4.14 and later can do only about 6Gbps.
>>>>>
>>>>> I also tried with user-space UDP traffic on a stock kernel, and I can get about 3.2Gbps combined tx+rx
>>>>> on 4.14 and about 4.4Gbps on 4.13.
>>>>>
>>>>> Attempting to bisect seems to be triggering a weirdness in git, and also lots of commits
>>>>> crash or do not bring up networking, which makes the bisect difficult.
>>>>>
>>>>> Looking at perf top, it would appear that some lock is probably to blame.
>>>>
>>>>
>>>> perf record -a -g -e cycles:pp sleep 5
>>>> perf report
>>>>
>>>> Then you'll be able to tell us which lock (or call graph) is killing your perf.
>>>>
>>>
>>> I seem to be chasing multiple issues. For 4.13, at least part of my problem was that LOCKDEP was enabled,
>>> during my bisect, though it does NOT appear enabled in 4.16. I think maybe CONFIG_LOCKDEP moved to CONFIG_PROVE_LOCKING
>>> in 4.16, or something like that? My 4.16 .config does have CONFIG_LOCKDEP_SUPPORT enabled, and I see no option to disable it:
>>>
>>> [greearb@ben-dt3 linux-4.16.x64]$ grep LOCKDEP .config
>>> CONFIG_LOCKDEP_SUPPORT=y
>>>
>>>
>>> For 4.16, I am disabling RETRAMPOLINE...are there any other such things I need
>>> to disable to keep from getting a performance hit from the spectre-related bug
>>> fixes? At this point, I do not care about the security implications.
>>>
>>> greearb@ben-dt3 linux-4.16.x64]$ grep RETPO .config
>>> # CONFIG_RETPOLINE is not set
>>>
>>>
>>> Thanks,
>>> Ben
>>>
>>
>> No idea really, you mention a 4.13 -> 4.14 regression and jump then to 4.16 :/
>
> I initially saw the problem in 4.16, then bisected, and 4.14 still showed the
> issue.
So, I guess I must have been enabling lockdep the whole time. This __lock_acquire
is from lockdep as far as I can tell, not normal locking. I re-built 4.16 after
verifying as best as I could that lockdep was not enabled, and now it performs
as expected.
I'm going to test a patch to change __lock_acquire to __lock_acquire_lockdep so
maybe someone else will not make the same mistake I made.
> + 17.78% 17.78% kpktgend_1 [kernel.kallsyms] [k] __lock_acquire.isra.3
Thanks,
Ben
--
Ben Greear <greearb@candelatech.com>
Candela Technologies Inc http://www.candelatech.com
^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2018-05-09 20:55 UTC | newest]
Thread overview: 6+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2018-05-08 16:44 Performance regression between 4.13 and 4.14 Ben Greear
2018-05-08 17:10 ` Eric Dumazet
2018-05-09 18:43 ` Ben Greear
2018-05-09 18:48 ` Eric Dumazet
2018-05-09 19:02 ` Ben Greear
2018-05-09 20:55 ` Ben Greear
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.