This is an automated email from the ASF dual-hosted git repository.
vatsrahul1001 pushed a commit to branch v3-3-test
in repository https://gitbox.apache.org/repos/asf/airflow.git
The following commit(s) were added to refs/heads/v3-3-test by this push:
new 92de22825e6 [v3-3-test] Stop CI duration alerts firing on one-off
image rebuilds (#71548) (#72914)
92de22825e6 is described below
commit 92de22825e6ffc588427c8db6b7c67f709090c23
Author: github-actions[bot]
<41898282+github-actions[bot]@users.noreply.github.com>
AuthorDate: Fri Sep 11 11:35:00 2026 +0530
[v3-3-test] Stop CI duration alerts firing on one-off image rebuilds
(#71548) (#72914)
* Stop CI duration alerts firing on one-off image rebuilds
The trend excluded a single step, "Prepare breeze & CI image", from a job's
wall clock. The image-cache push jobs do not have that step - they build and
push the image in a step of their own - so when a change to an early image
layer invalidates every layer after it, the resulting full rebuild and full
re-push is counted as work time and reported as a regression. The same
CI-only prefix also missed every job that prepares a PROD image.
Image build time is meant to be watched by the persistence check instead,
which only reports a slowdown that lasted for days rather than a single
night, so the exclusion has to cover the steps that carry it.
* Track one image-work figure instead of two overlapping ones
The prepare-breeze step is one of the image steps, so carrying its duration
alongside the wider image-work total meant two fields, two extraction
functions and fixtures that had to keep both in step - while the persistence
check still watched only the narrower of the two, so a slow build in a
cache-push job never reached it.
(cherry picked from commit 438f2bda03b5d7f4b1ac7245dc86c54711fd82a9)
Co-authored-by: Jarek Potiuk <[email protected]>
---
scripts/ci/analyze_ci_job_durations.py | 78 +++++++-----
scripts/tests/ci/test_analyze_ci_job_durations.py | 143 +++++++++++++++++-----
2 files changed, 158 insertions(+), 63 deletions(-)
diff --git a/scripts/ci/analyze_ci_job_durations.py
b/scripts/ci/analyze_ci_job_durations.py
index 56f3c463333..202dfb449e1 100644
--- a/scripts/ci/analyze_ci_job_durations.py
+++ b/scripts/ci/analyze_ci_job_durations.py
@@ -35,10 +35,11 @@ both a relative margin (``REL_THRESHOLD``) and an absolute
floor
(``MIN_ABS_INCREASE_MINUTES`` / ``JOB_MIN_ABS_INCREASE_MINUTES``) so short jobs
with noisy timings do not trigger spurious alerts.
-The image-build step ("Prepare breeze & CI image") occasionally balloons on a
-one-off cache miss, so its time is *excluded* from the run and per-job
durations
-used for the trend above. The image build is instead watched on its own and
only
-reported when it has stayed slow for longer than
``IMAGE_BUILD_PERSISTENCE_DAYS``
+Steps that build, pull or push images (``IMAGE_WORK_STEP_PREFIXES`` —
preparing the
+CI/PROD image in a test job, and the build+push of the image-cache jobs)
occasionally
+balloon on a one-off cache miss, so their time is *excluded* from the run and
per-job
+durations used for the trend above. That same image time is instead watched on
its own
+and only reported when it has stayed slow for longer than
``IMAGE_BUILD_PERSISTENCE_DAYS``
(so a single slow night never alerts).
Environment variables (required):
@@ -77,12 +78,23 @@ from pathlib import Path
from typing import TypedDict
ISO_SUFFIX_Z = "Z"
-PREPARE_BREEZE_STEP_PREFIX = "Prepare breeze & CI image"
+# Steps that build, pull or push a Docker image rather than doing test/work. A
change to
+# an early image layer (an apt package, a Dockerfile line) invalidates every
layer after
+# it, so on the first run after such a merge these steps take multiples of
their usual
+# time - a one-off that must not read as a work-time regression. Their names
come from
+# .github/workflows/push-image-cache.yml and
.github/actions/prepare_breeze_and_image.
+IMAGE_WORK_STEP_PREFIXES = (
+ "Prepare breeze & CI image",
+ "Prepare breeze & PROD image",
+ "Push CI ",
+ "Push PROD ",
+)
+IMAGE_WORK_LABEL = "Image build, pull & push"
class JobDuration(TypedDict):
duration: float
- prepare_breeze_duration: float | None
+ image_work_duration: float | None
def env_float(name: str, default: float) -> float:
@@ -249,39 +261,45 @@ def get_recent_runs(
return runs
-def get_prepare_breeze_step_duration(job: dict) -> float | None:
- """Return the prepare breeze step duration for a job, when the step
exists."""
+def get_image_work_seconds(job: dict) -> float | None:
+ """Return the total time a job spent building, pulling or pushing images.
+
+ Summed rather than first-match: the cache-push jobs both build an image
and push
+ it in separate steps, and a test job can prepare a CI and a PROD image.
+ """
+ total: float | None = None
for step in job.get("steps", []):
- name = step.get("name", "")
- if not name.startswith(PREPARE_BREEZE_STEP_PREFIX):
+ if not step.get("name", "").startswith(IMAGE_WORK_STEP_PREFIXES):
continue
- return duration_seconds(step.get("startedAt"), step.get("completedAt"))
- return None
+ seconds = duration_seconds(step.get("startedAt"),
step.get("completedAt"))
+ if seconds is not None:
+ total = seconds if total is None else total + seconds
+ return total
def calculate_work_duration(job_data: JobDuration) -> float:
- """Return a job's wall-clock with the image-build (prepare breeze) step
removed.
+ """Return a job's wall-clock with the image build/pull/push steps removed.
- The image build occasionally balloons — a cache miss forces a full rebuild
- (minutes → tens of minutes) — which would otherwise inflate the job's total
- and flag an unrelated job as "slower". The duration trend should track the
- actual test/work time, so image build is discounted from it and watched
- separately by :func:`detect_image_build_regression`.
+ Image work occasionally balloons — an invalidated early layer forces a
full rebuild
+ and a full re-push (minutes → tens of minutes) — which would otherwise
inflate the
+ job's total and flag a job that did not actually get slower. The duration
trend
+ should track the actual test/work time, so image work is discounted from
it and
+ watched separately by :func:`detect_image_build_regression`.
"""
- prepare_breeze = job_data["prepare_breeze_duration"] or 0.0
- return max(job_data["duration"] - prepare_breeze, 0.0)
+ image_work = job_data["image_work_duration"] or 0.0
+ return max(job_data["duration"] - image_work, 0.0)
def calculate_image_build_seconds(jobs: dict[str, JobDuration]) -> float |
None:
- """Return a representative image-build duration for a run.
+ """Return a representative image-work duration for a run.
- The same CI image is prepared by every job, so the median prepare-breeze
- duration across the run's jobs is a robust single figure for that run
- (ignoring jobs where the step is absent). None when no job recorded it.
+ Nearly every job prepares the same image, so the median image-work duration
+ across the run's jobs is a robust single figure for that run (ignoring jobs
+ that did no image work). The handful of cache-push jobs, which build and
push
+ rather than pull, sit far above that median and so do not move it. None
when
+ no job recorded any image work.
"""
- values = [
- job["prepare_breeze_duration"] for job in jobs.values() if
job["prepare_breeze_duration"] is not None
- ]
+ values = [job["image_work_duration"] for job in jobs.values() if
job["image_work_duration"] is not None]
if not values:
return None
return median(values)
@@ -320,7 +338,7 @@ def get_run_jobs(repo: str, run_id: int) -> dict[str,
JobDuration]:
if existing is None or seconds > existing["duration"]:
durations[name] = {
"duration": seconds,
- "prepare_breeze_duration":
get_prepare_breeze_step_duration(job),
+ "image_work_duration": get_image_work_seconds(job),
}
return durations
@@ -504,7 +522,7 @@ def format_slack_message(
f"🐳 *CI image build slow for
{image_build_regression['span_days']:.1f} days* "
f"(across {image_build_regression['elevated_runs']}
runs) — not a one-off "
f"cache miss:\n"
- f"• {PREPARE_BREEZE_STEP_PREFIX}: "
+ f"• {IMAGE_WORK_LABEL}: "
f"{format_duration(image_build_regression['baseline'])} → "
f"*{format_duration(image_build_regression['latest'])}* "
f"(+{round(image_build_regression['rel_increase'] *
100, 1)}%)"
@@ -617,7 +635,7 @@ def write_step_summary(
lines += [
f"### 🐳 CI image build slow for
{image_build_regression['span_days']:.1f} days",
"",
- f"- {PREPARE_BREEZE_STEP_PREFIX}: "
+ f"- {IMAGE_WORK_LABEL}: "
f"**{format_duration(image_build_regression['latest'])}** "
f"(baseline {format_duration(image_build_regression['baseline'])},
"
f"+{round(image_build_regression['rel_increase'] * 100, 1)}%) "
diff --git a/scripts/tests/ci/test_analyze_ci_job_durations.py
b/scripts/tests/ci/test_analyze_ci_job_durations.py
index efb930539b3..be5b3cbc2e1 100644
--- a/scripts/tests/ci/test_analyze_ci_job_durations.py
+++ b/scripts/tests/ci/test_analyze_ci_job_durations.py
@@ -266,9 +266,9 @@ class TestGetRunJobs:
completed = subprocess.CompletedProcess(args=[], returncode=0,
stdout=payload, stderr="")
with patch.object(subprocess, "run", return_value=completed):
jobs = durations_module.get_run_jobs("apache/airflow", 2)
- assert jobs == {"Tests": {"duration": 20 * 60,
"prepare_breeze_duration": 5 * 60}}
+ assert jobs == {"Tests": {"duration": 20 * 60, "image_work_duration":
5 * 60}}
- def test_omits_prepare_breeze_duration_when_step_missing(self,
durations_module):
+ def test_omits_image_work_duration_when_no_image_step(self,
durations_module):
payload = json.dumps(
{
"jobs": [
@@ -285,7 +285,7 @@ class TestGetRunJobs:
completed = subprocess.CompletedProcess(args=[], returncode=0,
stdout=payload, stderr="")
with patch.object(subprocess, "run", return_value=completed):
jobs = durations_module.get_run_jobs("apache/airflow", 2)
- assert jobs == {"Tests": {"duration": 20 * 60,
"prepare_breeze_duration": None}}
+ assert jobs == {"Tests": {"duration": 20 * 60, "image_work_duration":
None}}
def test_keeps_longest_duplicate_job_name(self, durations_module):
payload = json.dumps(
@@ -317,7 +317,7 @@ class TestGetRunJobs:
completed = subprocess.CompletedProcess(args=[], returncode=0,
stdout=payload, stderr="")
with patch.object(subprocess, "run", return_value=completed):
jobs = durations_module.get_run_jobs("apache/airflow", 2)
- assert jobs == {"Tests": {"duration": 20 * 60,
"prepare_breeze_duration": 5 * 60}}
+ assert jobs == {"Tests": {"duration": 20 * 60, "image_work_duration":
5 * 60}}
def test_empty_on_command_failure(self, durations_module):
completed = subprocess.CompletedProcess(args=[], returncode=1,
stdout="", stderr="boom")
@@ -325,43 +325,82 @@ class TestGetRunJobs:
assert durations_module.get_run_jobs("apache/airflow", 2) == {}
-class TestWorkDuration:
- def test_subtracts_image_build(self, durations_module):
- assert (
- durations_module.calculate_work_duration({"duration": 1200,
"prepare_breeze_duration": 300})
- == 900
+class TestGetImageWorkSeconds:
+ def _job(self, *steps):
+ return {"steps": [{"name": n, "startedAt": s, "completedAt": c} for n,
s, c in steps]}
+
+ def test_sums_every_image_step_of_a_cache_push_job(self, durations_module):
+ # The real shape of "Push CI Regular AMD:3.12 image cache": the
build+push step and
+ # the cache push step both belong to the image, and neither is a
"Prepare breeze" step.
+ job = self._job(
+ ("Install Breeze", "2026-08-13T04:47:45Z", "2026-08-13T04:48:05Z"),
+ (
+ "Push CI latest images: 3.12 (linux/amd64 only)",
+ "2026-08-13T04:48:05Z",
+ "2026-08-13T05:17:43Z",
+ ),
+ ("Push CI Regular AMD cache:3.12:linux/amd64",
"2026-08-13T05:17:43Z", "2026-08-13T05:17:56Z"),
)
+ assert durations_module.get_image_work_seconds(job) == 29 * 60 + 38 +
13
+
+ def test_covers_prod_prepare_and_push_steps(self, durations_module):
+ job = self._job(
+ ("Prepare breeze & PROD image: 3.10", "2026-08-13T04:00:00Z",
"2026-08-13T04:05:00Z"),
+ (
+ "Push PROD latest image: 3.10 (linux/amd64 ONLY)",
+ "2026-08-13T04:05:00Z",
+ "2026-08-13T04:15:00Z",
+ ),
+ )
+ assert durations_module.get_image_work_seconds(job) == 15 * 60
- def test_full_duration_when_no_image_build_step(self, durations_module):
- assert (
- durations_module.calculate_work_duration({"duration": 1200,
"prepare_breeze_duration": None})
- == 1200
+ def test_none_when_the_job_touches_no_image(self, durations_module):
+ job = self._job(("Run unit tests", "2026-08-13T04:00:00Z",
"2026-08-13T04:30:00Z"))
+ assert durations_module.get_image_work_seconds(job) is None
+
+ def test_ignores_steps_with_unusable_timestamps(self, durations_module):
+ job = self._job(
+ ("Prepare breeze & CI image: 3.10", "2026-08-13T04:00:00Z",
"2026-08-13T04:05:00Z"),
+ ("Push CI latest images: 3.10 (linux/amd64 only)", "", ""),
)
+ assert durations_module.get_image_work_seconds(job) == 5 * 60
- def test_never_negative(self, durations_module):
+
+class TestWorkDuration:
+ def test_subtracts_image_work(self, durations_module):
+ assert durations_module.calculate_work_duration({"duration": 1200,
"image_work_duration": 300}) == 900
+
+ def test_subtracts_image_work_beyond_the_prepare_step(self,
durations_module):
+ # A cache-push job: nothing was "prepared", but 25 of its 26 minutes
were image work.
+ assert durations_module.calculate_work_duration({"duration": 1560,
"image_work_duration": 1500}) == 60
+
+ def test_full_duration_when_no_image_step(self, durations_module):
assert (
- durations_module.calculate_work_duration({"duration": 100,
"prepare_breeze_duration": 300}) == 0
+ durations_module.calculate_work_duration({"duration": 1200,
"image_work_duration": None}) == 1200
)
+ def test_never_negative(self, durations_module):
+ assert durations_module.calculate_work_duration({"duration": 100,
"image_work_duration": 300}) == 0
+
class TestRunImageBuildSeconds:
def test_median_across_jobs(self, durations_module):
jobs = {
- "a": {"duration": 0, "prepare_breeze_duration": 300},
- "b": {"duration": 0, "prepare_breeze_duration": 500},
- "c": {"duration": 0, "prepare_breeze_duration": 400},
+ "a": {"duration": 0, "image_work_duration": 300},
+ "b": {"duration": 0, "image_work_duration": 500},
+ "c": {"duration": 0, "image_work_duration": 400},
}
assert durations_module.calculate_image_build_seconds(jobs) == 400
- def test_ignores_jobs_without_the_step(self, durations_module):
+ def test_ignores_jobs_that_did_no_image_work(self, durations_module):
jobs = {
- "a": {"duration": 0, "prepare_breeze_duration": None},
- "b": {"duration": 0, "prepare_breeze_duration": 500},
+ "a": {"duration": 0, "image_work_duration": None},
+ "b": {"duration": 0, "image_work_duration": 500},
}
assert durations_module.calculate_image_build_seconds(jobs) == 500
- def test_none_when_no_job_recorded_the_step(self, durations_module):
- jobs = {"a": {"duration": 0, "prepare_breeze_duration": None}}
+ def test_none_when_no_job_did_image_work(self, durations_module):
+ jobs = {"a": {"duration": 0, "image_work_duration": None}}
assert durations_module.calculate_image_build_seconds(jobs) is None
@@ -372,15 +411,15 @@ class TestAnalyzeJobs:
# slow-job work time (image build excluded): latest 2400 vs baseline
1500 -> +60%.
jobs_by_run_id = {
100: {
- "slow-job": {"duration": 2700, "prepare_breeze_duration": 300},
- "stable-job": {"duration": 600, "prepare_breeze_duration":
None},
- "new-job": {"duration": 999, "prepare_breeze_duration": 300},
+ "slow-job": {"duration": 2700, "image_work_duration": 300},
+ "stable-job": {"duration": 600, "image_work_duration": None},
+ "new-job": {"duration": 999, "image_work_duration": 300},
}
}
for i in range(5):
jobs_by_run_id[i] = {
- "slow-job": {"duration": 1800, "prepare_breeze_duration": 300},
- "stable-job": {"duration": 590, "prepare_breeze_duration":
None},
+ "slow-job": {"duration": 1800, "image_work_duration": 300},
+ "stable-job": {"duration": 590, "image_work_duration": None},
}
regressions = durations_module.analyze_jobs(
@@ -394,17 +433,17 @@ class TestAnalyzeJobs:
names = [r["job"] for r in regressions]
# slow-job regressed; stable-job did not; new-job lacks baseline
samples
assert names == ["slow-job"]
- # Job regressions no longer carry image-build detail; that is reported
separately.
- assert "prepare_breeze" not in regressions[0]
+ # Job regressions no longer carry image-work detail; that is reported
separately.
+ assert "image_work" not in regressions[0]
def test_image_build_spike_alone_does_not_flag_a_job(self,
durations_module):
"""A job whose total ballooned only because the image build spiked is
not flagged."""
latest_runs = [{"id": 100}]
baseline_runs = [{"id": i} for i in range(5)]
# latest total 1500 = +150% vs baseline 600, but work time (300) is
unchanged.
- jobs_by_run_id = {100: {"job": {"duration": 1500,
"prepare_breeze_duration": 1200}}}
+ jobs_by_run_id = {100: {"job": {"duration": 1500,
"image_work_duration": 1200}}}
for i in range(5):
- jobs_by_run_id[i] = {"job": {"duration": 600,
"prepare_breeze_duration": 300}}
+ jobs_by_run_id[i] = {"job": {"duration": 600,
"image_work_duration": 300}}
regressions = durations_module.analyze_jobs(
jobs_by_run_id,
@@ -416,6 +455,41 @@ class TestAnalyzeJobs:
)
assert regressions == []
+ def
test_cache_push_job_is_not_flagged_when_only_the_image_rebuild_grew(self,
durations_module):
+ """The image-cache push jobs have no prepare-breeze step - their
build+push is the image.
+
+ Modelled on the 2026-08-13 canary: an apt package added to an early
image layer
+ invalidated every layer after it, so the build+push step went 11m ->
30m while the
+ job did no more work than usual.
+ """
+ latest_runs = [{"id": 100}]
+ baseline_runs = [{"id": i} for i in range(5)]
+ jobs_by_run_id = {
+ 100: {
+ "Push CI Regular AMD:3.12 image cache": {
+ "duration": 1860,
+ "image_work_duration": 1791,
+ }
+ }
+ }
+ for i in range(5):
+ jobs_by_run_id[i] = {
+ "Push CI Regular AMD:3.12 image cache": {
+ "duration": 690,
+ "image_work_duration": 621,
+ }
+ }
+
+ regressions = durations_module.analyze_jobs(
+ jobs_by_run_id,
+ latest_runs,
+ baseline_runs,
+ min_baseline_runs=5,
+ rel_threshold=0.25,
+ min_abs_increase_seconds=360,
+ )
+ assert regressions == []
+
class TestDetectImageBuildRegression:
@staticmethod
@@ -426,7 +500,10 @@ class TestDetectImageBuildRegression:
for run_id, created_at, image_seconds in specs:
runs.append({"id": run_id, "created_at": created_at})
jobs_by_run_id[run_id] = {
- "job": {"duration": image_seconds, "prepare_breeze_duration":
image_seconds}
+ "job": {
+ "duration": image_seconds,
+ "image_work_duration": image_seconds,
+ }
}
return runs, jobs_by_run_id
