Skip to content

e2e: cozytest forks date for every trace line, so the HelmRelease wait costs minutes once date is slow #5302

Open

Description

The e2e test runner starts one date process for every line of trace it prints, and the HelmRelease wait prints a lot of trace. hack/cozytest.sh reads the set -x output of each test line by line and runs now=$(( $(date +%s) - START )) per line (cozytest.sh#L91). cozy_wait_all_helmreleases_ready keeps the full kubectl get helmreleases -A -o json output in snapshot and pipes it into jq four times per poll (e2e-wait-helmreleases.sh#L34-L75). Under set -x each of those lines puts the whole JSON into the trace. With 93 HelmReleases that is about 17.7k lines each time, about five times per poll. So the wait time grows with the number of HelmReleases times the cost of starting date, even when every release is already Ready.

It showed up when a change moved the e2e sandbox image from ubuntu:24.04 to ubuntu:26.04. On 26.04 /usr/bin/date is the uutils implementation (uutils 0.10.0), not GNU coreutils. I measured it natively on arm64 with no emulation. 5000 runs of date +%s from a dash loop took 1229 ms on 24.04 and 5324 ms on 26.04. 5000 runs of /bin/true took 1084 ms and 1150 ms, so process start did not get slower, only date did. Inside 26.04, gnudate took 786 ms for 3000 runs and the uutils date took 3205 ms, with or without TZ=UTC.

The effect on a real run is about ten minutes. In run 43325958157 all 93 HelmReleases were Ready on the first snapshot, and the wait still took 12.25 min, about 73 s per trace of the snapshot. Six full-suite runs from the same night on the 24.04 sandbox spent about 2.9 min in the same wait, about 18 s per trace. The install step took 38.9 min against 27.8 to 29.3 min. Chainsaw suites do not go through this trace loop, and their times matched the other runs. The job hit its 215-minute limit in the last suite, with every earlier suite passing. An earlier run of the same change (39157982253, also on 26.04) shows the same 12.3-minute wait.

This overlaps #4705, which is about the log size from the same snapshot trace. This issue is about the time. Fixing #4705 removes most of the cost in this one helper, but the per-line date in cozytest stays and hits any test with a long trace.

Fix shape: in run_one, stop starting a process per line. The timestamp can be taken only on lines that print one, or refreshed once every N lines. Separately, the snapshot jq pipelines in cozy_wait_all_helmreleases_ready can run under set +x, or read the snapshot from a file, so the JSON never reaches the trace. That second part is the #4705 fix.

A test that fails on the current code: a bats unit under hack/ puts a stub date first in PATH that counts its calls. It runs cozytest.sh on a one-test file that prints about 1000 lines and checks that the number of date calls stays a small constant instead of growing with the line count.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    triage/needs-triageIndicates an issue needs triage by a maintainer

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions