Re: 4.9 conntrack performance issues

[Guillaume Nault]

On Mon, Jan 30, 2017 at 01:37:43PM +0200, Denys Fedoryshchenko wrote:
> On 2017-01-30 13:26, Guillaume Nault wrote:
> > On Sun, Jan 15, 2017 at 01:05:58AM +0200, Denys Fedoryshchenko wrote:
> > > Hi!
> > > 
> > > Sorry if i added someone wrongly to CC, please let me know, if i
> > > should
> > > remove.
> > > I just run successfully 4.9 on my nat several days ago, and seems
> > > panic
> > > issue disappeared.
> > > 
> > Hi Denys,
> > 
> > After two weeks running Linux 4.9, do you confirm that the original
> > issue[1] is gone?
> > 
> > Regards,
> > 
> > Guillaume
> > 
> > [1]: https://www.spinics.net/lists/netdev/msg410795.html
> Yes, no more reboots at all and 4.9 patched for gc issues seems
> significantly better for NAT performance (CPU load lower almost twice than
> previous kernels, i dont have exact numbers).

Great! Thanks for the feedback.

Re: 4.9 conntrack performance issues

[Denys Fedoryshchenko]

On 2017-01-30 13:26, Guillaume Nault wrote:

On Sun, Jan 15, 2017 at 01:05:58AM +0200, Denys Fedoryshchenko wrote:

Hi!

Sorry if i added someone wrongly to CC, please let me know, if i 
should

remove.
I just run successfully 4.9 on my nat several days ago, and seems 
panic

issue disappeared.


Hi Denys,

After two weeks running Linux 4.9, do you confirm that the original
issue[1] is gone?

Regards,

Guillaume

[1]: https://www.spinics.net/lists/netdev/msg410795.html
Yes, no more reboots at all and 4.9 patched for gc issues seems 
significantly better for NAT performance (CPU load lower almost twice 
than previous kernels, i dont have exact numbers).

Re: 4.9 conntrack performance issues

[Guillaume Nault]

On Sun, Jan 15, 2017 at 01:05:58AM +0200, Denys Fedoryshchenko wrote:
> Hi!
> 
> Sorry if i added someone wrongly to CC, please let me know, if i should
> remove.
> I just run successfully 4.9 on my nat several days ago, and seems panic
> issue disappeared.
> 
Hi Denys,

After two weeks running Linux 4.9, do you confirm that the original
issue[1] is gone?

Regards,

Guillaume

[1]: https://www.spinics.net/lists/netdev/msg410795.html

Re: 4.9 conntrack performance issues

[Denys Fedoryshchenko]

On 2017-01-15 02:29, Florian Westphal wrote:

Denys Fedoryshchenko  wrote:

On 2017-01-15 01:53, Florian Westphal wrote:
>Denys Fedoryshchenko  wrote:
>
>I suspect you might also have to change
>
>1011 } else if (expired_count) {
>1012 gc_work->next_gc_run /= 2U;
>1013 next_run = msecs_to_jiffies(1);
>1014 } else {
>
>line 2013 to
>next_run = msecs_to_jiffies(HZ / 2);


I think its wrong to rely on "expired_count", with these
kinds of numbers (up to 10k entries are scanned per round
in Denys setup, its basically always going to be > 0.

I think we should only decide to scan more frequently if
eviction ratio is large, say, we found more than 1/4 of
entries to be stale.

I sent a small patch offlist that does just that.


>How many total connections is the machine handling on average?
>And how many new/delete events happen per second?
1-2 million connections, at current moment 988k
I dont know if it is correct method to measure events rate:

NAT ~ # timeout -t 5 conntrack -E -e NEW | wc -l
conntrack v1.4.2 (conntrack-tools): 40027 flow events have been shown.
40027
NAT ~ # timeout -t 5 conntrack -E -e DESTROY | wc -l
conntrack v1.4.2 (conntrack-tools): 40951 flow events have been shown.
40951


Thanks, thats exactly what I was looking for.
So I am not at all surprised that gc_worker eats cpu cycles...

It is not peak time, so values can be 2-3 higher at peak time, but 
even

right now, it is hogging one core, leaving only 20% idle left,
while others are 80-83% idle.


I agree its a bug.


>>   |--54.65%--gc_worker
>>   |  |
>>   |   --3.58%--nf_ct_gc_expired
>>   | |
>>   | |--1.90%--nf_ct_delete
>
>I'd be interested to see how often that shows up on other cores
>(from packet path).
Other CPU's totally different:
This is top entry
99.60% 0.00%  swapper  [kernel.kallsyms][k] 
start_secondary

|
---start_secondary
   |
--99.42%--cpu_startup_entry
  |

[..]


|--36.02%--process_backlog
 | |  
|

|  |
 | |  
|

|   --35.64%--__netif_receive_skb

gc_worker didnt appeared on other core at all.
Or i am checking something wrong?


Look for "nf_ct_gc_expired" and "nf_ct_delete".
Its going to be deep down in the call graph.
I tried my best to record as much data as possible, but it doesnt show 
it in callgraph, just a little bit in statistics:


 0.01% 0.00%  swapper  [nf_conntrack][k] 
nf_ct_delete
 0.01% 0.00%  swapper  [nf_conntrack][k] 
nf_ct_gc_expired

And thats it.

Re: 4.9 conntrack performance issues

[Florian Westphal]

Denys Fedoryshchenko  wrote:
> On 2017-01-15 01:53, Florian Westphal wrote:
> >Denys Fedoryshchenko  wrote:
> >
> >I suspect you might also have to change
> >
> >1011 } else if (expired_count) {
> >1012 gc_work->next_gc_run /= 2U;
> >1013 next_run = msecs_to_jiffies(1);
> >1014 } else {
> >
> >line 2013 to
> > next_run = msecs_to_jiffies(HZ / 2);

I think its wrong to rely on "expired_count", with these
kinds of numbers (up to 10k entries are scanned per round
in Denys setup, its basically always going to be > 0.

I think we should only decide to scan more frequently if
eviction ratio is large, say, we found more than 1/4 of
entries to be stale.

I sent a small patch offlist that does just that.

> >How many total connections is the machine handling on average?
> >And how many new/delete events happen per second?
> 1-2 million connections, at current moment 988k
> I dont know if it is correct method to measure events rate:
> 
> NAT ~ # timeout -t 5 conntrack -E -e NEW | wc -l
> conntrack v1.4.2 (conntrack-tools): 40027 flow events have been shown.
> 40027
> NAT ~ # timeout -t 5 conntrack -E -e DESTROY | wc -l
> conntrack v1.4.2 (conntrack-tools): 40951 flow events have been shown.
> 40951

Thanks, thats exactly what I was looking for.
So I am not at all surprised that gc_worker eats cpu cycles...

> It is not peak time, so values can be 2-3 higher at peak time, but even
> right now, it is hogging one core, leaving only 20% idle left,
> while others are 80-83% idle.

I agree its a bug.

> >>   |--54.65%--gc_worker
> >>   |  |
> >>   |   --3.58%--nf_ct_gc_expired
> >>   | |
> >>   | |--1.90%--nf_ct_delete
> >
> >I'd be interested to see how often that shows up on other cores
> >(from packet path).
> Other CPU's totally different:
> This is top entry
> 99.60% 0.00%  swapper  [kernel.kallsyms][k] start_secondary
> |
> ---start_secondary
>|
> --99.42%--cpu_startup_entry
>   |
[..]

> |--36.02%--process_backlog
>  | |  |
> |  |
>  | |  |
> |   --35.64%--__netif_receive_skb
> 
> gc_worker didnt appeared on other core at all.
> Or i am checking something wrong?

Look for "nf_ct_gc_expired" and "nf_ct_delete".
Its going to be deep down in the call graph.

Re: 4.9 conntrack performance issues

[Denys Fedoryshchenko]

On 2017-01-15 01:53, Florian Westphal wrote:

Denys Fedoryshchenko  wrote:

[ CC Nicolas since he also played with gc heuristics in the past ]

Sorry if i added someone wrongly to CC, please let me know, if i 
should

remove.
I just run successfully 4.9 on my nat several days ago, and seems 
panic
issue disappeared. But i started to face another issue, it seems 
garbage

collector is hogging one of CPU's.

It was handling load very well at 4.8 and below, it might be still 
fine, but

i suspect queues that belong to hogged cpu might experience issues.


The worker doesn't grab locks for long and calls scheduler for every
bucket to give a chance for other threads to run.

It also doesn't block softinterrupts.

Is there anything can be done to improve cpu load distribution or 
reduce

single core load?


No, I am afraid we don't export any of the heuristics as tuneables so
far.

You could try changing defaults in net/netfilter/nf_conntrack_core.c:

#define GC_MAX_BUCKETS_DIV  64u
/* upper bound of scan intervals */
#define GC_INTERVAL_MAX (2 * HZ)
/* maximum conntracks to evict per gc run */
#define GC_MAX_EVICTS   256u

(the first two result in ~2 minute worst case timeout detection
 on a fully idle system).

For instance you could use

GC_MAX_BUCKETS_DIV -> 128
GC_INTERVAL_MAX-> 30 * HZ

(This means that it takes one hour for a dead connection to be picked
 up on an idle system, but thats only relevant in case you use
 conntrack events to log when connection went down and need more 
precise

 accounting).

Not a big deal in my case.



I suspect you might also have to change

1011 } else if (expired_count) {
1012 gc_work->next_gc_run /= 2U;
1013 next_run = msecs_to_jiffies(1);
1014 } else {

line 2013 to
next_run = msecs_to_jiffies(HZ / 2);

or something like this to not have frequent rescans.

OK


The gc is also done from the packet path (i.e. accounted
towards (k)softirq).

How many total connections is the machine handling on average?
And how many new/delete events happen per second?

1-2 million connections, at current moment 988k
I dont know if it is correct method to measure events rate:

NAT ~ # timeout -t 5 conntrack -E -e NEW | wc -l
conntrack v1.4.2 (conntrack-tools): 40027 flow events have been shown.
40027
NAT ~ # timeout -t 5 conntrack -E -e DESTROY | wc -l
conntrack v1.4.2 (conntrack-tools): 40951 flow events have been shown.
40951

It is not peak time, so values can be 2-3 higher at peak time, but even 
right now, it is hogging one core, leaving only 20% idle left,

while others are 80-83% idle.




88.98% 0.00%  kworker/24:1  [kernel.kallsyms]   [k]
process_one_work
|
---process_one_work
   |
   |--54.65%--gc_worker
   |  |
   |   --3.58%--nf_ct_gc_expired
   | |
   | |--1.90%--nf_ct_delete


I'd be interested to see how often that shows up on other cores
(from packet path).

Other CPU's totally different:
This is top entry
99.60% 0.00%  swapper  [kernel.kallsyms][k] start_secondary
|
---start_secondary
   |
--99.42%--cpu_startup_entry
  |
   --98.04%--default_idle_call
 arch_cpu_idle
 |
 
|--48.58%--call_function_single_interrupt

 |  |
 |   
--46.36%--smp_call_function_single_interrupt
 | 
smp_trace_call_function_single_interrupt

 | |
 | 
|--44.18%--irq_exit

 | |  |
 | |  
|--43.37%--__do_softirq
 | |  |  
|
 | |  |  
 --43.18%--net_rx_action
 | |  |  
   |
 | |  |  
   |--36.02%--process_backlog
 | |  |  
   |  |
 | |  |  
   |   --35.64%--__netif_receive_skb



gc_worker didnt appeared on other core at all.
Or i am checking something wrong?

Re: 4.9 conntrack performance issues

[Florian Westphal]

Denys Fedoryshchenko  wrote:

[ CC Nicolas since he also played with gc heuristics in the past ]

> Sorry if i added someone wrongly to CC, please let me know, if i should
> remove.
> I just run successfully 4.9 on my nat several days ago, and seems panic
> issue disappeared. But i started to face another issue, it seems garbage
> collector is hogging one of CPU's.
>
> It was handling load very well at 4.8 and below, it might be still fine, but
> i suspect queues that belong to hogged cpu might experience issues.

The worker doesn't grab locks for long and calls scheduler for every
bucket to give a chance for other threads to run.

It also doesn't block softinterrupts.

> Is there anything can be done to improve cpu load distribution or reduce
> single core load?

No, I am afraid we don't export any of the heuristics as tuneables so
far.

You could try changing defaults in net/netfilter/nf_conntrack_core.c:

#define GC_MAX_BUCKETS_DIV  64u
/* upper bound of scan intervals */
#define GC_INTERVAL_MAX (2 * HZ)
/* maximum conntracks to evict per gc run */
#define GC_MAX_EVICTS   256u

(the first two result in ~2 minute worst case timeout detection
 on a fully idle system).

For instance you could use

GC_MAX_BUCKETS_DIV -> 128
GC_INTERVAL_MAX-> 30 * HZ

(This means that it takes one hour for a dead connection to be picked
 up on an idle system, but thats only relevant in case you use
 conntrack events to log when connection went down and need more precise
 accounting).

I suspect you might also have to change

1011 } else if (expired_count) {
1012 gc_work->next_gc_run /= 2U;
1013 next_run = msecs_to_jiffies(1);
1014 } else {

line 2013 to
next_run = msecs_to_jiffies(HZ / 2);

or something like this to not have frequent rescans.

The gc is also done from the packet path (i.e. accounted
towards (k)softirq).

How many total connections is the machine handling on average?
And how many new/delete events happen per second?

> 88.98% 0.00%  kworker/24:1  [kernel.kallsyms]   [k]
> process_one_work
> |
> ---process_one_work
>|
>|--54.65%--gc_worker
>|  |
>|   --3.58%--nf_ct_gc_expired
>| |
>| |--1.90%--nf_ct_delete

I'd be interested to see how often that shows up on other cores
(from packet path).