CIMetrics: report ccache hit rates with --ccache

.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

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 `<out>/<repo>/ccache/`. GitHub
+keeps logs for 90 days; older jobs are counted as unavailable.
+
+Tests: `uv run --with pytest pytest CIMetrics`

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")

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%"],
+    ]