[BUG] Extremely slow "add policy route"

[zsxsoft]

Kube-OVN Version

v1.12.28

Kubernetes Version

v1.31.2

Operation-system/Kernel Version

TencentOS Server 4.2
6.6.47-12.tl4.x86_64

Description

This issue contains 2 problems.

I have a cluster with 10 nodes, 260 subnets in 1 vpc, ~5k ports. Today, I discovered that my ovs-ovn on some nodes was killed due to OOM. Therefore, I increased the memory limit and restarted the kube-ovn-controller.

Then I found my Work Queue Latency has remained at a very high level. (>10min)

I noticed that the controller was continuously performing "add policy route" operations in the logs at a VERY SLOW pace (approximately 1-3 seconds per entry). This's the first problem.

I understand that after restarting the KubeOVN controller, it needs to traverse all 10 nodes and 260 subnets. I expected the number of add policy route operations to be ~2600.

[root@vm-master-1 a]# cat 2.log | grep 'add policy route' | wc -l
3558

However, after waiting for a long time, I found that this number far exceeded than it, and there appeared to be a large number of duplicate operations. (Same node, same subnet, but executed twice)

[root@vm-master-1 a]# cat 2.log | grep 'add policy route' | grep 'net.a'
I1212 17:05:13.323328       7 subnet.go:2524] add policy route for router: ovn-cluster, match ip4.src == $net.a.node.1_ip4, action reroute, extrenalID map[node:node-1 subnet:net-a vendor:kube-ovn]
I1212 17:11:55.754750       7 subnet.go:2524] add policy route for router: ovn-cluster, match ip4.src == $net.a.node.2_ip4, action reroute, extrenalID map[node:node-2 subnet:net-a vendor:kube-ovn]
I1212 17:14:03.134696       7 subnet.go:2524] add policy route for router: ovn-cluster, match ip4.src == $net.a.node.4_ip4, action reroute, extrenalID map[node:node-4 subnet:net-a vendor:kube-ovn]
I1212 17:19:21.932002       7 subnet.go:2524] add policy route for router: ovn-cluster, match ip4.src == $net.a.node.3_ip4, action reroute, extrenalID map[node:node-3 subnet:net-a vendor:kube-ovn]
I1212 17:21:50.341122       7 subnet.go:2524] add policy route for router: ovn-cluster, match ip4.src == $net.a.vm.master.1_ip4, action reroute, extrenalID map[node:vm-master-1 subnet:net-a vendor:kube-ovn]
I1212 17:23:18.262599       7 subnet.go:2524] add policy route for router: ovn-cluster, match ip4.src == $net.a.node.9_ip4, action reroute, extrenalID map[node:node-9 subnet:net-a vendor:kube-ovn]
I1212 17:31:00.166875       7 subnet.go:2524] add policy route for router: ovn-cluster, match ip4.src == $net.a.node.5_ip4, action reroute, extrenalID map[node:node-5 subnet:net-a vendor:kube-ovn]
I1212 17:33:28.833554       7 subnet.go:2524] add policy route for router: ovn-cluster, match ip4.src == $net.a.node.8_ip4, action reroute, extrenalID map[node:node-8 subnet:net-a vendor:kube-ovn]
I1212 17:34:44.164926       7 subnet.go:2524] add policy route for router: ovn-cluster, match ip4.src == $net.a.node.1_ip4, action reroute, extrenalID map[node:node-1 subnet:net-a vendor:kube-ovn]
I1212 17:34:46.367902       7 subnet.go:2524] add policy route for router: ovn-cluster, match ip4.src == $net.a.node.2_ip4, action reroute, extrenalID map[node:node-2 subnet:net-a vendor:kube-ovn]
I1212 17:34:49.141808       7 subnet.go:2524] add policy route for router: ovn-cluster, match ip4.src == $net.a.node.3_ip4, action reroute, extrenalID map[node:node-3 subnet:net-a vendor:kube-ovn]
I1212 17:34:51.828600       7 subnet.go:2524] add policy route for router: ovn-cluster, match ip4.src == $net.a.vm.master.1_ip4, action reroute, extrenalID map[node:vm-master-1 subnet:net-a vendor:kube-ovn]
I1212 17:34:54.537169       7 subnet.go:2524] add policy route for router: ovn-cluster, match ip4.src == $net.a.node.4_ip4, action reroute, extrenalID map[node:node-4 subnet:net-a vendor:kube-ovn]
I1212 17:34:57.445022       7 subnet.go:2524] add policy route for router: ovn-cluster, match ip4.src == $net.a.node.8_ip4, action reroute, extrenalID map[node:node-8 subnet:net-a vendor:kube-ovn]
I1212 17:35:00.533108       7 subnet.go:2524] add policy route for router: ovn-cluster, match ip4.src == $net.a.node.5_ip4, action reroute, extrenalID map[node:node-5 subnet:net-a vendor:kube-ovn]
I1212 17:35:03.406251       7 subnet.go:2524] add policy route for router: ovn-cluster, match ip4.src == $net.a.node.6_ip4, action reroute, extrenalID map[node:node-6 subnet:net-a vendor:kube-ovn]
I1212 17:35:06.634137       7 subnet.go:2524] add policy route for router: ovn-cluster, match ip4.src == $net.a.node.7_ip4, action reroute, extrenalID map[node:node-7 subnet:net-a vendor:kube-ovn]
I1212 17:35:09.738121       7 subnet.go:2524] add policy route for router: ovn-cluster, match ip4.src == $net.a.node.9_ip4, action reroute, extrenalID map[node:node-9 subnet:net-a vendor:kube-ovn]
I1212 17:36:34.646594       7 subnet.go:2524] add policy route for router: ovn-cluster, match ip4.src == $net.a.node.6_ip4, action reroute, extrenalID map[node:node-6 subnet:net-a vendor:kube-ovn]
I1212 17:44:43.345692       7 subnet.go:2524] add policy route for router: ovn-cluster, match ip4.src == $net.a.node.7_ip4, action reroute, extrenalID map[node:node-7 subnet:net-a vendor:kube-ovn]

Now I'm unable to create new subnets, so I plan to wait overnight and check again the next day to see if the operations have completed. If more information is needed, please contact me.

Steps To Reproduce

/

Current Behavior

/

Expected Behavior

/

[dosubot]

I found a similar closed issue that might be relevant to your problem: underlay subnet has an unexpected policy route. This issue was resolved by a pull request that fixed the logical router policy for the default subnet with logical gateway enabled ^[1].

Regarding the duplicate "add policy route" operations you're experiencing, Kube-OVN has a mechanism to handle policy routes and prevent duplicate entries. It uses functions like diffPolicyRouteWithExisted and diffPolicyRouteWithLogical to compare existing policy routes with target routes, determining which routes need to be added or deleted. This ensures that only necessary policy routes are added or removed, effectively handling duplicate entries by maintaining a single valid entry for each route ^[2][3].

If you're seeing a large number of duplicate operations, it might be worth checking if these functions are being correctly utilized in your setup or if there might be a specific configuration issue causing this behavior.

To continue talking to Dosu, mention @dosu.

---

^{Help Dosu learn! Give it feedback: Great Response | Irrelevant Answer | Incorrect Sources | Too Verbose | Hallucination | Other}

[zsxsoft]

Check the Work Queue Depth, I found the Subnet is decreasing with very low speed:

18:12:00 AddSubnet 243
18:24:00 AddSubnet 242
18:32:30 AddSubnet 233
18:41:00 AddSubnet 242 (Why go backed?)
18:52:30 AddSubnet 243 (huh?)
18:54:00 AddSubnet 240
18:59:30 AddSubnet 226 (Decreacing now)
19:08:00 AddSubnet 202
19:14:00 AddSUbnet 184

[zsxsoft]

Any reason for slow add policy route?

I1212 17:11:55.754750       7 subnet.go:2524] add policy route for router: ovn-cluster, match ip4.src == $net.a.node.2_ip4, action reroute, extrenalID map[node:node-2 subnet:net-a vendor:kube-ovn]
I1212 17:14:03.134696       7 subnet.go:2524] add policy route for router: ovn-cluster, match ip4.src == $net.a.node.4_ip4, action reroute, extrenalID map[node:node-4 subnet:net-a vendor:kube-ovn]
I1212 17:19:21.932002       7 subnet.go:2524] add policy route for router: ovn-cluster, match ip4.src == $net.a.node.3_ip4, action reroute, extrenalID map[node:node-3 subnet:net-a vendor:kube-ovn]

[dosubot]

The slow "add policy route" operation in Kube-OVN is primarily due to two issues:

1. Execution Time: Each policy route addition takes 1-3 seconds, which significantly slows down the processing of the entire queue.

2. Duplicate Operations: There are duplicate operations for the same node and subnet combinations, leading to more operations than expected. This is evident from the logs where the same node and subnet combinations are processed multiple times.

These factors contribute to the slow decrease in the "Work Queue Depth" for "Subnet," with occasional increases due to re-processing after events like a controller restart following an Out of Memory (OOM) issue ^[1].

To continue talking to Dosu, mention @dosu.

---

^{Help Dosu learn! Give it feedback: Great Response | Irrelevant Answer | Incorrect Sources | Too Verbose | Hallucination | Other}

[oilbeater]

@zsxsoft This may be related to the logic of adding policies. When add policy, the kube-ovn-controller needs to check if the policy exists by performing a long string match. In your environment, each policy addition requires approximately 260 × 10 checks, which amounts to a total of 260 × 260 × 10 checks.

[zsxsoft]

@oilbeater
I checked this

kube-ovn/pkg/controller/subnet.go

Line 2565 in 8701625

if err := c.addPolicyRouteToVpc(

It seems that each time addPolicyRouteToVpc is executed, a listLogicalRouterPoliciesByFilter is required. I found that running kubectl ko nbctl lr-policy-list ovn-cluster | wc -l is quite slow. So I guess listLogicalRouterPoliciesByFilter is slow too.
Despite the presence of a whereCache, I guess that each add operation may invalidate this cache. Given that the addPolicyRoute needs to be run count(node)*count(subnet) times, it might be beneficial to refactor the process to batch these API calls.

[zsxsoft]

I see #4538, is the patch useful? I didn't measure the time.

[oilbeater]

@zsxsoft it should help. I tested v1.14.0 with this patch and v1.12.28 without this patch in a cluster with 5 nodes and 250 subnets.

For v1.14.0, it takes about 10ms to process a listLogicalRouterPoliciesByFilter and it takes about 600ms in v1.12.28.