Kube-proxy facing locking timeout in large clusters during load test with services enabled

[shyamjvs]

Follows from discussion in #48052

We noticed this while performing load test on 4000 node clusters with services enabled. The iptables restore step in the proxier fails with:

E0625 09:03:14.873338       5 proxier.go:1574] Failed to execute iptables-restore: failed to acquire old iptables lock: timed out waiting for the condition

And the reason quite likely is because of "huge" size of iptables (tens of MBs) as we run 30 pods per node and each pod is part of exactly one service
=> 30 * 4000 = 120k service endpoints (and these updates happen on all 4000 nodes)

cc @kubernetes/sig-network-misc @kubernetes/sig-scalability-misc @danwinship @wojtek-t

[shyamjvs]

fyi, the logs for the run are here - http://gcsweb.k8s.io/gcs/kubernetes-jenkins/logs/ci-kubernetes-e2e-gce-enormous-cluster/10/

[freehan]

I suspect other components are holding the lock and fail to release.
Is kube-proxy able to have successful iptables-restore after first occurence?

[shyamjvs]

@freehan It's failing continuously (https://storage.googleapis.com/kubernetes-jenkins/logs/ci-kubernetes-e2e-gce-enormous-cluster/10/artifacts/e2e-enormous-cluster-minion-group-01nl/kube-proxy.log)

[shyamjvs]

Linking issue #47344 for tracking.

[shyamjvs]

cc @wojtek-t

[freehan]

Are the nodes running on CVM or COS? It looks like it is running on CVM, right?

[freehan]

Is there anyway we can execute lsof on a node in the bad state?

[freehan]

It looks like iptables util cannot open a specific linux domain socket. I suspect kube-proxy failed to close it during one run. Not sure why. I will send a PR to expose the error soon.

[shyamjvs]

@freehan The nodes were running on gci (which I guess is the same as cos). Ref: https://github.com/kubernetes/test-infra/blob/master/jobs/ci-kubernetes-e2e-gce-enormous-cluster.env#L33

[cmluciano]

May be related #45385.

I tried to find the dashboard where the enormous node test + services-enabled is. Can anyone provide a pointer to the testgrid runs?

[shyamjvs]

The job for gce 5k-node performance test - https://k8s-testgrid.appspot.com/google-gce-scale#gce-scale-performance
It's not automated yet, but I'm manually triggering the job almost everyday (fixing some bugs each time) until the test goes green.
And regarding services, we reduced it to half of the original no. (which was 16400) without changing total no. of pods involved in services (ref #48908), just to experiment.

[fejta-bot]

Issues go stale after 90d of inactivity.
Mark the issue as fresh with /remove-lifecycle stale.
Stale issues rot after an additional 30d of inactivity and eventually close.

Prevent issues from auto-closing with an /lifecycle frozen comment.

If this issue is safe to close now please do so with /close.

Send feedback to sig-testing, kubernetes/test-infra and/or @fejta.
/lifecycle stale

[bowei]

@shyamjvs does this remain an issue?

[wojtek-t]

I think that it actually still is.
But I will let @shyamjvs answer this (he is on vacation now, will be back on Monday)

[wojtek-t]

/lifecycle frozen

[spiffxp]

/remove-lifecycle frozen

[spiffxp]

whoops, I meant
/remove-lifecycle stale
/lifecycle frozen

[wojtek-t]

@danwinship - given all the above, I think the only open question that I still have is:
"what is grabbing iptables lock in our tests and keeps it for 2s+ so that kube-proxy is not able to grab it during some sync rounds".
I've looked into kubelet logs and didn't see any traces, meaning that it doesn't seem to be kubelet. Can this be something in OS?
@danwinship - thoughts?

[danwinship]

docker does iptables stuff internally in some cases, so that might be it. Your network plugin might also be doing stuff as part of pod setup.

[shyamjvs]

I've sent the above PR to experiment with ipvs in our scalability tests (as it seems GA now). The above problem with iptables might just become obsolete in case we're going to make a switch later.

[athenabot]

@shyamjvs
If this issue has been triaged, please comment /remove-triage unresolved.

If you aren't able to handle this issue, consider unassigning yourself and/or adding the help-wanted label.

🤖 I am a bot run by vllry. 👩‍🔬

[freehan]

reopen if needed

[wojtek-t]

Hmm - it still seems to be an issue - it was actually the main reason why we had to revert: #77541

[athenabot]

@shyamjvs
If this issue has been triaged, please comment /remove-triage unresolved.

If you aren't able to handle this issue, consider unassigning yourself and/or adding the help-wanted label.

🤖 I am a bot run by vllry. 👩‍🔬

[athenabot]

@shyamjvs
If this issue has been triaged, please comment /remove-triage unresolved.

If you aren't able to handle this issue, consider unassigning yourself and/or adding the help-wanted label.

🤖 I am a bot run by vllry. 👩‍🔬

[dcbw]

@squeed will add a metric for failed iptables calls

@wojtek-t what kernel versions do you have?

[dcbw]

/remove-triage unresolved

[squeed]

Filed #80061 for metrics enhancements.

[wojtek-t]

@wojtek-t what kernel versions do you have?

4.14. (I can't remember exactly).
Do you have any specific feature on your mind that helps here and was added in particular kernel version?

[vanyans]

Hello,

I am seeing this issue in my proxy pods:
E0117 08:12:44.604344 1 proxier.go:1402] Failed to execute iptables-restore: failed to acquire new iptables lock: timed out waiting for the condition
kube-proxy v1.15.4

Any solutions on this? Let me know if you need more info
Thank you!

kube-proxy-fail-log.txt

[aojea]

are you using the CNI portmap plugin?

[vanyans]

Hi. We are using NSX-T CNI.

[aojea]

I think that there can be multiple reasons, I can share what I did to find a problem with the portmap plugin holding the lock.

I just patched the kubelet 22665fc to log the pid of the process, then I monitored kube-proxy to trigger an script when it finds the error message

Failed to execute iptables-restore: failed to acquire new iptables lock: timed out waiting for the condition

that dumps all the processes so you can check "who" was holding the lock

Hope this can be useful

[vanyans]

Thank you! I will try this.
When you say portmap plugin, are you referring to this one: https://github.com/containernetworking/plugins/tree/master/plugins/meta/portmap

[aojea]

yeah, that one
This is the issue explaining the problem
containernetworking/plugins#418

[dcbw]

I think we can close this; multiple performance improvements in the kernel iptables/nftables code, improvements in iptables-nft, and the move to default to the IPVS proxy make iptables lock contention much less of an issue. If we do still see this, we can re-open.

/close

[k8s-ci-robot]

@dcbw: Closing this issue.

In response to this:

I think we can close this; multiple performance improvements in the kernel iptables/nftables code, improvements in iptables-nft, and the move to default to the IPVS proxy make iptables lock contention much less of an issue. If we do still see this, we can re-open.

/close

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.