diff --git a/.github/workflows/ci-metrics-tests.yml b/.github/workflows/ci-metrics-tests.yml new file mode 100644 index 0000000..4ab7990 --- /dev/null +++ b/.github/workflows/ci-metrics-tests.yml @@ -0,0 +1,19 @@ +name: CIMetrics tests + +on: + pull_request: + paths: [CIMetrics/**] + push: + branches: [main] + paths: [CIMetrics/**] + +permissions: + contents: read + +jobs: + test: + runs-on: ubuntu-latest + steps: + - uses: actions/checkout@v4.1.2 + - uses: astral-sh/setup-uv@v6 + - run: uv run --no-project --with pytest pytest CIMetrics diff --git a/CIMetrics/README.md b/CIMetrics/README.md index 5685205..276b8dd 100644 --- a/CIMetrics/README.md +++ b/CIMetrics/README.md @@ -27,3 +27,34 @@ runner (`ubuntu-medium`) is paid today; the other runners are covered by the inc Rerunning the baseline week reproduces the RFC's numbers: 3,621 8-core minutes for StaflLib (exactly) and 3,459 for coit-tower (the RFC has 3,443; jobs re-run after the original fetch add the difference). + +## ccache hit rates + +Add `--ccache` to also report ccache hit rates, for the gates of the shared ccache store rollout +(Proposal 2): + +```bash +uv run CIMetrics/ci_metrics.py StaflLib coit-tower-bms2000 --since 2026-09-17 --until 2026-09-23 --ccache +``` + +It downloads the log of every completed job that has a step with "ccache" in its name and reads the +last `ccache -s` output in it. Both layouts in use are handled: Ubuntu's ccache 4.5 ("Summary:") and +the IAR-capable fork, 4.12 ("Cacheable calls:"). A step that runs ccache must zero the stats first +(`ccache -z`, as `hendrikmuhs/ccache-action` does) and print `ccache -s` at the end, or the job +isn't measured. + +The report gains a ccache section per repo: + +- **By job:** jobs measured, jobs with no hits (they started with an empty cache), and the hit rate, + which is hits over cacheable calls summed over the jobs. +- **By PR state and base:** the same, split by the PR's draft state at run time and whether its base + is main/dev or another PR's branch (stacked). The base is the PR's base now, not at run time: + Graphite retargets a PR to main after the PR below it merges, so older weeks undercount stacked + runs. +- **Remote storage:** errors and timeouts, once jobs use the shared store. + +`jobs.tsv` gains `ccache_hits` and `ccache_cacheable` columns. Logs are large (a week of StaflLib +is about 1,800 of them), so only the parsed stats are cached, under `//ccache/`. GitHub +keeps logs for 90 days; older jobs are counted as unavailable. + +Tests: `uv run --with pytest pytest CIMetrics` diff --git a/CIMetrics/ci_metrics.py b/CIMetrics/ci_metrics.py index 817453e..b4eed5c 100644 --- a/CIMetrics/ci_metrics.py +++ b/CIMetrics/ci_metrics.py @@ -27,7 +27,7 @@ # Per-minute prices the billing API reports for Sep 2026. Only the 8-core runner is paid today; # the rest is covered by the included minutes. PRICE = {"ubuntu-medium (8-core)": 0.022, "linux-2core": 0.006, "windows": 0.010, "macos": 0.062} -PR_FIELDS = """number isDraft createdAt closedAt headRefName +PR_FIELDS = """number isDraft createdAt closedAt headRefName baseRefName timelineItems(itemTypes: [READY_FOR_REVIEW_EVENT, CONVERT_TO_DRAFT_EVENT], first: 100) { nodes { __typename ... on ReadyForReviewEvent { createdAt } ... on ConvertToDraftEvent { createdAt } } }""" @@ -88,7 +88,7 @@ def graphql_batch(repo, selections): return json.loads(gh("api", "graphql", "-f", f"query={q}"))["data"]["repository"] -def fetch_prs(repo, runs, out): +def fetch_prs(repo, runs, since, until, out): """PRs behind the pull_request runs, with their draft/ready transitions.""" def load(): numbers = {p["number"] for r in runs if r["event"] == "pull_request" for p in r["pull_requests"]} @@ -103,7 +103,87 @@ def load(): for p in (v["nodes"] if v and "nodes" in v else [v] if v else []): prs[p["number"]] = p return list(prs.values()) - return cached(f"{out}/{repo}/prs.json", load) + return cached(f"{out}/{repo}/prs_{since}_{until}.json", load) + + +TIMESTAMP = re.compile(r"^\d{4}-\d\d-\d\dT[\d:.]+Z ") +ANSI = re.compile(r"\x1b\[[0-9;]*m") +RATIO = r"\s+(\d+)\s*/\s*(\d+)" + + +def parse_ccache_stats(log): + """Hits and cacheable calls from the last `ccache -s` in a job log, or None if it has none. + + Handles ccache 4.5's "Summary:" layout and the "Cacheable calls:" layout of 4.6 and later. + The first Hits line of the block counts each cacheable call once; the per-storage Hits lines + below it count lookups. Remote errors and timeouts appear only when nonzero. ccache 4.5 calls + remote storage "Secondary storage". + """ + lines = [TIMESTAMP.sub("", ANSI.sub("", l)) for l in log.splitlines()] + starts = [i for i, l in enumerate(lines) if l.startswith(("Summary:", "Cacheable calls:"))] + if not starts: + return None + stats, section = {}, None + for line in lines[starts[-1]:]: + if line.startswith(("[command]", "##[", "Use the -v")) or not line.strip(): + break + if not line.startswith(" "): + section = line.strip().rstrip(":") + elif (m := re.match(r"\s+Hits:" + RATIO, line)) and "hits" not in stats: + stats["hits"], stats["cacheable"] = int(m.group(1)), int(m.group(2)) + elif section in ("Remote storage", "Secondary storage") and (m := re.match(r"\s+(Hits|Misses|Errors|Timeouts):\s+(\d+)", line)): + stats[f"remote_{m.group(1).lower()}"] = int(m.group(2)) + return stats if "hits" in stats else None + + +def uses_ccache(job): + return any("ccache" in (s.get("name") or "").lower() for s in job.get("steps") or []) + + +def fetch_ccache(repo, jobs, out): + """ccache stats for every completed job with a ccache step. + + Returns ({job id: stats, or None if the log has no stats}, number of logs that couldn't be + fetched). Only the parsed stats are cached; a log that can't be fetched (expired, or an API + error) is retried on the next run. + """ + def one(job): + path = f"{out}/{repo}/ccache/{job['id']}.json" + if os.path.exists(path): + return job["id"], json.load(open(path)) + try: + # Build logs carry color codes; gh refuses to print them without this flag. + log = gh("api", "--allow-escape-sequences", f"repos/{OWNER}/{repo}/actions/jobs/{job['id']}/logs") + except RuntimeError as e: + print(f"{repo}: no log for job {job['id']}: {e}", file=sys.stderr) + return job["id"], "unavailable" + stats = parse_ccache_stats(log) + os.makedirs(os.path.dirname(path), exist_ok=True) + with open(path + ".tmp", "w") as f: + json.dump(stats, f) + os.replace(path + ".tmp", path) + return job["id"], stats + + todo = [j for js in jobs.values() for j in js + if uses_ccache(j) and j.get("conclusion") in ("success", "failure")] + with concurrent.futures.ThreadPoolExecutor(8) as pool: + results = dict(pool.map(one, todo)) + unavailable = [k for k, v in results.items() if v == "unavailable"] + for k in unavailable: + del results[k] + return results, len(unavailable) + + +def ccache_job_label(name): + """Job name with its matrix values cut down to the build preset, e.g. + "cpp / cpp_build / build-embedded (arm-cm7-iar-Debug)". GitHub cuts job names at 100 characters, + so the closing parenthesis may be missing.""" + m = re.match(r"(.*?)\s*\((.*?)\)?\s*$", name) + if not m: + return name + items = [i.strip() for i in m.group(2).split(",")] + preset = next((i for i in items if re.search(r"-(Debug|Release|RelWithDebInfo|MinSizeRel)$", i)), items[0]) + return f"{m.group(1)} ({preset})" def runner_type(job): @@ -165,7 +245,53 @@ def md_table(headers, rows): return "\n".join(lines) -def report(repo, runs, jobs, prs): +def base_kind(run, pr_for): + """Whether a PR run's PR targets main/dev or another PR's branch. Uses the PR's base branch now, + not at run time: Graphite retargets a PR to main once the PR below it merges.""" + if run["event"] != "pull_request" or run["head_branch"].startswith("gtmq_"): + return "" + base = (pr_for(run) or {}).get("baseRefName") + if not base: + return "base unknown" + return "on main/dev" if base == "main" or base.startswith("dev") else "stacked" + + +def ccache_rows(key, measured): + """[key, jobs, jobs with no hits, share with no hits, hit rate] per group, biggest group first.""" + groups = collections.defaultdict(list) + for r in measured: + groups[key(r)].append(r) + rows = [] + for k, rs in sorted(groups.items(), key=lambda x: -len(x[1])): + cold = sum(1 for r in rs if r["ccache_hits"] == 0) + cacheable = sum(r["ccache_cacheable"] for r in rs) + rate = f"{100 * sum(r['ccache_hits'] for r in rs) / cacheable:.0f}%" if cacheable else "—" + rows.append([k, len(rs), cold, f"{100 * cold / len(rs):.0f}%", rate]) + return rows + + +def ccache_section(flat, ccache, unavailable): + measured = [r for r in flat if isinstance(r["ccache_cacheable"], int) and r["ccache_cacheable"] > 0] + no_stats = sum(1 for v in ccache.values() if v is None) + out = ["", "### ccache", "", + f"{len(measured):,} jobs with ccache stats. {no_stats:,} logs had none (usually a job that failed " + f"before the stats step) and {unavailable:,} logs couldn't be fetched. A job with no hits started " + "with an empty cache. Hit rate is hits over cacheable calls, summed over the jobs."] + if not measured: + return out + headers = ["Jobs", "No hits", "Share with no hits", "Hit rate"] + out += ["", md_table(["Job"] + headers, ccache_rows(lambda r: ccache_job_label(r["job"]), measured))] + by_state = ccache_rows(lambda r: f"{r['state']}, {r['base']}" if r["base"] else r["state"], measured) + out += ["", "By PR state at run time and the PR's current base:", "", md_table(["State"] + headers, by_state)] + errors = sum(ccache[r["job_id"]].get("remote_errors", 0) for r in measured) + timeouts = sum(ccache[r["job_id"]].get("remote_timeouts", 0) for r in measured) + remote = sum(1 for r in measured if "remote_hits" in ccache[r["job_id"]]) + if remote: + out += ["", f"{remote:,} jobs used remote storage, with {errors:,} errors and {timeouts:,} timeouts."] + return out + + +def report(repo, runs, jobs, prs, ccache=None, unavailable=0): by_number = {p["number"]: p for p in prs} by_branch = collections.defaultdict(list) for p in prs: @@ -181,11 +307,13 @@ def pr_for(run): flat = [] for run in runs: - state = pr_state(run, pr_for) + state, base = pr_state(run, pr_for), base_kind(run, pr_for) for j in jobs[run["id"]]: - flat.append(dict(run_id=run["id"], workflow=run["name"], event=run["event"], state=state, - job=j["name"], norm=re.sub(r"\s*\(.*\)\s*$", "", j["name"]), - runner=runner_type(j), conclusion=j.get("conclusion"), billed=billed_minutes(j))) + stats = (ccache or {}).get(j["id"]) or {} + flat.append(dict(run_id=run["id"], job_id=j["id"], workflow=run["name"], event=run["event"], + state=state, base=base, job=j["name"], norm=re.sub(r"\s*\(.*\)\s*$", "", j["name"]), + runner=runner_type(j), conclusion=j.get("conclusion"), billed=billed_minutes(j), + ccache_hits=stats.get("hits", ""), ccache_cacheable=stats.get("cacheable", ""))) by_runner = collections.Counter() for r in flat: @@ -213,6 +341,8 @@ def pr_for(run): rows = [[k.replace("|", "/"), f"{b:,}", f"{100 * b / repo_total:.0f}%", ", ".join(sorted(s))] for k, (b, s) in sorted(by_job.items(), key=lambda x: -x[1][0])[:15]] out += ["", "### Biggest jobs", "", md_table(["Job", "Billed min", "Share of repo", "Runner"], rows)] + if ccache is not None: + out += ccache_section(flat, ccache, unavailable) return "\n".join(out), flat @@ -222,6 +352,8 @@ def main(): ap.add_argument("--since", required=True, type=dt.date.fromisoformat, help="first day, UTC (YYYY-MM-DD)") ap.add_argument("--until", required=True, type=dt.date.fromisoformat, help="last day, UTC, inclusive") ap.add_argument("--out", default="ci-metrics-data", help="cache and output directory") + ap.add_argument("--ccache", action="store_true", + help="also report ccache hit rates, read from the log of every job with a ccache step") args = ap.parse_args() sections = [f"# CI minutes, {args.since} to {args.until} (UTC)", ""] @@ -230,8 +362,12 @@ def main(): runs = fetch_runs(repo, args.since, args.until, args.out) print(f"{repo}: fetching jobs for {len(runs)} runs", file=sys.stderr) jobs = fetch_jobs(repo, runs, args.out) - prs = fetch_prs(repo, runs, args.out) - text, flat = report(repo, runs, jobs, prs) + prs = fetch_prs(repo, runs, args.since, args.until, args.out) + ccache, unavailable = None, 0 + if args.ccache: + print(f"{repo}: fetching logs of jobs with a ccache step", file=sys.stderr) + ccache, unavailable = fetch_ccache(repo, jobs, args.out) + text, flat = report(repo, runs, jobs, prs, ccache, unavailable) sections += [text, ""] with open(f"{args.out}/{repo}/jobs.tsv", "w") as f: f.write("\t".join(flat[0]) + "\n") diff --git a/CIMetrics/test_ci_metrics.py b/CIMetrics/test_ci_metrics.py new file mode 100644 index 0000000..125b104 --- /dev/null +++ b/CIMetrics/test_ci_metrics.py @@ -0,0 +1,131 @@ +"""Tests for the ccache parts of ci_metrics.py: + + uv run --with pytest pytest CIMetrics +""" +from ci_metrics import ccache_job_label, ccache_rows, parse_ccache_stats, uses_ccache + +# hendrikmuhs/ccache-action's post step with Ubuntu's ccache 4.5.1 (StaflLib sil-integration, Sep 18). +CCACHE_4_5 = """\ +2026-09-18T17:41:07.7407139Z ##[group]ccache stats +2026-09-18T17:41:07.7411291Z [command]/usr/bin/ccache -s +2026-09-18T17:41:07.7466344Z Summary: +2026-09-18T17:41:07.7466540Z Hits: 880 / 1074 (81.94 %) +2026-09-18T17:41:07.7466726Z Direct: 815 / 1074 (75.88 %) +2026-09-18T17:41:07.7466901Z Preprocessed: 65 / 259 (25.10 %) +2026-09-18T17:41:07.7467066Z Misses: 194 +2026-09-18T17:41:07.7467207Z Direct: 259 +2026-09-18T17:41:07.7467434Z Preprocessed: 194 +2026-09-18T17:41:07.7467571Z Primary storage: +2026-09-18T17:41:07.7467710Z Hits: 1862 / 2247 (82.87 %) +2026-09-18T17:41:07.7467863Z Misses: 385 +2026-09-18T17:41:07.7468005Z Cache size (GB): 0.44 / 0.50 (88.73 %) +2026-09-18T17:41:07.7468163Z Cleanups: 12 +2026-09-18T17:41:07.7468256Z +2026-09-18T17:41:07.7468340Z Use the -v/--verbose option for more details. +""" + +# The IAR-capable ccache fork (4.12) in StaflLib's arm-cm7-iar-RelWithDebInfo build, Sep 18. +CCACHE_4_12 = """\ +2026-09-18T17:38:08.6945759Z ##[group]ccache stats +2026-09-18T17:38:08.7001667Z [command]/__w/StaflLib/StaflLib/ccache/ccache -s +2026-09-18T17:38:08.7044552Z Cacheable calls: 1066 / 1066 (100.0%) +2026-09-18T17:38:08.7045437Z Hits: 1044 / 1066 (97.94%) +2026-09-18T17:38:08.7046058Z Direct: 1044 / 1044 (100.0%) +2026-09-18T17:38:08.7046655Z Preprocessed: 0 / 1044 ( 0.00%) +2026-09-18T17:38:08.7047223Z Misses: 22 / 1066 ( 2.06%) +2026-09-18T17:38:08.7047762Z Local storage: +2026-09-18T17:38:08.7048747Z Cache size (GB): 0.1 / 0.5 (10.41%) +2026-09-18T17:38:08.7049324Z Hits: 1044 / 1066 (97.94%) +2026-09-18T17:38:08.7049707Z Misses: 22 / 1066 ( 2.06%) +2026-09-18T17:38:08.7054962Z [command]/__w/StaflLib/StaflLib/ccache/ccache --version +""" + +# The same layout with remote storage, as ccache prints it when errors and timeouts are nonzero. +CCACHE_REMOTE = """\ +2026-10-09T12:00:00.0000000Z Cacheable calls: 593 / 593 (100.0%) +2026-10-09T12:00:00.0000000Z Hits: 590 / 593 (99.49%) +2026-10-09T12:00:00.0000000Z Direct: 590 / 590 (100.0%) +2026-10-09T12:00:00.0000000Z Preprocessed: 0 / 590 ( 0.00%) +2026-10-09T12:00:00.0000000Z Misses: 3 / 593 ( 0.51%) +2026-10-09T12:00:00.0000000Z Local storage: +2026-10-09T12:00:00.0000000Z Cache size (GB): 0.0 / 5.0 ( 0.00%) +2026-10-09T12:00:00.0000000Z Remote storage: +2026-10-09T12:00:00.0000000Z Hits: 590 / 593 (99.49%) +2026-10-09T12:00:00.0000000Z Misses: 3 / 593 ( 0.51%) +2026-10-09T12:00:00.0000000Z Errors: 2 +2026-10-09T12:00:00.0000000Z Timeouts: 1 +""" + + +def test_ccache_4_5_uses_summary_hits_not_storage_lookups(): + assert parse_ccache_stats(CCACHE_4_5) == {"hits": 880, "cacheable": 1074} + + +def test_ccache_4_12(): + assert parse_ccache_stats(CCACHE_4_12) == {"hits": 1044, "cacheable": 1066} + + +def test_remote_storage_counts(): + assert parse_ccache_stats(CCACHE_REMOTE) == { + "hits": 590, "cacheable": 593, + "remote_hits": 590, "remote_misses": 3, "remote_errors": 2, "remote_timeouts": 1} + + +def test_ccache_4_5_secondary_storage_counts_as_remote(): + cleanups = " Cleanups: 12\n" + assert cleanups in CCACHE_4_5 + log = CCACHE_4_5.replace( + cleanups, + cleanups + + "2026-09-18T17:41:07.7468200Z Secondary storage:\n" + "2026-09-18T17:41:07.7468200Z Hits: 870 / 1074 (81.01 %)\n" + "2026-09-18T17:41:07.7468200Z Misses: 204\n" + "2026-09-18T17:41:07.7468200Z Errors: 4\n") + assert parse_ccache_stats(log) == { + "hits": 880, "cacheable": 1074, "remote_hits": 870, "remote_misses": 204, "remote_errors": 4} + + +def test_last_stats_block_wins(): + # Stats are cumulative within a job, so the last block is the job's total. + assert parse_ccache_stats(CCACHE_4_12 + CCACHE_REMOTE)["hits"] == 590 + + +def test_ansi_codes_are_stripped(): + assert parse_ccache_stats(CCACHE_4_12.replace("Cacheable", "\x1b[36mCacheable"))["cacheable"] == 1066 + + +def test_log_without_stats(): + assert parse_ccache_stats("2026-09-18T17:38:08.0000000Z ##[error]Process completed with exit code 1.\n") is None + + +def test_uses_ccache(): + assert uses_ccache({"steps": [{"name": "Set up job"}, {"name": "setup ccache"}]}) + assert not uses_ccache({"steps": [{"name": "Set up job"}, {"name": "Run clang-format"}]}) + assert not uses_ccache({"steps": None}) + + +def test_job_label_keeps_the_build_preset(): + assert ccache_job_label( + "cpp / cpp_build / build-embedded (arm-cm7-iar, arm-cm7-iar-Debug, ubuntu-iar, ghcr.io/x:2.0.0-0)" + ) == "cpp / cpp_build / build-embedded (arm-cm7-iar-Debug)" + # As the API returns it: cut at 100 characters, no closing parenthesis. + assert ccache_job_label( + "cpp / cpp_build / build-embedded (arm-cm4f-gcc, arm-cm4f-gcc-Release, ubuntu-latest, ghcr.io/staflsystems/st" + ) == "cpp / cpp_build / build-embedded (arm-cm4f-gcc-Release)" + assert ccache_job_label("cpp / cpp_test / test (host, host-Debug, host-Debug, true, true)") \ + == "cpp / cpp_test / test (host-Debug)" + assert ccache_job_label("build / build-embedded (target-Release)") == "build / build-embedded (target-Release)" + assert ccache_job_label("cpp / sil_integration_test / sil-integration") \ + == "cpp / sil_integration_test / sil-integration" + + +def test_rows_count_cold_jobs_and_weight_hit_rate_by_calls(): + measured = [ + {"job": "a", "ccache_hits": 0, "ccache_cacheable": 100}, + {"job": "a", "ccache_hits": 900, "ccache_cacheable": 900}, + {"job": "b", "ccache_hits": 50, "ccache_cacheable": 100}, + ] + assert ccache_rows(lambda r: r["job"], measured) == [ + ["a", 2, 1, "50%", "90%"], + ["b", 1, 0, "0%", "50%"], + ]