Broken SQL Connection pooling

[morzan1001]

Environmental Info:
K3s Version:
k3s version v1.28.10+k3s1 (a4c5612)
go version go1.21.9

Node(s) CPU architecture, OS, and Version:
Raspberry Pi 4 / Raspbian
Linux cluster-controller-1 6.6.31+rpt-rpi-v8 #1 SMP PREEMPT Debian 1:6.6.31-1+rpt1 (2024-05-29) aarch64 GNU/Linux

Cluster Configuration:
2 Servers and 6 Agents

Describe the bug:
Hi, I have been running a k3s cluster on Raspberry pis for about half a year. For this I have 2 servers and 6 agents as well as an external postgres database. until a few weeks ago everything went well until I got problems with the database. The pi that is responsible for the database is maxed out and runs at 100% on all cores (normally the database tasks are a piece of cake for it). So I tried to turn off all nodes one after the other and reduce them to a minimum setup (1 server and db) to see if the load is reduced. this is not the case. I have also frequently seen the following error in the server logs:

server error (FATAL: remaining connection slots are reserved for non-replication superuser connections (SQLSTATE 53300))

I tried to increase the max_connections of the Postgres database, but this only postpones the problem. I conclude from this that either connections to the db can no longer be terminated quickly enough or are no longer terminated at all. I actually thought K3s was using connection pooling here, but my guess is that something is going wrong here too. Of course, my database could simply be overloaded, but if you turn off the nodes and move to the database via cli, all queries are fast, so I have ruled this out for now.

Expected behavior:
As described, it should be possible to access an external database without any problems. Since I have a very small cluster, the resources provided should be sufficient.

Actual behavior:
Until a few weeks ago it was no problem at all to run my setup, but now I can no longer use the cluster because no more services are starting. I suspect there is a problem with the connection to the database or with the connection pooling.

Additional context / logs:
Flag:

--datastore-endpoint postgres://<name>:<pw>@<ip>:<port>/<db>

excerpt from the server logs

Aug 21 20:43:30 cluster-controller-1 k3s[7348]: time="2024-08-21T20:43:30+02:00" level=info msg="Slow SQL (started: 2024-08-21 20:43:28.130881168 +0200 CEST m=+88.578141900) (total time: 2.704447483s):  SELECT * FROM ( SELECT ( SELECT MAX(rkv.id) AS id FROM kine AS rkv), ( SELECT MAX(crkv.prev_revision) AS prev_revision FROM kine AS crkv WHERE crkv.name = 'compact_rev_key'), kv.id AS theid, kv.name, kv.created, kv.deleted, kv.create_revision, kv.prev_revision, kv.lease, kv.value, kv.old_value FROM kine AS kv JOIN ( SELECT MAX(mkv.id) AS id FROM kine AS mkv WHERE mkv.name LIKE $1 GROUP BY mkv.name) AS maxkv ON maxkv.id = kv.id WHERE kv.deleted = 0 OR $2 ) AS lkv ORDER BY lkv.theid ASC LIMIT 1 : [[/registry/leases/kube-system/kube-scheduler false]]"
Aug 21 20:43:30 cluster-controller-1 k3s[7348]: time="2024-08-21T20:43:30+02:00" level=error msg="error in txn compare:<target:MOD key:\"/registry/leases/kube-system/kube-scheduler\" mod_revision:249203471 > success:<request_put:<key:\"/registry/leases/kube-system/kube-scheduler\" value:\"k8s\\000\\n\\037\\n\\026coordination.k8s.io/v1\\022\\005Lease\\022\\361\\002\\n\\222\\002\\n\\016kube-scheduler\\022\\000\\032\\013kube-system\\\"\\000*$5930145b-1220-4155-9dc8-027f2fd0a2292\\0008\\000B\\010\\010\\366\\333\\243\\255\\006\\020\\000\\212\\001\\271\\001\\n\\003k3s\\022\\006Update\\032\\026coordination.k8s.io/v1\\\"\\010\\010\\320\\352\\230\\266\\006\\020\\0002\\010FieldsV1:|\\nz{\\\"f:spec\\\":{\\\"f:acquireTime\\\":{},\\\"f:holderIdentity\\\":{},\\\"f:leaseDurationSeconds\\\":{},\\\"f:leaseTransitions\\\":{},\\\"f:renewTime\\\":{}}}B\\000\\022Z\\n9cluster-controller-1_bde8544b-8d5b-4296-83fb-077d55f39bdb\\020\\017\\032\\013\\010\\304\\352\\230\\266\\006\\020\\320\\232\\343?\\\"\\013\\010\\320\\352\\230\\266\\006\\020\\250\\332\\224\\005(\\343\\010\\032\\000\\\"\\000\" > > failure:<request_range:<key:\"/registry/leases/kube-system/kube-scheduler\" > > : context canceled"
Aug 21 20:43:30 cluster-controller-1 k3s[7348]: E0821 20:43:30.836589    7348 writers.go:135] apiserver was unable to write a fallback JSON response: http: Handler timeout
Aug 21 20:43:30 cluster-controller-1 k3s[7348]: I0821 20:43:30.836737    7348 trace.go:236] Trace[2146868155]: "Update" accept:application/vnd.kubernetes.protobuf, */*,audit-id:af2b754f-a989-4a16-b46b-5930a3bc5552,client:127.0.0.1,protocol:HTTP/2.0,resource:leases,scope:resource,url:/apis/coordination.k8s.io/v1/namespaces/kube-system/leases/kube-scheduler,user-agent:k3s/v1.28.10+k3s1 (linux/arm64) kubernetes/a4c5612/leader-election,verb:PUT (21-Aug-2024 20:43:28.128) (total time: 2707ms):
Aug 21 20:43:30 cluster-controller-1 k3s[7348]: Trace[2146868155]: ["GuaranteedUpdate etcd3" audit-id:af2b754f-a989-4a16-b46b-5930a3bc5552,key:/leases/kube-system/kube-scheduler,type:*coordination.Lease,resource:leases.coordination.k8s.io 2707ms (20:43:28.129)
Aug 21 20:43:30 cluster-controller-1 k3s[7348]: Trace[2146868155]:  ---"Txn call failed" err:context canceled 2702ms (20:43:30.833)]
Aug 21 20:43:30 cluster-controller-1 k3s[7348]: Trace[2146868155]: [2.707742339s] [2.707742339s] END
Aug 21 20:43:30 cluster-controller-1 k3s[7348]: E0821 20:43:30.837556    7348 timeout.go:142] post-timeout activity - time-elapsed: 4.778637ms, PUT "/apis/coordination.k8s.io/v1/namespaces/kube-system/leases/kube-scheduler" result: <nil>
Aug 21 20:43:30 cluster-controller-1 k3s[7348]: E0821 20:43:30.877568    7348 leaderelection.go:369] Failed to update lock: Put "https://127.0.0.1:6444/apis/coordination.k8s.io/v1/namespaces/kube-system/leases/k3s-cloud-controller-manager?timeout=5s": context deadline exceeded
Aug 21 20:43:30 cluster-controller-1 k3s[7348]: I0821 20:43:30.877654    7348 leaderelection.go:285] failed to renew lease kube-system/k3s-cloud-controller-manager: timed out waiting for the condition
Aug 21 20:43:30 cluster-controller-1 k3s[7348]: E0821 20:43:30.877735    7348 controllermanager.go:273] "leaderelection lost"
Aug 21 20:43:31 cluster-controller-1 systemd[1]: k3s.service: Main process exited, code=exited, status=1/FAILURE
Aug 21 20:43:31 cluster-controller-1 systemd[1]: k3s.service: Failed with result 'exit-code'.
Aug 21 20:43:31 cluster-controller-1 systemd[1]: k3s.service: Unit process 2664 (containerd-shim) remains running after unit stopped.
Aug 21 20:43:31 cluster-controller-1 systemd[1]: k3s.service: Unit process 2665 (containerd-shim) remains running after unit stopped.
Aug 21 20:43:31 cluster-controller-1 systemd[1]: k3s.service: Unit process 2801 (containerd-shim) remains running after unit stopped.
Aug 21 20:43:31 cluster-controller-1 systemd[1]: k3s.service: Consumed 1min 37.550s CPU time.

many thanks for the help :)

[brandond]

Kine does use the default golang sql client connection pool support. There is nothing here that is K3s or Kine specific.

Connection pooling does not help you if your database is slow. If a client makes a request from the apiserver that requires a query to the datastore, and there are no pooled connections available (because all the current connections are tied up waiting for an existing query to complete), it will open a new connection. You now have even more queries running, and the database just gets even slower.

I would probably try to figure out why your database is running so slow. Is compaction failing? You should see this in your logs. If it is, you could try manually compacting, or just letting a single K3s server run for a while and see if it is able to compact successfully without additional client load.

[morzan1001]

thank you very much for the quick reply. I have already seen this issue here where you recommended running only one server in the hope that compacting will work.

Unfortunately, this has not helped me so far.

If a server is running (and therefore sending requests to the database at the same time) then queries are already very slow. Here is an example:

cluster=# select deleted,count(*) from kine group by deleted;
 deleted | count
---------+--------
       0 | 651986
       1 |  90360
(2 rows)

Time: 26874.141 ms (00:26.874)

I have checked the logs of the k3s server with journalctl. it seems to me that the compact last ran correctly 20 days ago. Since then it seems that I have these problems. currently it is not running. Is there any way to manually trigger or perform this to make the database faster again?

sudo journalctl -u k3s -r | grep msg=\"COMPACT
Aug 07 17:14:01 cluster-controller-1 k3s[332991]: time="2024-08-07T17:14:01+02:00" level=info msg="COMPACT compactRev=248468708 targetCompactRev=248469708 currentRev=249193181"

[brandond]

Are you able to raise it up to high enough for kine to stay up for >10 minutes, so that it can finish a compact cycle?

[morzan1001]

No I don't think 10 minutes is possible, I tried to allow 1000 connections to postgres but logically all connections get slower the more there are and then the problem multiplies.

[morzan1001]

In this issue here you have shown a query to execute the process manually on a sqlite. Could I try something similar in my postgres?

[brandond]

You can try running a manual compact query while k3s is down. This is mysql syntax; you might have to tweak it for postgres.

delete from kine where id in (select id  from (select id,name from kine where id NOT IN (select max(id) as  id from kine group by name)) as t)

[morzan1001]

Ok

cluster=# delete from kine where id in (select id  from (select id,name from kine where id NOT IN (select max(id) as  id from kine group by name)) as t);
DELETE 652110

Now I'm curious :D

[morzan1001]

as you can see here on startup of the server there are many queries. When the server starts i also see the old errors again, befor the service dies i can see this error:

Waiting to retrieve kube-proxy configuration; server is not ready: https://127.0.0.1:6443/v1-k3s/readyz: 500 Internal Server Error

I can try to increase the max connections again to see it the server can read an "active" status

[morzan1001]

Hey, I think I have to apologize, I was too impatient. the server has been restarted 4 or 5 times, but it looks like it is now running stable and the load on the database server is also small again. 🥳 I will now test adding workers and workloads again.