Controlplane part of forwarder-vpp leaks

[NikitaSkrynnik]

Description

forwarder-vpp has two interface leaks:

1. timeout chain element doesn't call Close for expired connections. Therefore, vpp interfaces are not deleted
2. Even if we call Close in forwarder-vpp it doesn't delete vxlan interfaces

Tasks

• Investigate why timeout doesn't call Close - 8h
  • Make timeout chain element close connetions faster - 1h
  • Add logs to timeout chain element - 1h
  • Run tests with the modified timeout - 3h
  • Check collected logs - 3h
• Fix timeout chain element - 24h
• Investigate why forwarder-vpp doesn't close vxlan interfaces - 6h
  • Run scaling tests - 3h
  • Check collected logs - 3h
• Fix vxlan problem - 16h

Total: 54h

[NikitaSkrynnik]

All changes that fix tap interface leaks are in these PRs:

1. Leak fixes sdk#1643
2. Some changes that fix inteface leaks sdk-vpp#835

[denis-tingaikin]

It seems like the problem is still existing and the forwarder is leaking.

The picture shows mem consumption for forwarder vpp.

forwarder-vpp_goroutineprofiles_20240920082027.tar.gz
forwarder-vpp_memprofiles_20240920082112.tar.gz

[NikitaSkrynnik]

Current plan

• Test 20 clients and 20 endpoint on Azure cluster with 2 nodes for 24 hours. Collect memory, goroutine profiles, vpp memory profiles and kubectl top after 10 min of testing and after 24 hours of testing.
• Test 40 clients and 1 endpoint on Azure cluster with 2 nodes for 24 hours. Scale clients for 0 to 40 every 60 seconds. Collect memory, goroutine profiles, vpp memory profiles and kubectl top at the beginning, after 10 min of testing and after 24 hours of testing.

[NikitaSkrynnik]

After fixing context leaks in nsmonitor and timeout chain element forwarder shows the next results on 30 NSCs and 10 NSEs:

3h of testing:

nsm-system    forwarder-vpp-gr729                   135m         363Mi           
nsm-system    forwarder-vpp-zjd5x                   200m         390Mi           
nsm-system    nsmgr-25vvt                           167m         92Mi            
nsm-system    nsmgr-f6rjf                           92m          71Mi

18h of testing:

nsm-system    forwarder-vpp-gr729                   132m         401Mi           
nsm-system    forwarder-vpp-zjd5x                   199m         438Mi           
nsm-system    nsmgr-25vvt                           175m         97Mi            
nsm-system    nsmgr-f6rjf                           92m          74Mi 

3d20h of testing:

nsm-system    forwarder-vpp-gr729                   272m         421Mi           
nsm-system    forwarder-vpp-zjd5x                   310m         443Mi           
nsm-system    nsmgr-25vvt                           197m         103Mi           
nsm-system    nsmgr-f6rjf                           101m         78Mi   

4d5h of testing:

nsm-system    forwarder-vpp-gr729                   228m         417Mi           
nsm-system    forwarder-vpp-zjd5x                   203m         448Mi           
nsm-system    nsmgr-25vvt                           213m         101Mi           
nsm-system    nsmgr-f6rjf                           110m         83Mi  

30m after testing:

nsm-system    forwarder-vpp-gr729                   66m          414Mi           
nsm-system    forwarder-vpp-zjd5x                   63m          428Mi           
nsm-system    nsmgr-25vvt                           49m          87Mi            
nsm-system    nsmgr-f6rjf                           46m          73Mi 

memory and goroutine profiles don't show any leaks 30m after testing. Here are all profiles: traces.zip

[denis-tingaikin]

@NikitaSkrynnik attached archive is empty, could you resend it?

[NikitaSkrynnik]

NSMGR Testing

We found that Go runtime in nsmgr (probably in forwarder-vpp too) is aware of the memory consumption shown by the metrics server in Kubernetes. Runtime can allocate big chunks of memory during highload tests but usually don't return them to the kernel. It's due to default memory management settings in Go.

Current memory consumption can be found in /sys/fs/cgroup/memory/memory.stat in nsmgr pod:

/ # cat /sys/fs/cgroup/memory/memory.stat
rss 129200128
...
inactive_anon 129175552
active_anon 12288
inactive_file 12288
active_file 0
...

As you can see memory consumption of nsmgr is about 129mb. This is the value after 1 hour of highload testing with 90 clients and 10 endpoints. There are also some fields that tell about what this memory is. inactive_anon field means memory that was used by nsmgr but now it's not.

Here are also the values from go runtime in nsmgr:

memStats.HeapReleased: 5
memStats.HeapIdle: 104
memStats.HeapInuse: 17
memStats.HeapSys: 121

HeapIdle tells that nsmgr have 104mb of memory that is not used right now but may be useful in the future so Go runtime keeps it. And HeapReleased means the amount of memory that has been reclaimed by the kernel. So it means runtime is aware of that inactive memory but keeps it for the future.

kubectl top before testing:

NAME                            CPU(cores)   MEMORY(bytes)   
forwarder-vpp-cqr7k             75m          273Mi           
nsmgr-phx2f                     36m          12Mi            
registry-k8s-7dd7f7d984-89p8h   1m           11Mi

Here is kubectl top during highload testing:

NAME                            CPU(cores)   MEMORY(bytes)   
forwarder-vpp-8k7pf             378m         427Mi           
nsmgr-khbhg                     421m         162Mi           
registry-k8s-7dd7f7d984-2wgj6   181m         57Mi       

and kubectl top after testing:

NAME                            CPU(cores)   MEMORY(bytes)   
forwarder-vpp-8k7pf             63m          342Mi           
nsmgr-khbhg                     421m         129Mi           
registry-k8s-7dd7f7d984-2wgj6   3m           24Mi       

nsmgr memory consumtion doesn't decrease even after several hours.

---

The default behaviour can be changed with env var GODEBUG=madvdontneed=1.

kubectl top before testing:

NAME                            CPU(cores)   MEMORY(bytes)   
forwarder-vpp-cqr7k             71m          276Mi           
nsmgr-phx2f                     37m          11Mi            
registry-k8s-7dd7f7d984-89p8h   1m           12Mi

kubectl top during testing:

NAME                            CPU(cores)   MEMORY(bytes)   
forwarder-vpp-cqr7k             449m         402Mi           
nsmgr-phx2f                     439m         124Mi           
registry-k8s-7dd7f7d984-89p8h   198m         54Mi            

kubectl top 2min after testing:

NAME                            CPU(cores)   MEMORY(bytes)   
forwarder-vpp-cqr7k             66m          333Mi           
nsmgr-phx2f                     31m          40Mi            
registry-k8s-7dd7f7d984-89p8h   2m           23Mi        

As you can see the nsmgr memory consumption has descreased 1min after the test is finished.

Go runtime memory stats:

memStats.HeapReleased: 96    
memStats.HeapIdle: 99  
memStats.HeapInuse: 18    
memStats.HeapSys: 118   

HeapReleased is much bigger now meaning that 96mb of memory has been reclaimed by the kernel.

---

nsmgr memory consumption is still 4 time bigger than on initial state: 40mb vs 11mb. Current memory consumtion reported by go runtime is 18mb (HeapInuse). There is also stack that consumes 10mb of memory(StackInuse):

memStats.HeapReleased: 96    
memStats.HeapIdle: 99  
memStats.HeapInuse: 18    
memStats.HeapSys: 118 
memStats.StackInuse: 10
memStats.StackSys: 10

So 28mb total. 40mb - 28mb = 12mb is still unknown. Part of the memory may be related to opened files because memory.stats from the kernel show:

inactive_file 6262784
active_file 2289664

Also the kernel shows that nsmgr has several opened sockets:

/ # ls -l /proc/1/fd
total 0
lrwx------    1 root     root            64 Nov 12 11:57 0 -> /dev/null
l-wx------    1 root     root            64 Nov 12 11:57 1 -> pipe:[18439221]
lrwx------    1 root     root            64 Nov 12 12:25 10 -> socket:[19743162]
lrwx------    1 root     root            64 Nov 12 12:25 11 -> socket:[19743164]
l---------    1 root     root            64 Nov 12 12:25 12 -> /listen.on.sock
lrwx------    1 root     root            64 Nov 12 12:25 13 -> socket:[19729952]
lrwx------    1 root     root            64 Nov 12 12:25 14 -> socket:[19743165]
l-wx------    1 root     root            64 Nov 12 11:57 2 -> pipe:[18439222]
lr-x------    1 root     root            64 Nov 12 12:25 29 -> anon_inode:inotify
lrwx------    1 root     root            64 Nov 12 11:57 3 -> socket:[18437267]
lrwx------    1 root     root            64 Nov 12 12:25 32 -> anon_inode:[eventpoll]
lr-x------    1 root     root            64 Nov 12 12:25 33 -> pipe:[18605780]
l-wx------    1 root     root            64 Nov 12 12:25 34 -> pipe:[18605780]
lrwx------    1 root     root            64 Nov 12 11:57 4 -> anon_inode:[eventpoll]
lrwx------    1 root     root            64 Nov 12 11:57 5 -> anon_inode:[eventfd]
l---------    1 root     root            64 Nov 12 12:19 540 -> /listen.on.sock
lrwx------    1 root     root            64 Nov 12 11:57 6 -> socket:[18429898]
lrwx------    1 root     root            64 Nov 12 11:57 7 -> socket:[18434588]
lrwx------    1 root     root            64 Nov 12 11:57 8 -> socket:[18435791]
lrwx------    1 root     root            64 Nov 12 11:57 9 -> socket:[18433938]

Further investigation will be related to open sockets.

[NikitaSkrynnik]

Forwarder VPPTesting

After 150h of highload testing with 30 clients and 10 endpoints on Azure cluster forwarder memory growth is:

forwarder memory consumption is slowly growing. Go memory profiles show 6mb of allocated memory after 150h, goroutine count is 288.

vpp memory usage for forwarder-vpp-qhn7q is: