Skip to content

Slow validate clusters with big OpenShift clusters #494

Description

@nirs

Description

validate clusters takes ~348 seconds (nearly 6 minutes) when gathering from large OpenShift clusters over WAN. The bottleneck is log streaming over high-latency network, with secondary impact from hundreds of empty list API calls.

Using --remote gather (as in #407) should reduce this to ~30–50 seconds.

Example — validate clusters with high-latency network

% du -sh out/clusters/validate-clusters.data
282M    out/clusters/validate-clusters.data

% du -sh out/clusters/validate-clusters.data/*
 99M    out/clusters/validate-clusters.data/arft-site02
 91M    out/clusters/validate-clusters.data/arft-site03
 92M    out/clusters/validate-clusters.data/hub

Total wall time 348 s, almost all of it spent gathering data (345.8 s):

Wall (s) Step
348.20 Total
345.80 gather
344.40 -- gather "arft-site02"
322.90 -- gather "hub"
125.40 -- gather "arft-site03"
0.95 check S3 profiles
0.05 validate clusters data
2.50 validate config

From the log — clusters gathered in parallel, wall time = slowest cluster:

2026-07-29T17:43:21.294  Gathering from clusters ["hub" "arft-site02" "arft-site03"]
2026-07-29T17:43:21.297  Gathering from cluster "arft-site03"
2026-07-29T17:43:21.297  Gathering from cluster "hub"
2026-07-29T17:43:21.297  Gathering from cluster "arft-site02"
2026-07-29T17:45:26.659  Gathered 6865 resources from cluster "arft-site03" in 125.36 seconds
2026-07-29T17:48:44.192  Gathered 4182 resources from cluster "hub" in 322.88 seconds
2026-07-29T17:49:05.668  Gathered 5206 resources from cluster "arft-site02" in 344.35 seconds

Per-cluster breakdown

Cluster Resources Data Wall time
arft-site02 5,206 99 MiB 344.4 s
hub 4,182 92 MiB 322.9 s
arft-site03 6,865 91 MiB 125.4 s

arft-site03 has more resources yet finishes 2.7× faster — the difference is log streaming performance.

Why local gather was slow

1. Log streaming over WAN (main cause)

Log streaming throughput was 0.05–0.11 MiB/s, setting the wall-time floor:

Cluster Log file Size (MiB) Duration (s) Throughput
hub ramen-hub-operator/manager/current.log 30.50 301.50 0.10 MiB/s
hub odf-multicluster-console/current.log 18.70 284.40 0.07 MiB/s
hub odfmo-controller-manager/current.log 12.70 273.60 0.05 MiB/s
arft-site02 ramen-dr-cluster-operator/previous.log 31.80 298.40 0.11 MiB/s
arft-site02 ramen-dr-cluster-operator/current.log 14.80 157.50 0.09 MiB/s
arft-site03 ramen-dr-cluster-operator/current.log 12.70 7.70 1.64 MiB/s

From the log — a single 30 MiB log takes 5 minutes to stream over WAN:

2026-07-29T17:48:24.939  hub.logs  Gathered "openshift-operators/ramen-hub-operator-55d4c66fbb-pzb92/manager/current.log" in 301.470 seconds (0.10 MiB/s)
2026-07-29T17:48:07.874  hub.logs  Gathered "openshift-operators/odf-multicluster-console-7549574c65-gcs9w/odf-multicluster-console/current.log" in 284.410 seconds (0.07 MiB/s)
2026-07-29T17:47:57.052  hub.logs  Gathered "openshift-operators/odfmo-controller-manager-954859499-v7cvt/odf-multicluster-orchestrator/current.log" in 273.588 seconds (0.05 MiB/s)
2026-07-29T17:48:22.197  arft-site02.logs  Gathered "openshift-dr-system/ramen-dr-cluster-operator-5b577cb69f-h875m/manager/previous.log" in 298.384 seconds (0.11 MiB/s)
2026-07-29T17:46:01.260  arft-site02.logs  Gathered "openshift-dr-system/ramen-dr-cluster-operator-5b577cb69f-h875m/manager/current.log" in 157.464 seconds (0.09 MiB/s)

Compare with site03 — same size log, 40× faster (different network path):

2026-07-29T17:43:30.752  arft-site03.logs  Gathered "openshift-dr-system/ramen-dr-cluster-operator-5b577cb69f-2bcm8/manager/current.log" in 7.698 seconds (1.64 MiB/s)

Hub and site02 wall time is bounded by the slowest log stream (~300 s each).
Site03 logs finished in <8 s (15–30× better throughput), so it wasn't bottlenecked.

2. WAN API latency (many empty list calls)

Cluster Total lists Empty lists Median RTT Sum empty-list time (worker-s)
arft-site02 859 679 (79%) 0.240 s 1,298 s
hub 569 406 (71%) 0.184 s 707 s
arft-site03 965 747 (77%) 0.253 s 447 s

Even "nothing here" responses cost 0.18–0.25 s round-trip over WAN.

From the log — typical empty list calls at ~0.23–0.25 s each:

2026-07-29T17:43:22.279  hub  Listed 0 "limitranges" in 0.229 seconds
2026-07-29T17:43:22.769  arft-site02  Listed 0 "limitranges" in 0.238 seconds
2026-07-29T17:49:05.415  arft-site02  Listed 0 "zen.cpd.ibm.com/zenextensions" in 0.238 seconds
2026-07-29T17:49:05.656  arft-site02  Listed 0 "metrics.k8s.io/pods" in 0.242 seconds

3. Slow API responses during log streaming

The "Listed" log measures only the k8s API List() call time (no queue waits).
Some List calls took 50–77 s for site02 and 30–40 s for hub — these are
genuinely slow API responses that correlate with concurrent log streaming:

Cluster Slowest list call # calls > 1 s Sum of slow calls
arft-site02 77.40 s 41 1,125 s
hub 40.20 s 53 637 s
arft-site03 45.00 s 6 263 s

From the log — List calls for basic resources taking 35–77 s during active log
streaming:

2026-07-29T17:45:28.878  arft-site02  Listed 0 "batch/jobs" in 77.384 seconds
2026-07-29T17:45:28.878  arft-site02  Listed 0 "batch/jobs" in 77.274 seconds
2026-07-29T17:44:22.321  hub  Listed 1 "networking.k8s.io/servicecidrs" in 34.413 seconds
2026-07-29T17:44:23.387  hub  Listed 1 "networking.k8s.io/ingressclasses" in 35.477 seconds
2026-07-29T17:44:24.481  hub  Listed 100 "networking.k8s.io/ipaddresses" in 36.573 seconds

The median List RTT is 0.18–0.24 s, but during active log streaming (which runs
for ~300 s on hub and site02), some API calls are inflated by 100–300×. We don't
know why — possible causes:

  • WAN link saturation — 500 Mbit/s WiFi locally, connecting via company VPN
    to servers in the US. Unknown networking between VPN endpoint and cluster.
  • API server CPU/resource pressure — concurrent log streaming puts load on
    the API server (kubelet proxy for pod logs), which may starve List requests.
  • IO limits on API server node — cloud instances often have IOPS limits that
    can throttle etcd reads when log streaming drives concurrent IO.

Note: the gather and inspect use separate unbuffered work queues (6 workers each).
"Listed" measures only the API call; "Gathered" includes the full loop
(list + inspect + dump) and can also stall when the inspect queue is full and
all inspect workers are busy streaming logs.

Where time goes per cluster

arft-site02 (344.4 s wall)

Activity Duration Notes
Log streaming (previous.log) 298.40 s 31.8 MiB @ 0.11 MiB/s — sets wall time
Log streaming (current.log) 157.50 s 14.8 MiB @ 0.09 MiB/s
List API calls (worker-time) 2,052.00 s 859 calls
2026-07-29T17:48:22.197  arft-site02.logs  Gathered ".../ramen-dr-cluster-operator-.../manager/previous.log" in 298.384 seconds (0.11 MiB/s)
2026-07-29T17:46:01.260  arft-site02.logs  Gathered ".../ramen-dr-cluster-operator-.../manager/current.log" in 157.464 seconds (0.09 MiB/s)
2026-07-29T17:49:05.668  Gathered 5206 resources from cluster "arft-site02" in 344.35 seconds

hub (322.9 s wall)

Activity Duration Notes
Log streaming (ramen-hub) 301.50 s 30.5 MiB @ 0.10 MiB/s — sets wall time
Log streaming (odf-console) 284.40 s 18.7 MiB @ 0.07 MiB/s
Log streaming (odfmo) 273.60 s 12.7 MiB @ 0.05 MiB/s
List API calls (worker-time) 1,841.00 s 569 calls
2026-07-29T17:48:24.939  hub.logs  Gathered ".../ramen-hub-operator-.../manager/current.log" in 301.470 seconds (0.10 MiB/s)
2026-07-29T17:48:07.874  hub.logs  Gathered ".../odf-multicluster-console-.../current.log" in 284.410 seconds (0.07 MiB/s)
2026-07-29T17:47:57.052  hub.logs  Gathered ".../odfmo-controller-manager-.../current.log" in 273.588 seconds (0.05 MiB/s)
2026-07-29T17:48:44.192  Gathered 4182 resources from cluster "hub" in 322.88 seconds

arft-site03 (125.4 s wall)

Activity Duration Notes
Log streaming (all 4) 17.00 s Fast — not a bottleneck
List API calls (worker-time) 732.00 s 965 calls / 6 workers ≈ 122 s
2026-07-29T17:43:30.752  arft-site03.logs  Gathered ".../ramen-dr-cluster-operator-.../manager/current.log" in 7.698 seconds (1.64 MiB/s)
2026-07-29T17:43:27.042  arft-site03.logs  Gathered ".../tekton-operator-webhook-.../current.log" in 3.981 seconds (0.76 MiB/s)
2026-07-29T17:43:25.886  arft-site03.logs  Gathered ".../openshift-pipelines-operator-.../current.log" in 2.830 seconds (0.50 MiB/s)
2026-07-29T17:43:25.773  arft-site03.logs  Gathered ".../openshift-pipelines-operator-.../current.log" in 2.717 seconds (0.46 MiB/s)
2026-07-29T17:45:26.659  Gathered 6865 resources from cluster "arft-site03" in 125.36 seconds

Page cache effect — second gather is 7–15× faster

validate clusters ran first; validate application ran ~3 minutes later,
gathering the same logs from the same pods. Same log files, dramatically
different throughput:

Log 1st run (s) 1st MiB/s 2nd run (s) 2nd MiB/s Speedup
hub: ramen-hub-operator current.log 301.50 0.10 28.50 1.08 10.6×
hub: odf-multicluster-console 284.40 0.07 25.00 0.75 11.4×
hub: odfmo-controller-manager 273.60 0.05 17.30 0.73 15.8×
arft-site02: ramen-dr-cluster current 157.50 0.09 41.80 0.55 3.8×
arft-site02: ramen-dr-cluster previous 298.40 0.11 43.50 0.73 6.9×
arft-site03: ramen-dr-cluster current 7.70 1.64 16.80 0.89 0.5×

From the validate-application log (2nd run):

2026-07-29T17:52:40.073  hub.logs  Gathered ".../ramen-hub-operator-.../manager/current.log" in 28.492 seconds (1.08 MiB/s)
2026-07-29T17:52:36.570  hub.logs  Gathered ".../odf-multicluster-console-.../current.log" in 25.006 seconds (0.75 MiB/s)
2026-07-29T17:52:28.873  hub.logs  Gathered ".../odfmo-controller-manager-.../current.log" in 17.304 seconds (0.73 MiB/s)
2026-07-29T17:53:00.631  arft-site02.logs  Gathered ".../ramen-dr-cluster-operator-.../manager/current.log" in 41.761 seconds (0.55 MiB/s)
2026-07-29T17:53:07.741  arft-site02.logs  Gathered ".../ramen-dr-cluster-operator-.../manager/previous.log" in 43.498 seconds (0.73 MiB/s)
2026-07-29T17:52:31.548  arft-site03.logs  Gathered ".../ramen-dr-cluster-operator-.../manager/current.log" in 16.777 seconds (0.89 MiB/s)

Hub and site02 logs went from 0.05–0.11 MiB/s to 0.55–1.08 MiB/s on the second
gather. The most likely explanation is page cache warming: the first gather
reads log data from storage (slow IO), and the second gather reads the same data
from the kernel page cache (fast).

arft-site03 is the exception — it was already fast on the first run (1.64 MiB/s)
and slightly slower on the second (0.89 MiB/s, more concurrent streams). This
suggests site03 logs were already cached before the first gather.

We cannot do anything about cold page cache, and it's very hard to test without
access to the nodes to drop caches. The takeaway is that we need to expect much
slower log gather in some cases (first gather after node restart, after memory
pressure evicts cached log data, or with large logs that exceed available cache).

Testing cold page cache

To reproduce the worst case (first gather after reboot), drop page cache on
every node before gathering:

for node in $(oc get nodes -o name); do
  oc debug "$node" -- chroot /host sh -c 'sync; echo 1 > /proc/sys/vm/drop_caches'
done

Value 1 drops page cache (file data in memory) — this is what makes log
streaming slow on cold nodes. No need for 3 (which also drops dentries/inodes);
the log IO cost dominates.

Test plan:

  1. Drop caches on all nodes
  2. Run validate clusters — expect ~300 s (cold)
  3. Run validate clusters again immediately — expect ~50 s (warm)
  4. Drop caches on all nodes again
  5. Run validate clusters --remote — compare with step 2

This isolates page cache vs. WAN latency as the two independent factors.

Next steps

  • More local gathers — compare page cache effect
  • Cold cache test (see above)
  • Remote gathers — compare with local

Dependencies

Activity

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

Metadata

Metadata

Assignees

Labels

performancePerformance issue or improvement

Type

Projects

No projects

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions