Skip to content

Commit cf2d9c6

Browse files
committed
test(e2e): split the tenant worker CPU time across QEMU threads
The node-join diagnostics phase samples the tenant worker's CPU counters twice on failure, but it reads them from the compute container's cgroup, and that cgroup holds every thread QEMU runs: the guest's vCPUs, QEMU's main thread, and its IO and worker threads. A container burning most of its quota while the guest reports no progress is two incompatible findings wearing one number, and no container-level counter separates them. Add a collector that execs into each Running worker's compute container, finds the QEMU process and copies every /proc/<pid>/task/<tid>/stat line into the artifact verbatim, with a legend beside them. Nothing is computed here. The legend names where utime and stime sit and why counting fields over whitespace reads the wrong column for exactly the threads the split is about: a KVM vCPU thread is named "CPU 0/KVM", that space is inside the comm parentheses, and every field after it shifts by one. It runs inside the sampling loop the two existing subjects already share, so it costs no second wait: both readings ride the interval already being paid, and the rate comes from the two files plus the stamps each one carries. Every way the read can come up short is a named outcome rather than an empty directory, and the legend and the pairing instruction are withheld from each of them: telling a reader to subtract two files asserts that both hold a whole reading. The probe shells out to nothing but getconf, whose absence it names, because a probe that needed cat would report a container missing coreutils as a container whose QEMU had exited, and it counts what it managed to read so that having read no process at all stays separable from having read them all without finding QEMU. Its stderr is suppressed on the walk rather than on either read: redirections are applied left to right, so a 2>/dev/null after an input redirect is not in place yet when opening the input fails, and a thread that exits between the glob and the read would otherwise put a shell complaint in the artifact beside a healthy capture. It also reports a QEMU that was named and then gone before its task files could be opened, because a process heading alone is enough to make the capture non-empty and would otherwise carry a legend describing columns the file does not have. The Pod listing the cAdvisor captures already share now takes its whole query as a parameter, so this collector reuses that read rather than carrying a third copy of it, and asks for the Running Pods only: a launcher left over from an earlier attempt costs the sibling caller nothing and would cost this one a bounded exec and a slot under its cap. The guard that holds the sampling group against the room the tenant snapshot needs now counts every capped walk in the loop rather than the two spelled the same way, so the new subject is inside the arithmetic rather than beside it. Assisted-By: Claude <[email protected]> Signed-off-by: Aleksei Sviridkin <[email protected]>
1 parent 66cd0fb commit cf2d9c6

7 files changed

Lines changed: 1330 additions & 73 deletions

File tree

‎docs/agents/e2e-testing.md‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -37,7 +37,7 @@ A Chainsaw `assert` polls until the resource matches its expected shape or the p
3737
3838
- Condition checks use the **filter-as-list** form `(conditions[?type == 'Ready'])`. Chainsaw v0.2.15 throws "field not found" on the indexed `(...)[0]` form.
3939
- Imperative checks that no Kubernetes API condition models — S3 reachability through a port-forward, an external LB HTTP path, MetalLB advertisement — stay in a `script` step. A bare `sleep N` inside such a script is allowed **only** when nothing better models the wait; annotate it with a `TODO(e2e-replace-fixed-timeouts):` comment. The bootstrap BATS (`hack/e2e-install-cozystack.bats`, `hack/e2e-chainsaw/_lib/run-kubernetes.sh`) carries the sanctioned `until kubectl get` exceptions.
40-
- A **measurement interval** is not one of those waits and does not take the marker. The rule above governs a `sleep` standing in for a condition nobody wrote a wait for, and the marker means "replace this once something models it". A gap between two readings of a cumulative counter models nothing and is the quantity itself: the diagnostics phase in `hack/e2e-chainsaw/_lib/run-kubernetes.sh` reads the tenant worker CPU counters and the sandbox nodes' `/proc/stat` on either side of one `COZY_DIAG_RATE_INTERVAL` wait, because a single reading of a counter that accumulates from container start is an average over the whole uptime and no rate at all. There is no event to wait for instead, so a `TODO` there would promise a replacement that cannot exist. Carve-outs are named here rather than judged case by case, and this is the only measurement-interval one.
40+
- A **measurement interval** is not one of those waits and does not take the marker. The rule above governs a `sleep` standing in for a condition nobody wrote a wait for, and the marker means "replace this once something models it". A gap between two readings of a cumulative counter models nothing and is the quantity itself: the diagnostics phase in `hack/e2e-chainsaw/_lib/run-kubernetes.sh` reads the tenant worker CPU counters, the sandbox nodes' `/proc/stat` and QEMU's per-thread `/proc/<pid>/task/<tid>/stat` on either side of one shared `COZY_DIAG_RATE_INTERVAL` wait, because a single reading of a counter that accumulates from container start is an average over the whole uptime and no rate at all. There is no event to wait for instead, so a `TODO` there would promise a replacement that cannot exist. Carve-outs are named here rather than judged case by case, and this is the only measurement-interval one.
4141

4242
### 3. Let Chainsaw own cleanup; no test-level EXIT/RETURN traps
4343

‎hack/e2e-chainsaw/_lib/run-kubernetes.sh‎

Lines changed: 338 additions & 51 deletions
Large diffs are not rendered by default.

‎hack/e2e-chainsaw/kubernetes-latest/chainsaw-test.yaml‎

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -36,8 +36,9 @@ spec:
3636
# serial-console family (~6m25s at worst, ~4m05s at the pool's minimum)
3737
# worker CPU usage and throttling counters, two samples
3838
# sandbox node CPU time, two samples
39-
# (those two alternate rather than run to completion in turn: both
40-
# take their first reading, one wait passes, both take their second)
39+
# worker per-thread CPU time inside virt-launcher, two samples
40+
# (those alternate rather than run to completion in turn: each takes
41+
# its first reading, one wait passes, each takes its second)
4142
# guest Talos capture
4243
# ghcr-mirror state, access log and warm-up Job
4344
# talos-image-cache diagnosis

‎hack/e2e-chainsaw/kubernetes-previous/chainsaw-test.yaml‎

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -30,8 +30,9 @@ spec:
3030
# serial-console family (~6m25s at worst, ~4m05s at the pool's minimum)
3131
# worker CPU usage and throttling counters, two samples
3232
# sandbox node CPU time, two samples
33-
# (those two alternate rather than run to completion in turn: both
34-
# take their first reading, one wait passes, both take their second)
33+
# worker per-thread CPU time inside virt-launcher, two samples
34+
# (those alternate rather than run to completion in turn: each takes
35+
# its first reading, one wait passes, each takes its second)
3536
# guest Talos capture
3637
# ghcr-mirror state, access log and warm-up Job
3738
# talos-image-cache diagnosis

‎hack/run-kubernetes-cpu-throttle_test.bats‎

Lines changed: 8 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -235,6 +235,12 @@ run_capture() {
235235
# name has to come from the Pod. Reading a fixed node, or the wrong one,
236236
# returns a healthy stranger's counters.
237237
assert_file_contains 'get --raw /api/v1/nodes/srv1/proxy/metrics/cadvisor' "$kubectl_calls"
238+
# And the node name comes from the field this caller asks the listing for.
239+
# That projection is a parameter of the shared listing, and the other caller
240+
# of it passes the Pod name instead; swapped, this capture would ask kubelets
241+
# named after Pods and get nothing, with no error to say why. The mock answers
242+
# any listing regardless of what was asked for, so nothing else here sees it.
243+
assert_file_contains 'jsonpath={range .items[*]}{.spec.nodeName}{"\n"}{end}' "$kubectl_calls"
238244
capture="$COZY_REPORT_DIR/snapshots/throttle-smoke/tenant-cpu-throttle/sample-1/srv1.txt"
239245
assert_file_contains 'container_cpu_cfs_throttled_periods_total' "$capture"
240246
# One assertion per alternative in the filter's regex, because a typo in an
@@ -567,7 +573,7 @@ run_capture() {
567573
fn=$(awk '/^cozy_capture_tenant_worker_cpu_throttle\(\)/,/^}/' "$lib"
568574
awk '/^_cozy_capture_worker_cadvisor\(\)/,/^}/' "$lib"
569575
awk '/^_cozy_cadvisor_node_stream\(\)/,/^}/' "$lib"
570-
awk '/^_cozy_cadvisor_worker_nodes\(\)/,/^}/' "$lib")
576+
awk '/^_cozy_virt_launcher_listing\(\)/,/^}/' "$lib")
571577
case "$fn" in
572578
*'max_nodes=3'*) ;;
573579
*) echo "expected the collector to cap the walk at the 3 nodes the comments state" >&2; return 1 ;;
@@ -668,7 +674,7 @@ run_capture() {
668674
# declined the cheaper reads around it -- which is the failure the phase
669675
# budget exists to prevent, reintroduced by the newest caller.
670676
lib=hack/e2e-chainsaw/_lib/run-kubernetes.sh
671-
gate=$(grep -n "^ *if cozy_diag_phase_has_time '(d) tenant worker CPU counters and sandbox node CPU time'; then$" \
677+
gate=$(grep -n "^ *if cozy_diag_phase_has_time '(d) tenant worker CPU counters, sandbox node CPU time and worker per-thread CPU time'; then$" \
672678
"$lib" | head -n 1 | cut -d: -f1)
673679
call=$(grep -n '^ *cozy_capture_tenant_worker_cpu_throttle "${_sample}" || true$' "$lib" | head -n 1 | cut -d: -f1)
674680
if [ -z "$gate" ] || [ -z "$call" ]; then

‎hack/run-kubernetes-node-join_test.bats‎

Lines changed: 25 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -232,6 +232,7 @@ stub_gated_collectors() {
232232
cozy_capture_tenant_worker_cpu_throttle() { printf 'cpu-throttle-stub\n'; }
233233
cozy_capture_tenant_worker_network_counters() { printf 'network-counters-stub\n'; }
234234
cozy_capture_sandbox_node_cpu_time() { printf 'sandbox-cpu-time-stub\n'; }
235+
cozy_capture_tenant_worker_thread_cpu() { printf 'thread-cpu-stub\n'; }
235236
ghcr_mirror_diagnose() { printf 'ghcr-mirror-stub\n'; }
236237
}
237238

@@ -702,7 +703,7 @@ assert_file_lacks_pattern() {
702703
# A rule written for additions does not catch a removal, so both directions
703704
# are named here.
704705
for marker in serial-console-stub talos-stub image-cache-stub cpu-throttle-stub \
705-
network-counters-stub ghcr-mirror-stub; do
706+
network-counters-stub sandbox-cpu-time-stub thread-cpu-stub ghcr-mirror-stub; do
706707
if grep -q "$marker" "$tmp/out"; then
707708
echo "FAIL: $marker ran after the phase ran out of budget" >&2
708709
false
@@ -711,7 +712,7 @@ assert_file_lacks_pattern() {
711712
assert_file_contains '(b1) tenant worker guest serial console: not collected' "$tmp/out"
712713
assert_file_contains '(b) in-guest Talos dmesg + kubelet logs + service states + links: not collected' "$tmp/out"
713714
assert_file_contains 're-probe talos-image-cache ClusterIP + cacher debug bundle: not collected' "$tmp/out"
714-
assert_file_contains '(d) tenant worker CPU counters and sandbox node CPU time: not collected' "$tmp/out"
715+
assert_file_contains '(d) tenant worker CPU counters, sandbox node CPU time and worker per-thread CPU time: not collected' "$tmp/out"
715716
assert_file_contains '(d2) tenant worker network counters: not collected' "$tmp/out"
716717
assert_file_contains 'ghcr-mirror state, access log and warm-up Job: not collected' "$tmp/out"
717718
rm -rf "$tmp"
@@ -933,6 +934,7 @@ assert_file_lacks_pattern() {
933934
cozy_capture_tenant_worker_network_counters() { :; }
934935
ghcr_mirror_diagnose() { :; }
935936
cozy_capture_sandbox_node_cpu_time() { :; }
937+
cozy_capture_tenant_worker_thread_cpu() { :; }
936938
kubectl() { printf "KUBECTL_RAN\n" >&2; }
937939
PATH='"$tmp"'/bin
938940
cozy_report_node_join_failure test-latest-version
@@ -1215,17 +1217,21 @@ assert_file_lacks_pattern() {
12151217
return 1
12161218
fi
12171219
done
1218-
# Every walk's cap, not the first one. The two subjects declare their own
1219-
# `local max_nodes` and are equal today, so taking the first would be right by
1220-
# accident: raise one alone and the arithmetic below would keep using the
1221-
# other, under-counting the pair while reading as satisfied.
1222-
caps=$(grep -oE 'local max_nodes=[0-9]+' "$lib" | sed -E 's/.*=//')
1220+
# Every walk's cap, not the first one, and not only the ones spelled
1221+
# `max_nodes`: the subjects declare their own literal and two of them are
1222+
# equal today, so taking the first would be right by accident, and a subject
1223+
# that walks Pods rather than nodes would be left out of the sum entirely --
1224+
# under-counting the pair while reading as satisfied.
1225+
#
1226+
# A literal cap only. The serial-console walk takes its cap from its caller,
1227+
# which is what keeps it out of this expression: it is not part of the pair.
1228+
caps=$(grep -oE 'local max_(nodes|pods)=[0-9]+' "$lib" | sed -E 's/.*=//')
12231229
# `|| true`: grep -c exits 1 on a count of zero, and under errexit that ends
12241230
# the test before the branch below can say what was missing -- the guard would
12251231
# still fail, with the diagnostic it was given replaced by silence.
12261232
ncaps=$(printf '%s\n' "$caps" | grep -c . || true)
1227-
if [ "$ncaps" -ne 2 ]; then
1228-
echo "expected two capped walks in $lib, found $ncaps; the pair arithmetic below is written for exactly the two subjects the sampling loop reads" >&2
1233+
if [ "$ncaps" -ne 3 ]; then
1234+
echo "expected three capped walks in $lib, found $ncaps; the pair arithmetic below is written for exactly the subjects the sampling loop reads" >&2
12291235
return 1
12301236
fi
12311237
# A capped walk costs a listing plus one read per node, each at the read bound
@@ -1293,9 +1299,10 @@ assert_file_lacks_pattern() {
12931299
return 1
12941300
fi
12951301
done
1296-
# Two subjects, two samples each, one walk apiece at that subject's own cap,
1297-
# plus the single wait. Summed per subject rather than doubling one walk, so a
1298-
# cap raised on one side alone is counted where it lands.
1302+
# Each subject, two samples each, one walk apiece at that subject's own cap,
1303+
# plus the single wait -- single because the subjects share the pass rather
1304+
# than each waiting for their own. Summed per subject rather than multiplying
1305+
# one walk, so a cap raised on one side alone is counted where it lands.
12991306
pair=$interval
13001307
for c in $caps; do
13011308
pair=$(( pair + 2 * (1 + c) * (bound + grace) ))
@@ -1372,9 +1379,10 @@ assert_file_lacks_pattern() {
13721379
# A helper renamed or a guard removed drops it out of `guarded`, and this
13731380
# fails; a capture dropped from the warning fails on the phrase check below.
13741381
for entry in \
1375-
'cozy_capture_tenant_worker_cpu_throttle:CPU throttling:_cozy_cadvisor_node_stream _cozy_cadvisor_worker_nodes' \
1376-
'cozy_capture_tenant_worker_network_counters:network counter:_cozy_cadvisor_node_stream _cozy_cadvisor_worker_nodes' \
1382+
'cozy_capture_tenant_worker_cpu_throttle:CPU throttling:_cozy_cadvisor_node_stream _cozy_virt_launcher_listing' \
1383+
'cozy_capture_tenant_worker_network_counters:network counter:_cozy_cadvisor_node_stream _cozy_virt_launcher_listing' \
13771384
'cozy_capture_sandbox_node_cpu_time:sandbox node CPU time:cozy_capture_sandbox_node_cpu_time' \
1385+
'cozy_capture_tenant_worker_thread_cpu:worker per-thread CPU time:cozy_capture_tenant_worker_thread_cpu _cozy_virt_launcher_listing' \
13781386
'ghcr_mirror_diagnose:ghcr-mirror:ghcr_mirror_diagnose _ghcr_mirror_bounded_read' \
13791387
'talos_image_cache_diagnose:talos-image-cache:talos_image_cache_diagnose _talos_image_cache_bounded_read'; do
13801388
fn=${entry%%:*}
@@ -1410,6 +1418,7 @@ ${carrier}
14101418
cozy_capture_tenant_worker_cpu_throttle) phrase='CPU throttling' ;;
14111419
cozy_capture_tenant_worker_network_counters) phrase='network counter' ;;
14121420
cozy_capture_sandbox_node_cpu_time) phrase='sandbox node CPU time' ;;
1421+
cozy_capture_tenant_worker_thread_cpu) phrase='worker per-thread CPU time' ;;
14131422
ghcr_mirror_diagnose) phrase='ghcr-mirror' ;;
14141423
talos_image_cache_diagnose) phrase='talos-image-cache' ;;
14151424
# The sentence enumerates the CAPTURES. Two other kinds of function guard
@@ -1421,7 +1430,7 @@ ${carrier}
14211430
# step. A function that is neither still fails below, which is what makes
14221431
# this a list of exemptions rather than a list of everything.
14231432
cozy_diag_read | _ghcr_mirror_bounded_read | _talos_image_cache_bounded_read) continue ;;
1424-
_cozy_cadvisor_node_stream | _cozy_cadvisor_worker_nodes) continue ;;
1433+
_cozy_cadvisor_node_stream | _cozy_virt_launcher_listing) continue ;;
14251434
cozy_report_node_join_failure | _talos_image_cache_deploy_state) continue ;;
14261435
*)
14271436
echo "$fn guards its call with command -v but this test has no phrase for it; add one here and to the warning" >&2
@@ -1473,6 +1482,7 @@ ${carrier}
14731482
case "$fn" in
14741483
cozy_capture_tenant_worker_cpu_throttle) phrase='worker CPU usage and throttling counters' ;;
14751484
cozy_capture_sandbox_node_cpu_time) phrase='sandbox node CPU time' ;;
1485+
cozy_capture_tenant_worker_thread_cpu) phrase='worker per-thread CPU time' ;;
14761486
cozy_capture_tenant_worker_network_counters) phrase='worker network counters' ;;
14771487
cozy_capture_tenant_serial_console) phrase='serial-console family' ;;
14781488
cozy_capture_tenant_talos) phrase='guest Talos capture' ;;

0 commit comments

Comments
 (0)