The Two-Minute Loop: Hunting a Control Plane That Never Sleeps

#

A single-node Kubernetes control plane was showing up as the busiest process on an otherwise idle machine. The interesting part wasn’t the CPU number — it was that three independent metric families disagreed with each other by three orders of magnitude, the log line that looked like the cause meant the exact opposite of what it appeared to mean, and the reconciler responsible wasn’t even in the repository named on the container image.

TL;DR

#

• The machine was not busy: 28 cores, load average 1.8, ~97% idle. But top and ps both showed the k3s process at the top, and both lied — one reports a lifetime average, the other an interval average. Sampling /proc/<pid>/stat directly showed the truth: ~12% of one core, then ~113% of one core, alternating on a ~60-second cycle.
• GC was not the problem, despite a CPU profile littered with runtime.scanObject. go_gc_duration_seconds barely moved. The process had allocated 23.5 TB over 42 days, but it wasn’t spending time collecting.
• The hot path was DELETE, through the admission chain: DeleteResource → Store.Delete → conditionalDelete → deleteValidation → webhook dispatch. 26.7% of all samples sat inside Webhook.Dispatch.
• One webhook accounted for 52,150,638 invocations — 99.1% of all admission webhook traffic in the cluster — on operation=DELETE of secrets. The storage layer agreed: 26,071,395 secret deletes. The cluster contained 90 secrets and had seen 85 creates.
• During a burst the webhook counter incremented at ~718/s while apiserver_request_total, summed across every series, incremented at 10.2/s. Three counters, one request stream, three answers.
• A second, independent loop: a Cluster API provider reconciler re-applying 13 CRDs per minute, forever, with no changes in the cluster. Root cause found by reading the running binary rather than the repository: a 2-minute default sync period plus a cache phase that force-applies everything precisely when the hash says nothing changed.
• Fixing that took it to 1 reconcile in 6 minutes and 0.0 CRD applies per minute.

The complaint

#

The setup is unremarkable: a single-node k3s control plane on a 28-core box, plus one worker. top sorted by CPU put k3s at the top, always, and ps agreed with a lifetime average of 11.7%. On a machine whose load average was 1.8 and which reported 97% idle, that reads as a control plane that is doing far too much work.

The first instinct is to believe the number and go looking for the work. Both parts of that are mistakes.

ps’s %CPU is (utime+stime)/elapsed — a lifetime average. Over 42 days it tells you almost nothing about now. top is better but still an interval average, and it can’t show you a process that is idle half the time and saturating a core the other half. The honest instrument is the kernel’s own accounting, sampled by hand:

def cpu():
    f = open('/proc/4666/stat').read().split()
    return (int(f[13]) + int(f[14])) / 100.0   # utime+stime, in seconds

prev = cpu()
for _ in range(20):
    time.sleep(5)
    cur = cpu()
    print(f"{(cur - prev) / 5 * 100:5.0f}%", end='  ')
    prev = cur

  24%   10%    9%    9%   10%   17%   10%   38%
  10%    9%   49%  113%  113%   98%  113%   98%
 114%   40%   10%   10%

There it is. Not a slowly-busy process — a bimodal one. Baseline is 10–14% of a single core; then it pegs a full core for roughly 30 seconds, then drops back. Over a minute that averages out to about 55% of one core, which is why the lifetime average (12%) and any short sample could both be “true” and both be unhelpful.

So: something runs on a ~60-second timer and costs about a core-second per second while it runs.

Ruling out the obvious: it isn’t GC

#

The Go CPU profile was full of allocator and collector frames — runtime.tryDeferToSpanScan, runtime.scanObject, runtime.(*lfstack).pop. That’s the signature of GC assist and mark work, and it’s a trap: those frames appear whenever a process allocates hard, not necessarily when it collects hard.

The runtime’s own counters settled it:

allocation rate : 37.5 MB/s
GC cycles       : 5.0 per minute
GC CPU (wall)   : 0.0% of one core

5 GC cycles a minute at 0% of a core. Allocation was heavy — 23.5 TB cumulatively — but the collector was nowhere near the bottleneck. The profile frames were incidental. If I’d stopped at “the profile says GC”, I’d have spent the afternoon tuning GOGC and changed nothing.

Getting a CPU profile out of a process you don’t own

#

k3s is one of those binaries that is really four binaries. The API server, controller manager, scheduler, and kubelet all live in the same Go process. That’s usually an operational annoyance; here it’s a gift, because it means one profile covers all of them.

If you started the API server with --profiling=true (k3s sets it, or you can add it), the standard handler is reachable through the API:

kubectl get --raw '/debug/pprof/profile?seconds=60' > cpu.pb
go tool pprof -top -cum cpu.pb

There’s a second route that’s less well known and very useful on a cluster where you can’t touch the server’s flags: proxying through a node.

kubectl get --raw '/api/v1/nodes/<node>/proxy/debug/pprof/profile?seconds=20' > kubelet.pb

Nominally that’s “the kubelet’s pprof”. Because the kubelet shares a process with the API server, you get the whole process. I used it to confirm the local picture matched what the server was telling me, and later to check whether a different node’s agent was the culprit.

To find when to profile, don’t guess — poll the counter until the burst is live, then snapshot:

while True:
    a = cpu(); time.sleep(3); b = cpu()
    if (b - a) / 3 * 100 > 60:
        break          # a burst is in progress; profile now

Profiling a bimodal process without gating on that condition is how you end up with a flat, useless profile — which is exactly what my first three attempts produced.

What the profile said

#

At 103% of a core, during a burst:

36.6%  DeleteResource.func1.1
       └─ registry.(*Store).Delete
          └─ storage/etcd3.(*store).Delete
             └─ conditionalDelete
                └─ rest.AdmissionToValidateObjectDeleteFunc.func1
                   └─ admission/plugin/webhook/generic.(*Webhook).Dispatch      26.7%
                      └─ mutating / validating dispatchers
      ~12%  encoding/json (appendCompact, checkValid, stateInString)
      ~18%  syscalls (network + filesystem)

Two things were surprising. First, AdmissionToValidateObjectDeleteFunc appears inside conditionalDelete, which looks like a call-graph inversion — admission should run before storage. It’s real: the delete validation callback is threaded down into the storage layer and invoked there, right before the conditional delete. If you’re reading a profile and think the ordering is impossible, check whether the “obviously wrong” nesting is actually a callback.

Second, admission was 26.7% of a fully-busy core, and 93% of that was the mutating dispatcher. Every one of these DELETE requests was making an HTTPS call out to a webhook, serialising the object, checking a rule set, and coming back.

That narrows it to one question: who is issuing a large number of deletes, and why?

The counters that disagree

#

Here is where the investigation stopped being linear. Three metric families describe the same traffic, and they gave three different answers.

The webhook instrumentation, aggregated over 42 days:

52,150,638 invocations, by webhook:
  52,150,638  rancher.cattle.io.secrets      (99.1%)
     451,180  rancher.cattle.io.clusters.management.cattle.io
       4,023  rancher.cattle.io.namespaces

Broken down by operation for that first webhook:

operation="DELETE", rejected="false", type="admit"        26,072,275
operation="DELETE", rejected="false", type="validating"   26,071,395
operation="UPDATE", rejected="false", type="validating"        5,773
operation="CREATE", rejected="false", type="validating"           59

The storage layer agreed with the webhook:

etcd_request_duration_seconds_count{operation="delete",resource="secrets"}  26,071,395

And the cluster contained 90 secrets, with 85 secret POSTs ever recorded. So this was 26 million deletes of secrets that do not exist.

But the request counters said something else entirely:

apiserver_request_total{resource="secrets",verb="DELETE",scope="resource"}    2,304
apiserver_request_duration_seconds_count{resource="secrets",verb="DELETE"}    2,304

Two thousand, not twenty-six million. And during a live burst, sampling all families together:

window 12s, k3s CPU 113% of core
  apiserver_request_total (all)     :     10.2/s
  secrets DELETE requests counted   :      0.0/s
  webhook invocations               :    718.1/s

718 webhook calls per second while the API server serves 10 requests per second. That ratio is not physically possible for ordinary admission — admission runs inside a request handler — and I never fully resolved it to my own satisfaction. The most economical explanation is that these requests enter through a path whose request-level instrumentation isn’t in the registry I was scraping, while the webhook and storage plugins are registered globally. I’m fairly confident about what is happening and less confident about why the counters disagree, and I’d rather write that down than paper over it.

What the correlation did establish beyond doubt:

Perfectly, repeatably anti-correlated with idle. Divide the webhook number by two — admit and validating both fire per call — and you get ~350 deletes per second during bursts. At roughly 700 bytes of request body each, that’s 245 KB/s, which is exactly the upload volume I measured coming off the far node.

The client that turned out to be me

#

The next step was to attribute the traffic to a source IP, and the first attempt produced a beautifully wrong answer.

ss -tin on the API server port gives per-socket byte counters. Sampling bytes_received twice and differencing tells you which peer is uploading. The first run showed two loopback connections at 1.7 MiB/s each — tens of times larger than anything else. Two internal clients hammering the API server. Very exciting.

It was my own kubectl invocations being counted. Every metrics scrape, every get --raw, every pod listing I’d run during the measurement was a localhost client, and I was sampling while running them.

Two lessons, both obvious in hindsight and neither of which I’d have avoided without stepping on them:

• Your probe is a client. Any per-peer traffic measurement taken while you’re also querying the API includes your own queries. I re-ran the same measurement with no kubectl in flight, and the 1.7 MiB/s vanished; the real signal was a steady 250–350 KB/s from a remote node.
• Check the units and the protocol. A sibling mistake the same afternoon: a metrics endpoint that appeared dead on curl was in fact a UDP push, and curl quite properly reported connection refused on TCP. Tools tell you about the protocol you asked for, not the one that’s in use.

With the noise gone, the picture was clean: bursts came from a node that was not the control plane, and all connections from it were owned by that node’s k3s-agent — but the agent process itself was idle, which meant it was a relay for a pod on that node, and the pod’s identity was another layer down: a local API load balancer, SNAT, conntrack, and network namespaces.

A useful trap encountered here, worth flagging for anyone else doing it: I tried to measure per-object churn by diffing each Lease’s resourceVersion and got 119 bumps per 30 seconds on every single lease — all of them identical. resourceVersion is a cluster-global revision, not a per-object counter, so that measurement was measuring the entire cluster’s write rate and attributing it to nineteen different objects. Reading it as per-object churn would have sent me hunting a phantom.

Meanwhile, a completely different loop

#

While inventorying write traffic I noticed counters that made no sense in aggregate:

• DELETE namespaces → 404 — 42,797 of them
• POST subjectaccessreviews — 164,026
• POST serviceaccounts/token — 42,820
• DELETE jobs/rolebindings/roles → 404 — 6,350 / 5,111 / 5,026
• APPLY customresourcedefinitions — 13.0 per minute, indefinitely

The first group is a cleanup loop reaping things that are already gone, roughly once per 85 seconds. Annoying, not hot. The last one was different, because I’d seen its log lines:

"Reconciling provider"
"Updating Secret: <namespace>/<provider>-env-variables"
"Applying provider configuration from cache"
"Applied all objects from cache"

Every ~60 seconds, every time with the same sequence, on a cluster where nothing was changing.

Read the binary, not the repository

#

The container image named a repository. The source at the tag that image claimed did not contain the file named in the log lines. Guessing at versions is a waste of time; the running binary knows.

# get the container's host PID
crictl inspect <container-id> | jq '.info.pid'

# extract and interrogate the actual executable
cp /proc/<pid>/exe /tmp/bin
go version -m /tmp/bin

path  github.com/rancher/turtles
      build  -tags=community

Good — but still the wrong tree, because the file in the logs wasn’t there. strings on the same binary answered it in one shot:

sigs.k8s.io/cluster-api-operator@v0.29.0/internal/controller/genericprovider_controller.go

The reconciler emitting those logs was a dependency, not the project itself. That’s why grepping the repository turned up nothing, and it’s the single highest-value technique in this whole investigation: when a log line’s file doesn’t exist in the repo, stop reading the repo and read the binary.

The root cause, in four parts

#

1. The manager’s resync period defaults to two minutes.

fs.DurationVar(&syncPeriod, "sync-period", 2*time.Minute,
    "The minimum interval at which watched resources are reconciled (e.g. 15m)")
...
Cache: cache.Options{
    SyncPeriod: &syncPeriod,
},

cache.Options.SyncPeriod is not a poll interval on a cache miss — it makes the informer deliver a synthetic Update event for every watched object, every cycle, whether or not anything changed. Two minutes, by default, with no override in the deployment.

2. The controller watches the exact Secret it writes.

The provider’s spec.configSecret pointed at <provider>-env-variables — and the reconciler’s own syncSecrets phase rewrites that same Secret on every pass. The Secret→provider mapper keys on spec.configSecret, so each resync cycle enqueues the provider twice: once from the provider informer, once from the synthetic event for its own config Secret. Predicted ~2 enqueues per 2-minute cycle; measured 58 reconciles per hour.

It doesn’t run away because the Secret write is a no-op at the API server — an identical Update doesn’t bump resourceVersion, so no watch event is generated. I confirmed that directly: the Secret’s resourceVersion stayed constant across two minutes containing two logged “Updating Secret” attempts. This loop survives on a technicality.

3. The wrapper’s phases run before the cache short-circuit.

The library offers an early-out: apply from cache, and if nothing changed, stop before doing expensive work. But the consuming project prepends its own phases ahead of it:

r.ReconcilePhases = []controller.PhaseFn{
    r.waitForClusterctlConfigUpdate,
    r.setProviderSpec,
    r.syncSecrets,                    // <-- unconditional write attempt
}
...
r.ReconcilePhases = append(r.ReconcilePhases, []controller.PhaseFn{
    rec.ApplyFromCache,               // <-- "nothing changed, stop early" is decided here
    ...

So the decision to stop is made after the side effects have already happened. (The cert-manager cleanup phase is the one that does short-circuit correctly, via a condition check — worth noting so it doesn’t get blamed.)

4. The cache-hit path is the expensive one.

cacheHash := fmt.Sprintf("%x", hash.Sum(nil))
if secret.GetAnnotations()[appliedSpecHashAnnotation] != cacheHash ||
   p.provider.GetAnnotations()[appliedSpecHashAnnotation] != cacheHash {
    log.Info("Provider or cache state has changed", ...)
    return &Result{}, nil                       // mismatch: don't apply
}

log.Info("Applying provider configuration from cache")
...
log.Info("Applied all objects from cache")       // hash MATCHED: apply everything

The hash covers the provider spec, the cache Secret, and the clusterctl config file. It does not cover live cluster state, and there is no per-object diff before applying. So:

• mismatch → apply nothing,
• match → server-side apply the entire bundle, with client.ForceOwnership.

A match is the steady state. The expensive branch is therefore the default branch, and the logs read backwards: “Provider or cache state has changed” means nothing was applied, and “Applying provider configuration from cache” means nothing changed.

Measured: 13 CRD applies per minute, 0.2–0.75 s per run, each one reclaiming field ownership from any other manager that had touched those CRDs.

The fix and the arithmetic

#

One argument, no code:

managerArguments:
  - --sync-period=10h

Same cluster, same provider, nothing else changed.

Two things worth saying about this fix. First, it is a mitigation: it stops the timer, it doesn’t make the cache-hit path cheap. If a genuine drift event arrives, that path still force-applies everything. Second, it is not the CPU fix — this loop was worth about 1% of a core. It’s a correctness and write-amplification fix, and the reason it mattered was the ForceOwnership fights, not the CPU.

What I’d take away

#

• Don’t trust %CPU for bimodal work. Lifetime and interval averages can both be accurate and both misleading. Sample the kernel counters yourself.
• A profile full of GC frames does not mean GC is the cost. Check go_gc_duration_seconds before you touch GOGC.
• Your instrumentation is part of the system. Two of my “discoveries” were my own probe traffic and my own wrong assumption about a wire protocol.
• resourceVersion is global. Never diff it per-object to infer per-object write rates.
• When a log line’s source file isn’t in the repository, read the binary. go version -m and strings found the real module and the real file in under a minute, after I’d wasted a while guessing at tags.
• Read the condition, not the message. The log line that looked like the cause was emitted on the branch that did nothing.
• Metric families can legitimately disagree by three orders of magnitude when they’re registered by different layers of the same process. Report the disagreement; don’t average it away into a tidy story.

Still open

#

The 350-deletes-per-second client is not identified. I have the volume (245 KB/s), the transport path (a remote node’s agent relaying, then SNAT, then a pod), the shape (deletes of non-existent secrets, so no watch events and no visible churn), and the timing (bursts on a ~60-second cycle, recently 13× the historical average). What I don’t have is a name, because the only per-user metric in the API server collapses every identity into a bucket literally called other, and request-level attribution needs an audit policy.

That’s the next step, and it needs a single API server restart. Given that the unidentified client is worth roughly one full core on a machine that is otherwise idle, it’s worth the interruption.