coilyco-flight-deck/infrastructure

Watch

kai-server k3s datastore answers every operation in ~190ms at only 9 requests/second #845

New issue

Open

opened 2026-08-15 20:47:40 +00:00 by coilyco-ops · 1 comment

coilyco-ops commented

2026-08-15 20:47:40 +00:00

Owner

Summary

The k3s datastore on kai-server is roughly 40x slower than a local backend should be, and the latency is nearly identical across operation shapes that should differ enormously. Request volume is low, so this is a latency problem rather than a load problem.

Split out of #839, which was closed because its CPU premise turned out to be a measurement error. This finding is real and independent of that.

Current rate and latency

Measured as a delta between two /metrics scrapes 79 seconds apart, so these are current values and not lifetime averages:

OP                REQ/SEC       AVG_MS
get                   5.8        175.8
update                1.6        226.6
listWithCount         1.7        214.8
create                0.2        196.7
list                  0.1        222.2
delete                0.0        190.0

Total load is about 9.4 requests per second. For a local backend, single-digit milliseconds is the expectation.

The uniformity is the interesting part

A point get and a listWithCount do completely different amounts of work. A get is a single indexed row lookup. listWithCount is a scan plus an aggregate. They land 39ms apart, and every operation type sits in a 176ms to 227ms band.

That shape does not look like disk seek time or query cost, both of which would spread widely across those operations. It looks like a fixed per-request cost sitting in front of the actual work: a serialization point, a lock, a batching interval, or a round trip.

Not an external datastore

The obvious explanation for a uniform fixed cost would be a network round trip to an external datastore. It is not that. There is no --datastore-endpoint anywhere in this repository, so k3s is on its default local sqlite via kine, on the node's NVMe.

Lifetime totals for scale

OP             COUNT        TOTAL_SEC   AVG_MS
get         20070597        2713166.2    135.2
listWithCount 2375153         288446.4    121.4
update       2196806         314879.9    143.3
list          539745         122869.5    227.6
create         62138           8485.7    136.6
delete         24194           3143.5    129.9

Lifetime averages are somewhat better than current (135ms vs 176ms for get), so this may be gradually degrading. Worth confirming rather than assuming, since it rests on two data points.

Suggested investigation

Datastore file size and WAL growth. Still blocked on the allowlist gap in coilyco-flight-deck/node-stats-mcp#23.
Whether kine compaction is running and keeping up. A datastore that has never compacted grows a large revision history that slows every query uniformly, which fits the observed shape.
etcd_request_errors_total and the duration histogram buckets, to see whether this is a uniform shift or a bimodal distribution being flattened by averaging.

Why it may not be urgent

Nothing is currently starved. Node CPU pressure stall full is 0.00%, and k3s-server draws 2.06 cores against a 2.34 core lifetime average. Roughly 1.8 datastore requests are in flight at any moment, which the system absorbs. This is headroom being quietly consumed rather than an active incident, and it would become an incident under a burst.

## Summary The k3s datastore on kai-server is roughly 40x slower than a local backend should be, and the latency is nearly identical across operation shapes that should differ enormously. Request volume is low, so this is a latency problem rather than a load problem. Split out of #839, which was closed because its CPU premise turned out to be a measurement error. This finding is real and independent of that. ## Current rate and latency Measured as a delta between two `/metrics` scrapes 79 seconds apart, so these are current values and not lifetime averages: ``` OP REQ/SEC AVG_MS get 5.8 175.8 update 1.6 226.6 listWithCount 1.7 214.8 create 0.2 196.7 list 0.1 222.2 delete 0.0 190.0 ``` Total load is about 9.4 requests per second. For a local backend, single-digit milliseconds is the expectation. ## The uniformity is the interesting part A point `get` and a `listWithCount` do completely different amounts of work. A `get` is a single indexed row lookup. `listWithCount` is a scan plus an aggregate. They land 39ms apart, and every operation type sits in a 176ms to 227ms band. That shape does not look like disk seek time or query cost, both of which would spread widely across those operations. It looks like a fixed per-request cost sitting in front of the actual work: a serialization point, a lock, a batching interval, or a round trip. ## Not an external datastore The obvious explanation for a uniform fixed cost would be a network round trip to an external datastore. It is not that. There is no `--datastore-endpoint` anywhere in this repository, so k3s is on its default local sqlite via kine, on the node's NVMe. ## Lifetime totals for scale ``` OP COUNT TOTAL_SEC AVG_MS get 20070597 2713166.2 135.2 listWithCount 2375153 288446.4 121.4 update 2196806 314879.9 143.3 list 539745 122869.5 227.6 create 62138 8485.7 136.6 delete 24194 3143.5 129.9 ``` Lifetime averages are somewhat better than current (135ms vs 176ms for `get`), so this may be gradually degrading. Worth confirming rather than assuming, since it rests on two data points. ## Suggested investigation - Datastore file size and WAL growth. Still blocked on the allowlist gap in `coilyco-flight-deck/node-stats-mcp#23`. - Whether kine compaction is running and keeping up. A datastore that has never compacted grows a large revision history that slows every query uniformly, which fits the observed shape. - `etcd_request_errors_total` and the duration histogram buckets, to see whether this is a uniform shift or a bimodal distribution being flattened by averaging. ## Why it may not be urgent Nothing is currently starved. Node CPU pressure stall `full` is 0.00%, and `k3s-server` draws 2.06 cores against a 2.34 core lifetime average. Roughly 1.8 datastore requests are in flight at any moment, which the system absorbs. This is headroom being quietly consumed rather than an active incident, and it would become an incident under a burst.

coilyco-ops commented

2026-08-15 20:59:48 +00:00

Author

Owner

Raw evidence

Recording the underlying counters so the derived numbers above can be checked without re-deriving them.

Method

Two scrapes of the k3s metrics endpoint, 79 seconds apart. Reachable read-only through the guarded surface:

aosguard ops kubectl get --raw /metrics

Timestamps: t1=1786826663, t2=1786826742, so dt=79s.

Raw datastore counters

etcd_request_duration_seconds_{sum,count}, aggregated across all type labels for each operation:

OP               SUM_t1      COUNT_t1        SUM_t2      COUNT_t2
get           2713170.0      20070597     2713250.0      20071052
listWithCount  288446.0       2375153      288475.0       2375288
update         314880.0       2196806      314909.0       2196934
list           122869.0        539745      122871.0        539754
create           8485.74         62138       8488.10         62150
delete           3143.45         24194       3144.02         24197

Derivation for get: (2713250.0 - 2713170.0) / (20071052 - 20070597) = 80.0 / 455 = 175.8ms, over 455 / 79 = 5.8 req/sec. The other rows follow the same arithmetic.

CPU counters, for the record

These belong to the closed #839 but are the basis for the "not CPU-starved" note above, so they are worth keeping next to the latency numbers.

m1  process_cpu_seconds_total  3.61844438e+06
m2  process_cpu_seconds_total  3.61860704e+06
    process_start_time_seconds 1.785280297e+09

Delta 162.66 cpu-seconds over 79s = 2.06 cores current. Lifetime 3618607 / (now - 1785280297) = 2.34 cores over 17.9 days uptime.

I checked the sample ordering explicitly rather than trusting output order, since a monotonic counter appearing to decrease would have meant a process restart and invalidated the whole calculation. File mtimes confirm m1 at 1786826663 and m2 at 1786826742, and the counter increases between them.

Supporting observations

go_goroutines                        10055
go_threads                             189
process_resident_memory_bytes   1.4846e+09

Concurrent watches by resource, from apiserver_longrunning_requests:

   100  configmaps
    37  secrets
    16  nodes
    12  pods
    11  services

Not investigated

Per the earlier list and deliberately left open: the duration histogram buckets, whether kine compaction is running, and the datastore file and WAL size (still blocked on coilyco-flight-deck/node-stats-mcp#23).

## Raw evidence Recording the underlying counters so the derived numbers above can be checked without re-deriving them. ### Method Two scrapes of the k3s metrics endpoint, 79 seconds apart. Reachable read-only through the guarded surface: ``` aosguard ops kubectl get --raw /metrics ``` Timestamps: `t1=1786826663`, `t2=1786826742`, so `dt=79s`. ### Raw datastore counters `etcd_request_duration_seconds_{sum,count}`, aggregated across all `type` labels for each `operation`: ``` OP SUM_t1 COUNT_t1 SUM_t2 COUNT_t2 get 2713170.0 20070597 2713250.0 20071052 listWithCount 288446.0 2375153 288475.0 2375288 update 314880.0 2196806 314909.0 2196934 list 122869.0 539745 122871.0 539754 create 8485.74 62138 8488.10 62150 delete 3143.45 24194 3144.02 24197 ``` Derivation for `get`: `(2713250.0 - 2713170.0) / (20071052 - 20070597)` = `80.0 / 455` = **175.8ms**, over `455 / 79` = **5.8 req/sec**. The other rows follow the same arithmetic. ### CPU counters, for the record These belong to the closed #839 but are the basis for the "not CPU-starved" note above, so they are worth keeping next to the latency numbers. ``` m1 process_cpu_seconds_total 3.61844438e+06 m2 process_cpu_seconds_total 3.61860704e+06 process_start_time_seconds 1.785280297e+09 ``` Delta `162.66` cpu-seconds over `79s` = **2.06 cores** current. Lifetime `3618607 / (now - 1785280297)` = **2.34 cores** over 17.9 days uptime. I checked the sample ordering explicitly rather than trusting output order, since a monotonic counter appearing to decrease would have meant a process restart and invalidated the whole calculation. File mtimes confirm `m1` at 1786826663 and `m2` at 1786826742, and the counter increases between them. ### Supporting observations ``` go_goroutines 10055 go_threads 189 process_resident_memory_bytes 1.4846e+09 ``` Concurrent watches by resource, from `apiserver_longrunning_requests`: ``` 100 configmaps 37 secrets 16 nodes 12 pods 11 services ``` ### Not investigated Per the earlier list and deliberately left open: the duration histogram buckets, whether kine compaction is running, and the datastore file and WAL size (still blocked on `coilyco-flight-deck/node-stats-mcp#23`).

coilyco-ops added the

role/sysadmin

priority

labels

2026-08-25 08:02:09 +00:00

coilyco-ops added the

autonomy

async-consult

label

2026-08-25 09:30:59 +00:00

coilyco-ops added this to the Storage and capacity milestone

2026-08-29 06:09:10 +00:00