Kube-router: High CPU usage on headless service update

[sepich]

What happened?
We have k8s app running ~100 pods and having some churn of these pods (pod is running for 2-3min and then deleted, new one is started).
There is headless service with selector targeting for these pods:

apiVersion: v1
kind: Service
metadata:
  name: browsers
  namespace: moon
spec:
  clusterIP: None
  publishNotReadyAddresses: true
  selector:
    moon: browser
  sessionAffinity: None
  type: ClusterIP

$ k -n moon describe svc browsers
Name:              browsers
Namespace:         moon
Labels:            <none>
Annotations:       <none>
Selector:          moon=browser
Type:              ClusterIP
IP:                None
Session Affinity:  None
Events:            <none>

So service have no Endpoints (used only for DNS discovery) and should be ignored by kube-router.
But unfortunately we see very high kube-router CPU usage on all cluster nodes, when we try to start the application:

What did you expect to happen?
Kube-router should ignore headless services.

How can we reproduce the behavior you experienced?
Could be reproduced in some testing cluster like so:

1. Get some empty/calm cluster. Login to any node and see that kube-router has no execve calls:

strace -ftp $(pgrep kube-router) 2>&1 | grep exec
# nothing is printed for minutes

1. Apply this objects:

---
apiVersion: v1
kind: Service
metadata:
  name: browsers
  namespace: default
spec:
  clusterIP: None
  publishNotReadyAddresses: true
  selector:
    moon: browser
  sessionAffinity: None
  type: ClusterIP
---
apiVersion: apps/v1
kind: Deployment
metadata:
  labels:
    app: test
    moon: browser
  name: test
  namespace: default
spec:
  replicas: 10
  selector:
    matchLabels:
      app: test
      moon: browser
  template:
    metadata:
      labels:
        app: test
        moon: browser
    spec:
      containers:
      - image: busybox
        name: busybox
        command:
        - sh
        - -c
        - sleep 600
        ports:
        - containerPort: 4444
          protocol: TCP
        - containerPort: 5900
          protocol: TCP
        - containerPort: 4545
          protocol: TCP
      subdomain: browsers

1. Wait till all pods are up. Now run strace again - you should still see no events.
2. Now delete any pod in other console:
   kubectl -n default delete po test-68f9886bf5-rq5p6
   You would see hundreds of calls in strace console like:

[pid 11406] 08:25:02 execve("/sbin/iptables", ["/sbin/iptables", "-t", "filter", "-N", "KUBE-NWPLCY-JHTJJCDQMS2KXTOK", "--wait"], 0xc4207c0000 /* 51 vars */ <unfinished ...>
[pid 11406] 08:25:02 <... execve resumed>) = 0
[pid 11407] 08:25:02 execve("/usr/sbin/ipset", ["/usr/sbin/ipset", "add", "-exist", "kube-router-ipvs-services-", "172.31.168.64,tcp:30090"], 0xc42035fd40 /* 51 vars */ <unfinished ...>
[pid 11407] 08:25:02 <... execve resumed>) = 0
[pid 11408] 08:25:02 execve("/sbin/iptables", ["/sbin/iptables", "-t", "filter", "-F", "KUBE-NWPLCY-JHTJJCDQMS2KXTOK", "--wait"], 0xc4207c0340 /* 51 vars */ <unfinished ...>
[pid 11408] 08:25:02 <... execve resumed>) = 0
[pid 11409] 08:25:02 execve("/usr/sbin/ipset", ["/usr/sbin/ipset", "add", "-exist", "kube-router-ipvs-services-", "10.96.0.1,tcp:443"], 0xc4209b21a0 /* 51 vars */ <unfinished ...>
[pid 11409] 08:25:02 <... execve resumed>) = 0
[pid 11411] 08:25:02 execve("/sbin/iptables", ["/sbin/iptables", "-t", "filter", "-X", "KUBE-NWPLCY-JHTJJCDQMS2KXTOK", "--wait"], 0xc4207c0680 /* 51 vars */ <unfinished ...>

When we start the app in prod cluster - we could see that kube-router doing couple of full resyncs per second.
For example we could also grep for KUBE-NWPLCY-JHTJJCDQMS2KXTOK and see exact same commands running multiple times per second in same order for this chain.

* System Information (please complete the following information):*

• Kube-Router Version (kube-router --version): 1.0.1
• Kube-Router Parameters:

        - --run-router=true
        - --run-firewall=true
        - --run-service-proxy=true
        - --bgp-graceful-restart=true

• Kubernetes Version (kubectl version) : 1.16.14
• Cloud Type: on premise
• Kubernetes Deployment Type: Kubeadm
• Kube-Router Deployment Type: DaemonSet
• Cluster Size: ~20

* Logs, other output, metrics *

logs -v=5

I0828 08:36:51.185282       1 health_controller.go:187] Health controller tick
I0828 08:36:51.185282       1 metrics_controller.go:181] Metrics controller tick
I0828 08:36:51.185337       1 health_controller.go:80] Received heartbeat from MC
I0828 08:36:53.309487       1 network_services_controller.go:798] Received update to endpoint: default/browsers from watch API
I0828 08:36:53.309554       1 network_services_controller.go:1094] Skipping service name:kube-state-metrics namespace:kube-system as there is no cluster IP
I0828 08:36:53.309587       1 network_services_controller.go:1094] Skipping service name:browsers namespace:default as there is no cluster IP
I0828 08:36:53.309518       1 ecmp_vip.go:243] Received update to endpoint: default/browsers from watch API
I0828 08:36:53.309638       1 ecmp_vip.go:142] Updating service default/browsers triggered by endpoint update event
I0828 08:36:53.309668       1 network_services_controller.go:811] Syncing IPVS services sync for update to endpoint: default/browsers
I0828 08:36:53.309682       1 network_services_controller.go:391] Performing requested sync of ipvs services
I0828 08:36:53.309881       1 health_controller.go:80] Received heartbeat from NSC
I0828 08:36:53.388457       1 network_policy_controller.go:266] Received update to pod: default/test-68f9886bf5-62p4s
I0828 08:36:53.388481       1 network_policy_controller.go:283] Full sync request queue was empty so a full sync request was successfully sent
I0828 08:36:53.388523       1 network_policy_controller.go:171] Received request for a full sync, processing
I0828 08:36:53.388531       1 network_policy_controller.go:308] Starting sync of iptables with version: 1598603813388528055
I0828 08:36:53.388773       1 health_controller.go:80] Received heartbeat from NPC
I0828 08:36:53.406836       1 service_endpoints_sync.go:436] Cleaning up if any, old service IPs on dummy interface
I0828 08:36:53.407940       1 service_endpoints_sync.go:477] Cleaning up if any, old ipvs service and servers which are no longer needed
I0828 08:36:53.449228       1 network_policy_controller.go:422] Iptables chains in the filter table are synchronized with the network policies.
I0828 08:36:53.449488       1 network_policy_controller.go:357] Syncing network policy chains took 34.386408ms
I0828 08:36:53.459291       1 network_policy_controller.go:1122] Found policy chain to cleanup KUBE-NWPLCY-FLWK35JPDMTDAICR
I0828 08:36:53.463146       1 service_endpoints_sync.go:417] Setting up policy routing required for Direct Server Return functionality.
I0828 08:36:53.465578       1 service_endpoints_sync.go:422] Custom routing table kube-router-dsr required for Direct Server Return is setup as expected.
I0828 08:36:53.465788       1 service_endpoints_sync.go:424] Setting up custom route table required to add routes for external IP's.
I0828 08:36:53.470928       1 network_policy_controller.go:1150] Deleted network policy chain: KUBE-NWPLCY-FLWK35JPDMTDAICR from the filter table
I0828 08:36:53.470955       1 network_policy_controller.go:1122] Found policy chain to cleanup KUBE-NWPLCY-NDI3L3O4FTG4AX3X
I0828 08:36:53.472132       1 service_endpoints_sync.go:430] Custom routing table external_ip required for Direct Server Return is setup as expected.
I0828 08:36:53.472149       1 service_endpoints_sync.go:77] IPVS servers and services are synced to desired state
I0828 08:36:53.472158       1 service_endpoints_sync.go:28] sync ipvs services took 162.468469ms
I0828 08:36:53.472175       1 health_controller.go:80] Received heartbeat from NSC
I0828 08:36:53.476696       1 network_policy_controller.go:1150] Deleted network policy chain: KUBE-NWPLCY-NDI3L3O4FTG4AX3X from the filter table
I0828 08:36:53.476715       1 network_policy_controller.go:305] sync iptables took 88.181894ms
I0828 08:36:54.185252       1 metrics_controller.go:181] Metrics controller tick
I0828 08:36:54.185293       1 health_controller.go:80] Received heartbeat from MC
I0828 08:36:55.754381       1 network_policy_controller.go:266] Received update to pod: default/test-68f9886bf5-62p4s
I0828 08:36:55.754428       1 network_policy_controller.go:283] Full sync request queue was empty so a full sync request was successfully sent
I0828 08:36:55.754435       1 network_policy_controller.go:171] Received request for a full sync, processing
I0828 08:36:55.754444       1 network_policy_controller.go:308] Starting sync of iptables with version: 1598603815754440568
I0828 08:36:55.754738       1 health_controller.go:80] Received heartbeat from NPC
I0828 08:36:55.761896       1 network_services_controller.go:798] Received update to endpoint: default/browsers from watch API
I0828 08:36:55.761926       1 network_services_controller.go:1094] Skipping service name:browsers namespace:default as there is no cluster IP
I0828 08:36:55.761931       1 network_services_controller.go:1094] Skipping service name:kube-state-metrics namespace:kube-system as there is no cluster IP
I0828 08:36:55.762015       1 network_services_controller.go:811] Syncing IPVS services sync for update to endpoint: default/browsers
I0828 08:36:55.762027       1 network_services_controller.go:391] Performing requested sync of ipvs services
I0828 08:36:55.762304       1 health_controller.go:80] Received heartbeat from NSC
I0828 08:36:55.762319       1 ecmp_vip.go:243] Received update to endpoint: default/browsers from watch API
I0828 08:36:55.762326       1 ecmp_vip.go:142] Updating service default/browsers triggered by endpoint update event
I0828 08:36:55.777304       1 service_endpoints_sync.go:436] Cleaning up if any, old service IPs on dummy interface
I0828 08:36:55.777544       1 service_endpoints_sync.go:477] Cleaning up if any, old ipvs service and servers which are no longer needed
I0828 08:36:55.813382       1 network_policy_controller.go:422] Iptables chains in the filter table are synchronized with the network policies.
I0828 08:36:55.815109       1 network_policy_controller.go:357] Syncing network policy chains took 40.230745ms
I0828 08:36:55.822023       1 network_policy_controller.go:1122] Found policy chain to cleanup KUBE-NWPLCY-H7367Q66Q2UDVUNI
I0828 08:36:55.827036       1 network_policy_controller.go:1150] Deleted network policy chain: KUBE-NWPLCY-H7367Q66Q2UDVUNI from the filter table
I0828 08:36:55.829268       1 network_policy_controller.go:1122] Found policy chain to cleanup KUBE-NWPLCY-SY6YLHBYPAL55T22
I0828 08:36:55.828465       1 service_endpoints_sync.go:417] Setting up policy routing required for Direct Server Return functionality.
I0828 08:36:55.832139       1 service_endpoints_sync.go:422] Custom routing table kube-router-dsr required for Direct Server Return is setup as expected.
I0828 08:36:55.832158       1 service_endpoints_sync.go:424] Setting up custom route table required to add routes for external IP's.
I0828 08:36:55.835657       1 network_policy_controller.go:1150] Deleted network policy chain: KUBE-NWPLCY-SY6YLHBYPAL55T22 from the filter table
I0828 08:36:55.835669       1 service_endpoints_sync.go:430] Custom routing table external_ip required for Direct Server Return is setup as expected.
I0828 08:36:55.835703       1 service_endpoints_sync.go:77] IPVS servers and services are synced to desired state
I0828 08:36:55.835712       1 service_endpoints_sync.go:28] sync ipvs services took 73.678475ms
I0828 08:36:55.835725       1 health_controller.go:80] Received heartbeat from NSC
I0828 08:36:55.835677       1 network_policy_controller.go:305] sync iptables took 81.232053ms
I0828 08:36:56.185446       1 health_controller.go:187] Health controller tick
I0828 08:36:57.185282       1 metrics_controller.go:181] Metrics controller tick
I0828 08:36:57.185326       1 health_controller.go:80] Received heartbeat from MC
I0828 08:37:00.185348       1 metrics_controller.go:181] Metrics controller tick
I0828 08:37:00.185382       1 health_controller.go:80] Received heartbeat from MC
I0828 08:37:01.185342       1 health_controller.go:187] Health controller tick
I0828 08:37:03.185274       1 metrics_controller.go:181] Metrics controller tick
I0828 08:37:03.185316       1 health_controller.go:80] Received heartbeat from MC

[aauren]

@sepich Thanks for your very detailed bug report! I appreciate all of the detail that you've provided here.

I think that the headless service here is a non sequitur in this case. The truth is that when the NetworkPolicyController is run (which is what --run-firewall=true controls) it watches on all pod updates and then takes action. This is the result of the NetworkPolicy spec that we implement from upstream Kubernetes being driven by network policy and pod selectors instead of service. You can see that in the code here: https://github.com/cloudnativer/kube-router-cnlabs/blob/master/pkg/cmd/kube-router.go#L137

Unfortunately, at this time, the only action that the NetworkPolicyController takes is to run a full sync which you can see here: https://github.com/cloudnativelabs/kube-router/blob/master/pkg/controllers/netpol/network_policy_controller.go#L1780 which then goes through every pod, checks to see if they are selected by a network policy, and then, if so, converts that policy to iptables operations.

This is a performance deficiency that we're going to be working on in the upcoming 1.2 release: https://github.com/cloudnativelabs/kube-router/projects/8 and tracking via this long standing issue: https://github.com/cloudnativelabs/kube-router/issues/585

In addition to separating pod events from network policy full syncs we'll also be looking into making full syncs more performant as well (right now full syncs are very costly as they can trigger thousands of individual iptables execution context shifts).

If you're alright with it I'd rather close this issue and work off of #585 now that the issues have been linked.

[sepich]

Got it, and thank you for detailed explanation!

[sepich]

I've had a chance to reconfigure kube-router to --run-firewall=false on couple of nodes and try to run app again.
Unfortunately nothing changed, kube-router CPU usage on these nodes is still ~80%, memory usage grows, and then kube-router starts to miss livenessProbe timeout and gets restarted.
Also tested on empty cluster (as in repro), but with --run-firewall=false. When i delete a test pod, i see hundreds requests for ipset kube-router-ipvs-services- and it is being swaped 4 times for just one pod deletion (re-creation is another 4 times). Logs are still mentioning services sync for update to endpoint: default/browsers which has no endpoints because it is headless:

logs -v=5

I0902 16:17:43.852465       1 network_services_controller.go:798] Received update to endpoint: default/browsers from watch API
I0902 16:17:43.852619       1 network_services_controller.go:1094] Skipping service name:kube-state-metrics namespace:kube-system as there is no cluster IP
I0902 16:17:43.852776       1 network_services_controller.go:1094] Skipping service name:browsers namespace:default as there is no cluster IP
I0902 16:17:43.852978       1 network_services_controller.go:811] Syncing IPVS services sync for update to endpoint: default/browsers
I0902 16:17:43.853101       1 network_services_controller.go:391] Performing requested sync of ipvs services
I0902 16:17:43.852618       1 ecmp_vip.go:243] Received update to endpoint: default/browsers from watch API
I0902 16:17:43.853728       1 ecmp_vip.go:142] Updating service default/browsers triggered by endpoint update event
I0902 16:17:43.854365       1 health_controller.go:80] Received heartbeat from NSC
I0902 16:17:43.891177       1 metrics_controller.go:181] Metrics controller tick
I0902 16:17:43.891362       1 health_controller.go:80] Received heartbeat from MC
I0902 16:17:44.092862       1 service_endpoints_sync.go:436] Cleaning up if any, old service IPs on dummy interface
I0902 16:17:44.096633       1 service_endpoints_sync.go:477] Cleaning up if any, old ipvs service and servers which are no longer needed
I0902 16:17:44.503337       1 service_endpoints_sync.go:417] Setting up policy routing required for Direct Server Return functionality.
I0902 16:17:44.515795       1 service_endpoints_sync.go:422] Custom routing table kube-router-dsr required for Direct Server Return is setup as expected.
I0902 16:17:44.518351       1 service_endpoints_sync.go:424] Setting up custom route table required to add routes for external IP's.
I0902 16:17:44.536350       1 service_endpoints_sync.go:430] Custom routing table external_ip required for Direct Server Return is setup as expected.
I0902 16:17:44.539075       1 service_endpoints_sync.go:77] IPVS servers and services are synced to desired state
I0902 16:17:44.540390       1 service_endpoints_sync.go:28] sync ipvs services took 687.190686ms
I0902 16:17:44.542522       1 health_controller.go:80] Received heartbeat from NSC
I0902 16:17:45.892420       1 health_controller.go:187] Health controller tick
I0902 16:17:45.909823       1 network_services_controller.go:798] Received update to endpoint: default/browsers from watch API
I0902 16:17:45.910235       1 network_services_controller.go:1094] Skipping service name:kube-state-metrics namespace:kube-system as there is no cluster IP
I0902 16:17:45.910330       1 network_services_controller.go:1094] Skipping service name:browsers namespace:default as there is no cluster IP
I0902 16:17:45.910893       1 network_services_controller.go:811] Syncing IPVS services sync for update to endpoint: default/browsers
I0902 16:17:45.911714       1 network_services_controller.go:391] Performing requested sync of ipvs services
I0902 16:17:45.910308       1 ecmp_vip.go:243] Received update to endpoint: default/browsers from watch API
I0902 16:17:45.912344       1 ecmp_vip.go:142] Updating service default/browsers triggered by endpoint update event
I0902 16:17:45.916050       1 health_controller.go:80] Received heartbeat from NSC
I0902 16:17:46.166784       1 service_endpoints_sync.go:436] Cleaning up if any, old service IPs on dummy interface
I0902 16:17:46.171860       1 service_endpoints_sync.go:477] Cleaning up if any, old ipvs service and servers which are no longer needed
I0902 16:17:46.747351       1 service_endpoints_sync.go:417] Setting up policy routing required for Direct Server Return functionality.
I0902 16:17:46.761116       1 service_endpoints_sync.go:422] Custom routing table kube-router-dsr required for Direct Server Return is setup as expected.
I0902 16:17:46.761750       1 service_endpoints_sync.go:424] Setting up custom route table required to add routes for external IP's.
I0902 16:17:46.785354       1 service_endpoints_sync.go:430] Custom routing table external_ip required for Direct Server Return is setup as expected.
I0902 16:17:46.786131       1 service_endpoints_sync.go:77] IPVS servers and services are synced to desired state
I0902 16:17:46.788186       1 service_endpoints_sync.go:28] sync ipvs services took 875.944382ms
I0902 16:17:46.790168       1 health_controller.go:80] Received heartbeat from NSC
I0902 16:17:46.892214       1 metrics_controller.go:181] Metrics controller tick
I0902 16:17:46.892360       1 health_controller.go:80] Received heartbeat from MC
I0902 16:17:49.891622       1 metrics_controller.go:181] Metrics controller tick
I0902 16:17:49.891972       1 health_controller.go:80] Received heartbeat from MC
I0902 16:17:50.891739       1 health_controller.go:187] Health controller tick

Looking forward to test v1.2, hopefully it would help

[aauren]

Yeah, I wonder how much of this you're hitting: https://github.com/cloudnativelabs/kube-router/issues/962

[aauren]

Reopening as a point of improvement for 1.2. It doesn't look like it really took too much time (less than a second for each run of the services sync), but never-the-less we may be able to tune for headless services when we receive updates for them before running sync logic.