From 7085b5e468d103c26570d2e8e0a395a6fd2f4a7e Mon Sep 17 00:00:00 2001 From: Jarry Shaw Date: Mon, 19 Oct 2026 04:46:57 -0400 Subject: [PATCH] ci(timing): budget the job reads and publish a cut-short report (#1930) - util/ci_timing.py: read the listings, workflow files and JUnit artifacts first and the job reads last, interleaved so every prefix spans each sample; stop them at --budget-minutes (default 30) or --max-calls and still write the report, with a note and a warning annotation - util/ci_timing.py: print a progress line per step to stderr, so a run killed by a cap shows how far it got; skip or abandon the runner-pool measurement once the budget is spent - ci-timing.yml: give the report step a 35-minute cap and the job a 40-minute one, above the measured 16.6-minute full run; add the summary and upload the report on always() - docstring, workflow comments and workflows.rst carry the measured calls and where the time goes - tests: the read order, both budgets writing a report, progress on stderr, and the nested caps Closes #1930 --- .github/workflows/ci-timing.yml | 27 +++- docs/source/contributing/workflows.rst | 18 ++- tests/project/test_ci_timing.py | 130 +++++++++++++++- util/ci_timing.py | 197 +++++++++++++++++++++---- 4 files changed, 322 insertions(+), 50 deletions(-) diff --git a/.github/workflows/ci-timing.yml b/.github/workflows/ci-timing.yml index a8e2a6bf35..eee734ec0d 100644 --- a/.github/workflows/ci-timing.yml +++ b/.github/workflows/ci-timing.yml @@ -30,7 +30,7 @@ on: # Read-only: the runs, jobs and artifacts need `actions: read`, the workflow # files at each run's sha need `contents: read`. GITHUB_TOKEN allows 1,000 API -# requests an hour per repository; a default run was estimated at about 690. +# requests an hour per repository; a default run made 677 (#1930). permissions: actions: read contents: read @@ -43,7 +43,14 @@ jobs: report: name: CI timing report runs-on: ubuntu-latest - timeout-minutes: 15 + # Three nested limits, each under the next, so that a slow week ends in a + # smaller report rather than none (#1930). The script stops reading jobs at + # --budget-minutes and writes what it has. The step's cap is the backstop, and + # sits far enough above to let a request already in flight finish its retries. + # This one leaves room for the setup steps and the uploads after it. Measured + # for #1930, a full sample took 16.6 minutes, nearly all of it job reads, which + # the API answers at up to 2.4 s each and which are made one at a time. + timeout-minutes: 40 steps: - uses: actions/checkout@v7 @@ -83,25 +90,33 @@ jobs: done echo "::notice title=No baseline::No earlier ci-timing-report artifact was found, so the week-over-week checks are skipped." + # Progress goes to the log as it happens, so a run stopped by a cap shows + # how far it got. - name: Report CI timing + timeout-minutes: 35 env: GH_TOKEN: ${{ github.token }} REPO: ${{ github.repository }} DAYS: ${{ inputs.days || 7 }} CONCURRENCY_HOURS: ${{ inputs.concurrency_hours || 0 }} run: | - status=0 python util/ci_timing.py --repo "$REPO" --days "$DAYS" \ --concurrency-hours "$CONCURRENCY_HOURS" --baseline prev/report.json \ - --out report.json --summary report.md || status=$? + --budget-minutes 30 --out report.json --summary report.md + + # `always()`, not `!cancelled()`, here and below: a report written before a + # cap stopped the job is still worth having (#1930), and with none written + # there is nothing to add. + - name: Add the report to the job summary + if: ${{ always() }} + run: | if [ -f report.md ]; then cat report.md >> "$GITHUB_STEP_SUMMARY" fi - exit "$status" # 90 days, so the trend is a series of weekly reports rather than one. - name: Upload the report - if: ${{ !cancelled() }} + if: ${{ always() }} uses: actions/upload-artifact@v7 with: name: ci-timing-report diff --git a/docs/source/contributing/workflows.rst b/docs/source/contributing/workflows.rst index ed56ffdba0..e228617945 100644 --- a/docs/source/contributing/workflows.rst +++ b/docs/source/contributing/workflows.rst @@ -491,12 +491,18 @@ its two-hour legs stay measured), a day per query because a filtered listing sto at 1,000 runs (Pages completed 1,154 in the week to 2026-10-09). It then reads the jobs of an evenly spaced sample -- 150 push and 150 pull-request runs of Unit Tests, 60 runs of each other workflow -- and the summary says how many runs each sample -holds and which span they cover. That is about 690 calls (estimate: 63 listing -pages, one per workflow per day and one more per further 100 runs, by the week to -2026-10-09's run counts with Experimental Tests taken as Unit Tests' 10, since it -runs on the same events; at most 300 + 300 job reads; 15 for the JUnit artifacts; -up to 12 workflow-file reads) of ``GITHUB_TOKEN``'s 1,000 an hour, on a read-only token -(``actions: read``, ``contents: read``). A job is measured by its own outcome: one +holds and which span they cover. For the week to 2026-10-19 that was 677 calls +(`#1930 `__: 49 listing pages, +one per workflow per day and one more per further 100 runs; 601 job reads; 15 for +the JUnit artifacts; 12 workflow-file reads) of ``GITHUB_TOKEN``'s 1,000 an hour, on +a read-only token (``actions: read``, ``contents: read``). It took 16.6 minutes, +908 seconds of it on the job reads, which the API answers at up to 2.4 s each and +which are made one at a time. So they are read last, in an order every prefix of +which spans each sample, and stop at ``--budget-minutes`` (30): the report is then +written on the runs read, with a note saying so. The step's cap (35 minutes) and the +job's (40) sit above that budget, and the summary and upload steps run on +``always()``, so a report written before a cap stopped the job is still published. +Progress goes to the log as the script runs. A job is measured by its own outcome: one cancelled at 95% of its cap or later timed out and counts, even in a run that reads ``cancelled`` for that reason; one cancelled earlier was superseded and does not. A step cap written as an expression differs by leg and reads as none. diff --git a/tests/project/test_ci_timing.py b/tests/project/test_ci_timing.py index 609755c5e8..93d273fee1 100644 --- a/tests/project/test_ci_timing.py +++ b/tests/project/test_ci_timing.py @@ -184,18 +184,22 @@ def listing(self, runs: 'list[dict]', query: 'dict[str, list[str]]') -> 'tuple[b return json.dumps(body).encode(), headers -def run_main(*argv: 'str', api: 'FakeAPI', - baseline: 'Optional[dict]' = None) -> 'tuple[int, str, dict, str]': - """``main`` against ``api``; returns the status, stdout, report.json and report.md.""" +def run_main(*argv: 'str', api: 'FakeAPI', baseline: 'Optional[dict]' = None, + stderr: 'Optional[io.StringIO]' = None, **options: 'Any') -> 'tuple[int, str, dict, str]': + """``main`` against ``api``; returns the status, stdout, report.json and report.md. + + ``stderr``, if given, receives the progress lines; ``options`` go to ``main``. + + """ with tempfile.TemporaryDirectory() as tmp: out, md = os.path.join(tmp, 'report.json'), os.path.join(tmp, 'report.md') before = os.path.join(tmp, 'baseline.json') if baseline is not None: pathlib.Path(before).write_text(json.dumps(baseline), encoding='utf-8') stdout = io.StringIO() - with contextlib.redirect_stdout(stdout), contextlib.redirect_stderr(io.StringIO()): + with contextlib.redirect_stdout(stdout), contextlib.redirect_stderr(stderr or io.StringIO()): status = ci_timing.main(['--repo', REPO, '--out', out, '--summary', md, - '--baseline', before, *argv], transport=api, now=NOW) + '--baseline', before, *argv], transport=api, now=NOW, **options) report = json.loads(pathlib.Path(out).read_text(encoding='utf-8')) if os.path.exists(out) else {} text = pathlib.Path(md).read_text(encoding='utf-8') if os.path.exists(md) else '' return status, stdout.getvalue(), report, text @@ -735,6 +739,105 @@ def test_a_day_past_the_listing_cap_is_reported(self) -> 'None': _, _, report, _ = run_main(api=FakeAPI(inflate=ci_timing.LISTING_CAP)) self.assertTrue(any('of which the API returned 3' in note for note in report['notes']), report['notes']) + def test_every_prefix_of_the_read_order_spans_the_window(self) -> 'None': + """#1930: a read stopped part way through still covers the whole window.""" + for size in range(40): + order = ci_timing.prefix_order(list(range(size))) + with self.subTest(size=size): + self.assertEqual(sorted(order), list(range(size))) + self.assertEqual(order[:2], [0, size - 1][:size]) + for count in range(2, size + 1): + chosen = sorted(order[:count]) + widest = max(high - low for low, high in zip(chosen, chosen[1:])) + # Each level of halving at most halves the widest gap. + self.assertLessEqual(widest, 2 * (size - 1) / (count - 1) + 1, (count, chosen)) + + def test_the_groups_are_read_in_step(self) -> 'None': + """At any point each sample has had about the same share read; ``first`` leads.""" + big = [{'id': n} for n in range(12)] + small = [{'id': 100 + n} for n in range(4)] + queue = ci_timing.read_order([big, small], first=[big[5], small[1]]) + ids = [run['id'] for run in queue] + self.assertEqual(sorted(ids), sorted(run['id'] for run in big + small)) + self.assertEqual(ids[:2], [5, 101]) + for count in range(2, len(ids) + 1): + read = ids[2:count] + shares = [sum(1 for n in read if n in group) / len(group) + for group in ({n for n in range(12)} - {5}, {100, 102, 103})] + self.assertLessEqual(abs(shares[0] - shares[1]), 0.5, (count, read)) + + +class _Clocked(FakeAPI): + """:class:`FakeAPI` with a clock that each job read moves on ``minutes``.""" + + def __init__(self, minutes: 'float') -> 'None': + super().__init__() + self.minutes, self.now = minutes, 0.0 + + def __call__(self, url: 'str', accept: 'str') -> 'tuple[bytes, dict[str, str]]': + if '/attempts/1/jobs' in url: + self.now += self.minutes * 60 + return super().__call__(url, accept) + + def clock(self) -> 'float': + return self.now + + +def job_reads(api: 'FakeAPI') -> 'list[int]': + return [int(m.group(1)) for url, _ in api.requests if (m := re.search(r'/runs/(\d+)/attempts/1/jobs', url))] + + +@unittest.skipUnless(HAS_LXML, NO_LXML) +class TestBudget(unittest.TestCase): + """#1930: a run that runs out of time or calls reading jobs still writes a report.""" + + def test_a_spent_time_budget_still_writes_a_report(self) -> 'None': + # Ten minutes a read, 25 to spend: the third read starts at 20, the fourth would at 30. + api = _Clocked(10) + with mock.patch.object(ci_timing, 'MIN_SAMPLES', 1): + status, stdout, report, summary = run_main( + '--budget-minutes', '25', '--concurrency-hours', '1', api=api, clock=api.clock) + self.assertNotIn(status, (ci_timing.EXIT_API, ci_timing.EXIT_CRASH)) + # The JUnit push leads, so ms per test keeps its jobs; then each event in turn. + self.assertEqual(job_reads(api), [PUSH_RUN, CANCELLED_RUN, PR_RUN]) + self.assertEqual(report['window']['read']['unit-tests.yml']['read'], 3) + self.assertEqual(report['window']['read']['unit-tests.yml']['listed'], 4) + self.assertEqual(report['derived']['test_counts'][0]['run_id'], PUSH_RUN) + stopped = [note for note in report['notes'] if note.startswith('Jobs were read for 3 of the 4 runs')] + self.assertEqual(len(stopped), 1, report['notes']) + self.assertIn('25-minute budget (--budget-minutes) ran out', stopped[0]) + self.assertIn(stopped[0], summary) + self.assertIn(f'::warning title=CI timing stopped early::{stopped[0]}', stdout) + # The runner pool is not measured on what is left over. + self.assertIsNone(report.get('concurrency')) + self.assertTrue(any('runner-pool measurement was skipped' in note for note in report['notes'])) + self.assertFalse(any('/actions/runs?' in url for url, _ in api.requests)) + + def test_running_out_of_calls_reading_jobs_still_writes_a_report(self) -> 'None': + """Out of calls while listing, there is nothing to report; out while reading jobs, there is.""" + whole = FakeAPI() + run_main(api=whole) + before = next(n for n, (url, _) in enumerate(whole.requests) if '/attempts/1/jobs' in url) + api = FakeAPI() + with mock.patch.object(ci_timing, 'MIN_SAMPLES', 1): + status, stdout, report, _ = run_main('--max-calls', str(before + 2), api=api) + self.assertNotIn(status, (ci_timing.EXIT_API, ci_timing.EXIT_CRASH), stdout) + self.assertEqual(len(api.requests), before + 2) + self.assertEqual(report['window']['read']['unit-tests.yml']['read'], 2) + self.assertTrue(any(note.startswith('Jobs were read for 2 of the 4 runs') + and '(--max-calls)' in note for note in report['notes']), report['notes']) + + def test_progress_goes_to_stderr(self) -> 'None': + """A run killed by a cap leaves a trail of how far it got.""" + stderr = io.StringIO() + run_main(api=FakeAPI(), stderr=stderr) + lines = stderr.getvalue().splitlines() + self.assertTrue(lines) + self.assertTrue(all(line.startswith('[ci-timing ') for line in lines), lines) + self.assertTrue(any(line.endswith('unit-tests.yml: 4 runs listed, 4 sampled.') for line in lines), lines) + self.assertTrue(any('JUnit: run 37998639834, junit-unit-3.13' in line for line in lines), lines) + self.assertTrue(lines[-1].endswith('Jobs read for 4 of 4 runs.'), lines) + class TestExitStatus(unittest.TestCase): """1 is a HARD finding; a failure to read or to run says so with a status of its own.""" @@ -1073,12 +1176,25 @@ def test_permissions_are_read_only(self) -> 'None': def test_the_job(self) -> 'None': specs = ci_timing.parse_workflow(self.text) - self.assertEqual([(spec['name'], spec['timeout']) for spec in specs], [('CI timing report', 15)]) + self.assertEqual([(spec['name'], spec['timeout']) for spec in specs], [('CI timing report', 40)]) self.assertIn('python util/ci_timing.py', self.code) # The upload and the baseline download name the same artifact. self.assertIn('name: ci-timing-report', self.code) self.assertIn('-n ci-timing-report', self.code) + def test_a_capped_run_still_publishes_its_report(self) -> 'None': + """#1930: the script's budget sits under its step's cap, which sits under the job's.""" + job = ci_timing.parse_workflow(self.text)[0] + step = next(step for step in job['steps'] if step['name'] == 'Report CI timing') + budget = float(re.search(r'--budget-minutes (\d+)', self.code).group(1)) + self.assertLess(budget, step['timeout']) + self.assertLess(step['timeout'], job['timeout']) + # Neither the summary nor the upload is skipped when a cap stops the job. + for name in ('Add the report to the job summary', 'Upload the report'): + with self.subTest(step=name): + self.assertRegex(self.code, rf"- name: {name}\n if: \$\{{\{{ always\(\) \}}\}}\n") + self.assertNotIn('!cancelled()', self.code) + def test_yaml_agrees(self) -> 'None': try: import yaml # pylint: disable=import-outside-toplevel @@ -1088,7 +1204,7 @@ def test_yaml_agrees(self) -> 'None': # PyYAML reads the bare key ``on`` as the boolean True. self.assertEqual(sorted(data[True]), ['schedule', 'workflow_dispatch']) self.assertEqual(data['permissions'], {'actions': 'read', 'contents': 'read'}) - self.assertEqual(data['jobs']['report']['timeout-minutes'], 15) + self.assertEqual(data['jobs']['report']['timeout-minutes'], 40) if __name__ == '__main__': diff --git a/util/ci_timing.py b/util/ci_timing.py index c22bffbe59..4e9a1c4da1 100644 --- a/util/ci_timing.py +++ b/util/ci_timing.py @@ -40,14 +40,26 @@ for the newest :data:`JUNIT_RUNS` successful push runs. Each testcase's own ``time`` is used; a suite's ``tests=`` count includes subtests and is not. -A default run makes about 690 API calls (estimate, for the week to 2026-10-09: 63 -listing pages, one per workflow per day and one more per further 100 runs, from -that week's run counts, with Experimental Tests taken as Unit Tests' 10 since it -runs on the same events; at most 300 + 300 job reads; 15 for artifacts; up to 12 -workflow reads), inside ``GITHUB_TOKEN``'s 1,000 per hour; ``--max-calls`` stops -it before it can take more. ``--concurrency-hours`` adds the runner-pool -measurement, which costs one call per run of every workflow in that window and is -therefore off unless asked for. +A default run made 677 API calls for the week to 2026-10-19, measured for #1930: +49 listing pages, one per workflow per day and one more per further 100 runs; 601 +job reads, at most ``--runs`` per event plus :data:`JUNIT_RUNS` pushes for Unit +Tests and ``--other-runs`` per other workflow, one more for a run past 100 jobs; 15 +for artifacts; up to 12 workflow reads. That is inside ``GITHUB_TOKEN``'s 1,000 +per hour, and ``--max-calls`` stops it before it can take more. + +**The time goes on the job reads**, which are made one at a time, as GitHub asks +of an integration: 908 of that run's 993 seconds, and 734 on Unit Tests' runs +alone, at 2.4 s for each page of about 100 jobs with their steps. The listings, the +workflow files and the JUnit artifacts are therefore read first, and the job reads +last, in an order every prefix of which spans each sample (:func:`read_order`). +Once ``--budget-minutes`` is spent, or ``--max-calls``, no further run's jobs are +read: the report is still written, on the runs read, and says so in a note and an +annotation. Each step prints a progress line to stderr as it goes, so a run killed +by its cap shows how far it got. + +``--concurrency-hours`` adds the runner-pool measurement, which costs one call per +run of every workflow in that window and is therefore off unless asked for. It is +skipped, or abandoned part way, once the budget is spent. It fetches with :mod:`requests` and parses JUnit XML with lxml (#1894), which the workflow installs, and needs nothing else outside the standard library. @@ -201,6 +213,9 @@ def _coverage_legs() -> 'tuple[str, tuple[str, ...]]': TOP_TESTS = 30 DEFAULT_MAX_CALLS = 900 +#: Minutes after which no further run's jobs are read; ci-timing.yml's step and job +#: caps sit above it, so that the report is written, and uploaded, before either. +DEFAULT_BUDGET_MINUTES = 30 #: Transient failures retried, with these waits in seconds. RETRY_WAITS = (5, 20) #: A filtered run listing returns at most this many runs, whatever total_count says. @@ -559,11 +574,64 @@ def spread(items: 'list[Any]', count: 'int') -> 'list[Any]': return [items[round(i * (len(items) - 1) / (count - 1))] for i in range(count)] +def prefix_order(items: 'list[Any]') -> 'list[Any]': + """``items`` reordered so that every prefix of the result spans all of them. + + The first and the last come first, then each gap's midpoint, a level of halving + at a time, so a read stopped part way through has still covered the whole window + rather than its newest days (#1930). + + """ + if len(items) <= 2: + return list(items) + order = [0, len(items) - 1] + gaps = collections.deque([(0, len(items) - 1)]) + while gaps: + low, high = gaps.popleft() + if high - low < 2: + continue + middle = (low + high) // 2 + order.append(middle) + gaps.extend(((low, middle), (middle, high))) + return [items[index] for index in order] + + +def read_order(groups: 'Iterable[list[dict[str, Any]]]', + first: 'Iterable[dict[str, Any]]' = ()) -> 'list[dict[str, Any]]': + """The runs of every sample, in the order their jobs are read, each once. + + ``first`` leads. The groups' runs follow, interleaved so that at any point each + group has had about the same share of its runs read, and those runs span its + window (:func:`prefix_order`). A read cut short by the budget therefore leaves a + smaller sample of every workflow, not a whole sample of some and none of others. + + """ + keyed = [] # type: list[tuple[float, int, dict[str, Any]]] + for group in groups: + ordered = prefix_order(group) + keyed += [(rank / len(ordered), len(keyed) + rank, run) for rank, run in enumerate(ordered)] + seen = set() # type: set[int] + queue = [] + for run in list(first) + [run for _, _, run in sorted(keyed, key=lambda item: item[:2])]: + if run['id'] not in seen: + seen.add(run['id']) + queue.append(run) + return queue + + def collect(client: 'Client', repo: 'str', *, now: 'datetime.datetime', days: 'float', runs: 'int' = 150, other_runs: 'int' = 60, junit_runs: 'int' = JUNIT_RUNS, - concurrency_hours: 'float' = 0) -> 'dict[str, Any]': + concurrency_hours: 'float' = 0, budget: 'float' = math.inf, + clock: 'Callable[[], float]' = time.monotonic, + progress: 'Optional[Callable[[str], None]]' = None) -> 'dict[str, Any]': """Everything the report is computed from, read from the API. + The run listings, the workflow files and the JUnit artifacts are read first, and + the job listings last, in :func:`read_order`. The job listings are what the time + goes on (see the module docstring), so they are what ``budget`` cuts short: once + it is spent, or the client's ``--max-calls`` is, no further run's jobs are read, + the runs not read leave the sample, and ``data['stopped']`` says why. + Args: client: The API. repo: ``owner/name``. @@ -574,13 +642,26 @@ def collect(client: 'Client', repo: 'str', *, now: 'datetime.datetime', days: 'f junit_runs: Successful push runs whose JUnit artifacts are read. concurrency_hours: Hours of every workflow's runs to measure the runner pool over; 0 skips it. + budget: Seconds, from the call, after which no further jobs are read. + clock: Replaces :func:`time.monotonic`, for tests. + progress: Receives one line per step, so that a killed run leaves a trail. """ + started = clock() + + def say(message: 'str') -> 'None': + if progress is not None: + progress(f'[ci-timing {clock() - started:6.0f} s, {client.calls} calls] {message}') + since = now - datetime.timedelta(days=days) base = f'/repos/{repo}/actions' data = {'repo': repo, 'since': iso(since), 'until': iso(now), 'days': days, - 'workflows': {}, 'junit': [], 'concurrency': None, 'notes': []} # type: dict[str, Any] + 'workflows': {}, 'junit': [], 'concurrency': None, 'notes': [], + 'stopped': None} # type: dict[str, Any] + say(f'Reading {repo}, {iso(since)} to {iso(now)}; no jobs are read after ' + f'{budget / 60:g} min.') + groups = [] # type: list[list[dict[str, Any]]] for workflow in (UNIT_TESTS,) + OTHER_WORKFLOWS: listed = [run for run in list_runs(client, f'{base}/workflows/{workflow}/runs', since, now, data['notes'], status='completed') @@ -588,7 +669,8 @@ def collect(client: 'Client', repo: 'str', *, now: 'datetime.datetime', days: 'f if workflow == UNIT_TESTS: chosen = [] # type: list[dict[str, Any]] for event in ('pull_request', 'push'): - chosen += spread([run for run in listed if run.get('event') == event], runs) + groups.append(spread([run for run in listed if run.get('event') == event], runs)) + chosen += groups[-1] # The pushes whose JUnit artifacts are read need their jobs read too. chosen += [run for run in listed if run.get('event') == 'push' and run['conclusion'] == 'success'][:junit_runs] @@ -596,8 +678,8 @@ def collect(client: 'Client', repo: 'str', *, now: 'datetime.datetime', days: 'f key=lambda run: run['created_at'], reverse=True) else: chosen = spread(listed, other_runs) - for run in chosen: - run['jobs'] = list(client.paginate(f'{base}/runs/{run["id"]}/attempts/1/jobs', 'jobs')) + groups.append(chosen) + say(f'{workflow}: {len(listed)} runs listed, {len(chosen)} sampled.') counts = collections.Counter((run.get('event'), run['conclusion']) for run in listed) data['workflows'][workflow] = { 'runs': chosen, 'specs': {}, @@ -622,8 +704,8 @@ def collect(client: 'Client', repo: 'str', *, now: 'datetime.datetime', days: 'f data['workflows'][workflow]['specs'][label] = (sha, text) pushes = [run for run in data['workflows'][UNIT_TESTS]['runs'] - if run.get('event') == 'push' and run.get('conclusion') == 'success'] - for run in pushes[:junit_runs]: + if run.get('event') == 'push' and run.get('conclusion') == 'success'][:junit_runs] + for run in pushes: artifacts = {item['name']: item for item in client.paginate(f'{base}/runs/{run["id"]}/artifacts', 'artifacts') if not item.get('expired')} @@ -631,31 +713,72 @@ def collect(client: 'Client', repo: 'str', *, now: 'datetime.datetime', days: 'f artifact = artifacts.get(JUNIT_ARTIFACT.format(leg=leg)) if artifact is None: continue - archive = zipfile.ZipFile(io.BytesIO(client.fetch(artifact['archive_download_url'])[0])) + raw = client.fetch(artifact['archive_download_url'])[0] + say(f'JUnit: run {run["id"]}, {JUNIT_ARTIFACT.format(leg=leg)}, {len(raw) / 1e6:.2f} MB.') + archive = zipfile.ZipFile(io.BytesIO(raw)) members = [name for name in archive.namelist() if name.endswith('.xml')] if members: data['junit'].append({'run_id': run['id'], 'created_at': run['created_at'], 'leg': leg, **parse_junit(archive.read(members[0]))}) if not data['junit']: data['notes'].append(f'No {JUNIT_ARTIFACT.format(leg="*")} artifact in the newest ' - f'{min(len(pushes), junit_runs)} successful push runs, so there ' + f'{len(pushes)} successful push runs, so there ' 'are no test-level timings.') - if concurrency_hours: - start = now - datetime.timedelta(hours=concurrency_hours) - spans = [] # type: list[tuple[datetime.datetime, datetime.datetime, str]] - for run in list_runs(client, f'{base}/runs', start, now, data['notes']): - for job in client.paginate(f'{base}/runs/{run["id"]}/jobs', 'jobs', filter='all'): - begun = parse_time(job.get('started_at')) - if not job.get('runner_name') or begun is None: - continue - ended = parse_time(job.get('completed_at')) or now - labels = ' '.join(job.get('labels') or ()) - spans.append((begun, ended, 'macos' if 'macos' in labels else 'other')) - data['concurrency'] = {'hours': concurrency_hours, **pool_concurrency(spans)} + # The JUnit pushes lead: ms per test needs their jobs as well as their artifacts. + queue = read_order(groups, first=pushes) + for done, run in enumerate(queue): + reason = None # type: Optional[str] + if clock() - started >= budget: + reason = f'the {budget / 60:g}-minute budget (--budget-minutes) ran out' + else: + try: + run['jobs'] = list(client.paginate(f'{base}/runs/{run["id"]}/attempts/1/jobs', 'jobs')) + except BudgetExceeded as error: + reason = str(error) + if reason: + data['stopped'] = (f'Jobs were read for {done} of the {len(queue)} runs sampled: ' + f'{reason}. The rest are left out of the sample, which still ' + 'spans the window.') + break + if (done + 1) % 25 == 0 or done + 1 == len(queue): + say(f'Jobs read for {done + 1} of {len(queue)} runs.') + if data['stopped']: + say(data['stopped']) + data['notes'].append(data['stopped']) + for info in data['workflows'].values(): + info['runs'] = [run for run in info['runs'] if 'jobs' in run] + + if concurrency_hours and data['stopped']: + data['notes'].append('The runner-pool measurement was skipped, the job reads having ' + 'stopped short.') + elif concurrency_hours: + data['concurrency'] = _concurrency(client, base, now, concurrency_hours, data['notes'], + lambda: clock() - started >= budget) + say('Runner pool measured.' if data['concurrency'] else 'Runner pool not measured.') return data +def _concurrency(client: 'Client', base: 'str', now: 'datetime.datetime', hours: 'float', + notes: 'list[str]', spent: 'Callable[[], bool]') -> 'Optional[dict[str, Any]]': + """The runner pool over the last ``hours``, or ``None`` if the budget runs out first.""" + start = now - datetime.timedelta(hours=hours) + spans = [] # type: list[tuple[datetime.datetime, datetime.datetime, str]] + for run in list_runs(client, f'{base}/runs', start, now, notes): + if spent(): + notes.append('The runner-pool measurement was abandoned, the budget having run ' + 'out part way through it.') + return None + for job in client.paginate(f'{base}/runs/{run["id"]}/jobs', 'jobs', filter='all'): + begun = parse_time(job.get('started_at')) + if not job.get('runner_name') or begun is None: + continue + ended = parse_time(job.get('completed_at')) or now + labels = ' '.join(job.get('labels') or ()) + spans.append((begun, ended, 'macos' if 'macos' in labels else 'other')) + return {'hours': hours, **pool_concurrency(spans)} + + def parse_xml(raw: 'bytes') -> 'Any': """``raw``'s root element, parsed strictly by lxml (#1894). @@ -1204,13 +1327,18 @@ def summary(report: 'dict[str, Any]', findings: 'list[dict[str, str]]') -> 'str' def main(argv: 'Optional[list[str]]' = None, *, transport: 'Optional[Transport]' = None, - now: 'Optional[datetime.datetime]' = None) -> 'int': + now: 'Optional[datetime.datetime]' = None, + clock: 'Callable[[], float]' = time.monotonic) -> 'int': """Collect, analyse, evaluate, write. Returns the exit status. + Progress goes to stderr as it happens, and the report to stdout at the end. + Args: argv: Command-line arguments. transport: Replaces the network, for tests. now: Replaces the current time, for tests. + clock: Replaces :func:`time.monotonic`, which ``--budget-minutes`` is + measured on, for tests. """ parser = argparse.ArgumentParser(description=__doc__.split('\n', 1)[0]) @@ -1230,6 +1358,9 @@ def main(argv: 'Optional[list[str]]' = None, *, transport: 'Optional[Transport]' parser.add_argument('--summary', help='write the Markdown summary here') parser.add_argument('--max-calls', type=int, default=DEFAULT_MAX_CALLS, help=f'API call budget (default: {DEFAULT_MAX_CALLS})') + parser.add_argument('--budget-minutes', type=float, default=DEFAULT_BUDGET_MINUTES, + help='read no further jobs after this many minutes, and report on what ' + f'was read (default: {DEFAULT_BUDGET_MINUTES})') args = parser.parse_args(argv) token = os.environ.get('GH_TOKEN') or os.environ.get('GITHUB_TOKEN') @@ -1246,7 +1377,9 @@ def main(argv: 'Optional[list[str]]' = None, *, transport: 'Optional[Transport]' try: data = collect(client, args.repo, now=moment, days=args.days, runs=args.runs, other_runs=args.other_runs, junit_runs=args.junit_runs, - concurrency_hours=args.concurrency_hours) + concurrency_hours=args.concurrency_hours, + budget=args.budget_minutes * 60, clock=clock, + progress=lambda line: print(line, file=sys.stderr, flush=True)) except (BudgetExceeded, OSError) as error: print(f'::error title=CI timing could not read the API::{error}. ' 'No threshold was evaluated.') @@ -1281,6 +1414,8 @@ def _report(args: 'argparse.Namespace', client: 'Client', data: 'dict[str, Any]' with open(args.summary, 'w', encoding='utf-8') as file: file.write(text) print(text) + if data.get('stopped'): + print(f"::warning title=CI timing stopped early::{data['stopped']}") for item in findings: kind = 'error' if item['level'] == 'hard' else 'warning' message = item['message'].replace('`', '').replace('%', '%25')