fix(instrumentation): exclude admission/queue-wait from provisioning metrics (AKS + Machine API)

[Xu Xue (xuexu6666)]

Problem

Telescope over-reports provisioning latency because it bills time spent waiting to be admitted by ARM against the operation itself. This is not GPU-specific — it affects multiple pipelines:

• AKS node-pool CRUD (create / scale / progressive; GPU and non-GPU) via begin_create_or_update_with_retry: ARM returns 409 OperationNotAllowed while a previous operation on the cluster is still running, and the sleep-retry loop runs inside the timed region. Real example (H100 scale_up, run 78200-2d6bbfea): reported 606s, ~180s of which was pre-accept queue-wait (utils.provisioning_instrumentation - WARNING - Cluster has an in-progress operation, retrying in 30s (attempt 6/10): OperationNotAllowed).
• Machine API scale (aks_machine_client) via BatchPutMachine: the 429 throttle backoff runs inside command_execution_time and the operation duration.
• EKS: unaffected (boto3 waiters, no pre-accept serialization).

Fix — measure from the accepted (2xx) request, exclude the failed-attempt wait (shared Operation.exclude_time primitive)

AKS node pool — measure from the start of the attempt ARM accepts (2xx):

• begin_create_or_update_with_retry stamps each attempt's start and returns (request_started_at, retry_occurred) for the attempt that succeeds. A 409 OperationNotAllowed raises before a poller exists, so its stamp is discarded.
• instrument_nodepool_provisioning measures command_execution_time and node_readiness_time from request_started_at. This counts the accepted request's own frontend time (submit → 2xx) plus the async provisioning, while the failed prior attempts (409 frontend round-trip + backoff) are excluded as queue-wait.

Machine API — exclude the throttle backoff:

• Each 429 backoff sleep is recorded as a (start, end) interval per concurrent worker; scale_machine excludes their wall-clock union (utils.union_seconds — parallel backoffs overlap, so summing would over-count) from command_execution_time and the operation duration.

Shared:

• Both paths record the excluded wait as in_progress_wait_seconds metadata (clamped to the wall-clock elapsed, so it can never exceed the duration adjustment applied).
• Operation.exclude_time() / end() shift the effective start forward by the excluded wait so start / end / duration stay consistent.

Files

• crud/operation.py — exclude_time() primitive + duration adjustment (clamped).
• utils/provisioning_instrumentation.py — measure from the accepted attempt's start (counts its frontend time).
• utils/common.py — union_seconds() interval-merge helper.
• clients/aks_machine_client.py — record + exclude 429 throttle backoff.

Tests

union_seconds interval merge; request-start return + timing exclusion incl. the excess-wait clamp; batch throttle-interval recording and scale_machine exclusion; Operation duration adjustment. pytest green (the pre-existing test_log_gpu_mode_console_echo failure is Python-3.10-only assertNoLogs, unrelated); pylint clean on changed files.

[github-actions]

For reviewers only: reply /run-tf-integration to trigger the terraform integration pipeline before approving the PR.

[Copilot]

Pull request overview

This PR adjusts Telescope’s provisioning instrumentation so node-pool provisioning latency metrics no longer include “queue-wait” time spent blocked by a previous in-progress ARM/AKS operation (OperationNotAllowed/EtagMismatch), while still recording that wait for transparency.

Changes:

• begin_create_or_update_with_retry now returns the accumulated in-progress wait time in seconds (0 if accepted immediately).
• instrument_nodepool_provisioning subtracts that wait from command_execution_time/node_readiness_time, calls Operation.exclude_time(...), and records in_progress_wait_seconds.
• Operation gains exclude_time() and adjusts end() to shift the effective start time forward so timestamps and duration remain consistent; added unit tests for the new behavior.

Reviewed changes

Copilot reviewed 4 out of 4 changed files in this pull request and generated 1 comment.

File	Description
modules/python/utils/provisioning_instrumentation.py	Returns/consumes “in-progress wait seconds” and excludes it from provisioning timing metrics and operation duration.
modules/python/crud/operation.py	Adds exclude_time() and updates end() to compute duration using an effective start time that accounts for excluded seconds.
modules/python/tests/utils/test_provisioning_instrumentation.py	Updates tests to validate the new wait-seconds return value and exclusion behavior in instrumentation.
modules/python/tests/crud/test_operation.py	Adds tests covering excluded-time accumulation and end() duration/start-timestamp adjustment.

---

💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.

[Xu Xue (xuexu6666)]

Good catch — fixed in 9e2a010. end() now records the clamped excluded value in in_progress_wait_seconds so the metadata can never exceed the wall-clock elapsed and always matches the duration adjustment applied. Added a unit test (test_operation_end_clamps_excluded_to_wall_clock) covering the excess-wait edge case (duration floors at 0, metadata == wall-clock).

[Xu Xue (xuexu6666)]

Ran a 3-reviewer pass over this PR and applied fixes (commit 64c400fc):

Fixed (issues multiple reviewers converged on):

• in_progress_wait_seconds double-write — callers wrote the raw wait and Operation.end() then overwrote it with the clamped value (two writers, possible disagreement). Operation.end() is now the single owner; removed the caller-side writes in instrument_nodepool_provisioning and scale_machine, so the metadata always equals the amount actually removed from duration.
• union_seconds hardening — now drops inverted/zero-length intervals (end <= start) so a non-monotonic clock reading can never contribute negative time. Added tests (touching, inverted, zero-length).
• exclude_time guard clarified (seconds is not None and seconds > 0); excluded_seconds initialized as float.
• Test coverage gaps — added: budget-exhaustion re-raises the last error; retries=0 → RuntimeError guard; asserted command_execution_time in the machine throttle test; union_seconds edge cases.
• Documented the batch-only scope of throttle exclusion (the individual PUT path uses opaque transport-level retries) and the concurrency ordering assumption in the mocked-time instrument tests.

Deliberately not changed (rationale):

• Second-granularity timestamps (%Y-%m-%dT%H:%M:%SZ): pre-existing across all Operations; changing precision has broad ADX/test blast radius, so out of scope for this PR (worth a separate follow-up).
• node_readiness_time measured from command_start: intentional — command and readiness share the same origin, so the ARM-vs-K8s Delta cancels it and stays correct while both exclude the queue-wait.
• Cross-pipeline command_execution_time meaning (AKS = submit+provision vs Machine = submit-only): pre-existing field-semantics divergence, not introduced here.

Tests green (pre-existing test_log_gpu_mode_console_echo is Python-3.10-only assertNoLogs), pylint clean, all modules under the 1000-line cap.

[Karen Chen (karenychen)]

Code review

Found 1 issue:

1. The union of every worker's 429 sleep is not necessarily time the concurrent scale command was blocked. If one batch worker sleeps while another is still actively submitting (and the active worker determines the overall completion time), subtracting that interval removes productive wall time from both command_execution_time and the entire operation duration. This can under-report Machine API latency; exclusion needs to be based on periods when the critical path/all unfinished workers are blocked, or measured per worker and composed by the actual completion critical path.

telescope/modules/python/clients/aks_machine_client.py

Lines 545 to 555 in 8b6fbe6

	# 429 throttle backoff is queue-wait to be admitted, not provisioning
	# latency; exclude its wall-clock union from command time and duration.
	# Only the Batch endpoint retries 429 with backoff (recorded in
	# _make_batch_request); individual PUTs are single-shot (no retry), so a
	# 429 fails the machine and throttle_wait stays 0. end() owns the metadata.
	throttle_wait = union_seconds(request.throttle_intervals)
	op.exclude_time(throttle_wait)
	op.add_metadata(
	"command_execution_time",
	max(0.0, time.time() - command_t0 - throttle_wait),
	)

[Xu Xue (xuexu6666)]

Karen Chen (@karenychen) great catch — you're right, union_seconds under-reports latency: a 429 sleep on a worker that isn't on the completion critical path is hidden behind another worker's productive work and shouldn't be excluded at all. Fixed in 20603f86.

Replaced the union with a critical-path (makespan) attribution. Each chunk's backoff is pure additive delay on its own timeline, so its throttle-free finish is finish − backoff. The command finishes at the makespan max(finish); without throttle it would finish at max(finish − backoff). The delay actually charged to the command is:

throttle_wait = makespan − max_i(finish_i − backoff_i)

This is exactly "measured per worker and composed by the actual completion critical path": off-critical-path backoff doesn't move the max, so it contributes 0; and when the critical chunk's backoff would drop it below the runner-up, the exclusion is correctly capped at the runner-up's finish (not the full backoff).

Changes:

• _make_batch_request now returns its total 429 backoff (0 if no retry) instead of recording raw sleep intervals.
• _create_batch_machines records (finish_time, backoff) per chunk.
• scale_machine computes the exclusion via utils.throttle_makespan_delay(...) (replaces union_seconds).

Tests cover the three cases: lone-chunk backoff counts fully; off-critical-path backoff → 0 (your scenario); critical-path backoff capped by the runner-up's throttle-free finish. (Individual PUTs are single-shot / no 429 retry, so their chunk_throttle is empty → 0.)

[Karen Chen (karenychen)]

Code review

Found 2 issues:

1. A batch chunk that exhausts its 429 retries never reaches the code that appends (finish_time, backoff) to request.chunk_throttle. _scale_machine_batch swallows that worker exception and returns a partial success list, so scale_machine computes the failed operation exclusion from successful chunks only. If the failed chunk spent 1+2+4 seconds backing off, those 7 seconds remain in command_execution_time and the operation duration—the exact queue wait this PR intends to remove. Preserve the accumulated backoff/finish data on the failure path as well.

telescope/modules/python/clients/aks_machine_client.py

Lines 914 to 925 in f814e6b

	start_time = datetime.now(timezone.utc)
	chunk_backoff = self._make_batch_request(
	"PUT", url, body, put_timeout,
	batch_header_value=batch_header_value,
	chunk_idx=chunk_idx,
	first_machine_name=first_machine_name,
	)
	end_time = datetime.now(timezone.utc)
	execution_time_seconds = (end_time - start_time).total_seconds()
	# Record this chunk's finish + 429 backoff for makespan throttle attribution.
	with request.throttle_lock:
	request.chunk_throttle.append((time.time(), chunk_backoff))

2. Node-pool queue wait is also applied only after both concurrent futures succeed. When ARM retries one or more OperationNotAllowed responses and then the accepted operation fails, or when Kubernetes readiness fails after ARM succeeds, the early exception branch re-raises before reading command_start and calling op.exclude_time. Failed operation records therefore still include all pre-accept queue wait. Carry the accepted-attempt timing through the failure path when available and exclude it before re-raising.

telescope/modules/python/utils/provisioning_instrumentation.py

Lines 53 to 83 in f814e6b

	arm_exc = arm_future.exception()
	k8s_exc = k8s_future.exception()
	if arm_exc or k8s_exc:
	elapsed = time.time() - start_time
	arm_status = f"FAILED: {arm_exc}" if arm_exc else "succeeded"
	k8s_status = f"FAILED: {k8s_exc}" if k8s_exc else "succeeded"
	logger.error(
	"Concurrent operation failed after %.2fs - ARM: %s, K8s readiness: %s",
	elapsed, arm_status, k8s_status
	)
	if arm_exc:
	raise arm_exc
	raise k8s_exc
	(command_start, retry_occurred), arm_timestamp = arm_future.result()
	ready_nodes, ready_timestamp = k8s_future.result()
	# command_start is when the accepted (2xx) attempt's PUT was issued, so timings
	# include that request's own frontend time (submit -> accept) plus the async
	# provisioning. Everything before command_start is queue-wait for a *previous*
	# in-progress operation (the failed OperationNotAllowed/EtagMismatch attempts),
	# which is excluded from the duration.
	in_progress_wait = max(0, command_start - start_time)
	command_execution_time = max(0, arm_timestamp - command_start)
	node_readiness_time = max(0, ready_timestamp - command_start)
	# exclude_time feeds the operation duration; Operation.end() records the
	# (clamped) excluded amount as in_progress_wait_seconds -- single owner of
	# that metadata key, so it always matches the duration adjustment applied.
	op.exclude_time(in_progress_wait)

[Karen Chen (karenychen)]

Code review

Found 1 issue:

1. When every create/update attempt is rejected with OperationNotAllowed or EtagMismatch, the final-attempt branch re-raises the HttpResponseError without attaching any timing information. instrument_nodepool_provisioning therefore sees no request_started_at and excludes none of the preceding rejected-attempt round trips or backoff sleeps. With the default retry budget, a never-admitted operation still records roughly 270 seconds of queue wait in its failed-operation duration, contrary to the queue-wait exclusion. Preserve the timing anchor or accumulated wait on this terminal rejection path as well.

telescope/modules/python/utils/provisioning_instrumentation.py

Lines 151 to 164 in 16eedb7

	except HttpResponseError as e:
	if any(code in str(e) for code in ("OperationNotAllowed", "EtagMismatch")) and attempt < retries - 1:
	retry_occurred = True
	error_code = e.error.code if e.error else str(e)
	logger.warning(
	f"Cluster has an in-progress operation, retrying in {retry_wait}s "
	f"(attempt {attempt + 1}/{retries}): {error_code}"
	)
	time.sleep(retry_wait)
	continue
	raise
	# Accepted (2xx). If the async operation now fails or times out, the
	# pre-accept queue-wait still happened, so attach the accept time to the
	# exception so the caller can exclude it from the failed op's duration.

[Xu Xue (xuexu6666)]

Karen Chen (@karenychen) fixed in f319aa19 — thanks, you're right.

The terminal-rejection branch in begin_create_or_update_with_retry now anchors the exclusion at the give-up moment:

# Terminal rejection (retries exhausted / never admitted, or non-retryable):
# the elapsed rejected attempts + backoff are all queue-wait.
e.request_started_at = time.time()
raise

instrument_nodepool_provisioning already reads getattr(arm_exc, "request_started_at", None) on the failure branch, so a never-admitted op now excludes the full rejected-attempt wait (~270s at the default budget) from its failed-operation duration instead of leaving it in. Anchoring at now also does the right thing for an immediate non-retryable failure — now ≈ start, so it excludes ~0 (nothing was waited).

Added test_terminal_rejection_attaches_timing_anchor. All three failure modes now exclude queue-wait consistently: accepted-then-failed, K8s-readiness-failed, and never-admitted.

[Karen Chen (karenychen)]

Code review

Found 1 issue:

1. This terminal branch also handles non-retryable HttpResponseErrors (for example validation, auth, or not-found responses), but it always stamps request_started_at after begin_create_or_update returns. The caller consequently subtracts the entire failed request round trip and records it as in_progress_wait_seconds, even though no in-progress-operation retry or backoff occurred. A slow 400/403/404 can therefore collapse the failed operation duration toward zero and mislabel real ARM frontend latency as queue wait. Only use the give-up timestamp when the terminal error is the final OperationNotAllowed/EtagMismatch; non-retryable errors should retain the operation start/no exclusion.

telescope/modules/python/utils/provisioning_instrumentation.py

Lines 151 to 167 in f319aa1

	except HttpResponseError as e:
	if any(code in str(e) for code in ("OperationNotAllowed", "EtagMismatch")) and attempt < retries - 1:
	retry_occurred = True
	error_code = e.error.code if e.error else str(e)
	logger.warning(
	f"Cluster has an in-progress operation, retrying in {retry_wait}s "
	f"(attempt {attempt + 1}/{retries}): {error_code}"
	)
	time.sleep(retry_wait)
	continue
	# Terminal rejection (retries exhausted / never admitted, or a
	# non-retryable error): the elapsed rejected attempts + backoff are all
	# queue-wait, so anchor the exclusion at now -- the caller drops them
	# from the failed op's duration (an immediate non-retryable failure
	# anchors at ~start, excluding ~0).
	e.request_started_at = time.time()
	raise

[Xu Xue (xuexu6666)]

Karen Chen (@karenychen) fixed in c2ca33c9 — good catch, the anchor was too broad.

The terminal branch now only anchors the exclusion when the error is an exhausted in-progress rejection; a non-retryable error attaches nothing:

in_progress = any(code in str(e) for code in ("OperationNotAllowed", "EtagMismatch"))
if in_progress and attempt < retries - 1:
    ...  # retry
# Terminal:
if in_progress:                       # exhausted OperationNotAllowed/EtagMismatch
    e.request_started_at = time.time()  # all queue-wait -> exclude
raise                                 # non-retryable (400/403/404/...) -> no anchor, real ARM latency retained

So a slow 400/403/404 keeps its full round trip in the failed-op duration and is not mislabeled as in_progress_wait_seconds. Added an assertion to test_raises_non_retryable_error that no timing anchor is attached.

[Karen Chen (karenychen)]

Code review

Found 1 issue:

1. throttle_makespan_delay computes how much 429 backoff delayed only the concurrent PUT phase, but op.exclude_time(throttle_wait) removes that amount from the entire scale operation through agent-pool provisioning and node readiness. Those phases can have a different critical path: for example, chunk A may finish its PUT last solely because of a 5s backoff, while a machine from chunk B becomes the last Ready node. Removing chunk A backoff then shortens the recorded end-to-end provisioning duration even though it did not delay completion. Keep this exclusion scoped to command_execution_time, or derive end-to-end exclusion from the chunk that actually determines operation completion.

telescope/modules/python/clients/aks_machine_client.py

Lines 545 to 555 in c2ca33c

	command_end = time.time()
	# 429 throttle backoff is queue-wait, not provisioning latency. Under
	# concurrency only backoff on the completion critical path delays the
	# command (see throttle_makespan_delay); individual PUTs don't retry, so
	# chunk_throttle is empty -> 0. Operation.end() owns the metadata.
	throttle_wait = throttle_makespan_delay(request.chunk_throttle)
	op.exclude_time(throttle_wait)
	op.add_metadata(
	"command_execution_time",
	max(0.0, command_end - command_t0 - throttle_wait),
	)

[Xu Xue (xuexu6666)]

Karen Chen (@karenychen) fixed in 91557882 — agreed, the whole-duration exclusion was wrong for the concurrent case.

Scoped the throttle exclusion to command_execution_time only; the operation duration is no longer adjusted:

throttle_wait = throttle_makespan_delay(request.chunk_throttle)
op.add_metadata("command_execution_time", max(0.0, command_end - command_t0 - throttle_wait))
op.add_metadata("throttle_wait_seconds", throttle_wait)   # recorded for visibility
# (op.exclude_time is no longer called on the machine path)

Rationale: throttle_makespan_delay measures the throttle's delay to the PUT-phase makespan, which is correct for command_execution_time. But as you noted, the PUT-phase critical path can differ from the end-to-end one — the last-Ready machine may be a different chunk — so PUT-phase throttle doesn't necessarily delay completion, and removing it from the whole operation duration can shorten it incorrectly. Deriving the true end-to-end exclusion would require correlating each chunk's backoff to the specific machine that determines readiness completion, which isn't reliably available here, so the conservative scope is the right call. The throttle is still visible as throttle_wait_seconds.

Updated the test to assert command_execution_time/throttle_wait_seconds are set and op.exclude_time is NOT called on the machine path.

Note this makes the two pipelines intentionally asymmetric: the AKS node-pool path still excludes queue-wait from the duration (single PUT -> the pre-accept wait strictly delays everything downstream, one critical path), whereas the concurrent Machine path scopes it to command time only.