diff --git a/.github/scripts/fhir-bench/README.md b/.github/scripts/fhir-bench/README.md new file mode 100644 index 0000000000..327735b56f --- /dev/null +++ b/.github/scripts/fhir-bench/README.md @@ -0,0 +1,97 @@ +# FHIR benchmark scripts + +Scripts for `.github/workflows/fhir-benchmark.yml`. The workflow runs one job per storage leg; these files start the backends, run the suites and build the summary. + +## Legs + +Six legs: `sqlite`, `postgres`, `mongodb`, `sqlite-elasticsearch`, `postgres-elasticsearch`, `mongodb-elasticsearch` (`resolve-matrix.sh` maps the `backend` input to legs). + +## Suites, in run order + +1. `prewarm` +2. `import` +3. `crud` +4. `search` +5. `sql-run` (HFS's own read-only SQL-on-FHIR suite, `k6/sql-run.js`) +6. `insert` +7. `bulk-import` (`bulk-import.sh` and `bulk_import.py`; not a k6 suite; `$bulk-submit` into a fresh database; always last) + +The `indexing` (`$reindex`) suite was removed. Recover it from git history if needed. + +## Indexing mode per leg (`bulk-import`) + +| Leg | Mode | +|---|---| +| `sqlite`, `postgres`, `mongodb` | deferred (`HFS_BULK_SUBMIT_DEFER_INDEXING=true`): ingest, then one index rebuild | +| the three `*-elasticsearch` legs | inline (`HFS_BULK_SUBMIT_DEFER_INDEXING=false`) with file concurrency 4, batch size 1000, Elasticsearch bulk concurrency 4 | + +`bulk-import.sh` sets these; a variable already set in the environment wins. Reasons and measurements: [`$bulk-submit` indexing mode per storage backend](../../../crates/rest/README.md#bulk-submit-indexing-mode-per-storage-backend). + +## Report rows + +On the Elasticsearch legs the rows `↳ search indexing (seconds)` read `(= ingest)`: the index was built while ingesting, so the value is the ingest time, not a separate rebuild. + +## Report outputs + +Each run produces, in this order: + +- **Job summary text.** The comparison tables (unchanged), then a collapsed `### Charts` section: one for the compare job (`md_charts.py compare --in comparison.md`) and one per leg (`md_charts.py leg --box ... --leg ... --run-dir ...`). Both are display only and never fail the job. +- **Run history block** (`history.py`): the last 5 runs of the branch plus the latest `main` run, as tables and Mermaid charts. Old and new row labels are joined (see `LABEL_ALIASES`), except the old `index rebuild` row, which is a different quantity from `search indexing` and stays apart. +- **Standalone HTML report**, artifact `fhir-bench-report-`: one dark file (`report_html.py`, template `report_template.html`), uploaded with `archive: false` so it is not zipped. It opens in the browser through the `Full report (HTML)` link on the last line of the summary; that link works for signed-in viewers of the repository only. + Sections: run summary, 1 Is this run valid?, 2 Results, 3 Detail (timeline and host load, Bulk Import and Batch/Transaction Import by phase, import comparison, `$sql-run` by view, trend), 4 Full data. CI passes `--no-shapes`, so there is no "Search by query shape" section. +- **Report data**, artifact `fhir-bench-report-data-` (`report-data.json`). Later runs read it (`history.py --data-dir`) for the trend in the HTML report. + +All four artifacts and the summary are best effort (`continue-on-error`); a failure here never fails the benchmark. + +## Run time + +`run_timing.py` splits the wall-clock of a run per leg (jobs API plus `runner-info.txt`): + +- **Waiting for resources**: runner queue, the Docker host capacity gate (`capacity_wait_s`) and, if a leg records `host_wait_s`, a wait for a quiet host. +- **Behind earlier legs**: queue time spent because `max_parallel` sequences the legs. +- **Working**: the rest. + +Outputs: `run-time.md` and `run-timing.json`. `compare_legs.py --timing run-time.md` inserts the Markdown under the header; `report_html.py --timing-json run-timing.json` draws the HTML tile and timeline. A failure leaves the report unchanged. + +## Build job + +`build_features.py ''` derives the `cargo build --features` list from the selected legs: `R4` always, plus only the backends needed (`sqlite`, `postgres`, `mongodb`; `elasticsearch` for any `*-elasticsearch` leg), in fixed order. The workflow builds `helios-hfs` in release mode with `--no-default-features --features `. + +Rust cache: `actions/cache@v5` stores the cargo registry/git data and `target/release/{deps,build,.fingerprint}`. Key = runner OS + feature list + `Cargo.lock` hash, with restore-keys falling back to the same features, then any bench cache. The first run per key is cold. + +## Docker host + +Every leg uses the remote Docker daemon from the `DOCKER_HOST` secret, shared with the rest of CI (18 workflows use it). The capacity gate (`capacity-gate.sh`) prints the host `MemTotal` (20000 MB in run 40385370213) and waits for enough `MemAvailable` only at the start of a leg; it does not give exclusive use. Overlapping CI jobs can halve crud/search results (run 40353889556), so check running workflows before dispatching. + +## Run workflow form + +`Use workflow from` selects the branch whose workflow and scripts run. Fields: `backend`, `tests`, `vus`, `duration`, `run_id`, `log_level`; Postgres: `pg_shared_buffers`, `pg_effective_cache_size`, `pg_work_mem`, `pg_max_wal_size`, `pg_min_wal_size`, `pg_wal_buffers`, `pg_checkpoint_timeout`, `hfs_pg_max_connections`; `max_parallel` (1..2); `es_heap`, `es_sync_mode`; `mongo_wt_cache_gb`, `hfs_mongo_max_connections`. The indexing recipes are fixed per leg type in `bulk-import.sh` (see above) and are deliberately not form fields. + +## Tests + +`.github/workflows/fhir-bench-tests.yml` runs on pull requests touching `.github/scripts/fhir-bench/**`, `fhir-benchmark.yml` or itself (and on manual dispatch): the unit tests, `bash -n` / `py_compile` on every script, and a YAML check of `fhir-benchmark.yml`. Locally: + +```bash +cd .github/scripts/fhir-bench && python3 -m unittest discover -s . -p 'test_*.py' +``` + +## Run the generators locally + +```bash +gh run download -D DIR # DIR//... +cd .github/scripts/fhir-bench +python3 md_charts.py compare --in DIR/fhir-bench-comparison-/comparison.md > charts.md +python3 report_html.py --run-dir DIR --run-id --no-shapes \ + --out report.html --dump-json report-data.json +``` + +Drop `--no-shapes` to include the search-by-shape section when `search-points.json` is present. `md_charts.py leg` also needs the leg's box Markdown (`--box`), which CI captures inside the leg job. + +## Test GitHub rendering cheaply + +Push a throwaway `tmp/` branch whose workflow is triggered by `push`, with `permissions: actions: read`, and have it download the artifacts of an earlier run (`actions/download-artifact` with `run-id` and `github-token`). It then runs the generators above and appends to `$GITHUB_STEP_SUMMARY`, with no servers and no benchmark. Delete the branch afterwards. + +## Known limits + +- The job summary cannot be previewed locally; check it on GitHub. +- Artifact links, including the HTML report, need a signed-in session with access to the repository. diff --git a/.github/scripts/fhir-bench/build_features.py b/.github/scripts/fhir-bench/build_features.py new file mode 100644 index 0000000000..de52947d4c --- /dev/null +++ b/.github/scripts/fhir-bench/build_features.py @@ -0,0 +1,46 @@ +#!/usr/bin/env python3 +"""Derive the `cargo build --features` list from the resolved benchmark matrix. + +Usage: build_features.py '' (or the JSON on stdin) + +The matrix is resolve-matrix.sh's output, {"include":[{"backend":"postgres-elasticsearch",...}]}. +Mapping: sqlite -> sqlite; postgres -> postgres; mongodb -> mongodb; +-elasticsearch -> x plus elasticsearch. FHIR R4 is always on (no other +FHIR version is ever compiled). Output order is fixed so the same leg set +always yields the same string (it is also part of the build cache key). +""" +import json +import sys + +PRIMARIES = ("sqlite", "postgres", "mongodb") +ORDER = ("R4", "sqlite", "postgres", "mongodb", "elasticsearch") + + +def features_for(matrix): + feats = {"R4"} + legs = matrix.get("include", []) + if not legs: + raise ValueError("matrix has no legs") + for leg in legs: + name = leg["backend"] + base, sep, es = name.partition("-") + if base not in PRIMARIES or (sep and es != "elasticsearch"): + raise ValueError(f"unknown backend leg {name!r}") + feats.add(base) + if sep: + feats.add("elasticsearch") + return ",".join(f for f in ORDER if f in feats) + + +def main(argv): + raw = argv[1] if len(argv) > 1 else sys.stdin.read() + try: + print(features_for(json.loads(raw))) + except (ValueError, KeyError, TypeError) as e: + print(f"::error::build_features: {e}", file=sys.stderr) + return 1 + return 0 + + +if __name__ == "__main__": + sys.exit(main(sys.argv)) diff --git a/.github/scripts/fhir-bench/bulk-import.sh b/.github/scripts/fhir-bench/bulk-import.sh index 19b592d1b4..21f6f34b9a 100755 --- a/.github/scripts/fhir-bench/bulk-import.sh +++ b/.github/scripts/fhir-bench/bulk-import.sh @@ -127,6 +127,20 @@ case "$BACKEND" in # otherwise; HFS's documented import setting is no per-request refresh # (bulk-data-submit SKILL.md, "Rebuild knobs"). export HFS_ELASTICSEARCH_REINDEX_REFRESH="${HFS_ELASTICSEARCH_REINDEX_REFRESH:-false}" + # Indexing recipe per leg, from owner-reviewed measurements: on a 133,527- + # resource slice HFS's defaults took ~82 s against 18-52 s for this recipe + # (index while ingesting, 4 files x 4 ES bulk workers, batches of 1000; on + # sqlite-elasticsearch HFS ingests one file at a time whatever FILE_CONCURRENCY says). + # No refresh interval is set: measured, no gain. Env vars from the caller win. + export HFS_BULK_SUBMIT_DEFER_INDEXING="${HFS_BULK_SUBMIT_DEFER_INDEXING:-false}" + export HFS_BULK_SUBMIT_FILE_CONCURRENCY="${HFS_BULK_SUBMIT_FILE_CONCURRENCY:-4}" + export HFS_BULK_SUBMIT_BATCH_SIZE="${HFS_BULK_SUBMIT_BATCH_SIZE:-1000}" + export HFS_ELASTICSEARCH_BULK_CONCURRENCY="${HFS_ELASTICSEARCH_BULK_CONCURRENCY:-4}" + ;; + *) + # Standalone legs (sqlite, postgres, mongodb): deferred indexing was 26-27% + # faster on postgres and sqlite and a tie on mongodb (same slice). + export HFS_BULK_SUBMIT_DEFER_INDEXING="${HFS_BULK_SUBMIT_DEFER_INDEXING:-true}" ;; esac diff --git a/.github/scripts/fhir-bench/capacity-gate.sh b/.github/scripts/fhir-bench/capacity-gate.sh index 0389694077..25dd7d968d 100755 --- a/.github/scripts/fhir-bench/capacity-gate.sh +++ b/.github/scripts/fhir-bench/capacity-gate.sh @@ -6,7 +6,7 @@ # # `max_parallel`'s clamp (1..2, see the `setup` job / resolve-matrix.sh) only # bounds THIS run's own legs — it cannot see the rest of CI sharing the same -# 4-CPU / 11 GB Docker host, which is exactly what has OOM-killed a mongod +# 4-CPU Docker host (its MemTotal is printed below), which is exactly what has OOM-killed a mongod # here before. NEED_MB is a rough per-backend model, not a real cgroup # budget: # postgres family: shared_buffers, +1.5G for the rest of the server diff --git a/.github/scripts/fhir-bench/compare_legs.py b/.github/scripts/fhir-bench/compare_legs.py index 2dbfcd20a2..0c98ecc04f 100644 --- a/.github/scripts/fhir-bench/compare_legs.py +++ b/.github/scripts/fhir-bench/compare_legs.py @@ -3,20 +3,19 @@ # Cross-leg comparison for the FHIR Benchmark run summary: three metric tables # (throughput, p95 latency, errors) with suites as rows and legs as columns, # a legend, and a leg-health table, so a reader does not have to scroll six -# stacked per-leg summaries. The three rows that load the corpus sit together (LOADING_ROWS) +# stacked per-leg summaries. The rows that load the corpus sit together (LOADING_ROWS) # and name the operation each one times (ROW_LABELS): import is k6 POSTing # transaction Bundles to the base URL (HFS has no `$import`), bulk-import is -# `$bulk-submit` into a fresh database, reindex is the opt-in `indexing` suite's -# one timed `$reindex` (only when `tests` names it). The import row is not k6's request figures: its throughput +# `$bulk-submit` into a fresh database. The import row is not k6's request figures: its throughput # is resources/s and its p95 is per Bundle (IMPORT_NOTE, _import_row_values). # The `insert` row is HFS's own suite (k6/insert.js, not upstream): its # throughput row is labelled creates/s and it never carries the corpus marker -# `†` (see INSERT_NOTE). bulk-import and reindex are read from bulk-import.txt -# and indexing.txt instead of a k6 summary; bulk-import also adds a bulk +# `†` (see INSERT_NOTE). bulk-import is read from bulk-import.txt +# instead of a k6 summary; bulk-import also adds a bulk # detail table after the leg-health table. The Throughput table also splits the # bulk-import row into its two phases, directly under it: ingest (resources/s and -# seconds, how long loading the corpus takes) and index rebuild (seconds of the -# deferred search-index rebuild after it, `inline (during ingest)` when the +# seconds, how long loading the corpus takes) and search indexing (seconds: the +# deferred rebuild after it, the ingest seconds `(= ingest)` when the # backend indexed while ingesting; BULK_PHASES_NOTE). Display only: it never # decides anything, it always exits 0 and every problem goes out as a `::warning` # instead. @@ -84,26 +83,17 @@ "postgres-elasticsearch", "mongodb-elasticsearch", ] -# "Run benchmark suites" CANONICAL: what tests=all runs, in run order. `indexing` -# is opt-in and not in it; its row still shows when `tests` names it or a leg -# wrote indexing.txt (_render's extras). -CANONICAL_SUITES = ["prewarm", "import", "crud", "search", "insert", "bulk-import"] +# "Run benchmark suites" CANONICAL: what tests=all runs, in run order. +CANONICAL_SUITES = ["prewarm", "import", "crud", "search", "sql-run", "insert", "bulk-import"] # Shown in every comparison, as n/a (not requested) when the run did not ask for them. CORE_ROWS = ("crud", "search") # bulk-import is not a k6 suite: bulk-import.sh writes bulk-import.txt (key=value), # and it runs after search against its own fresh database. BULK_SUITE = "bulk-import" BULK_FILE = "bulk-import.txt" -# Nor is indexing: it is opt-in (never in tests=all), and "Run benchmark suites" -# runs it where `tests` lists it (after search), always before insert and -# bulk-import, in the suite loop (run_indexing_suite in suite-lib.sh); it writes -# indexing.txt (key=value). Its row is labelled reindex, the operation it times; -# its seconds and resource counts are in the leg's job summary (REINDEX_NOTE). -INDEXING_SUITE = "indexing" -INDEXING_FILE = "indexing.txt" -# The rows that load or reindex the corpus, shown together in this order where +# The rows that load the corpus, shown together in this order where # the first of them would fall (_shown). Markers still read the run order. -LOADING_ROWS = ("import", BULK_SUITE, INDEXING_SUITE) +LOADING_ROWS = ("import", BULK_SUITE) MAX_JSON_BYTES = 8 * 1024 * 1024 MAX_TXT_BYTES = 1024 * 1024 IMPORT_TARGET = 1000 @@ -118,20 +108,17 @@ TITLE = "Leg comparison" LEGEND = ( - "`†` crud/search/reindex ran on an incomplete corpus (import below 1000/1000 bundles or not " - "run before it, or the ES index not drained); on Bulk Import and its index rebuild, search " + "`†` crud/search ran on an incomplete corpus (import below 1000/1000 bundles or not " + "run before it, or the ES index not drained); on Bulk Import and its search indexing, search " "did not return every resource it ingested · `‡` more than 1% errors or failed checks in " - "that suite (on Bulk Import and its ingest, any resource not ingested; on its initial " - "index, a rebuild that did not complete or reported errors; on reindex, any reindex error " - "or a failed job) · `⚠` contended host (postgres crud above 3 ms/call) or a backend " + "that suite (on Bulk Import and its ingest, any resource not ingested; on its search " + "indexing, a rebuild that did not complete or reported errors) · `⚠` contended host (postgres crud above 3 ms/call) or a backend " "container died · **bold** = best in its row, shown only when no leg in that row carries a " - "marker or `(partial)` (on the Bulk Import ingest and index rebuild rows, also only when " + "marker or `(partial)` (on the Bulk Import ingest and search indexing rows, also only when " "every leg indexed the same way) · Bulk Import is resources/s through `$bulk-submit` into a " - "fresh database, kick-off until the search index covers it, and its ingest and initial " - "index rows split that time (see the note below the tables); reindex is resources/s of one " - "`$reindex` of the " - "type its row names, in the corpus import loaded, `(partial)` when it did not finish (the " - "reason is in that leg's job summary); each is one asynchronous job, so its p95 is n/a · " + "fresh database, kick-off until the search index covers it, and its ingest and search " + "indexing rows split that time (see the note below the tables); it is one asynchronous job, so " + "its p95 is n/a · " "n/a = no result (reason in brackets)" ) FOOTER = ( @@ -145,26 +132,28 @@ # The loading rows also name the operation they time, in every table: HFS has # no `$import`, and `import` is k6 POSTing transaction Bundles to the base URL. ROW_LABELS = { - ("import", "rps"): "Batch/Transaction Import, `POST /` Bundles (resources/s)", - ("import", "p95"): "Batch/Transaction Import, `POST /` Bundles (per Bundle)", - ("import", "err"): "Batch/Transaction Import, `POST /` Bundles", + ("import", "rps"): "Batch/Transaction Import (`/ui/batch`: `POST /` Bundles) (resources/s)", + ("import", "p95"): "Batch/Transaction Import (`/ui/batch`: `POST /` Bundles) (per Bundle)", + ("import", "err"): "Batch/Transaction Import (`/ui/batch`: `POST /` Bundles)", # every insert.js request is one create ("insert", "rps"): "insert (creates/s)", + # sql-run.js: every request is one $sql-run; sql_run_rows counts the NDJSON rows returned + ("sql-run", "rps"): "SQL-on-FHIR `$sql-run` (requests/s)", + ("sql-run", "rows_rps"): "SQL-on-FHIR `$sql-run` (rows/s)", + ("sql-run", "p95"): "SQL-on-FHIR `$sql-run`", + ("sql-run", "err"): "SQL-on-FHIR `$sql-run`", # one $bulk-submit job: resources ingested per second until searchable - ("bulk-import", "rps"): "Bulk Import, `$bulk-submit` (resources/s)", - ("bulk-import", "p95"): "Bulk Import, `$bulk-submit`", - ("bulk-import", "err"): "Bulk Import, `$bulk-submit`", - # one $reindex job; %s is " " when every leg reindexed the same type (_reindex_type) - ("indexing", "rps"): "reindex, `$reindex`%s (resources/s)", - ("indexing", "p95"): "reindex, `$reindex`%s", - ("indexing", "err"): "reindex, `$reindex`%s", + ("bulk-import", "rps"): "Bulk Import (`/ui/bulk-import`: `$bulk-submit`, until searchable) (resources/s)", + ("bulk-import", "p95"): "Bulk Import (`/ui/bulk-import`: `$bulk-submit`)", + ("bulk-import", "err"): "Bulk Import (`/ui/bulk-import`: `$bulk-submit`)", } # The two phases of the bulk-import job, as Throughput rows right under the # combined bulk-import row (_bulk_phase_lines). -BULK_INGEST_LABEL = "Bulk Import: ingest (resources/s, seconds)" -BULK_INDEX_LABEL = "Bulk Import: index rebuild (seconds)" +BULK_INGEST_LABEL = "↳ ingest, until Completed (resources/s, seconds)" +BULK_INDEX_LABEL = "↳ search indexing (seconds)" # index_seconds is 0 when HFS indexed while ingesting; that is not a free index. INLINE_INDEX = "inline (during ingest)" +INGEST_SUFFIX = " (= ingest)" # bulk_import.py index_status values that mean the deferred rebuild did not finish cleanly. _BULK_INDEX_BAD = ("failed", "permanent-errors", "cancelled") IMPORT_NOTE = ( @@ -175,22 +164,29 @@ "plus the transaction POST. k6's `http_reqs` is not used for import: it counts a corpus " "GET beside every Bundle POST. Bundles/s is in Leg health. Its resources/s is not " "comparable with the Bulk Import row's: committed Bundle entries per second of the k6 " - "scenario, against resources until the search index covers them." + "scenario, against resources until the search index covers them. k6 drives it with 20 concurrent clients." ) BULK_PHASES_NOTE = ( - "Bulk Import ingest and index rebuild rows: the same `$bulk-submit` load as the " + "Bulk Import ingest and search indexing rows (↳): the same `$bulk-submit` load as the " "Bulk Import row, split into the two times a user waits for. **Ingest** = resources " - "ingested ÷ seconds from kick-off until the status manifest is final, those seconds in " - "brackets: how long loading the corpus takes. **Index rebuild** = seconds from then until " - "HFS's deferred search-index rebuild of that freshly loaded data has finished " - "(HFS_BULK_SUBMIT_DEFER_INDEXING, the default); the Search check in the Bulk import table " - "then confirms it is searchable. `inline (during ingest)` = the backend indexed each batch " - "while ingesting (DEFER_INDEXING=false), so its indexing time is inside its ingest seconds " - "— it is not a zero-second index; `+ N s rebuild` is a follow-up rebuild of the types the " + "ingested ÷ seconds from kick-off until the status manifest is final (the web UI then " + "shows the submission as Completed), those seconds in brackets: how long loading the " + "corpus takes. **Search indexing** = the time spent indexing that freshly loaded data. " + "On Elasticsearch legs indexing runs during ingest, so its time is the ingest time " + "(`N s (= ingest)`, DEFER_INDEXING=false); elsewhere it is the deferred rebuild after " + "Completed, in seconds from Completed until HFS's deferred search-index rebuild has " + "finished (HFS_BULK_SUBMIT_DEFER_INDEXING, the default); the Search check in the Bulk import " + "table then confirms it is searchable. `+ N s rebuild` is a follow-up rebuild of the types the " "index rejected. No best is marked on either row when legs indexed differently. Both rows " "are in the Throughput table only (one asynchronous job: no p95; failed resources are in " "the Bulk Import Errors row)." ) +SQL_RUN_NOTE = ( + "`sql-run` is HFS's own suite (`.github/scripts/fhir-bench/k6/sql-run.js`, 10 VUs for 1 " + "minute): `$sql-run` over the stored corpus, one resource type per view. Its rows are " + "requests/s and rows/s (NDJSON lines returned); per-view numbers are in each leg's job " + "summary. It runs after search and before insert." +) INSERT_NOTE = ( "`insert` is HFS's own suite (`.github/scripts/fhir-bench/k6/insert.js`, load shape " "in its header): single-resource `POST Patient` and `POST Observation` creates, each " @@ -198,21 +194,6 @@ "row is creates/s. It runs last, after search and after the result-size snapshot, so its " "resources are in neither, and it never carries `†` because it does not read the corpus." ) -REINDEX_NOTE = ( - "Reindex row (the opt-in `indexing` suite: it runs only when `tests` names it and is not " - "part of `all`): one timed `POST //$reindex` per leg, after search and before " - "`insert`: HFS re-reads every stored resource of that type, re-extracts its search " - "parameters and rewrites the index that serves search (the primary's own index on " - "sqlite/postgres/mongodb, Elasticsearch on the +ES legs). **resources/s** = processed ÷ " - "(completedAt − startedAt) from `$reindex-status`. This is not the index cost paid inside " - "import, which stays in the Batch/Transaction Import row, nor the index rebuild time of freshly loaded " - "data, which is the Bulk Import index rebuild row; it rewrites the index right before " - "`insert` and `bulk-import`, so a run that includes it may skew both. A job still running " - "at the budget (`budget_s` in indexing.txt) is cancelled and its rate covers the part that " - "ran (`(partial)`). Its seconds, resources reindexed, index entries per resource and phase " - "split are in each leg's job summary (writer-reported, so not comparable across " - "backends)." -) # ── Sources and the one reader ────────────────────────────────────── @@ -580,6 +561,7 @@ def _load_suite(src, suite, names): "reason": None, "rps": _num(_field(m, "http_reqs", "rate")), "p95": _num(_field(m, "http_req_duration", "p(95)")), + "rows_rps": _num(_field(m, "sql_run_rows", "rate")), "iter_p95": _num(_field(m, "iteration_duration", "p(95)")), "err": None if err is None else err * 100.0, "passes": _count(checks.get("passes")), @@ -612,32 +594,6 @@ def _load_bulk_import(src, names): } -_INDEXING_RAN = ("completed", "partial", "failed") - - -def _reindex_row(ix): - """The reindex row: indexing.txt (run_indexing_suite) instead of a k6 summary. - A failed job keeps its rate; _indexing_markers gives it `‡`.""" - if ix is None: - return {"reason": "not run"} - st = ix.get("status") or "?" - if st == "kickoff-failed": - return {"reason": "kick-off HTTP %s" % (ix.get("kickoff_http") or "?")} - if st not in _INDEXING_RAN: - return {"reason": st} - processed, errors = _int(ix.get("processed")), _int(ix.get("errors")) - return { - "reason": None, - "rps": _fnum(ix.get("resources_per_s")), - "p95": None, - "err": 100.0 * max(errors, 0) / processed if errors is not None and processed else None, - "passes": max(processed - max(errors or 0, 0), 0) if processed is not None else 0, - "fails": max(errors, 0) if errors is not None else 0, - "na": {"p95": "one async job"}, - "partial": st == "partial", - } - - def _load_counts(text): rows = [] for line in text.splitlines()[1:]: @@ -687,19 +643,15 @@ def _import_row_values(d): def _load_leg(leg, src, rows): names = src.names() d = {"leg": leg, "status": "ok", "suites": {}} - it = _text(src, INDEXING_FILE) - d["indexing"] = _kv(it, "=") if it is not None else None for suite in rows: if suite == BULK_SUITE: d["suites"][suite] = _load_bulk_import(src, names) - elif suite == INDEXING_SUITE: - d["suites"][suite] = _reindex_row(d["indexing"]) else: d["suites"][suite] = _load_suite(src, suite, names) - # "no k6 summaries" is about the k6 suites; bulk-import and indexing only count - # when they are all there is. + # "no k6 summaries" is about the k6 suites; bulk-import only counts + # when it is all there is. k6 = [s for n, s in d["suites"].items() - if n not in (BULK_SUITE, INDEXING_SUITE)] or list(d["suites"].values()) + if n != BULK_SUITE] or list(d["suites"].values()) if not any(s["reason"] is None for s in k6): d["status"] = "no-summaries" @@ -761,8 +713,6 @@ def _markers(d, suite, rows): s = d["suites"].get(suite) if not s or s["reason"] is not None: return "" - if suite == INDEXING_SUITE: - return _indexing_markers(d) out = "" # insert writes new resources and reads none of the corpus, and bulk-import # loads its own fresh database: neither gets the corpus `†`. @@ -803,10 +753,9 @@ def _fmt_err(e): def _crowned(loaded, suite, key, pick, fmt, rows, nocrown): cand = [d for d in loaded if d["suites"].get(suite, {"reason": "x"})["reason"] is None - and d["suites"][suite][key] is not None] + and d["suites"][suite].get(key) is not None] if nocrown or len(cand) < 2: return set() - # a partial reindex rate covers only the part of the job that ran if any(_markers(d, suite, rows) or d["suites"][suite].get("partial") for d in cand): return set() best = fmt(pick(d["suites"][suite][key] for d in cand)) @@ -827,15 +776,12 @@ def _metric_cell(d, suite, kind, crown, rows): if s["fails"] > 0: text += " · **{:,} ✗**".format(s["fails"]) return text - value = s[kind] + value = s.get(kind) if value is None: text = "n/a (%s)" % md_cell(s.get("na", {}).get(kind, "no data")) - # a reindex with no rate (no startedAt or completedAt) still shows its - # `(partial)` and markers, so a failed or cut-short job stays visible - if suite != INDEXING_SUITE or kind != "rps": - return text + return text else: - text = _fmt_rps(value) if kind == "rps" else _fmt_p95(value) + text = _fmt_p95(value) if kind == "p95" else _fmt_rps(value) if d["leg"] in crown: text = "**%s**" % text if s.get("partial"): @@ -855,60 +801,29 @@ def _shown(rows): return others[:at] + loading + others[at:] -def _reindex_type(loaded): - """The resource type every leg that ran `$reindex` reindexed, or None.""" - types = set(d["indexing"].get("resource_type") or "" for d in loaded - if d.get("indexing") is not None - and d["indexing"].get("status") in _INDEXING_RAN) - if len(types) == 1: - t = types.pop() - if re.fullmatch(r"[A-Za-z][A-Za-z0-9]*", t): - return t - return None - - -def _row_label(suite, kind, rtype): - text = ROW_LABELS.get((suite, kind), suite) - if suite == INDEXING_SUITE: - text = text % (" " + rtype if rtype else "") - return md_cell(text) +def _row_label(suite, kind): + return md_cell(ROW_LABELS.get((suite, kind), suite)) def _metric_table(title, kind, datas, loaded, rows, nocrown): - rtype = _reindex_type(loaded) lines = ["### " + title, ""] lines.append("| Suite | " + " | ".join(label(d["leg"]) for d in datas) + " |") lines.append("|---|" + "---:|" * len(datas)) for suite in _shown(rows): - crown = set() - if kind == "rps": - crown = _crowned(loaded, suite, "rps", max, _fmt_rps, rows, nocrown) - elif kind == "p95": - crown = _crowned(loaded, suite, "p95", min, _fmt_p95, rows, nocrown) - cells = [_metric_cell(d, suite, kind, crown, rows) for d in datas] - lines.append("| " + _row_label(suite, kind, rtype) + " | " + " | ".join(cells) + " |") + for k in ((kind, "rows_rps") if kind == "rps" and suite == "sql-run" else (kind,)): + crown = set() + if k in ("rps", "rows_rps"): + crown = _crowned(loaded, suite, k, max, _fmt_rps, rows, nocrown) + elif k == "p95": + crown = _crowned(loaded, suite, "p95", min, _fmt_p95, rows, nocrown) + cells = [_metric_cell(d, suite, k, crown, rows) for d in datas] + lines.append("| " + _row_label(suite, k) + " | " + " | ".join(cells) + " |") if suite == BULK_SUITE and kind == "rps": lines += _bulk_phase_lines(datas, loaded, nocrown) lines.append("") return lines -def _indexing_markers(d): - ix = d["indexing"] - out = "" - ok = d["ic"]["bundles_ok"] if d["ic"] else None - undrained = d["leg"].endswith("-elasticsearch") and ( - d["drain"] is None or d["drain"].get("status") != "drained") - if ok is None or ok < IMPORT_TARGET or undrained: - out += "†" - errors = _int(ix.get("errors")) - if ix.get("status") == "failed" or (errors is not None and errors > 0): - out += "‡" - if d["died"]: - out += "⚠" - return out - - def _runner_cell(d): ri = d["ri"] name = ri.get("runner_name") @@ -1024,9 +939,9 @@ def _health_row(d, rows): "Each leg loaded the corpus `import` loads (its 2 seed bundles and 1,000 bundles, converted to " "per-resource-type NDJSON) through `$bulk-submit`, in a fresh database served by a second HFS, " "after the search suite. **Ingest** is kick-off until the status manifest is final; **Index** " - "is the deferred search-index rebuild that follows (followed in the second HFS's log); " + "is the search indexing that follows (followed in the second HFS's log); " "**Total** is both, and is what the Bulk Import row above divides the ingested resources " - "by; the ingest and index rebuild rows above show **Ingest** and **Index** on their own. " + "by; the ingest and search indexing rows above show **Ingest** and **Index** on their own. " "**Index** reads `inline (during ingest)` when HFS indexed while ingesting, so that time is " "inside **Ingest**. **Search check** compares Patient and Observation totals and two " "indexed queries with the " @@ -1051,7 +966,7 @@ def _bulk_inline(kv): def _bulk_index_text(kv): - """The initial-index time of a complete bulk-import run as text, or None when the + """The search-index rebuild time of a complete bulk-import run as text, or None when the run recorded no index_status (an older artifact; the caller decides). Inline indexing is named, never shown as a zero-second index.""" istatus = kv.get("index_status") @@ -1116,7 +1031,13 @@ def _bulk_phase(d): secs = _fnum(kv.get("index_seconds")) comparable = (istatus == "completed" and not _bulk_inline(kv) and secs is not None and secs >= 0) - return ingest, _phase_cell(_bulk_index_text(kv), "", mk, secs if comparable else None) + text = _bulk_index_text(kv) + if istatus == "inline": + # indexed while ingesting: its time is the ingest time, never n/a or empty + isecs = _seconds(kv.get("ingest_seconds")) + text = ("{:,.0f} s".format(isecs) + INGEST_SUFFIX) if isecs is not None \ + else INLINE_INDEX + return ingest, _phase_cell(text, "", mk, secs if comparable else None) def _fmt_secs(v): @@ -1124,7 +1045,7 @@ def _fmt_secs(v): def _bulk_phase_lines(datas, loaded, nocrown): - """The ingest and initial-index rows (BULK_INGEST_LABEL, BULK_INDEX_LABEL) that sit + """The ingest and search indexing rows (BULK_INGEST_LABEL, BULK_INDEX_LABEL) that sit under the combined bulk-import row in the Throughput table. Bold follows the other rows (no best across a marker, a hardware mismatch or fewer than two legs), and also when legs mixed inline and deferred indexing: their times measure different things.""" @@ -1254,7 +1175,7 @@ def _notes(loaded): return notes -def _render(root, env, warn, zips): +def _render(root, env, warn, zips, timing=None): run_id = (env.get("BENCH_RUN_ID") or "").strip() sources, unreadable = _discover(root, warn, zips) found = _group(sources, unreadable, run_id, warn) @@ -1282,8 +1203,6 @@ def _render(root, env, warn, zips): s = n[:-len(".json")] if (s + ".log") in names and s not in requested and not s.endswith("-points"): extras.add(s) - if INDEXING_FILE in names and INDEXING_SUITE not in requested: - extras.add(INDEXING_SUITE) rows = requested + sorted(extras) # crud and search are what a run is compared on: a run that did not ask for # them still shows their rows, as n/a (not requested), so a trimmed run @@ -1332,6 +1251,8 @@ def _render(root, env, warn, zips): parts.append("%d of %d legs have results" % (k, len(datas))) lines = [_header(env), "", " · ".join(parts), ""] + if timing: + lines += timing.strip("\n").split("\n") + [""] outcome = (env.get("DOWNLOAD_OUTCOME") or "").strip() if outcome and outcome != "success": lines += ["> ⚠ The artifact download step ended with `%s`; legs shown as n/a may have " @@ -1353,13 +1274,14 @@ def _render(root, env, warn, zips): "|---|---|---|---|---|---|---|"] lines += [_health_row(d, rows) for d in datas] lines += _bulk_table(datas, rows) - for note in (_notes(loaded) + ([REINDEX_NOTE] if INDEXING_SUITE in rows else []) + for note in (_notes(loaded) + + ([SQL_RUN_NOTE] if "sql-run" in rows else []) + ([INSERT_NOTE] if "insert" in rows else []) + [FOOTER]): lines += ["", note] return lines, k, len(datas) -def render(root, env): +def render(root, env, timing=None): """Pure: (markdown, workflow-command lines) for the downloaded artifacts.""" annotations = [] seen = set() @@ -1371,7 +1293,7 @@ def warn(msg): zips = [] try: - lines, k, n = _render(root, env, warn, zips) + lines, k, n = _render(root, env, warn, zips, timing) finally: for zf in zips: try: @@ -1393,13 +1315,28 @@ def main(argv=None): except Exception: pass argv = sys.argv if argv is None else argv - root = argv[1] if len(argv) > 1 else "bench-artifacts" + pos, timing_path, i = [], None, 1 + while i < len(argv): + if argv[i] == "--timing" and i + 1 < len(argv): + timing_path = argv[i + 1] + i += 2 + else: + pos.append(argv[i]) + i += 1 + root = pos[0] if pos else "bench-artifacts" + timing = None + if timing_path: + try: + with open(timing_path, encoding="utf-8") as f: + timing = f.read() or None + except Exception: + timing = None env = {} for key in ("BENCH_RUN_ID", "BENCH_MATRIX", "BENCH_IN_TESTS", "BENCH_REF_NAME", "BENCH_SHA", "DOWNLOAD_OUTCOME"): env[key] = os.environ.get(key, "") try: - markdown, annotations = render(root, env) + markdown, annotations = render(root, env, timing) except Exception as e: msg = ("%s: %s" % (type(e).__name__, e)).replace("\r", " ").replace("\n", " ")[:200] markdown = "%s\n\n_Leg comparison failed: %s. The per-leg summaries are unaffected._\n" % ( diff --git a/.github/scripts/fhir-bench/history.py b/.github/scripts/fhir-bench/history.py new file mode 100644 index 0000000000..5efea97a0a --- /dev/null +++ b/.github/scripts/fhir-bench/history.py @@ -0,0 +1,401 @@ +#!/usr/bin/env python3 +"""Progress over time of the FHIR benchmark, for the job summary. + +Reads the comparison.md artifact of earlier successful runs (via the gh CLI), +parses its Throughput / p95 tables generically and writes a collapsible +Markdown block with per-row tables and Mermaid xychart-beta line charts. +Best effort: every failure is swallowed and the exit code is always 0. +""" +import argparse +import glob +import json +import os +import re +import subprocess +import sys +import tempfile + +MAX_CHARTS = 6 +MAX_BYTES = 200 * 1024 +NUM_RE = re.compile(r"^-?\d[\d,]*(?:\.\d+)?") + + +NEW_BATCH = "Batch/Transaction Import (`/ui/batch`: `POST /` Bundles) (resources/s)" +NEW_BULK = "Bulk Import (`/ui/bulk-import`: `$bulk-submit`, until searchable) (resources/s)" +NEW_INGEST = "↳ ingest, until Completed (resources/s, seconds)" +NEW_INDEX = "↳ search indexing (seconds)" +OLD_REBUILD = "↳ search-index rebuild after Completed (seconds)" +# older wordings of renamed rows -> canonical (new) wording, so they join into one row +LABEL_ALIASES = { + "Batch/Transaction Import, `POST /` Bundles (resources/s)": NEW_BATCH, + "Bulk Import, `$bulk-submit` (resources/s)": NEW_BULK, + "Bulk Import: ingest (resources/s, seconds)": NEW_INGEST, + "↳ ingest (resources/s, seconds)": NEW_INGEST, + # a REAL deferred rebuild: a different measurement from NEW_INDEX (whose ES + # cells are "= ingest"), so it stays its own row and never joins NEW_INDEX + "Bulk Import: index rebuild (seconds)": OLD_REBUILD, +} + + +def canon_label(label): + return LABEL_ALIASES.get(label.strip(), label) + + +def parse_cell(cell): + """Numeric value of a table cell, or None. Strips bold/markers/commas.""" + c = cell.strip().replace("**", "").replace("`", "").strip() + m = NUM_RE.match(c) + if not m: + return None + try: + return float(m.group(0).replace(",", "")) + except ValueError: + return None + + +def _split_row(line): + line = line.strip() + if line.startswith("|"): + line = line[1:] + if line.endswith("|"): + line = line[:-1] + return [c.strip() for c in line.split("|")] + + +def parse_tables(md): + """Return {'throughput': T, 'p95': T}; T = {'legs': [...], 'rows': [(label, [vals])]}.""" + lines = md.splitlines() + tables = [] + i = 0 + heading = "" + while i < len(lines): + ln = lines[i] + if ln.startswith("#"): + heading = ln.lower() + if re.match(r"^\|\s*Suite\s*\|", ln): + legs = _split_row(ln)[1:] + rows = [] + i += 2 # skip separator + while i < len(lines) and lines[i].strip().startswith("|"): + cells = _split_row(lines[i]) + label = canon_label(cells[0]) + if any(label == r[0] for r in rows): + i += 1 + continue + vals = [parse_cell(c) for c in cells[1:1 + len(legs)]] + vals += [None] * (len(legs) - len(vals)) + rows.append((label, vals)) + i += 1 + tables.append((heading, {"legs": legs, "rows": rows})) + continue + i += 1 + out = {} + for h, t in tables: + if "throughput" in h and "throughput" not in out: + out["throughput"] = t + elif "p95" in h and "p95" not in out: + out["p95"] = t + if "throughput" not in out and tables: + out["throughput"] = tables[0][1] + return out + + +# ---- fetching (gh CLI) ---- + +def _gh(args): + return subprocess.run(["gh"] + args, capture_output=True, text=True, timeout=180) + + +def _list_runs(repo, workflow, branch, per_page): + r = _gh(["api", f"repos/{repo}/actions/workflows/{workflow}/runs" + f"?branch={branch}&status=completed&per_page={per_page}"]) + if r.returncode != 0: + return [] + # a run with one failed matrix leg is "failure" yet may still have uploaded + # the comparison artifact; fetch_comparison skips it silently when it did not + return [x for x in json.loads(r.stdout).get("workflow_runs", []) + if x.get("conclusion") in ("success", "failure")] + + +def _norm(run): + return {"id": int(run["id"]), "number": run.get("run_number"), + "date": (run.get("created_at") or "")[:10], + "branch": run.get("head_branch") or "", + "url": run.get("html_url") or ""} + + +def fetch_runs(repo, workflow, branch, exclude_id, max_runs): + runs = [] + try: + runs = [_norm(x) for x in _list_runs(repo, workflow, branch, max_runs + 5) + if int(x["id"]) != int(exclude_id)][:max_runs] + except Exception as e: # noqa: BLE001 + print(f"history: branch run list failed: {e}", file=sys.stderr) + if branch != "main": + try: + for x in _list_runs(repo, workflow, "main", 5): + if int(x["id"]) != int(exclude_id): + n = _norm(x) + if all(n["id"] != r["id"] for r in runs): + runs.append(n) + break + except Exception as e: # noqa: BLE001 + print(f"history: main run list failed: {e}", file=sys.stderr) + return runs + + +def fetch_comparison(repo, run, artifact_name): + """comparison.md text of a run's artifact (-), or None.""" + try: + with tempfile.TemporaryDirectory() as d: + r = _gh(["run", "download", str(run["id"]), "-R", repo, + "-n", f"{artifact_name}-{run['id']}", "-D", d]) + if r.returncode != 0: + return None + found = glob.glob(os.path.join(d, "**", "comparison.md"), recursive=True) + if not found: + found = glob.glob(os.path.join(d, "**", "*.md"), recursive=True) + if not found: + return None + with open(found[0], encoding="utf-8") as f: + return f.read() + except Exception as e: # noqa: BLE001 + print(f"history: download failed for {run.get('id')}: {e}", file=sys.stderr) + return None + + +def fetch_data(repo, run, data_dir): + """Best effort: report-data.json artifact of a run into data_dir/.""" + try: + _gh(["run", "download", str(run["id"]), "-R", repo, + "-n", f"fhir-bench-report-data-{run['id']}", + "-D", os.path.join(data_dir, str(run["id"]))]) + except Exception as e: # noqa: BLE001 + print(f"history: data download failed for {run.get('id')}: {e}", file=sys.stderr) + + +def suites_of(text): + """The `suites:` text of a comparison.md header, or None when not parseable.""" + m = re.search(r"^.*\bsuites:\s*([^·\n]+?)\s*(?:·|$)", text or "", re.M) + return m.group(1).strip() if m else None + + +# ---- rendering ---- + +def fmt_num(v): + if v is None: + return "–" + return f"{v:,.0f}" if abs(v) >= 100 else f"{v:,.1f}" + + +def pct(prev, cur): + if prev is None or cur is None or prev == 0: + return "" + p = (cur - prev) / abs(prev) * 100 + return f"{p:+.0f}%" + + +def _is_chart_row(label): + l = label.lower() + return not (l.startswith("prewarm") or l.startswith("↳") or "seconds)" in l) + + +def _clean(s): + return re.sub(r'["\[\]\n|`]', "", s).strip() + + +def headline_leg(legs, data): + """First leg with a value in every plotted run (never invent a point).""" + for lg in legs: + vs = data.get(lg) or [] + if len(vs) >= 2 and all(v is not None for v in vs): + return lg + return None + + +def y_unit(label): + """Axis unit from the row label, e.g. '(resources/s)'; plain rows are requests/s.""" + l = label.lower() + for u in ("resources/s", "creates/s", "rows/s", "req/s", "seconds", "ms"): + if u in l: + return "requests/s" if u == "req/s" else u + return "requests/s" + + +def render_chart(label, leg, vals, xlabels): + """Single-series trend chart; the title names the row and the leg.""" + if len(vals) < 2 or any(v is None for v in vals): + return "" + return "\n".join([ + "```mermaid", "xychart-beta", + f' title "{_clean(label)[:80]} - {_clean(leg)}"', + " x-axis [" + ", ".join(f'"{_clean(x)}"' for x in xlabels) + "]", + f' y-axis "{_clean(y_unit(label))}"', + " line [" + ", ".join(f"{v:.1f}" for v in vals) + "]", + "```"]) + "\n" + + +def build(args, fetch_runs_fn, fetch_comparison_fn, current_text=None, fetch_data_fn=None): + try: + runs = fetch_runs_fn(args.repo, args.workflow, args.branch, + args.run_id, args.max_runs) + except Exception as e: # noqa: BLE001 + print(f"history: listing failed: {e}", file=sys.stderr) + runs = [] + data_dir = getattr(args, "data_dir", None) + if data_dir and fetch_data_fn: + for run in runs: + try: + fetch_data_fn(args.repo, run, data_dir) + except Exception: # noqa: BLE001 + pass + cur_suites = suites_of(current_text) + entries = [] # (run dict, tables) + for run in sorted(runs, key=lambda r: (r.get("date", ""), r.get("id", 0))): + try: + text = fetch_comparison_fn(args.repo, run, args.artifact_name) + if not text: + continue + run_suites = suites_of(text) + if (cur_suites and run_suites and run_suites != cur_suites + and run.get("branch") != "main"): + continue # a different suite selection is not comparable + tabs = parse_tables(text) + if "throughput" in tabs and tabs["throughput"]["rows"]: + entries.append((run, tabs)) + except Exception as e: # noqa: BLE001 + print(f"history: run {run.get('id')} skipped: {e}", file=sys.stderr) + if current_text: + try: + tabs = parse_tables(current_text) + if "throughput" in tabs and tabs["throughput"]["rows"]: + entries.append(({"id": int(args.run_id), "number": None, "date": "", + "branch": args.branch, "current": True, + "url": f"https://github.com/{args.repo}/actions/runs/{args.run_id}"}, + tabs)) + except Exception as e: # noqa: BLE001 + print(f"history: current parse failed: {e}", file=sys.stderr) + if len(entries) < 2: + return "_Progress over time: fewer than 2 runs with a comparison artifact available yet._\n" + + def xl(run): + return "this run" if run.get("current") else f"#{run.get('number') or run['id']}" + + xlabels = [xl(r) for r, _ in entries] + out = [f"
Progress over the last {len(entries)} runs\n"] + out.append("Runs, oldest to newest: " + " · ".join( + f"[{xl(r)}]({r['url']}) ({r['branch']}{', ' + r['date'] if r.get('date') else ''})" + for r, _ in entries) + "\n") + out.append("Throughput per run (change vs the previous run in brackets; higher is better " + "for resources/s and creates/s, lower for seconds rows).\n") + + # row labels in order of first appearance, from the newest table backwards + labels, seen = [], set() + for _, tabs in reversed(entries): + for lab, _v in tabs["throughput"]["rows"]: + if lab not in seen: + seen.add(lab) + labels.append(lab) + order = {} + for _, tabs in entries: + for i, (lab, _v) in enumerate(tabs["throughput"]["rows"]): + order.setdefault(lab, i) + labels.sort(key=lambda l: order[l]) + + charts = [] + for lab in labels: + legs = [] + for _, tabs in entries: + for lg in tabs["throughput"]["legs"]: + if lg not in legs: + legs.append(lg) + data = {lg: [] for lg in legs} + for _, tabs in entries: + t = tabs["throughput"] + row = dict(t["rows"]).get(lab) + for lg in legs: + v = None + if row is not None and lg in t["legs"]: + v = row[t["legs"].index(lg)] + data[lg].append(v) + if all(v is None for vs in data.values() for v in vs): + continue + sec = [f"**{lab}**\n", "| Leg | " + " | ".join(xlabels) + " |", + "|---|" + "---:|" * len(xlabels)] + for lg in legs: + vs = data[lg] + if all(v is None for v in vs): + continue + cells = [] + for i, v in enumerate(vs): + c = fmt_num(v) + d = pct(vs[i - 1], v) if i else "" + cells.append(f"{c} ({d})" if d else c) + sec.append(f"| `{lg}` | " + " | ".join(cells) + " |") + out.append("\n".join(sec) + "\n") + if _is_chart_row(lab) and len(charts) < MAX_CHARTS: + lg = headline_leg(legs, data) + c = render_chart(lab, lg, data[lg], xlabels) if lg else "" + if c: + charts.append(c) + + if charts: + out.append("Trend of the headline leg per row (runs oldest to newest; " + "the other legs are in the tables above):\n") + out.extend(charts) + return _finish(out) + + +def _finish(sections, max_bytes=None): + """Join atomic sections, cutting at a section boundary when over the limit, + then close any open fence and the
block.""" + limit = (max_bytes or MAX_BYTES) - 400 + kept, size, cut = [], 0, False + for sec in sections: + n = len(sec.encode("utf-8")) + 1 + if size + n > limit and kept: + cut = True + break + kept.append(sec) + size += n + text = "\n".join(kept) + if text.count("```") % 2: + text += "\n```" + if cut: + text += "\n\n_(output cut here: the rest of the history was left out to stay within the size limit)_" + return text + "\n
\n" + + +def main(argv=None): + ap = argparse.ArgumentParser() + ap.add_argument("--repo", required=True) + ap.add_argument("--branch", required=True) + ap.add_argument("--run-id", required=True) + ap.add_argument("--current", required=True) + ap.add_argument("--artifact-name", required=True) + ap.add_argument("--out", required=True) + ap.add_argument("--max-runs", type=int, default=5) + ap.add_argument("--workflow", default="fhir-benchmark.yml") + ap.add_argument("--data-dir", default=None) + try: + args = ap.parse_args(argv) + except SystemExit: + return 0 + try: + try: + with open(args.current, encoding="utf-8") as f: + cur = f.read() + except OSError: + cur = None + text = build(args, lambda *a: fetch_runs(*a), + lambda repo, run, name: fetch_comparison(repo, run, name), cur, + fetch_data if args.data_dir else None) + with open(args.out, "w", encoding="utf-8") as f: + f.write(text) + except Exception as e: # noqa: BLE001 + print(f"history: failed: {e}", file=sys.stderr) + return 0 + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/.github/scripts/fhir-bench/k6/sql-run.js b/.github/scripts/fhir-bench/k6/sql-run.js new file mode 100644 index 0000000000..fd50cddfe8 --- /dev/null +++ b/.github/scripts/fhir-bench/k6/sql-run.js @@ -0,0 +1,158 @@ +// The `sql-run` suite of .github/workflows/fhir-benchmark.yml: SQL-on-FHIR +// ViewDefinition runs over the stored corpus (GET /$sql-run). HFS's own suite, +// not upstream's: the "Run benchmark suites" step uses a file in this +// directory in place of upstream's k6/.js. +// +// Why it exists: no other suite exercises the SQL-on-FHIR runner, which reads +// the stored resources through each backend's own runner (native SQL on +// sqlite and postgres, an aggregation pipeline on mongodb, the primary store's +// runner on the *-elasticsearch legs). +// +// Views: on the resource types with the most entries in the corpus import +// loads (Observation about 42%, Claim and ExplanationOfBenefit about 10% each; +// Patient is only about 1,000, so it would measure a tiny table). A +// ViewDefinition has one resource type, so Claim and ExplanationOfBenefit are +// two views. +// observation_page flat Observation, _limit=100 +// observation_large flat Observation, _limit=10000 +// observation_filter Observation with a low-cardinality `where` on the +// code (four codes, one view each, rotated): the +// database has to read rows until the limit is filled +// claim flat Claim, _limit=1000 +// eob flat ExplanationOfBenefit, _limit=1000 +// A request with a flat view and a LIMIT returns after the first rows, so the +// first two views measure "first page", not a scan, and every VU reads the +// same rows (warm cache). The `where` view is the honest scan. Read the +// per-view rows, not one blended figure. +// +// Load shape: constant-vus, 10 VUs for 1 minute (gracefulStop 30s). Every +// request is a heavier read than a search, so 10 is well below search's 30. +// k6 --vus / --duration replace this scenario, as they do the other suites'. +// +// Output: the k6 http_reqs rate is requests/s; `sql_run_rows` counts the +// NDJSON lines returned, so rows/s is its rate. The response body is read +// (responseType text) only to count rows; the server streams NDJSON either +// way. The check 'sql-run rows > 0' fails a 200 with an empty body, which +// would otherwise look very fast. setup() creates the ViewDefinitions and +// teardown() deletes them, so they do not appear in the result-size counts. +// +// The request asks for gzip like any real client. HFS used to answer a gzip-encoded +// `_format=ndjson` run with 200 and an empty body (k6 reported status 0, "error +// decompressing response body"); the body fix in channel_body_response +// (crates/rest/src/handlers/sof/run.rs) removed that. +// +// Never pass `patient` or `group`: on the *-elasticsearch legs the primary's +// search index is not written, so a compartment filter would return no rows. +// It is read-only, so it runs before insert (after search). + +import http from 'k6/http' +import { check } from 'k6' +import { Counter } from 'k6/metrics' + +export const options = { + scenarios: { + sql_run: { + executor: 'constant-vus', + vus: 10, + duration: '1m', + gracefulStop: '30s', + }, + }, + thresholds: { + 'http_req_duration{view:observation_page}': ['max>=0'], + 'http_req_duration{view:observation_large}': ['max>=0'], + 'http_req_duration{view:observation_filter}': ['max>=0'], + 'http_req_duration{view:claim}': ['max>=0'], + 'http_req_duration{view:eob}': ['max>=0'], + }, +} + +const BASE_URL = __ENV.BASE_URL +const JSON_HEADERS = { 'Accept': 'application/json', 'Content-Type': 'application/json' } +const rows = new Counter('sql_run_rows') + +// Top-level Observation.code values in the Synthea corpus (8480-6 is only a component +// of the 85354-9 panel, so it would match no row and fail the rows > 0 check). +const FILTER_CODES = ['8302-2', '29463-7', '8867-4', '39156-5'] + +function view(name, resource, columns, where) { + const vd = { + resourceType: 'ViewDefinition', + name, + status: 'active', + resource, + select: [{ column: columns.map(([n, path]) => ({ name: n, path })) }], + } + if (where) vd.where = [{ path: where }] + return vd +} + +const OBSERVATION_COLUMNS = [ + ['id', 'id'], + ['patient', 'subject.reference'], + ['code', 'code.coding.first().code'], + ['value', 'value.ofType(Quantity).value'], + ['unit', 'value.ofType(Quantity).unit'], + ['effective', 'effective.ofType(dateTime)'], +] + +const CLAIM_COLUMNS = [ + ['id', 'id'], + ['patient', 'patient.reference'], + ['status', 'status'], + ['created', 'created'], + ['total', 'total.value'], +] + +const EOB_COLUMNS = [ + ['id', 'id'], + ['patient', 'patient.reference'], + ['status', 'status'], + ['created', 'created'], + ['total', 'total.first().amount.value'], +] + +function create(vd) { + const r = http.post(`${BASE_URL}/ViewDefinition`, JSON.stringify(vd), { headers: JSON_HEADERS }) + if (r.status !== 201) throw new Error(`POST ViewDefinition ${vd.name}: ${r.status} ${r.body}`) + return r.json('id') +} + +export function setup() { + const ids = { + observation: create(view('bench_observation', 'Observation', OBSERVATION_COLUMNS)), + claim: create(view('bench_claim', 'Claim', CLAIM_COLUMNS)), + eob: create(view('bench_eob', 'ExplanationOfBenefit', EOB_COLUMNS)), + filter: FILTER_CODES.map((code) => + create(view(`bench_observation_${code}`, 'Observation', OBSERVATION_COLUMNS, + `code.coding.first().code = '${code}'`))), + } + return ids +} + +export function teardown(ids) { + const all = [ids.observation, ids.claim, ids.eob].concat(ids.filter) + for (const id of all) http.del(`${BASE_URL}/ViewDefinition/${id}`) +} + +function run(id, limit, tag) { + const url = `${BASE_URL}/$sql-run?subjectReference=ViewDefinition/${id}&_format=ndjson&_limit=${limit}` + const r = http.get(url, { headers: { 'Accept': 'application/x-ndjson', 'Accept-Encoding': 'gzip' }, + responseType: 'text', tags: { view: tag } }) + const n = r.status === 200 && r.body ? r.body.split('\n').filter((l) => l.length > 0).length : 0 + rows.add(n) + check(r, { + 'sql-run 200': (x) => x.status === 200, + 'sql-run rows > 0': () => n > 0, + }) +} + +export default function (ids) { + switch ((__VU + __ITER) % 5) { + case 0: run(ids.observation, 100, 'observation_page'); break + case 1: run(ids.observation, 10000, 'observation_large'); break + case 2: run(ids.filter[__ITER % FILTER_CODES.length], 1000, 'observation_filter'); break + case 3: run(ids.claim, 1000, 'claim'); break + default: run(ids.eob, 1000, 'eob') + } +} diff --git a/.github/scripts/fhir-bench/md_charts.py b/.github/scripts/fhir-bench/md_charts.py new file mode 100644 index 0000000000..00de31b27c --- /dev/null +++ b/.github/scripts/fhir-bench/md_charts.py @@ -0,0 +1,580 @@ +#!/usr/bin/env python3 +"""Collapsed Mermaid charts for the GitHub job summary of the FHIR benchmark. + + python3 md_charts.py compare --in comparison.md --layout sidebyside + python3 md_charts.py leg --box leg-summary.md --leg sqlite --run-dir bench-results --layout sidebyside + +Both print a `### Charts` Markdown section on stdout, meant to be APPENDED after the +unchanged report text (`cat summary.md; python3 md_charts.py ...`). Nothing of the +original is ever rewritten. The charts read their numbers from the tables of the text +they sit under, so a chart cannot disagree with its table; the run-phase timeline and +the bulk-import phases of a leg also read the leg's result files. + +Always exits 0 and prints nothing (or one short note) when something cannot be parsed. +Standard library only. GitHub renders Mermaid (xychart-beta, gantt) in job summaries; +inline SVG, data: images and colour styles are stripped, so colours go through the +`%%{init}%%` theme variables. +""" +import argparse +import json +import math +import os +import re +import sys +import zlib + +BLUE = "#2f81f7" +RAMP_P99, RAMP_P95, RAMP_P50 = "#54aeff", "#2f81f7", "#0969da" # p99 drawn at the back +GANTT_BAR = "#0969da" +GANTT_BAR_2 = "#54aeff" +GRID = "#8c959f" +XY_W, XY_H = 540, 260 +XY_W_CELL = 440 # two cells must fit GitHub's ~1012 px content width +SPREAD_NOTE = 50.0 +MAX_OUT_BYTES = 600_000 # a step summary is capped at 1 MiB; the report text comes first + +# Leg colours: the six known legs keep the colours of the approved prototype's HTML report +# (mid tones readable on both GitHub themes); any other leg name gets one of EXTRA, picked +# by a hash of its name so it is stable, and moved on if another leg of the chart has it. +LEG_COLOURS = { + "postgres": "#236bcf", "sqlite": "#008622", "mongodb": "#9348b1", + "postgres-elasticsearch": "#4a91f8", "sqlite-elasticsearch": "#3fac4a", + "mongodb-elasticsearch": "#b96dd8", +} +EXTRA = ["#db6d28", "#bf8700", "#cf222e", "#1b9aaa", "#e5609a", "#6e7781", "#8a5a00", "#57ab5a", + "#c2410c", "#0e7490"] + +MARKERS = "†‡⚠" + + +# ── table parsing ─────────────────────────────────────────────────────────── +def cells(line): + return [c.strip() for c in line.strip().strip("|").split("|")] + + +def find_table(lines, heading, lo=0): + """(header, rows, last_row_index) of the first table after a line starting with `heading`.""" + for i in range(lo, len(lines)): + if not lines[i].startswith(heading): + continue + j = i + 1 + while j < len(lines) and not lines[j].startswith("|"): + if lines[j].startswith("#"): + return None + j += 1 + if j + 1 >= len(lines) or not re.match(r"^\|[-:| ]+\|$", lines[j + 1].strip()): + return None + head = cells(lines[j]) + rows, k = [], j + 2 + while k < len(lines) and lines[k].startswith("|"): + row = cells(lines[k]) + rows.append(row + [""] * (len(head) - len(row))) + k += 1 + return head, rows, k - 1 + return None + + +def num(text): + """First number of a cell (markers, bold and thousands commas ignored), or None for n/a.""" + t = text.replace("**", "").lstrip(" " + MARKERS) + m = re.match(r"^(-?\d[\d,]*(?:\.\d+)?|-?\.\d+)", t) + return float(m.group(1).replace(",", "")) if m else None + + +def plain(text): + """A cell as text safe inside a quoted Mermaid string.""" + t = text.replace("**", "").replace("`", "").replace('"', "'") + t = t.replace("#", "").replace(";", ",").replace("[", "(").replace("]", ")").replace("\\", "") + return re.sub(r"\s+", " ", t).strip() + + +def title_safe(text): + return plain(text).replace("$", "").replace("|", "/").replace("*", "").replace("_", " ") + + +def short_name(label): + """'Batch/Transaction Import (`/ui/batch`: ...) (resources/s)' -> ('Batch/Transaction Import', '(resources/s)').""" + label = label.replace("**", "") + unit = re.findall(r"\(([^()]*)\)", label) + name = re.split(r"[,(]", label, maxsplit=1)[0].strip() + if name.startswith("↳"): # phase rows of the bulk job: name them in full + name = "Bulk Import " + name.lstrip("↳ ").strip() + name = title_safe(name) + u = "" + if unit: + # last parenthesised group that looks like a unit ("per Bundle" is a latency note, kept as is) + u = "(%s)" % title_safe(unit[-1]) + return name, u + + +def canon_leg(label): + t = label.replace("`", "").strip().lower() + if t.endswith("+es"): + t = t[:-3] + "-elasticsearch" + return t + + +def leg_colours(names): + """{name: colour}, distinct within `names`, stable per name for the known legs.""" + out, used = {}, set() + for n in names: + c = LEG_COLOURS.get(canon_leg(n)) + if c: + out[n] = c + used.add(c) + for n in names: + if n in out: + continue + start = zlib.crc32(canon_leg(n).encode("utf-8")) % len(EXTRA) + pick = None + for k in range(len(EXTRA)): + c = EXTRA[(start + k) % len(EXTRA)] + if c not in used: + pick = c + break + if pick is None: # more legs than colours: cycle + pick = EXTRA[(start + len(used)) % len(EXTRA)] + out[n] = pick + used.add(pick) + return out + + +# ── Mermaid builders ──────────────────────────────────────────────────────── +def nice_top(v): + if v <= 0: + return 1 + e = 10 ** math.floor(math.log10(v * 1.08)) + for f in (1, 1.2, 1.5, 2, 2.5, 3, 4, 5, 6, 8, 10): + if f * e >= v * 1.08: + return int(f * e) if f * e >= 1 else f * e + return 10 * e + + +def mnum(v): + return ("%.2f" % v).rstrip("0").rstrip(".") + + +def xy(cats, series, palette, y_label, horizontal=False, width=XY_W, height=XY_H, value_ticks=True): + """series: list of ('bar'|'line', values); None counts as 0.""" + top = nice_top(max([v or 0 for _, vals in series for v in vals] + [0])) + cfg = {"width": width, "height": height, "useMaxWidth": False} + if not value_ticks: + cfg["yAxis"] = {"showLabel": False, "showTick": False} + init = {"xyChart": cfg, + "themeVariables": {"xyChart": {"plotColorPalette": ", ".join(palette), + "backgroundColor": "transparent"}}} + out = ["```mermaid", "%%{init: " + json.dumps(init) + "}%%", + "xychart-beta" + (" horizontal" if horizontal else ""), + " x-axis [" + ", ".join('"%s"' % c for c in cats) + "]", + ' y-axis "%s" 0 --> %s' % (plain(y_label), top)] + for kind, vals in series: + out.append(" %s [%s]" % (kind, ", ".join(mnum(v or 0) for v in vals))) + out.append("```") + return out + + +def hms(s): + s = int(s) % 86400 + return "%02d:%02d:%02d" % (s // 3600, s % 3600 // 60, s % 60) + + +def gantt_init(left): + return {"gantt": {"useMaxWidth": False, "barHeight": 16, "barGap": 4, + "fontSize": 11, "sectionFontSize": 11, "leftPadding": left}, + "themeVariables": {"taskBkgColor": GANTT_BAR, "taskBorderColor": GANTT_BAR, + "taskTextColor": "#ffffff", "taskTextLightColor": "#ffffff", + "doneTaskBkgColor": GANTT_BAR_2, "doneTaskBorderColor": GANTT_BAR_2, + "taskTextDarkColor": "#1f2328", "gridColor": GRID, + "sectionBkgColor": "transparent", "altSectionBkgColor": "transparent", + "sectionBkgColor2": "transparent"}, + "themeCSS": ".grid .tick line{stroke:%s;stroke-opacity:.6}" % GRID} + + +def gtext(s): + """Task and section names: no colon, comma, semicolon or hash.""" + return re.sub(r"[:,;#]", " ", plain(s)).strip() or "leg" + + +def bulk_gantt(rows): + """rows: (leg, ingest_s, rebuild_s or None). Elapsed time since kick-off. A leg without a + rebuild (indexing ran during ingest) gets the ingest bar only.""" + # The axis is elapsed time since kick-off: minutes:seconds below one hour (a 210 s bar + # ends at 03:30), hours:minutes above. %H:%M alone read "00:03" for 210 s as "3". + longest = max([round(a) + round(b or 0) for _, a, b in rows] or [0]) + # Units are literal characters in the format, so "03m 30s" cannot be read as 3. + axis = "%Mm %Ss" if longest < 3600 else "%Hh %Mm" + out = ["```mermaid", "%%{init: " + json.dumps(gantt_init(150)) + "}%%", "gantt", + " dateFormat YYYY-MM-DD HH:mm:ss", " axisFormat " + axis, " todayMarker off"] + for n, (leg, a, b) in enumerate(rows): + out.append(" section %s" % gtext(leg)) + out.append(" ingest %d s :i%d, 2000-01-01 00:00:00, 2000-01-01 %s" % (round(a), n, hms(round(a)))) + if b and b > 0: + out.append(" rebuild %d s :done, x%d, after i%d, %ds" % (round(b), n, n, max(1, round(b)))) + out.append("```") + return out + + +def phase_gantt(ph): + out = ["```mermaid", "%%{init: " + json.dumps(gantt_init(60)) + "}%%", "gantt", + " dateFormat YYYY-MM-DD HH:mm:ss", " axisFormat %H:%M", " todayMarker off", + " section Suites"] + for i, (suite, a, b) in enumerate(ph): + da, db = "2000-01-%02d" % (1 + a // 86400), "2000-01-%02d" % (1 + b // 86400) + out.append(" %s :t%d, %s %s, %s %s" % (gtext(suite), i, da, hms(a), db, hms(b))) + out.append("```") + return out + + +def details(summary, body): + return ["", "
Chart: %s" % summary, ""] + body + ["", "
"] + + +def titled(title, how, chart): + return ["**%s**" % title, "", how, ""] + chart + + +def grid(blocks, layout): + out = [] + if layout == "sidebyside": + out.append("") + for i in range(0, len(blocks), 2): + out.append("") + for b in blocks[i:i + 2]: + out += ['"] + out.append("") + out.append("
', ""] + b + ["", "
") + else: + for i, b in enumerate(blocks): + out += ([""] if i else []) + b + return out + + +def spread(vals): + pos = [v for v in vals if v and v > 0] + return max(pos) / min(pos) if len(pos) > 1 else 1.0 + + +def section(blocks): + """The `### Charts` section from [(summary, body_lines, table_name)].""" + body = [] + for summary, lines, table in blocks: + lines = [l.replace("values in the table above", "values in the %s table above" % table) + for l in lines] + body += details(summary, lines) + return ["", "### Charts"] + body if body else [] + + +# ── bulk import rows ──────────────────────────────────────────────────────── +def _secs_in_parens(text): + m = re.search(r"\(\s*([\d,]+(?:\.\d+)?)\s*s\s*\)", text) + return float(m.group(1).replace(",", "")) if m else None + + +def _rebuild_from_text(text): + """Seconds of a REAL deferred rebuild in an indexing cell, else None. + `210 s (= ingest)` and `inline (during ingest)` mean: indexed during ingest, no rebuild.""" + t = text.replace("**", "").replace("`", "") + inline = re.match(r"^\s*[" + MARKERS + r"]*\s*inline\b", t, re.I) + if "= ingest" in t or (inline and "rebuild" not in t): + return None + m = re.search(r"\+\s*([\d,]+(?:\.\d+)?)\s*s\s+rebuild", t) + if m: + return float(m.group(1).replace(",", "")) + if re.match(r"^\s*[" + MARKERS + r"]*\s*\d", t): + v = num(t) + return v if v and v > 0 else None + return None + + +def bulk_phases_from_throughput(head, rows): + """[(leg, ingest_s, rebuild_s|None)] from the `↳ ingest` / `↳ search indexing` rows; None without an ingest row.""" + ing = idx = None + for row in rows: + lab = row[0].replace("**", "") + if not lab.startswith("↳"): + continue + low = lab.lower() + if "ingest" in low and "indexing" not in low: + ing = row + elif "index" in low: + idx = row + if not ing: + return None # no ingest row at all (old wording): the caller may try the Bulk import table + main_row = None + for row in rows: + lab = row[0].replace("**", "") + if lab.startswith("Bulk Import") and not lab.startswith("↳"): + main_row = row + break + out = [] + for i, leg in enumerate(head[1:], start=1): + if main_row and re.match(r"^\s*n/a\b", main_row[i].replace("**", ""), re.I): + continue # the leg's Bulk Import did not run or failed: no ingest bar + a = _secs_in_parens(ing[i]) + if a is None: + continue + b = _rebuild_from_text(idx[i]) if idx else None + out.append((plain(leg), a, b)) + return out + + +def bulk_phases_from_table(head, rows): + col = {h: i for i, h in enumerate(head)} + if "Ingest" not in col or "Index" not in col: + return [] + out = [] + for row in rows: + a = num(row[col["Ingest"]]) + if a is None: + continue + out.append((plain(row[0]), a, _rebuild_from_text(row[col["Index"]]))) + return out + + +def bulk_gantt_block(phases, source="the table above"): + any_rebuild = any(b for _, _, b in phases) + how = ("Per leg, ingest until Completed (dark)" + + (", then the deferred search-index rebuild (light) on the legs that run one; the others index during ingest" + if any_rebuild else "; indexing runs during ingest on these legs, so each bar is the ingest alone") + + ", on elapsed time since kick-off (axis: minutes and seconds, or hours and minutes from one hour); " + "shorter is better; values in %s." % source) + title = ("Bulk Import: ingest until Completed, then search-index rebuild" if any_rebuild + else "Bulk Import: ingest until Completed") + return titled(title, how, bulk_gantt(phases)) + + +# ── comparison ────────────────────────────────────────────────────────────── +def compare_section(lines, layout): + w = XY_W_CELL if layout == "sidebyside" else XY_W + blocks = [] + for heading, kind, tname in (("### Throughput", "thr", "Throughput"), + ("### p95 latency", "p95", "p95 latency")): + r = find_table(lines, heading) + if not r: + continue + head, rows, _ = r + legs = [plain(h) for h in head[1:]] + colours = leg_colours(legs) + charts = [] + for row in rows: + vals = [num(c) for c in row[1:]] + if not vals or all(v is None for v in vals): + continue # e.g. Bulk Import p95: n/a (one async job) + name, unit = short_name(row[0]) + if kind == "thr" and not unit: + unit = "(requests/s)" + inner = unit.strip("()") + seconds_only = "seconds" in inner and "/s" not in inner + lower = kind == "p95" or seconds_only + order = sorted(range(len(legs)), key=lambda i: -(vals[i] or 0)) + cats = ["%s · %s" % (legs[i], plain(row[1 + i])) for i in order] + ovals = [vals[i] for i in order] + series = [] + for pos, i in enumerate(order): + series.append(("bar", [(vals[i] or 0) if p == pos else 0 for p in range(len(order))])) + pal = [colours[legs[i]] for i in order] + how = ("One bar per leg, largest first, %s is better; values in the table above, repeated " + "in each label (with its † ‡ ⚠ markers)." % ("shorter" if lower else "longer")) + if spread(ovals) > SPREAD_NOTE: + how += (" Values span %dx (no log axis in Mermaid): short bars are read from their " + "label." % spread(ovals)) + title = "%s %s" % (name, "p95 (ms)" if kind == "p95" else unit) + ylab = "ms" if kind == "p95" else inner.split(",")[0] + charts.append(titled(title, how, xy(cats, series, pal, ylab, horizontal=True, width=w, + height=max(220, 100 + 20 * len(legs)), value_ticks=False))) + if charts: + what = ("throughput by leg, one chart per row" if kind == "thr" + else "p95 latency by leg, one chart per row") + blocks.append((what, grid(charts, layout), tname)) + phases, tname = [], "Throughput" + r = find_table(lines, "### Throughput") + if r: + phases = bulk_phases_from_throughput(r[0], r[1]) + if phases is None: + r = find_table(lines, "### Bulk import") + if r: + phases, tname = bulk_phases_from_table(r[0], r[1]), "Bulk import" + if phases: + blocks.append(("Bulk Import phases by leg", bulk_gantt_block(phases), tname)) + return section(blocks) + + +# ── one leg ───────────────────────────────────────────────────────────────── +def read_kv(path, sep="="): + kv = {} + try: + with open(path, encoding="utf-8", errors="replace") as fh: + for line in fh: + if sep in line: + k, v = line.rstrip("\n").split(sep, 1) + kv[k.strip()] = v.strip() + except OSError: + pass + return kv + + +def result_dir(run_dir, leg): + for d in (run_dir, os.path.join(run_dir, leg), os.path.join(run_dir, leg, leg)): + if d and os.path.isdir(d) and (os.path.exists(os.path.join(d, "host-contention.txt")) + or os.path.exists(os.path.join(d, "bulk-import.txt"))): + return d + return run_dir if run_dir and os.path.isdir(run_dir) else None + + +def phases(d): + if not d: + return [] + try: + with open(os.path.join(d, "host-contention.txt"), encoding="utf-8", errors="replace") as fh: + text = fh.read() + except OSError: + return [] + start, out, day, last = {}, [], 0, None + for m in re.finditer(r"^(\d\d):(\d\d):(\d\d)Z suite=(\S+) phase=(start|end)", text, re.M): + s = int(m.group(1)) * 3600 + int(m.group(2)) * 60 + int(m.group(3)) + if last is not None and s + day < last: + day += 86400 + s += day + last = s + if m.group(5) == "start": + start[m.group(4)] = s + elif m.group(4) in start: + out.append((m.group(4), start.pop(m.group(4)), s)) + return out + + +def leg_bulk_phase(d, leg): + kv = read_kv(os.path.join(d, "bulk-import.txt")) if d else {} + if kv.get("status", "complete") != "complete": + return [] # timeout / error / incomplete: no ingest time worth drawing + try: + a = float(kv["ingest_seconds"]) + except (KeyError, ValueError): + return [] + b = None + if kv.get("index_status") == "completed": + try: + b = float(kv.get("index_seconds", "")) + except ValueError: + b = None + return [(leg, a, b if b and b > 0 else None)] + + +def leg_section(lines, leg, run_dir, layout): + colour = leg_colours([leg])[leg] + d = result_dir(run_dir, leg) if run_dir else None + start = 0 + for i, l in enumerate(lines): + if l.startswith("## FHIR Benchmark") and "(%s)" % leg in l: + start = i + break + r = find_table(lines, "### Results", start) or find_table(lines, "### Results") + blocks = [] + ph = phases(d) + if ph: + how = ("Each bar is one suite of this leg, from its start to its end (UTC, from " + "host-contention.txt); gaps are setup between suites.") + blocks.append(("%s run phases (UTC)" % plain(leg), + titled("%s: run phases (UTC)" % title_safe(leg), how, phase_gantt(ph)), "Results")) + bp = leg_bulk_phase(d, leg) + if bp: + blocks.append(("%s Bulk Import phases" % plain(leg), bulk_gantt_block(bp, "bulk-import.txt (seconds), not the Results table"), "Results")) + if r: + head, rows, _ = r + col = {h: i for i, h in enumerate(head)} + if "Throughput" in col: + th, imp, lat = [], [], [] + for row in rows: + suite = row[0].replace("**", "") + if suite.startswith("↳"): + continue + v = num(row[col["Throughput"]]) + name, _u = short_name(suite) + if suite.startswith("Batch/Transaction Import") or suite.startswith("Bulk Import"): + if v is not None: + imp.append(("batch import" if suite.startswith("Batch") else "bulk import", v)) + continue + if v is not None: + th.append((title_safe(plain(suite)) if "(" not in suite else name, v)) + p = [num(row[col[k]]) if k in col else None for k in ("p50 ms", "p95 ms", "p99 ms")] + if None not in p: + lat.append((plain(suite), p)) + wl = XY_W_CELL if layout == "sidebyside" else XY_W + pair = [] + if th: + how = "One bar per k6 suite, higher is better; values in the Results table above." + if spread([v for _, v in th]) > SPREAD_NOTE: + how = how[:-1] + "; values span more than %dx, so read short bars in the table." % SPREAD_NOTE + pair.append(titled("%s: k6 suites throughput (requests/s)" % title_safe(leg), how, + xy([n for n, _ in th], [("bar", [v for _, v in th])], [colour], + "requests per second", width=wl))) + if imp: + how = ("One bar per way of loading the corpus, higher is better; values in the Results " + "table above (batch: committed Bundle entries per second of the k6 scenario; " + "bulk: resources until the search index covers them).") + pair.append(titled("%s: Import throughput (resources/s)" % title_safe(leg), how, + xy([n for n, _ in imp], [("bar", [v for _, v in imp])], [colour], + "resources per second", width=wl))) + body = grid(pair, layout) if pair else [] + if lat: + how = ("Overlaid bars per suite, light to dark blue: p99 (back), p95, p50 (front); lower " + "is better; values in the Results table above (import, per Bundle, is left out).") + if spread([x for _, p in lat for x in p]) > SPREAD_NOTE: + how += " Values span more than %dx; read small ones in the table." % SPREAD_NOTE + cats = [n for n, _ in lat] + series = [("bar", [p[2] for _, p in lat]), ("bar", [p[1] for _, p in lat]), + ("bar", [p[0] for _, p in lat])] + body += ([""] if body else []) + titled( + "%s: latency per suite (ms)" % title_safe(leg), how, + xy(cats, series, [RAMP_P99, RAMP_P95, RAMP_P50], "ms")) + if body: + blocks.append(("%s throughput and latency" % plain(leg), body, "Results")) + return section(blocks) + + +# ── CLI ───────────────────────────────────────────────────────────────────── +def read_lines(path): + with open(path, encoding="utf-8", errors="replace") as fh: + t = fh.read() + return t[:-1].split("\n") if t.endswith("\n") else t.split("\n") + + +def render(lines): + out = "\n".join(lines) + "\n" if lines else "" + return out if len(out.encode("utf-8")) <= MAX_OUT_BYTES else "" + + +def main(argv=None): + try: + ap = argparse.ArgumentParser(description=__doc__.split("\n")[0]) + sub = ap.add_subparsers(dest="cmd") + c = sub.add_parser("compare") + c.add_argument("--in", dest="inp", required=True) + c.add_argument("--layout", choices=("stacked", "sidebyside"), default="sidebyside") + g = sub.add_parser("leg") + g.add_argument("--box", required=True) + g.add_argument("--leg", required=True) + g.add_argument("--run-dir") + g.add_argument("--layout", choices=("stacked", "sidebyside"), default="sidebyside") + a = ap.parse_args(argv) + if a.cmd == "compare": + res = compare_section(read_lines(a.inp), a.layout) + elif a.cmd == "leg": + res = leg_section(read_lines(a.box), a.leg, a.run_dir, a.layout) + else: + return 0 + text = render(res) + if text: + sys.stdout.write(text) + except SystemExit: + pass + except BaseException as e: # never fail the job over charts + try: + print("" % type(e).__name__) + except Exception: + pass + return 0 + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/.github/scripts/fhir-bench/report_html.py b/.github/scripts/fhir-bench/report_html.py new file mode 100644 index 0000000000..e2c9df2a24 --- /dev/null +++ b/.github/scripts/fhir-bench/report_html.py @@ -0,0 +1,874 @@ +#!/usr/bin/env python3 +"""Standalone dark HTML report of one FHIR Server Benchmark run (single self-contained file). + + python3 report_html.py --run-dir DIR --run-id ID --repo OWNER/REPO --branch BRANCH --sha SHA \ + --out fhir-bench-report-ID.html --dump-json report-data.json \ + [--trend-dir DIR] [--no-shapes] [--headline-leg LEG] + +DIR holds the results of every leg, either as `fhir-benchmark--//` (what +`actions/download-artifact` with a pattern leaves) or as `/` (already extracted); legs are +discovered from the folder names. A `comparison.md` in DIR (or in a `fhir-bench-comparison-*` +folder of DIR, or next to it) feeds the summary tables at the top. + +--trend-dir holds `/report-data.json` of EARLIER runs (the --dump-json output of this +script); the Trend section charts what is there. --no-shapes skips the heavy search-points.json +(search-by-shape.md is used when present). + +Standard library only. Every number and every validity flag comes from the artifacts, with the +thresholds of compare_legs.py. A missing file or leg is shown as "no data". The exit code is +always 0: on any failure a minimal valid HTML page is still written. +""" +import argparse +import html +import json +import math +import os +import re +import sys +from array import array +from concurrent.futures import ProcessPoolExecutor + +# Same thresholds as compare_legs.py +IMPORT_TARGET = 1000 +ERR_PCT_HIGH = 1.0 +PG_CONTENDED_MS = 3.0 +TREND_MAX = 8 + +K6_SUITES = ["prewarm", "import", "crud", "search", "sql-run", "insert"] +LEG_LABEL_ES = " + ES" +ISO_RE = re.compile(r"(20\d\d-\d\d-\d\d)T(\d\d:\d\d:\d\d)") +HERE = os.path.dirname(os.path.abspath(__file__)) +LEG_FILES = ("runner-info.txt", "import.json", "crud.json", "search.json", "sql-run.json", "insert.json", + "prewarm.json", "host-contention.txt", "bulk-import.txt") + +# v8 colours of the six known legs (validated with the dataviz palette validator). +PAL_KNOWN = { + "dark": {"postgres": "#236bcf", "sqlite": "#008622", "mongodb": "#9348b1", + "postgres-elasticsearch": "#4a91f8", "sqlite-elasticsearch": "#3fac4a", + "mongodb-elasticsearch": "#b96dd8"}, + "light": {"postgres": "#1a52a1", "sqlite": "#036819", "mongodb": "#723789", + "postgres-elasticsearch": "#4780d2", "sqlite-elasticsearch": "#419547", + "mongodb-elasticsearch": "#9f63b9"}} +# Hues for any other backend, cycled in the order of the sorted backend names. +PAL_EXTRA = {"dark": ["#c9a227", "#d1568f", "#2fb5bd", "#d9783c", "#8f9bb3", "#7cb342"], + "light": ["#8a6d00", "#a63a6e", "#16757c", "#a8501a", "#5b6785", "#4a7a1c"]} +KNOWN_BASES = ("postgres", "sqlite", "mongodb") + + +def label(leg): + if leg.endswith("-elasticsearch"): + return leg[:-len("-elasticsearch")] + LEG_LABEL_ES + return leg + + +# ── tolerant reading ──────────────────────────────────────────────── + +def read_text(path): + try: + with open(path, encoding="utf-8", errors="replace") as fh: + return fh.read() + except OSError: + return None + + +def kv(path, sep): + out = {} + for line in (read_text(path) or "").splitlines(): + if sep in line: + k, v = line.strip().split(sep, 1) + out[k.strip()] = v.strip() + return out + + +def fnum(v): + try: + x = float(str(v).replace(",", "")) + return x if math.isfinite(x) else None + except (TypeError, ValueError): + return None + + +def inum(v): + x = fnum(v) + return None if x is None else int(x) + + +def rnd(v, n=2): + return None if v is None else round(v, n) + + +def _is_leg_dir(d): + return os.path.isdir(d) and any(os.path.exists(os.path.join(d, f)) for f in LEG_FILES) + + +def _find_leg_dir(p, name): + """The folder with the files of a leg inside p: p/, p itself, or any single sub-folder.""" + for c in (os.path.join(p, name), p): + if _is_leg_dir(c): + return c + try: + for sub in sorted(os.listdir(p)): + c = os.path.join(p, sub) + if _is_leg_dir(c): + return c + except OSError: + pass + return None + + +def leg_dirs(run_dir): + """{leg: path}. Layouts: fhir-benchmark--//, / or //.""" + out = {} + if not run_dir or not os.path.isdir(run_dir): + return out + try: + names = sorted(os.listdir(run_dir)) + except OSError: + return out + for name in names: + p = os.path.join(run_dir, name) + if not os.path.isdir(p) or name.startswith("fhir-bench-comparison"): + continue + m = re.match(r"^fhir-benchmark-(.+?)(?:-(\d+))?$", name) + guess = m.group(1) if m else name + d = _find_leg_dir(p, guess) + if not d: + continue + leg = guess if m else name + out[leg] = d + if not out and _is_leg_dir(run_dir): # DIR is itself one leg + out[os.path.basename(os.path.normpath(run_dir))] = run_dir + return out + + +def order_legs(legs): + """Stable order: known backends first (plain before +ES), then the rest alphabetically.""" + known = ["postgres", "postgres-elasticsearch", "sqlite", "sqlite-elasticsearch", "mongodb", + "mongodb-elasticsearch"] + return [l for l in known if l in legs] + sorted(l for l in legs if l not in known) + + +# ── per-leg extraction ─────────────────────────────────────────────── + +def load_suite(d, suite, ic): + t = read_text(os.path.join(d, suite + ".json")) + if t is None: + return None + try: + m = json.loads(t)["metrics"] + except (ValueError, KeyError, TypeError): + return None + if not isinstance(m, dict): + return None + hr, hf = m.get("http_reqs"), m.get("http_req_failed") + if not isinstance(hr, dict) or fnum(hr.get("count")) is None or not isinstance(hf, dict) \ + or fnum(hf.get("value")) is None: + return None # incomplete summary: missing data, not zeros + + def g(name, key): + x = m.get(name) + return x.get(key) if isinstance(x, dict) else None + + s = {"rps": rnd(fnum(g("http_reqs", "rate"))), "reqs": inum(g("http_reqs", "count")), + "p50": rnd(fnum(g("http_req_duration", "med"))), "p95": rnd(fnum(g("http_req_duration", "p(95)"))), + "p99": rnd(fnum(g("http_req_duration", "p(99)"))), "max": rnd(fnum(g("http_req_duration", "max"))), + "err": rnd((fnum(g("http_req_failed", "value")) or 0) * 100, 3), + "ok": inum(g("checks", "passes")), "fail": inum(g("checks", "fails")), + "vus": inum(g("vus_max", "max")), "unit": "req/s"} + if suite == "import": + # resources/s = entries / scenario_seconds; latency per Bundle (iteration_duration) + ent, sc = fnum(ic.get("entries")), fnum(ic.get("scenario_seconds")) + s["rps"] = rnd(ent / sc) if ent is not None and sc else None + s["p50"], s["p95"] = rnd(fnum(g("iteration_duration", "med"))), rnd(fnum(g("iteration_duration", "p(95)"))) + s["p99"], s["max"] = rnd(fnum(g("iteration_duration", "p(99)"))), rnd(fnum(g("iteration_duration", "max"))) + s["unit"] = "resources/s" + if suite == "sql-run": + s["rows_rps"] = rnd(fnum(g("sql_run_rows", "rate")), 1) + s["rows"] = inum(g("sql_run_rows", "count")) + views = [] + for k, v in m.items(): + vm = re.match(r"^http_req_duration\{view:([^}]+)\}$", k) + if vm and isinstance(v, dict): + views.append({"name": vm.group(1), "p50": rnd(fnum(v.get("med"))), "p95": rnd(fnum(v.get("p(95)"))), + "p99": rnd(fnum(v.get("p(99)"))), "max": rnd(fnum(v.get("max"))), + "n": inum(v.get("count"))}) + views.sort(key=lambda r: r["name"]) + s["views"] = views + return s + + +def host_points(d): + pts = [] + for line in (read_text(os.path.join(d, "host-contention.txt")) or "").splitlines(): + m = re.match(r"(\d\d:\d\d:\d\d)Z suite=(\S+) phase=(\S+) host_loadavg=(\S+) (\S+) (\S+)" + r"(?: host_containers=(\S+))?(?: host_mem_avail_mb=(\S+))?", line) + if m and fnum(m.group(4)) is not None: + pts.append({"t": m.group(1), "suite": m.group(2), "phase": m.group(3), + "la1": fnum(m.group(4)), "la5": fnum(m.group(5)), + "containers": inum(m.group(7)), "mem_mb": fnum(m.group(8))}) + return pts + + +def pg_ms(d): + """Mean ms per Postgres call in crud; None when the leg has no Postgres statistics.""" + t = read_text(os.path.join(d, "crud-pgstat.txt")) + m = re.search(r"^\s*([\d.]+)\s*\|\s*[\d.]+\s*\|\s*(\d+)\s*$", t or "", re.M) + if not m or not int(m.group(2)): + return None + return round(float(m.group(1)) * 1000 / int(m.group(2)), 3) + + +def leg_start(d, pts): + """Approximate ISO start of the leg: first ISO date in its files + first host reading time.""" + day = None + for f in ("containers-state.txt", "bulk-import-hfs.log", "bulk-import.log"): + m = ISO_RE.search(read_text(os.path.join(d, f)) or "") + if m: + day = m.group(1) + break + if day is None: + try: + with open(os.path.join(d, "search-points.json"), encoding="utf-8", errors="replace") as fh: + for _ in range(50): + m = ISO_RE.search(fh.readline()) + if m: + day = m.group(1) + break + except OSError: + pass + if day is None or not pts: + return None # no host reading: the start is unknown, never T00:00:00Z + return "%sT%sZ" % (day, pts[0]["t"]) + + +def shape_stats(points_path): + """Port of search_by_shape.py: http_req_duration per shape (med = s[n//2], p95 = s[floor(n*.95)]).""" + by = {} + try: + with open(points_path, "r", encoding="utf-8", errors="replace") as fh: + for line in fh: + if '"Point"' not in line or '"http_req_duration"' not in line: + continue + try: + o = json.loads(line) + except ValueError: + continue + if not isinstance(o, dict) or o.get("type") != "Point" or o.get("metric") != "http_req_duration": + continue + data = o.get("data") or {} + v = data.get("value") + if not isinstance(v, (int, float)) or isinstance(v, bool): + continue + tags = data.get("tags") or {} + st = tags.get("searchType") + if st in (None, False): + continue + key = (str(st), "%s?%s" % (tags.get("resourceType") or "?", tags.get("name") or "?")) + by.setdefault(key, array("d")).append(float(v)) + except OSError: + return None + rows = [] + for (typ, q), vals in by.items(): + s = sorted(vals) + n = len(s) + rows.append({"type": typ, "q": q, "n": n, "p50": round(s[n // 2], 2), + "p95": round(s[min(math.floor(n * 0.95), n - 1)], 2), "max": round(s[-1], 2)}) + rows.sort(key=lambda r: (-r["p95"], r["type"] + r["q"])) + return rows + + +def shapes_from_md(path): + rows = [] + for line in (read_text(path) or "").splitlines(): + m = re.match(r"\| `(\S+) (.+?)` \| (\d+) \| (\d+) \| (\d+) \| (\d+) \|", line) + if m and m.group(1) != "?": + rows.append({"type": m.group(1), "q": m.group(2), "n": int(m.group(3)), "p50": int(m.group(4)), + "p95": int(m.group(5)), "max": int(m.group(6))}) + return rows or None + + +def docker_host_from(ri): + """(cpus, ram_gb) of the Docker host when a runner-info key states them; else (None, None).""" + cpus = ram = None + for k, v in ri.items(): + kl = k.lower() + if "docker" not in kl: + continue + x = fnum(v) + if x is None or x <= 0: + continue + if "cpu" in kl: + cpus = int(x) + elif "gb" in kl: + ram = x + elif "mb" in kl: + ram = x / 1024.0 + elif "byte" in kl or "mem" in kl or "ram" in kl: + ram = x / 1e9 if x > 1e6 else x + return cpus, (round(ram) if ram else None) + + +def load_leg(leg, d): + ic_raw = kv(os.path.join(d, "import-completeness.txt"), "=") + ri = kv(os.path.join(d, "runner-info.txt"), ":") + out = {"leg": leg, "label": label(leg), "runner": ri.get("runner_name"), "cpus": ri.get("runner_cpus"), + "ram": ri.get("runner_ram"), "sha": (ri.get("git_sha") or "")[:9] or None, + "ref": ri.get("git_ref"), "run": ri.get("github_run"), "suites": {}} + out["docker_cpus"], out["docker_ram_gb"] = docker_host_from(ri) + for s in K6_SUITES: + v = load_suite(d, s, ic_raw) + if v: + out["suites"][s] = v + elif os.path.exists(os.path.join(d, s + ".json")): + out["suites"][s] = None # file present but unreadable/incomplete: no data + out["ic"] = None + if ic_raw: + out["ic"] = {"bundles_ok": inum(ic_raw.get("bundles_ok")), "entries": inum(ic_raw.get("entries")), + "scenario": fnum(ic_raw.get("scenario_seconds")), "setup": fnum(ic_raw.get("setup_seconds")), + "wall": fnum(ic_raw.get("wall_seconds"))} + bi = kv(os.path.join(d, "bulk-import.txt"), "=") + out["bulk"] = None + if bi: + ingest, index = fnum(bi.get("ingest_seconds")), fnum(bi.get("index_seconds")) + status = bi.get("index_status") + inline = status == "inline" + out["bulk"] = {"status": bi.get("status"), "reason": bi.get("reason") or "", "phase": bi.get("phase"), + "convert": fnum(bi.get("convert_seconds")), "ingest": ingest, + "index": None if inline else index, "index_inline": inline, + # seconds shown on the "search indexing" row: inline indexing happens during ingest + "index_eff": ingest if inline else index, + "total": fnum(bi.get("total_seconds")), + "rps": fnum(bi.get("resources_per_s")), "ingest_rps": fnum(bi.get("ingest_resources_per_s")), + "ok": inum(bi.get("resources_ok")), "submitted": inum(bi.get("resources_submitted")), + "failed": inum(bi.get("resources_failed")), "index_status": status, + "searchable": bi.get("searchable") == "yes", + "searchable_s": fnum(bi.get("searchable_seconds"))} + dr = kv(os.path.join(d, "es-drain.txt"), "=") if leg.endswith("-elasticsearch") else {} + out["drain"] = ({"status": dr.get("status"), "missing": dr.get("missing"), "sync": dr.get("sync_mode")} + if dr else None) + cs_t = read_text(os.path.join(d, "containers-state.txt")) + lines = [l.strip() for l in (cs_t or "").splitlines() if l.strip() and not l.startswith("hfs-bench-tgz-")] + out["containers_known"] = cs_t is not None + out["containers"] = [" ".join(l.split()[:3]) for l in lines if "Status=" in l or "inspect-failed" in l] + out["died"] = any(re.search(r"OOMKilled=true|Status=(exited|dead)|inspect-failed gone", l) for l in lines) + out["host"] = host_points(d) + out["pg_ms"] = pg_ms(d) + out["counts"] = [] + for l in (read_text(os.path.join(d, "search-counts.txt")) or "").splitlines()[1:]: + p = l.strip().split("|") + if len(p) == 4: + out["counts"].append({"q": p[0], "total": p[1], "http": p[2]}) + res = kv(os.path.join(d, "crud-residue.txt"), "=") + out["residue"] = sum(int(v) for v in res.values() if v.isdigit()) if res else None + out["start"] = leg_start(d, out["host"]) + out["markers"] = markers(out) + return out + + +def markers(d): + """Rules of compare_legs.py _markers().""" + mk = {} + ok = d["ic"]["bundles_ok"] if d["ic"] else None + for s, v in d["suites"].items(): + if not v: + continue + m = "" + if s in ("crud", "search"): + inc = not d["suites"].get("import") or ok is None or ok < IMPORT_TARGET + if not inc and s == "search" and d["leg"].endswith("-elasticsearch"): + inc = not d["drain"] or d["drain"]["status"] != "drained" + if inc: + m += "†" + if v["err"] > ERR_PCT_HIGH or (v["fail"] or 0) > 0: + m += "‡" + if d["died"] or (s == "crud" and d["leg"] == "postgres" and d["pg_ms"] is not None and d["pg_ms"] > PG_CONTENDED_MS): + m += "⚠" + mk[s] = m + b = d["bulk"] + if b and b["status"] == "complete": + m = "" if b["searchable"] else "†" + if b["failed"] is not None and b["submitted"] and (100.0 * b["failed"] / b["submitted"] > ERR_PCT_HIGH or b["failed"] > 0): + m += "‡" + if d["died"]: + m += "⚠" + mk["bulk"] = m + return mk + + +# ── validity ───────────────────────────────────────────────────────── + +def r0(v): + return int(math.floor(v + 0.5)) + + +def fmt_int(v): + return "n/a" if v is None else "{:,}".format(r0(v)) + + +def fmt1(v): + return "n/a" if v is None else "{:,.1f}".format(v) + + +def leg_checks(d, cpus): + c = {} + ok = d["ic"]["bundles_ok"] if d["ic"] else None + if ok is None: + c["corpus"] = ["bad" if d["suites"].get("import") else "na", "no data"] + else: + c["corpus"] = ["ok" if ok >= IMPORT_TARGET else "bad", "%s/%s" % (fmt_int(ok), fmt_int(IMPORT_TARGET))] + hard, soft = [], [] + nodata = [s for s in K6_SUITES if s in d["suites"] and not d["suites"][s]] + for s in K6_SUITES: + v = d["suites"].get(s) + if not v: + continue + if v["err"] > ERR_PCT_HIGH: + hard.append("%s %s %%" % (s, fmt1(v["err"]))) + elif v["fail"] is None: + nodata.append("%s checks n/a" % s) + elif v["fail"] > 0: + soft.append("%s %s ✗" % (s, fmt_int(v["fail"]))) + b = d["bulk"] + if b and b["failed"] is None: + nodata.append("bulk failures n/a") + elif b and b["failed"]: + hard.append("bulk %s failed" % fmt_int(b["failed"])) + if not any(d["suites"].values()) and not b: + c["err"] = ["na", "no data"] + elif hard: + c["err"] = ["bad", ", ".join(hard + soft + [x if x.endswith("n/a") else "%s no data" % x for x in nodata])] + elif nodata: + c["err"] = ["na", ", ".join(soft + [x if x.endswith("n/a") else "%s no data" % x for x in nodata])] + elif soft: + c["err"] = ["warn", ", ".join(soft) + " (<1 %)"] + else: + c["err"] = ["ok", "0 %"] + if d["died"]: + c["cont"] = ["bad", "down"] + elif d["containers"]: + c["cont"] = ["ok", "alive"] + else: + c["cont"] = ["na", "no container" if d["containers_known"] else "no data"] + if d["leg"].endswith("-elasticsearch"): + st = d["drain"]["status"] if d["drain"] else None + c["es"] = ["ok", "drained"] if st == "drained" else ["bad", st or "no data"] + else: + c["es"] = ["na", "—"] + pk = max((p["la1"] for p in d["host"]), default=None) + if pk is None: + c["load"] = ["na", "no data"] + else: + c["load"] = ["warn" if cpus and pk > cpus else ("ok" if cpus else "na"), "peak %s" % fmt1(pk)] + if d["pg_ms"] is not None: + c["load"][1] += " · pg %.2f ms/call" % d["pg_ms"] + # compare_legs.py applies the contention rule to the leg named `postgres` only + if d["leg"] == "postgres" and d["pg_ms"] > PG_CONTENDED_MS: + c["load"][0] = "bad" + d["peak"] = pk + return c + + +def hum(s): + """Humanised duration in English: 11 s, 53 min 15 s, 1 h 05 min.""" + s = int(max(0, s)) + if s < 60: + return "%d s" % s + if s < 3600: + m, r = divmod(s, 60) + return "%d min" % m + (" %02d s" % r if r else "") + h, r = divmod(s, 3600) + return "%d h %02d min" % (h, r // 60) + + +WAIT_WARN_FRACTION = 0.10 +_TIMING_INTS = ("total_s", "waiting_s", "working_s") +_JOB_INTS = ("queued_s", "behind_legs_s", "capacity_wait_s", "host_wait_s", "waiting_s", "working_s") +_JOB_KINDS = ("setup", "build", "leg", "compare", "other") + + +def _is_int(v): + return isinstance(v, int) and not isinstance(v, bool) and v >= 0 + + +def load_timing(path): + """Validated run_timing.py JSON, or None (absent or invalid: the report is then as without it).""" + if not path: + return None + try: + with open(path, encoding="utf-8") as fh: + t = json.load(fh) + ok_ = (isinstance(t, dict) and isinstance(t.get("run_id"), str) + and all(_is_int(t.get(k)) for k in _TIMING_INTS) and isinstance(t.get("jobs"), list)) + if ok_: + for j in t["jobs"]: + if not (isinstance(j, dict) and isinstance(j.get("name"), str) and j.get("kind") in _JOB_KINDS + and (j.get("leg") is None or isinstance(j.get("leg"), str)) + and all(_is_int(j.get(k)) for k in _JOB_INTS)): + ok_ = False + break + if not ok_: + print("report_html: --timing-json %s is not a valid timing file; ignored" % path, file=sys.stderr) + return None + return t + except Exception as e: # noqa: BLE001 + print("report_html: --timing-json unreadable (%s); ignored" % e, file=sys.stderr) + return None + + +def timing_view(t): + """Texts for the tile, derived from the data only.""" + if not t: + return None + warn = t["total_s"] > 0 and t["waiting_s"] >= WAIT_WARN_FRACTION * t["total_s"] + return {"label": "Waiting vs working", + "value": "Waiting %s \u00b7 Working %s" % (hum(t["waiting_s"]), hum(t["working_s"])), + "sub": "of %s total" % hum(t["total_s"]), "warn": warn, + "sentence": ("This run waited %s for resources: it is slower to finish, not slower to run." + % hum(t["waiting_s"])) if warn else None} + + +def verdict_all(legs, order, cpus, missing, timing=None): + """Verdict for the HTML: every leg is judged alike.""" + items = [] + four = ("corpus", "err", "cont", "es") + valid = [l for l in order if all(legs[l]["checks"][k][0] != "bad" for k in four) + and legs[l]["checks"]["corpus"][0] == "ok" and legs[l]["checks"]["err"][0] != "na"] + if valid: + items.append(["ok", "Valid (corpus, errors, containers, ES all fine): %s." % ", ".join(label(l) for l in valid)]) + for key, what, why in ( + ("corpus", "incomplete corpus", "its crud and search ran over less data and are not compared"), + ("err", "errors or failed checks", "see the full table"), + ("cont", "container down", "do not use its numbers"), + ("es", "Elasticsearch not drained", "its search did not see all the data")): + hit = [l for l in order if legs[l]["checks"][key][0] in ("bad", "warn")] + if hit: + sev = "bad" if any(legs[l]["checks"][key][0] == "bad" for l in hit) else "warn" + items.append([sev, "%s: %s (%s); %s." % (", ".join(label(l) for l in hit), what, + ", ".join(legs[l]["checks"][key][1] for l in hit), why)]) + peaks = [legs[l]["peak"] for l in order if legs[l].get("peak") is not None] + if peaks and cpus: + over = sum(1 for p in peaks if p > cpus) + if over: + items.append(["warn", "Docker host above its %d CPUs in %d of %d legs (peak load %s to %s)." % ( + cpus, over, len(peaks), fmt1(min(peaks)), fmt1(max(peaks))), "load"]) + elif peaks: + items.append(["na", "Host peak load %s to %s (host CPU count unknown)." % ( + fmt1(min(peaks)), fmt1(max(peaks))), "load"]) + if missing: + items.append(["bad", "Legs without artifacts: %s." % ", ".join(label(l) for l in missing)]) + tv = timing_view(timing) + if tv and tv["warn"]: + items.append(["warn", tv["sentence"]]) + runners = sorted({legs[l]["runner"] for l in order if legs[l]["runner"]}) + items.append(["na", "This is a single run on a shared host%s: it is a sample, not proof." % ( + " and the legs used %d different runners" % len(runners) if len(runners) > 1 else "")]) + total = len(order) + len(missing) + title = "%d of %d legs valid" % (len(valid), total) + if not order and not missing: + title = "no leg artifacts in this directory" + sev = "bad" if not valid else ("ok" if len(valid) == total and not any(i[0] in ("bad", "warn") for i in items) + else "warn") + return {"title": title, "items": items, "sev": sev} + + +# ── comparison.md (summary tables at the top) ────────────────────────── + +def _cell(c): + return re.sub(r"\s+", " ", c.replace("**", "").replace("`", "")).strip() + + +def find_comparison(run_dir): + cands = [] + for base in (run_dir, os.path.dirname(os.path.normpath(run_dir)) if run_dir else None): + if not base or not os.path.isdir(base): + continue + cands.append(os.path.join(base, "comparison.md")) + try: + for n in sorted(os.listdir(base)): + if n.startswith("fhir-bench-comparison"): + cands.append(os.path.join(base, n, "comparison.md")) + except OSError: + pass + return next((c for c in cands if os.path.isfile(c)), None) + + +def parse_comparison(path): + """{"head": str, "tables": [{"title", "header", "rows"}]} of the `### ...` tables of comparison.md.""" + t = read_text(path) if path else None + if not t: + return None + out = {"head": "", "tables": []} + title = "" + cur = None + for line in t.splitlines(): + if line.startswith("Commit ") and "legs" in line and not out["head"]: + out["head"] = _cell(line) + if line.startswith("#"): + title = line.lstrip("#").strip() + cur = None + continue + if line.strip().startswith("|"): + cells = [_cell(c) for c in line.strip().strip("|").split("|")] + if cur is None: + if cells and cells[0] == "Suite": + cur = {"title": title, "header": cells, "rows": []} + out["tables"].append(cur) + continue + if set("".join(cells)) <= set("-: "): + continue + cur["rows"].append(cells) + else: + cur = None + return out if out["tables"] else None + + +# ── trend ──────────────────────────────────────────────────────────── + +def trend_point(leg, x): + """The slim record of one leg that later runs chart in their Trend section.""" + if not any(x["suites"].values()) and not x["bulk"]: + return None + cs = next((p for p in x["host"] if p["suite"] == "crud" and p["phase"] == "start"), None) + suites = {s: {"rps": v["rps"], "p95": v["p95"]} for s, v in x["suites"].items() if v and s != "prewarm"} + sq = x["suites"].get("sql-run") + if sq: + suites["sql_rows"] = {"rps": sq.get("rows_rps"), "p95": sq["p95"]} + b = x["bulk"] + return {"run": x["run"], "date": x["start"], "sha": x["sha"], "branch": x["ref"], "runner": x["runner"], + "suites": suites, + "bulk": b and {"rps": b["rps"], "total": b["total"], "ingest_rps": b["ingest_rps"], + "ingest": b["ingest"], "index_eff": b["index_eff"]}, + "bundles_ok": x["ic"]["bundles_ok"] if x["ic"] else None, "pg_ms": x["pg_ms"], + "crud_load": cs["la1"] if cs else None, "markers": x["markers"]} + + +def run_key(t): + r = str(t.get("run") or "") + return (int(r) if r.isdigit() else 0, t.get("date") or "") + + +def load_history(trend_dir): + """[(run id, dump)] of the earlier runs found as //report-data.json.""" + out = [] + if not trend_dir or not os.path.isdir(trend_dir): + return out + for name in sorted(os.listdir(trend_dir)): + p = os.path.join(trend_dir, name, "report-data.json") + try: + with open(p, encoding="utf-8") as fh: + doc = json.load(fh) + if isinstance(doc, dict) and isinstance(doc.get("legs"), dict): + out.append((name, doc)) + except (OSError, ValueError): + continue + return out + + +def leg_trend(leg, cur_point, history, run): + """(previous point or None, trend list including the current run). Nothing assumes earlier runs exist.""" + pts = [] + for name, doc in history: + lg = doc["legs"].get(leg) + pt = lg.get("point") if isinstance(lg, dict) else None + if isinstance(pt, dict) and isinstance(pt.get("suites"), dict): + pt = dict(pt) + pt["run"] = pt.get("run") or doc.get("run") or name + if str(pt["run"]) != str(run): + pts.append(pt) + seen, trend = set(), [] + for t in sorted(pts, key=run_key)[-(TREND_MAX - 1):] + ([cur_point] if cur_point else []): + if str(t["run"]) not in seen: + seen.add(str(t["run"])) + trend.append(t) + trend.sort(key=run_key) + prev = None + if cur_point: + older = [t for t in trend if run_key(t) < run_key(cur_point) + and any(s in t["suites"] for s in ("search", "crud", "import"))] + same = [t for t in older if t.get("branch") == cur_point.get("branch")] + prev = (same or older or [None])[-1] + return prev, trend + + +# ── palette ──────────────────────────────────────────────────────────── + +def _hex_mix(a, b, t): + A, B = [int(a[i:i + 2], 16) for i in (1, 3, 5)], [int(b[i:i + 2], 16) for i in (1, 3, 5)] + return "#" + "".join("%02x" % round(x + (y - x) * t) for x, y in zip(A, B)) + + +def palette(order): + """{theme: {leg: hex}}: v8 colours for the six known legs, a stable cycle for any other backend; + the +Elasticsearch variant of an unknown backend is a lighter tint of its base colour.""" + bases = sorted({l[:-len("-elasticsearch")] if l.endswith("-elasticsearch") else l for l in order} + - set(KNOWN_BASES)) + out = {} + for theme in ("dark", "light"): + pal, extra = dict(PAL_KNOWN[theme]), PAL_EXTRA[theme] + for l in order: + if l in pal: + continue + es = l.endswith("-elasticsearch") + base = l[:-len("-elasticsearch")] if es else l + col = extra[bases.index(base) % len(extra)] + pal[l] = _hex_mix(col, "#ffffff", 0.3) if es else col + out[theme] = {l: pal[l] for l in order} + return out + + +# ── assembly ─────────────────────────────────────────────────────────── + +def _shapes_job(args): + leg, d, allow_points = args + md = shapes_from_md(os.path.join(d, "search-by-shape.md")) + if md is not None: + return leg, md, "search-by-shape.md" + p = os.path.join(d, "search-points.json") + if allow_points and os.path.exists(p): + return leg, shape_stats(p), "search-points.json" + return leg, None, None + + +def load_shapes(dirs, order, no_shapes): + jobs = [(l, dirs[l], not no_shapes) for l in order] + heavy = (not no_shapes) and len(jobs) > 1 + if heavy: + try: + with ProcessPoolExecutor(max_workers=min(6, len(jobs))) as ex: + return list(ex.map(_shapes_job, jobs)) + except Exception: # noqa: BLE001 - sandboxes without multiprocessing: go serial + pass + return [_shapes_job(j) for j in jobs] + + +def build_data(a): + dirs = leg_dirs(a.run_dir) + order = order_legs(dirs) + legs = {l: load_leg(l, dirs[l]) for l in order} + expected = [x.strip() for x in (a.expect_legs or "").split(",") if x.strip()] + missing = [l for l in expected if l not in legs] + for leg, rows, src in load_shapes(dirs, order, a.no_shapes): + legs[leg]["shapes"], legs[leg]["shapes_src"] = rows, src + first = legs[order[0]] if order else {} + docker_cpus = a.docker_cpus or next((legs[l]["docker_cpus"] for l in order if legs[l]["docker_cpus"]), None) + docker_ram = a.docker_ram_gb or next((legs[l]["docker_ram_gb"] for l in order if legs[l]["docker_ram_gb"]), None) + run = str(a.run_id or first.get("run") or os.path.basename(os.path.normpath(a.run_dir or "")) or "n/a") + for l in order: + if not legs[l].get("run"): + legs[l]["run"] = run + legs[l]["checks"] = leg_checks(legs[l], docker_cpus) + history = load_history(a.trend_dir) + for l in order: + pt = trend_point(l, dict(legs[l], run=run, ref=a.branch or legs[l]["ref"])) + legs[l]["point"] = pt + legs[l]["prev"], legs[l]["trend"] = leg_trend(l, pt, history, run) + head = a.headline_leg if a.headline_leg in legs else (next((l for l in order if any(legs[l]["suites"].values()) + or legs[l]["bulk"]), order[0] if order else None)) + starts = sorted(legs[l]["start"] for l in order if legs[l]["start"]) + timing = load_timing(getattr(a, "timing_json", None)) + sha = (a.sha or first.get("sha") or "")[:9] or None + extra = {"timing": timing, "timing_view": timing_view(timing)} if timing else {} + return {**extra, "run": run, "date": starts[0] if starts else None, "sha": sha, "sha_full": a.sha or None, + "ref": a.branch or first.get("ref"), "repo": a.repo, "docker_cpus": docker_cpus, + "docker_ram_gb": docker_ram, "headline": head, "order": order, "missing": missing, "legs": legs, + "has_shapes": any(legs[l].get("shapes") for l in order), "history_runs": len(history), + "palette": palette(order), "comparison": parse_comparison(find_comparison(a.run_dir)), + "verdict_all": verdict_all(legs, order, docker_cpus, missing, timing), + "thresholds": {"import_target": IMPORT_TARGET, "err_pct_high": ERR_PCT_HIGH, + "pg_contended_ms": PG_CONTENDED_MS}} + + +LIGHT_TOKENS = ( + "color-scheme: light;" + "--page:#f6f8fa; --surface:#ffffff; --surface-2:#f6f8fa;" + "--ink:#1f2328; --ink-2:#424a53; --muted:#59636e;" + "--grid:#d8dee4; --axis:#afb8c1; --border:#d0d7de;" + "--accent:#0969da; --prev:#bc4c00;" + "--band-a:#f6f8fa; --band-b:#eaeef2;" + "--good:#1a7f37; --good-bg:#dafbe1; --warn:#7d4e00; --warn-bg:#fff8c5;" + "--bad:#cf222e; --bad-bg:#ffebe9; --na:#59636e; --na-bg:#eaeef2;" + "--cpu:#cf222e; --tip-bg:#1f2328; --tip-fg:#ffffff; --tip-bd:#1f2328;" + "--btn-on:#0969da; --btn-on-fg:#ffffff; --shadow:0 0 0 1px #d0d7de;") + + +def render_html(data): + tpl = read_text(os.path.join(HERE, "report_template.html")) + if tpl is None: + raise OSError("report_template.html not found next to report_html.py") + # Embedded in a +FHIR Benchmark + + + +
+
+
+

FHIR Server Benchmark

+
+
+
+ +
+
+
+ +
+

Run summary

+

How to read this: the tables of the run's comparison.md, one column per leg; the same numbers appear in the charts below. Marks are explained in the glossary.

+
+
+ +
+

1Is this run valid?

+

Before looking at speeds: every leg must have loaded the whole corpus, with no errors and with its containers alive.

+
+

How to read this: ✓ok met · !warning use with care · ✗fail those numbers are not comparable · – not applicable.

+

+
+ +
+

2Results

+

Headline numbers by leg

+

How to read this: pick a leg; every leg gets the same tiles. The comparison with the previous run appears only for legs that have data in that run.

+
+
+

+ +

Throughput by suite, all legs

+

How to read this: longer bar = more per second (the search indexing panel is in seconds: shorter is better); each panel has its own scale, so compare legs within a panel, not across panels.

+
† ‡ ⚠ validity marks (see glossary)
+
+ +

Latency by suite (logarithmic scale)

+

How to read this: the dot is the median (p50), the vertical tick is the p95 and the end of the line is the p99; further left is faster and each axis mark is 10 times the previous one.

+
● p50 (typical)┃ p95 (slowest 1 in 20)┤ p99 (slowest 1 in 100)
+
+
+ +
+

3Detail

+ +

Timeline and host load

+

How to read this: pick All to compare every leg at once: one line per leg in its own colour (dashed line and diamond markers = the leg with Elasticsearch), with the leg name at the end of the line and the phases of each leg in a lane below. Pick a single leg to see its phase bands. The line is the Docker host load (1-minute average);

+
+
+

There is only one reading at the start and one at the end of each phase; between readings the line is an interpolation. Each band covers the whole suite step (k6 plus diagnostic captures), not just the load. In the All view the legs are aligned at their own start, not at the same clock time.

+ +

Bulk Import (/ui/bulk-import, $bulk-submit) by phase

+

How to read this: each bar is the time until the data can be searched; shorter is better. The official clock adds ingest and search indexing; the NDJSON conversion beforehand is shown separately. Where indexing runs inline (during ingest), as on the Elasticsearch legs, it has no bar of its own: its time is inside the ingest bar. The colour of each bar is the leg.

+
conversion (not in the total)ingestsearch indexing (deferred rebuild)
+
+ +

Batch/Transaction Import (/ui/batch, k6 import) by phase

+

How to read this: each bar is the whole k6 step; shorter is better. The solid part is the import scenario, which is what resources/s divides by; the light part is k6 setup(), which seeds the Bundles before the load starts. Below each bar: resources, resources/s, Bundles completed out of the target († if the corpus is incomplete) and the error rate (‡ above the threshold).

+
k6 setup() (seed Bundles)import scenario
+
+

Latency per Bundle (logarithmic scale)

+

How to read this: time of one whole Bundle (iteration_duration): the dot is p50, the vertical tick p95 and the end of the line p99; further left is faster.

+
+ +

Import: Batch/Transaction vs Bulk (resources/s)

+

How to read this: for each leg, the solid bar is the Batch/Transaction Import and the outlined bar is the Bulk Import; longer is faster.

+
Batch/Transaction (/ui/batch)Bulk (/ui/bulk-import)
+
+

These are different workloads: the Batch/Transaction Import is concurrent k6 clients posting Bundles, and the Bulk Import is a single $bulk-submit job; compare them as two ways to load data, not as the same test.

+ +
+

SQL-on-FHIR $sql-run by view (logarithmic scale)

+

How to read this: one panel per ViewDefinition run by the sql-run suite; the dot is p50, the tick p95 and the end of the line p99 of the requests to that view; further left is faster.

+
+
+ +
+

Search by query shape

+

How to read this: the search average hides slow queries; here each row is a query type, the dark part reaches the median and the light part reaches the p95.

+
+
+
+

Percentiles by index without interpolation, same as search_by_shape.py in CI; that is why they do not match k6 exactly.

+
+ +

+
+

+

How to read this: one point per run (leg colour = this run, orange = other runs), higher is better; with a single data point per date and different hosts, the line shows context, not a proven trend.

+
+
+
+ +
+

4Full data

+

All the numbers of the run; tap a header to sort.

+
+

+ +

Health of each leg

+
+ +

Result size cross-check

+

How to read this: totals each leg returned for the same queries; if they differ, the legs did not search over the same data.

+
+
+ +
+

Glossary

+
+
LegA storage combination tested separately (e.g. postgres + Elasticsearch).
+
VU (virtual user)A simulated client with a single request in flight; N VUs are N clients at once, not N req/s.
+
req/sHTTP requests completed per second (more is better).
+
resources/sFHIR resources stored per second; used for Batch/Transaction Import and Bulk Import, where one request carries many resources.
+
p50 / p95 / p99Response time that 50 %, 95 % or 99 % of requests do not exceed (less is better).
+
Err%Percentage of requests with an HTTP error; it does not check whether the content is correct.
+
Checks ✓/✗k6 script verifications that passed or failed (e.g. "the Bundle was imported").
+
Load (load average)Average number of processes wanting CPU; above the CPU count there is waiting.
+
† ‡ ⚠
+
Suites and concurrency
+
+
+ +
+
+ + + + + diff --git a/.github/scripts/fhir-bench/resolve-matrix.sh b/.github/scripts/fhir-bench/resolve-matrix.sh index 218a75f0c3..26c8f94b03 100755 --- a/.github/scripts/fhir-bench/resolve-matrix.sh +++ b/.github/scripts/fhir-bench/resolve-matrix.sh @@ -72,7 +72,7 @@ LEG_COUNT=$(echo "$LEGS" | wc -w) # default inputs) needs about 6 GB (the capacity gate's own formula: # 2048+1536 primary, 1024*2+512 ES = 6144MB, so 8 GB free with its # 2 GB margin), so 2 concurrent legs already use most of the shared -# 4-CPU / 11 GB Docker host that the rest of CI also runs on. +# 4-CPU Docker host that the rest of CI also runs on. MAX_PARALLEL="${IN_MAX_PARALLEL:-1}" case "$MAX_PARALLEL" in *[!0-9]*) @@ -97,7 +97,7 @@ case "$MAX_PARALLEL" in FAIL=1 MAX_PARALLEL=1 elif [ "$MAX_PARALLEL" -gt 2 ]; then - echo "::warning::max_parallel=$MAX_PARALLEL clamped to 2 (shared 4-CPU / 11 GB Docker host)" + echo "::warning::max_parallel=$MAX_PARALLEL clamped to 2 (shared 4-CPU Docker host)" MAX_PARALLEL=2 fi fi diff --git a/.github/scripts/fhir-bench/run_timing.py b/.github/scripts/fhir-bench/run_timing.py new file mode 100644 index 0000000000..45a1e9847c --- /dev/null +++ b/.github/scripts/fhir-bench/run_timing.py @@ -0,0 +1,244 @@ +#!/usr/bin/env python3 +"""Run time section for the FHIR Server Benchmark report. + +Splits the wall-clock of a workflow run into time WAITING for resources +(runner queue, capacity gate, quiet-host gate, dispatch) and time WORKING, so a +queued run is not mistaken for a slow one. Always exits 0. + + run_timing.py --repo OWNER/REPO --run-id ID --run-dir DIR \ + --out run-time.md --dump-json run-timing.json +""" +import argparse +import glob +import json +import os +import subprocess +import sys +from datetime import datetime, timezone + + +def parse_ts(s): + return int(datetime.strptime(s, "%Y-%m-%dT%H:%M:%SZ") + .replace(tzinfo=timezone.utc).timestamp()) + + +def iso(t): + return datetime.fromtimestamp(t, timezone.utc).strftime("%Y-%m-%dT%H:%M:%SZ") + + +def humanize(s): + s = int(round(s)) + if s < 60: + return f"{s} s" + m, sec = divmod(s, 60) + if m < 60: + return f"{m} min {sec} s" if sec else f"{m} min" + h, m = divmod(m, 60) + return f"{h} h {m} min" if m else f"{h} h" + + +def default_fetcher(kind, repo, run_id): + """kind 'run' -> dict, 'jobs' -> list of job dicts.""" + base = f"repos/{repo}/actions/runs/{run_id}" + if kind == "run": + out = subprocess.run(["gh", "api", base], capture_output=True, + text=True, check=True, timeout=60).stdout + return json.loads(out) + out = subprocess.run( + ["gh", "api", "--paginate", base + "/jobs?per_page=100", "--jq", ".jobs[]"], + capture_output=True, text=True, check=True, timeout=120).stdout + return [json.loads(line) for line in out.splitlines() if line.strip()] + + +def read_runner_info(run_dir, leg): + pats = [os.path.join(run_dir, f"fhir-benchmark-{leg}-*", leg, "runner-info.txt"), + os.path.join(run_dir, leg, "runner-info.txt")] + for p in pats: + for f in sorted(glob.glob(p)): + info = {} + try: + with open(f, encoding="utf-8", errors="replace") as fh: + for line in fh: + if ":" in line: + k, v = line.split(":", 1) + info[k.strip()] = v.strip() + except OSError: + continue + return info + return {} + + +def _int(v): + try: + return max(0, int(float(v))) + except (TypeError, ValueError): + return 0 + + +def union(intervals): + out = [] + for a, b in sorted(i for i in intervals if i[1] > i[0]): + if out and a <= out[-1][1]: + out[-1][1] = max(out[-1][1], b) + else: + out.append([a, b]) + return out + + +def covered(a, b, merged): + return sum(max(0, min(b, y) - max(a, x)) for x, y in merged) + + +def kind_of(name): + n = name.lower() + if name.startswith("Benchmark ("): + return "leg" + if n.startswith("resolve"): + return "setup" + if n.startswith("build"): + return "build" + if n.startswith("compare"): + return "compare" + return "other" + + +def compute(run, jobs, run_dir, now): + run_created = parse_ts(run["created_at"]) + rows = [] + for j in jobs: + created = parse_ts(j["created_at"]) + if j.get("started_at"): + started = parse_ts(j["started_at"]) + else: + started = now + running = not j.get("completed_at") + completed = None if running else parse_ts(j["completed_at"]) + end = now if running else completed + end = max(end, started) + name = j["name"] + kind = kind_of(name) + leg = name[len("Benchmark ("):].rstrip(")") if kind == "leg" else None + rows.append(dict(name=name, kind=kind, leg=leg, created=created, + started=started, completed=completed, end=end, + running=running)) + rows.sort(key=lambda r: (r["created"], r["started"])) + + for r in rows: + info = read_runner_info(run_dir, r["leg"]) if r["leg"] else {} + r["cap"] = _int(info.get("capacity_wait_s")) + r["host"] = _int(info.get("host_wait_s")) + r["queued"] = max(0, r["started"] - r["created"]) + run_s = r["end"] - r["started"] + # the gates happen inside the job; never take more than it ran + r["cap"] = min(r["cap"], run_s) + r["host"] = min(r["host"], run_s - r["cap"]) + others = union([(o["started"], o["end"]) for o in rows + if o["kind"] == "leg" and o is not r]) + r["behind"] = (min(r["queued"], covered(r["created"], r["started"], others)) + if r["kind"] == "leg" else 0) + r["waiting"] = r["queued"] - r["behind"] + r["cap"] + r["host"] + r["working"] = run_s - r["cap"] - r["host"] + + dispatch = 0 + if rows: + dispatch = max(0, rows[0]["created"] - run_created) + rows[0]["waiting"] += dispatch + end_all = max(r["end"] for r in rows) + else: + end_all = now + total = max(0, end_all - run_created) + busy = sum(b - a for a, b in union([(r["started"], r["end"]) for r in rows])) + gates = sum(r["cap"] + r["host"] for r in rows) + working = max(0, min(total, busy - gates)) + waiting = total - working + return dict(run_id=str(run.get("id", "")), total_s=total, waiting_s=waiting, + working_s=working, rows=rows, dispatch_s=dispatch) + + +def to_json(rep): + jobs = [] + for r in rep["rows"]: + jobs.append({ + "name": r["name"], "kind": r["kind"], "leg": r["leg"], + "queued_s": r["queued"], "behind_legs_s": r["behind"], + "capacity_wait_s": r["cap"], "host_wait_s": r["host"], + "waiting_s": r["waiting"], "working_s": r["working"], + "created": iso(r["created"]), "started": iso(r["started"]), + "completed": iso(r["completed"]) if r["completed"] is not None else None, + "running": r["running"], + }) + return {"run_id": rep["run_id"], "total_s": rep["total_s"], + "waiting_s": rep["waiting_s"], "working_s": rep["working_s"], + "jobs": jobs} + + +def to_markdown(rep): + lines = ["", "### Run time", "", + f"**Total {humanize(rep['total_s'])}** · waiting for resources " + f"**{humanize(rep['waiting_s'])}** · working **{humanize(rep['working_s'])}**", + "", + "| Stage | Waiting for resources | Behind earlier legs (by design) | Working |", + "|---|---:|---:|---:|"] + for i, r in enumerate(rep["rows"]): + stage = f"`{r['leg']}`" if r["leg"] else r["name"] + if r["running"]: + stage += " (running)" + wait = humanize(r["waiting"]) + if r["kind"] == "leg" and (r["cap"] or r["host"]): + runner = r["waiting"] - r["cap"] - r["host"] + parts = [f"runner {humanize(runner)}"] + if r["cap"]: + parts.append(f"capacity gate {humanize(r['cap'])}") + if r["host"]: + parts.append(f"quiet host {humanize(r['host'])}") + wait += " (" + " + ".join(parts) + ")" + behind = humanize(r["behind"]) if r["behind"] else "–" + lines.append(f"| {stage} | {wait} | {behind} | {humanize(r['working'])} |") + lines += ["", + "_Waiting for resources = the wait for a runner plus the capacity gate " + "(plus the wait for a quiet host when that exists). \"Behind earlier " + "legs\" is sequencing (max_parallel), not idle time._", + ""] + return "\n".join(lines) + + +def build(repo, run_id, run_dir, fetcher=default_fetcher, now=None): + now = int(now if now is not None else datetime.now(timezone.utc).timestamp()) + run = fetcher("run", repo, run_id) + jobs = fetcher("jobs", repo, run_id) + if isinstance(jobs, dict): + jobs = jobs.get("jobs", []) + run = dict(run) + run.setdefault("id", run_id) + rep = compute(run, jobs, run_dir or "", now) + return rep + + +def main(argv=None, fetcher=default_fetcher, now=None): + ap = argparse.ArgumentParser() + ap.add_argument("--repo", required=True) + ap.add_argument("--run-id", required=True) + ap.add_argument("--run-dir", default="") + ap.add_argument("--out") + ap.add_argument("--dump-json") + try: + a = ap.parse_args(argv) + except SystemExit: + return 0 + try: + rep = build(a.repo, a.run_id, a.run_dir, fetcher, now) + md = to_markdown(rep) + js = json.dumps(to_json(rep), indent=2) + if a.out: + with open(a.out, "w", encoding="utf-8") as f: + f.write(md) + if a.dump_json: + with open(a.dump_json, "w", encoding="utf-8") as f: + f.write(js + "\n") + except Exception as e: # never fail the report + print(f"run_timing: skipped ({e})", file=sys.stderr) + return 0 + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/.github/scripts/fhir-bench/start-mongodb.sh b/.github/scripts/fhir-bench/start-mongodb.sh index 58b6d1025d..292ca7f47f 100755 --- a/.github/scripts/fhir-bench/start-mongodb.sh +++ b/.github/scripts/fhir-bench/start-mongodb.sh @@ -13,8 +13,8 @@ # directConnection=true (skips replica-set topology discovery), the # same pattern as inferno-us-core.yml's Mongo wiring. # -# Explicit engine caps, because this runs on the shared 4-CPU / 11 GB -# host: +# Explicit engine caps, because this runs on the shared 4-CPU +# Docker host: # --wiredTigerCacheSizeGB mongod's own default is ~50% of (host RAM # - 1GB), which risks an OOM on this host # (crates/persistence/tests/mongodb_tests.rs @@ -49,7 +49,7 @@ set -euo pipefail MONGO_WT_CACHE_GB="${IN_MONGO_WT_CACHE_GB:-2}" if ! [[ "$MONGO_WT_CACHE_GB" =~ ^[0-9]+(\.[0-9]+)?$ ]] \ || ! awk -v v="$MONGO_WT_CACHE_GB" 'BEGIN { exit !(v >= 0.25 && v <= 6) }'; then - echo "::error::mongo_wt_cache_gb must be a number in 0.25..6 (got '$MONGO_WT_CACHE_GB'); the Docker host has 11 GB shared with all CI" + echo "::error::mongo_wt_cache_gb must be a number in 0.25..6 (got '$MONGO_WT_CACHE_GB'); the Docker host is shared with all CI" exit 1 fi MONGO_IMAGE="mongo:7.0" diff --git a/.github/scripts/fhir-bench/suite-lib.sh b/.github/scripts/fhir-bench/suite-lib.sh index 1a9f95d6e7..6135c6a14d 100644 --- a/.github/scripts/fhir-bench/suite-lib.sh +++ b/.github/scripts/fhir-bench/suite-lib.sh @@ -26,9 +26,7 @@ # already set BY THE TIME THE FUNCTION IS CALLED (not by the time it is # defined) — in particular RESULTS_DIR (the leg's output directory) and # ES_DRAIN_TIMEOUT_S (the ES drain deadline), both set once near the top of -# the step, INDEXING_TYPE / INDEXING_BATCH_SIZE / INDEXING_BUDGET_S (the -# indexing suite's resource type, $reindex page size and time budget, set -# next to ES_DRAIN_TIMEOUT_S) and the optional HFS_BENCH_LOG override (the +# the step, and the optional HFS_BENCH_LOG override (the # HFS log path; defaults to the file 'Start HFS server' writes, set only for # offline smoke runs), and, inside its per-suite loop, SUITE_WALL (the # current suite's wall-clock seconds, set right before each call this file's @@ -81,15 +79,6 @@ # what it creates) when that suite is # listed; re-runs es_drain_gate first # if it never ran this leg. -# run_indexing_suite the `indexing` suite (opt-in: only -# when tests names it, never in `all`; -# after search, before insert): -# one timed POST //$reindex, -# cancelled at $INDEXING_BUDGET_S. Writes -# indexing.txt, indexing-status.txt and -# indexing-hfs-log.txt. -# indexing_status_field BODY NAME one value[x] of a $reindex Parameters -# body. # write_containers_state containers-state.txt (container # OOM/exit state + per-volume `du`) plus # the end-of-run Elasticsearch volume @@ -482,166 +471,6 @@ write_search_counts() { } > "$RESULTS_DIR/search-counts.txt" || echo "::warning::search-counts cross-check failed" } -# ── Indexing suite (`indexing`, opt-in via tests, after search) ────── -# One timed `POST /$INDEXING_TYPE/$reindex` against the corpus import -# loaded: HFS re-reads every stored resource of that type, re-extracts -# its search parameters and rewrites the index that serves search — -# the primary's own search index on sqlite/postgres/mongodb, -# Elasticsearch on the *-elasticsearch legs (an offloaded primary is not -# a reindex target there, or its writer is a no-op: hfs main.rs -# es_only_when_offloaded / mongodb storage.rs is_search_offloaded). -# Same operation, resource type and page size on every leg, so -# resources/s is comparable across all six; it is NOT the index cost -# paid inside import (that stays folded into the import row). -# -# Opt-in: it runs only when `tests` names it and is not part of `all`. -# Users never run a $reindex when they load data, and it rewrites the -# index right before insert and bulk-import, so a run that includes it -# may skew both; bulk-import's initial-index row is the default -# indexing number. -# -# Timing is the job's own `$reindex-status` startedAt → completedAt -# (seconds=), not this 2 s poll loop (wall_seconds=). Bounded: past -# $INDEXING_BUDGET_S the job is cancelled (DELETE /$reindex-status/) -# and the rate covers the part that ran (status=partial -# reason=time-cap). Never fails the leg. Worst case with an -# unresponsive HFS: 30 s kick-off + budget + one 15 s poll + 30 s -# cancel + 45 s cancel wait, about budget + 2 min; with a responsive -# one, the budget plus one poll. -# -# Writes indexing.txt, indexing-status.txt (the last status body, or -# the kick-off answer when it failed — .txt, not .json, so "Generate -# step summary"'s *.json Results glob never reads it as a k6 summary) -# and indexing-hfs-log.txt (this job's `reindex ...` lines from the HFS -# log, read from the byte offset taken before kick-off so the -# 470-530 MB *-elasticsearch logs are not rescanned). -run_indexing_suite() { - local base="http://localhost:$BENCH_PORT" - local hfs_log="${HFS_BENCH_LOG:-/tmp/hfs-bench-$BACKEND.log}" - local out="$RESULTS_DIR/indexing.txt" - local t0=$SECONDS log_off=0 kick="" http=000 job="" body="" last="" st="" - local cancelled=false cancel_http="" cancel_until=0 - local status="" reason="" total="" processed="" entries="" errors="" - local started="" completed="" s0="" s1="" seconds="" rate="" per_res="" es_refresh=n/a - - case "$BACKEND" in - *-elasticsearch) es_refresh="${HFS_ELASTICSEARCH_REINDEX_REFRESH:-${HFS_ELASTICSEARCH_WRITE_REFRESH:-unknown}}" ;; - esac - if [ -f "$hfs_log" ]; then - log_off=$(stat -c %s "$hfs_log" 2>/dev/null) || log_off=0 - fi - - echo "── Indexing: POST /$INDEXING_TYPE/\$reindex (batchSize $INDEXING_BATCH_SIZE, budget ${INDEXING_BUDGET_S}s) ──" - kick=$(curl -s --max-time 30 -w '\n%{http_code}' -X POST \ - -H 'Content-Type: application/fhir+json' \ - -d "{\"resourceType\":\"Parameters\",\"parameter\":[{\"name\":\"batchSize\",\"valueInteger\":$INDEXING_BATCH_SIZE}]}" \ - "$base/$INDEXING_TYPE/\$reindex" 2>/dev/null) || kick=$'\n000' - http=$(printf '%s\n' "$kick" | tail -n1) - job=$(indexing_status_field "$(printf '%s\n' "$kick" | head -n -1)" jobId) - [[ "$job" =~ ^[A-Za-z0-9-]+$ ]] || job="" - - if [ "$http" != 202 ] || [ -z "$job" ]; then - { - echo "status=kickoff-failed" - echo "reason=http-$http" - echo "resource_type=$INDEXING_TYPE" - echo "kickoff_http=$http" - echo "batch_size=$INDEXING_BATCH_SIZE" - echo "budget_s=$INDEXING_BUDGET_S" - } > "$out" - printf '%s\n' "$kick" | head -n -1 | head -c 4096 > "$RESULTS_DIR/indexing-status.txt" || true - cat "$out" - echo "::warning::indexing suite: POST /$INDEXING_TYPE/\$reindex answered HTTP $http — no indexing number for this leg (indexing.txt)." - return 0 - fi - - while :; do - body=$(curl -sf --max-time 15 "$base/\$reindex-status/$job" 2>/dev/null) || body="" - [ -n "$body" ] && last="$body" - st=$(indexing_status_field "$body" status) - echo " t=$((SECONDS - t0))s status=${st:-?} processed=$(indexing_status_field "$body" processed)/$(indexing_status_field "$body" total)" - case "$st" in completed|failed|cancelled) break ;; esac - if [ "$cancelled" = false ] && [ $((SECONDS - t0)) -ge "$INDEXING_BUDGET_S" ]; then - cancel_http=$(curl -s -o /dev/null -w '%{http_code}' --max-time 30 -X DELETE \ - "$base/\$reindex-status/$job" 2>/dev/null) || cancel_http=000 - echo " t=$((SECONDS - t0))s budget reached — DELETE \$reindex-status/$job → HTTP $cancel_http" - cancelled=true - cancel_until=$((SECONDS + 45)) - elif [ "$cancelled" = true ] && [ "$SECONDS" -ge "$cancel_until" ]; then - break - fi - sleep 2 - done - - st=$(indexing_status_field "$last" status) - total=$(indexing_status_field "$last" total) - processed=$(indexing_status_field "$last" processed) - entries=$(indexing_status_field "$last" entriesCreated) - errors=$(indexing_status_field "$last" errorCount) - started=$(indexing_status_field "$last" startedAt) - completed=$(indexing_status_field "$last" completedAt) - if [ -n "$started" ] && [ -n "$completed" ]; then - s0=$(date -u -d "$started" +%s.%N 2>/dev/null) || s0="" - s1=$(date -u -d "$completed" +%s.%N 2>/dev/null) || s1="" - if [ -n "$s0" ] && [ -n "$s1" ]; then - seconds=$(awk -v a="$s0" -v b="$s1" 'BEGIN { printf "%.3f", b - a }') - fi - fi - if [[ "$processed" =~ ^[0-9]+$ ]] && [ -n "$seconds" ]; then - rate=$(awk -v p="$processed" -v s="$seconds" 'BEGIN { if (s > 0) printf "%.1f", p / s }') - fi - if [[ "$processed" =~ ^[0-9]+$ ]] && [ "$processed" -gt 0 ] && [[ "$entries" =~ ^[0-9]+$ ]]; then - per_res=$(awk -v e="$entries" -v p="$processed" 'BEGIN { printf "%.2f", e / p }') - fi - - case "$st" in - completed) status=completed ;; - cancelled) status=partial; reason=$([ "$cancelled" = true ] && echo time-cap || echo cancelled) ;; - failed) status=failed; reason=$(indexing_status_field "$last" errorMessage | tr '\r\n' ' ' | cut -c1-200) ;; - *) status=partial; reason=cancel-unconfirmed ;; - esac - - { - echo "status=$status" - echo "reason=$reason" - echo "resource_type=$INDEXING_TYPE" - echo "job_id=$job" - echo "kickoff_http=$http" - echo "cancel_http=$cancel_http" - echo "total=${total:-unknown}" - echo "processed=${processed:-unknown}" - echo "entries=${entries:-unknown}" - echo "errors=${errors:-unknown}" - echo "started_at=$started" - echo "completed_at=$completed" - echo "seconds=${seconds:-unknown}" - echo "wall_seconds=$((SECONDS - t0))" - echo "resources_per_s=${rate:-unknown}" - echo "entries_per_resource=${per_res:-unknown}" - echo "batch_size=$INDEXING_BATCH_SIZE" - echo "budget_s=$INDEXING_BUDGET_S" - echo "es_refresh=$es_refresh" - } > "$out" - printf '%s\n' "$last" | head -c 65536 > "$RESULTS_DIR/indexing-status.txt" || true - if [ -f "$hfs_log" ]; then - tail -c +$((log_off + 1)) "$hfs_log" 2>/dev/null | grep -F "job_id=$job " | tail -n 50 | cut -c1-2000 \ - > "$RESULTS_DIR/indexing-hfs-log.txt" || true - fi - cat "$out" - if [ "$status" != completed ] || { [[ "$errors" =~ ^[0-9]+$ ]] && [ "$errors" -gt 0 ]; }; then - echo "::warning::indexing suite: \$reindex of $INDEXING_TYPE ended status=$status${reason:+ reason=$reason} (processed ${processed:-?}/${total:-?}, errors ${errors:-?}) — see indexing.txt." - fi - return 0 -} - -# One field of a `$reindex` Parameters body (run_indexing_suite): the -# first value[x] of the parameter named $2, or empty. -indexing_status_field() { - printf '%s' "$1" | jq -r --arg n "$2" \ - '[.parameter[]? | select(.name == $n) | (.valueInteger // .valueString // .valueCode // .valueDateTime // .valueDecimal)][0] // empty' \ - 2>/dev/null || true -} - # ── Container / volume final state (end of step) ─────────────────── # k6 runs with `|| true` throughout, so a mid-run OOM would otherwise # only ever show up as mysteriously bad numbers, never as a failed diff --git a/.github/scripts/fhir-bench/summary_backends.py b/.github/scripts/fhir-bench/summary_backends.py index efdb8509db..e0bd747f72 100755 --- a/.github/scripts/fhir-bench/summary_backends.py +++ b/.github/scripts/fhir-bench/summary_backends.py @@ -2,7 +2,7 @@ # # Per-leg benchmark diagnostics for the step summary: tuning table, import # completeness and throughput (resources/s), bulk-import ($bulk-submit) -# result, ES drain status, the indexing suite (timed `$reindex`), host load at +# result, ES drain status, host load at # crud start, "how to read this leg" guidance, the result-size cross-check + # crud-residue caption, the insert suite's per-type line, Mongo # transaction-error heuristic, composite ES sync-failure count, and @@ -40,7 +40,7 @@ # bench-results// — runner-info.txt, import-completeness.txt, # bulk-import.txt, es-drain.txt, host-contention.txt, search-counts.txt, crud-residue.txt, # import-mongo-txn-errors.txt, es-sync-metrics-after-drain.txt, -# containers-state.txt, indexing.txt, indexing-hfs-log.txt, plus insert.json +# containers-state.txt, plus insert.json # (the insert suite's k6 --summary-export). Each section below is skipped, # not fatal, when its file is absent (e.g. a leg that died before that file # was ever written). @@ -171,14 +171,14 @@ def bi_n(key): if bi_status == "complete": # index_seconds=0 with index_status=inline means HFS indexed while ingesting, # not that indexing was free; say so instead of printing a zero-second rebuild. - bi_ingest = f"Bulk Import: ingest {bi.get('ingest_seconds', '?')} s" + bi_ingest = f"ingest until Completed {bi.get('ingest_seconds', '?')} s" if bi.get("index_status") == "inline" or bi.get("defer_indexing") == "false": bi_phases = f"{bi_ingest}, search index built inline during ingest" if bi.get("index_status") not in ("inline", "", None): bi_phases += (f" + {bi.get('index_seconds', '?')} s rebuild of rejected types, " f"`{bi.get('index_status')}`") else: - bi_phases = (f"{bi_ingest} + Bulk Import: index rebuild {bi.get('index_seconds', '?')} s, " + bi_phases = (f"{bi_ingest} + search-index rebuild {bi.get('index_seconds', '?')} s, " f"`{bi.get('index_status', '?')}`") print(f"\n**Bulk Import (`$bulk-submit`):** {bi_n('resources_ok')}/{bi_n('resources_submitted')} " f"resources in {bi.get('total_seconds', '?')} s ({bi_phases}) = " @@ -215,63 +215,6 @@ def bi_n(key): f"es_live={drain.get('es_live', '?')} missing={d_missing} " f"needs_reindex={drain.get('needs_reindex_after', '?')}.{d_warn}") -# Indexing suite (opt-in: only when tests names it): one timed `POST //$reindex` after search -# (run_indexing_suite in suite-lib.sh documents what it measures and why it -# is comparable across legs). indexing-hfs-log.txt holds the job's own -# `reindex job finished` line from the HFS log: where the time went. -ix = read_kv(f"{results_dir}/indexing.txt", "=") -if ix: - ix_status = ix.get("status", "?") - ix_type = ix.get("resource_type", "?") - if ix_status == "kickoff-failed": - print(f"\n**Indexing:** `POST /{ix_type}/$reindex` answered HTTP " - f"{ix.get('kickoff_http', '?')} — no indexing number for this leg. ⚠") - else: - def ix_int(key): - try: - return f"{int(ix.get(key, '')):,}" - except ValueError: - return "?" - try: - ix_rate = f"{float(ix.get('resources_per_s', '')):,.0f}" - except ValueError: - ix_rate = "?" - try: - ix_secs = f"{float(ix.get('seconds', '')):.1f}" - except ValueError: - ix_secs = "?" - ix_line = (f"\n**Indexing (`$reindex` of {ix_type}):** {ix_status} — " - f"{ix_int('processed')}/{ix_int('total')} resources in " - f"{ix_secs} s = **{ix_rate} resources/s**; " - f"{ix_int('entries')} index entries ({ix.get('entries_per_resource', '?')}/resource), " - f"{ix.get('errors', '?')} errors; batchSize {ix.get('batch_size', '?')}, " - f"budget {ix.get('budget_s', '?')} s") - if ix.get("es_refresh", "n/a") != "n/a": - ix_line += f", Elasticsearch refresh `{ix['es_refresh']}`" - ix_line += "." - if ix_status == "partial": - ix_line += (f" ⚠ partial ({ix.get('reason', '?')}): the job was cancelled at the budget; " - "the rate covers the part that ran.") - elif ix_status == "failed": - ix_line += f" ⚠ the job failed: {ix.get('reason', '?')}." - if ix.get("errors", "0") not in ("0", "unknown"): - ix_line += " ⚠ resources left unindexed (indexing-status.txt lists them)." - print(ix_line) - ix_log = f"{results_dir}/indexing-hfs-log.txt" - if os.path.exists(ix_log): - fin = [l for l in open(ix_log) if "reindex job finished" in l] - if fin: - fin_kv = dict(re.findall(r"(\w+)=(\S+)", fin[-1])) - def ix_s(key): - try: - return f"{int(fin_kv[key]) / 1000:.1f} s" - except (KeyError, ValueError): - return "?" - print(f"\n_HFS reindex phases (job): fetch {ix_s('fetch_ms')} · write " - f"{ix_s('write_ms')} (extract {ix_s('extract_ms')} · database/Elasticsearch " - f"wait {ix_s('db_wait_ms')}) · other {ix_s('other_ms')} of " - f"{ix_s('elapsed_ms')}; a writer that does not time a phase reports 0._") - # Host load (F9), every leg — not just Postgres ones (see the # Environment paragraph further below, which stays Postgres-only). contention_path = f"{results_dir}/host-contention.txt" @@ -406,6 +349,57 @@ def _ins_check(rt, key): " · ".join(ins_parts), (" · ⚠ **{:,} failed**".format(ins_failed) if ins_failed > 0 else ""))) +# sql-run suite: HFS's own k6/sql-run.js. Per-view requests and latency from +# the http_req_duration{view:} submetrics (exported because sql-run.js +# names them in always-passing thresholds), rows from the sql_run_rows counter. +# k6's --summary-export gives avg/min/med/max/p(90)/p(95) per trend (p(99) only +# if --summary-trend-stats asked for it); a column is shown only if some view +# has it. Requests per view come from the submetric's `count` (older exports +# lack it: shown as ?). +SQL_RUN_VIEWS = ("observation_page", "observation_large", "observation_filter", "claim", "eob") +try: + with open(f"{results_dir}/sql-run.json") as fh: + sqr = json.load(fh) +except (OSError, ValueError): + sqr = None +if isinstance(sqr, dict) and isinstance(sqr.get("metrics"), dict): + sm = sqr["metrics"] + schecks = (sqr.get("root_group") or {}).get("checks") if isinstance(sqr.get("root_group"), dict) else None + if not isinstance(schecks, dict): + schecks = {} + + def _sm(name, key): + m = sm.get(name) + return m.get(key) if isinstance(m, dict) else None + + def _num(v): + return isinstance(v, (int, float)) and not isinstance(v, bool) + + lat_cols = [(lbl, key) for lbl, key in (("avg", "avg"), ("p50", "med"), ("p90", "p(90)"), + ("p95", "p(95)"), ("p99", "p(99)"), ("max", "max")) + if any(_num(_sm("http_req_duration{view:%s}" % v, key)) for v in SQL_RUN_VIEWS)] + print("\n**SQL-on-FHIR `$sql-run` by view**\n") + print("| View | Requests | " + " | ".join(l + " ms" for l, _ in lat_cols) + " |") + print("|---|---:|" + "---:|" * len(lat_cols)) + for v in SQL_RUN_VIEWS: + d = "http_req_duration{view:%s}" % v + cnt = _sm(d, "count") + cells = [_fmt_or_q(_sm(d, k), ".1f") for _, k in lat_cols] + print("| %s | %s | %s |" % (v, _fmt_or_q(cnt, ","), " | ".join(cells))) + srows_n, srows_r = _sm("sql_run_rows", "count"), _sm("sql_run_rows", "rate") + sfail = _sm("http_req_failed", "value") + sbad = [] + for cn in ("sql-run 200", "sql-run rows > 0"): + c = schecks.get(cn) + f = c.get("fails") if isinstance(c, dict) else None + sbad.append("%s ✓" % cn if f == 0 else "%s ✗ %s" % (cn, _fmt_or_q(f, ","))) + print("\nRows returned: %s total, %s rows/s · errors %s%% · checks: %s" % ( + _fmt_or_q(srows_n, ","), _fmt_or_q(srows_r, ",.0f"), + _fmt_or_q(sfail * 100 if _num(sfail) else None, ".2f"), "; ".join(sbad))) + print("\n_The first two views read the first rows of a flat view (warm cache, LIMIT stops " + "early); the filtered view is the scan; Mongo returns unsorted rows; *-elasticsearch " + "legs use the primary store's runner._") + # Mongo transaction-abort count (F8): this counts matching HFS log # LINES across the whole log (startup, prewarm and import), not # bundles — a heuristic, not an exact bundle-failure count (a diff --git a/.github/scripts/fhir-bench/test_build_features.py b/.github/scripts/fhir-bench/test_build_features.py new file mode 100644 index 0000000000..7f62ea02eb --- /dev/null +++ b/.github/scripts/fhir-bench/test_build_features.py @@ -0,0 +1,45 @@ +import json +import unittest + +from build_features import features_for + + +def m(*legs): + return {"include": [{"backend": b, "port": 1} for b in legs]} + + +class BuildFeatures(unittest.TestCase): + def test_single_legs(self): + self.assertEqual(features_for(m("sqlite")), "R4,sqlite") + self.assertEqual(features_for(m("postgres")), "R4,postgres") + self.assertEqual(features_for(m("mongodb")), "R4,mongodb") + + def test_composite_legs(self): + self.assertEqual(features_for(m("sqlite-elasticsearch")), "R4,sqlite,elasticsearch") + self.assertEqual(features_for(m("postgres-elasticsearch")), "R4,postgres,elasticsearch") + self.assertEqual(features_for(m("mongodb-elasticsearch")), "R4,mongodb,elasticsearch") + + def test_core_is_todays_list(self): + legs = ["sqlite", "postgres", "mongodb", "sqlite-elasticsearch", + "postgres-elasticsearch", "mongodb-elasticsearch"] + self.assertEqual(features_for(m(*legs)), "R4,sqlite,postgres,mongodb,elasticsearch") + + def test_order_independent(self): + self.assertEqual(features_for(m("postgres", "sqlite")), "R4,sqlite,postgres") + + def test_elasticsearch_group(self): + legs = ["sqlite-elasticsearch", "postgres-elasticsearch", "mongodb-elasticsearch"] + self.assertEqual(features_for(m(*legs)), "R4,sqlite,postgres,mongodb,elasticsearch") + + def test_errors(self): + with self.assertRaises(ValueError): + features_for(m("redis")) + with self.assertRaises(ValueError): + features_for({"include": []}) + + def test_json_roundtrip(self): + self.assertEqual(features_for(json.loads(json.dumps(m("sqlite")))), "R4,sqlite") + + +if __name__ == "__main__": + unittest.main() diff --git a/.github/scripts/fhir-bench/test_compare_legs.py b/.github/scripts/fhir-bench/test_compare_legs.py index 67d8ca0891..f07b037043 100644 --- a/.github/scripts/fhir-bench/test_compare_legs.py +++ b/.github/scripts/fhir-bench/test_compare_legs.py @@ -19,16 +19,17 @@ import compare_legs as cl # noqa: E402 RUN = "100" -SUITES = ("prewarm", "import", "crud", "search") +SUITES = ("prewarm", "import", "crud", "search", "sql-run") INSERT_ROW = "insert (creates/s)" -IMPORT = "Batch/Transaction Import, `POST /` Bundles" # Errors label; Throughput and p95 add a unit +IMPORT = "Batch/Transaction Import (`/ui/batch`: `POST /` Bundles)" # Errors label; Throughput and p95 add a unit IMPORT_ROW = IMPORT + " (resources/s)" -BULK = "Bulk Import, `$bulk-submit`" -BULK_ROW = BULK + " (resources/s)" -INGEST_ROW = "Bulk Import: ingest (resources/s, seconds)" -INDEX_ROW = "Bulk Import: index rebuild (seconds)" -REINDEX = "reindex, `$reindex` Encounter" -REINDEX_ROW = REINDEX + " (resources/s)" +BULK = "Bulk Import (`/ui/bulk-import`: `$bulk-submit`)" +BULK_ROW = "Bulk Import (`/ui/bulk-import`: `$bulk-submit`, until searchable) (resources/s)" +INGEST_ROW = "↳ ingest, until Completed (resources/s, seconds)" +INDEX_ROW = "↳ search indexing (seconds)" +SQL_ROW = "SQL-on-FHIR `$sql-run` (requests/s)" +SQL_ROWS_ROW = "SQL-on-FHIR `$sql-run` (rows/s)" +SQL = "SQL-on-FHIR `$sql-run`" # p95 and Errors label _guard = {"on": False} @@ -50,6 +51,7 @@ def summary(rps, p95, err=0.0, fails=0, it_p95=None): "http_req_duration": {"p(95)": p95}, "http_req_failed": {"value": err}, "checks": {"passes": 10, "fails": fails}} + metrics["sql_run_rows"] = {"count": 100, "rate": 2500.0} if it_p95 is not None: metrics["iteration_duration"] = {"p(95)": it_p95} return json.dumps({"metrics": metrics}) @@ -74,14 +76,6 @@ def leg_files(leg, bundles=1000, run=RUN, **override): return dict((k, v) for k, v in files.items() if v is not None) -def indexing(status="completed", rate="1200.4", processed=5000, total=5000, errors=0, - reason="", seconds="4.2", rtype="Encounter"): - return ("status=%s\nreason=%s\nresource_type=%s\njob_id=j\nkickoff_http=202\n" - "total=%d\nprocessed=%d\nentries=%d\nerrors=%d\nseconds=%s\nwall_seconds=5\n" - "resources_per_s=%s\nentries_per_resource=9.00\nbatch_size=1000\nbudget_s=240\n" - "es_refresh=n/a\n" % (status, reason, rtype, total, processed, processed * 9, errors, - seconds, rate)) - def bulk_txt(status="complete", **kv): """A bulk-import.txt body (key=value), complete by default.""" fields = {"status": status, "resources_submitted": 1630685, "resources_ok": 1630685, @@ -297,99 +291,6 @@ def test_insert_errors_block_crown(self): self.assertEqual(row(md, "Throughput", INSERT_ROW), "| insert (creates/s) | 900 ‡ | 500 |") self.assertIn("**2.0%** · **30 ✗**", row(md, "Errors", "insert")) - def test_reindex_row_and_crown(self): - put_dir(self.root, "sqlite", leg_files("sqlite", **{"indexing.txt": indexing()})) - put_dir(self.root, "postgres", leg_files("postgres", **{ - "indexing.txt": indexing(rate="800")})) - md = render(self.root, ["sqlite", "postgres"]) - self.assertEqual(row(md, "Throughput", REINDEX_ROW), "| " + REINDEX_ROW + " | **1,200** | 800 |") - self.assertEqual(row(md, "p95", REINDEX), - "| " + REINDEX + " | n/a (one async job) | n/a (one async job) |") - self.assertEqual(row(md, "Errors", REINDEX), "| " + REINDEX + " | 0.0% | 0.0% |") - self.assertNotIn("### Indexing", md) # the detail is in each leg's job summary - self.assertIn(cl.REINDEX_NOTE, md) - self.assertNotIn("| indexing |", md) - - def test_indexing_partial_errors_and_short_import(self): - put_dir(self.root, "sqlite", leg_files("sqlite", **{"indexing.txt": indexing( - status="partial", reason="time-cap", processed=3000, rate="500.0", seconds="180.2")})) - put_dir(self.root, "postgres", leg_files("postgres", bundles=874, **{ - "indexing.txt": indexing(errors=2)})) - md = render(self.root, ["sqlite", "postgres"]) - self.assertEqual(row(md, "Throughput", REINDEX_ROW), - "| " + REINDEX_ROW + " | 500 (partial) | 1,200 †‡ |") - self.assertEqual(row(md, "Errors", REINDEX), "| " + REINDEX + " | 0.0% | 0.0% · **2 ✗** |") - - def test_reindex_partial_or_failed_blocks_crown(self): - put_dir(self.root, "sqlite", leg_files("sqlite", **{"indexing.txt": indexing( - status="partial", reason="time-cap", processed=3000, rate="1500.0")})) - put_dir(self.root, "postgres", leg_files("postgres", **{"indexing.txt": indexing(rate="800")})) - md = render(self.root, ["sqlite", "postgres"]) - # no marker on either leg, but a partial rate is not a whole job's rate - self.assertEqual(row(md, "Throughput", REINDEX_ROW), - "| " + REINDEX_ROW + " | 1,500 (partial) | 800 |") - other = os.path.join(self.root, "failed") - put_dir(other, "sqlite", leg_files("sqlite", **{"indexing.txt": indexing( - status="failed", reason="boom")})) - put_dir(other, "postgres", leg_files("postgres", **{"indexing.txt": indexing(rate="800")})) - md = render(other, ["sqlite", "postgres"]) - self.assertEqual(row(md, "Throughput", REINDEX_ROW), "| " + REINDEX_ROW + " | 1,200 ‡ | 800 |") - - def test_reindex_without_a_rate(self): - put_dir(self.root, "sqlite", leg_files("sqlite", **{"indexing.txt": indexing( - status="partial", reason="cancel-unconfirmed", rate="unknown", seconds="unknown")})) - put_dir(self.root, "postgres", leg_files("postgres", **{ - "indexing.txt": indexing(rate="800"), - "bulk-import.txt": bulk_txt(resources_per_s="unknown")})) - md = render(self.root, ["sqlite", "postgres"]) - self.assertEqual(row(md, "Throughput", REINDEX_ROW), - "| " + REINDEX_ROW + " | n/a (no data) (partial) | 800 |") - # bulk-import with no rate used to raise AttributeError (its na was a str) - self.assertEqual(row(md, "Throughput", BULK_ROW), "| " + BULK_ROW + " | n/a (not run) | n/a (no data) |") - # a failed job with no rate (no startedAt) keeps its `‡` - other = os.path.join(self.root, "x") - put_dir(other, "sqlite", leg_files("sqlite", **{"indexing.txt": indexing( - status="failed", reason="boom", rate="unknown", seconds="unknown")})) - put_dir(other, "postgres", leg_files("postgres", **{"indexing.txt": indexing(rate="800")})) - md = render(other, ["sqlite", "postgres"]) - self.assertEqual(row(md, "Throughput", REINDEX_ROW), "| " + REINDEX_ROW + " | n/a (no data) ‡ | 800 |") - - def test_indexing_shown_when_requested_hidden_otherwise(self): - put_dir(self.root, "sqlite", leg_files("sqlite")) - put_dir(self.root, "postgres", leg_files("postgres")) - md = render(self.root, ["sqlite", "postgres"], tests="prewarm,import,crud,search") - self.assertNotIn("| reindex", md) # not requested, nothing written (older runs) - self.assertNotIn(cl.REINDEX_NOTE, md) - md = render(self.root, ["sqlite", "postgres", "mongodb"]) # tests=all: indexing is opt-in - self.assertNotIn("| reindex", md) - self.assertNotIn(cl.REINDEX_NOTE, md) - md = render(self.root, ["sqlite", "postgres", "mongodb"], - tests="prewarm,import,crud,search,indexing,insert,bulk-import") # named - for heading, name in (("Throughput", REINDEX_ROW), ("p95", REINDEX), ("Errors", REINDEX)): - name = name.replace(" Encounter", "") # no leg reindexed anything - self.assertEqual(row(md, heading, name), - "| %s | n/a (not run) | n/a (not run) | n/a (no artifact) |" % name) - other = os.path.join(self.root, "x") - put_dir(other, "sqlite", leg_files("sqlite", **{ - "indexing.txt": "status=kickoff-failed\nreason=http-501\nkickoff_http=501\n"})) - put_dir(other, "postgres", leg_files("postgres", **{"indexing.txt": "status=weird\n"})) - md = render(other, ["sqlite", "postgres"]) - name = "reindex, `$reindex` (resources/s)" - self.assertEqual(row(md, "Throughput", name), - "| %s | n/a (kick-off HTTP 501) | n/a (weird) |" % name) - unasked = os.path.join(self.root, "unasked") # written but not requested: still shown - put_dir(unasked, "sqlite", leg_files("sqlite", **{"indexing.txt": indexing()})) - md = render(unasked, ["sqlite"], tests="prewarm,import,crud,search") - self.assertEqual(row(md, "Throughput", REINDEX_ROW), "| " + REINDEX_ROW + " | 1,200 |") - self.assertIn(cl.REINDEX_NOTE, md) - - def test_indexing_not_in_default_suites(self): - self.assertNotIn("indexing", cl.CANONICAL_SUITES) - put_dir(self.root, "sqlite", leg_files("sqlite", **{"indexing.txt": indexing()})) - md = render(self.root, ["sqlite"]) # tests=all, but the leg wrote indexing.txt - self.assertEqual(row(md, "Throughput", REINDEX_ROW), "| " + REINDEX_ROW + " | 1,200 |") - self.assertIn(cl.REINDEX_NOTE, md) - def test_canonical_matches_workflow(self): # the suites tests=all runs are listed in two places; keep them in step here = os.path.dirname(os.path.abspath(__file__)) @@ -398,75 +299,46 @@ def test_canonical_matches_workflow(self): m = re.search(r'CANONICAL="([^"]+)"', fh.read()) self.assertIsNotNone(m) self.assertEqual(m.group(1), " ".join(cl.CANONICAL_SUITES)) - self.assertNotIn("indexing", m.group(1).split()) - - def test_reindex_label_names_one_type_only(self): - put_dir(self.root, "sqlite", leg_files("sqlite", **{"indexing.txt": indexing()})) - put_dir(self.root, "postgres", leg_files("postgres", **{ - "indexing.txt": indexing(rate="800", rtype="Observation")})) - md = render(self.root, ["sqlite", "postgres"]) - self.assertEqual(row(md, "Throughput", "reindex, `$reindex` (resources/s)"), - "| reindex, `$reindex` (resources/s) | **1,200** | 800 |") - - def test_reindex_type_must_be_a_plain_name(self): - for i, bad in enumerate(("Enc|ounter", "", "Enc`ounter")): - root = os.path.join(self.root, "t%d" % i) - put_dir(root, "sqlite", leg_files("sqlite", **{"indexing.txt": indexing(rtype=bad)})) - put_dir(root, "postgres", leg_files("postgres", **{"indexing.txt": indexing(rtype=bad)})) - md = render(root, ["sqlite", "postgres"]) - self.assertEqual(row(md, "Throughput", "reindex, `$reindex` (resources/s)"), - "| reindex, `$reindex` (resources/s) | **1,200** | **1,200** |") - self.assertNotIn("ounter", md) - - def test_indexing_no_crown_on_hardware_mismatch(self): - put_dir(self.root, "sqlite", leg_files("sqlite", **{"indexing.txt": indexing()})) - put_dir(self.root, "postgres", leg_files("postgres", **{ - "indexing.txt": indexing(rate="800"), - "runner-info.txt": "runner_name: x\nrunner_cpus: 4\nrunner_ram: 23G\ngithub_run: 100\n"})) - md = render(self.root, ["sqlite", "postgres"]) - self.assertEqual(row(md, "Throughput", REINDEX_ROW), "| " + REINDEX_ROW + " | 1,200 | 800 |") - - def test_indexing_marks_undrained_es_leg(self): - put_dir(self.root, "sqlite-elasticsearch", leg_files("sqlite-elasticsearch", **{ - "indexing.txt": indexing()})) # no es-drain.txt: never drained - put_dir(self.root, "postgres-elasticsearch", leg_files("postgres-elasticsearch", **{ - "indexing.txt": indexing(rate="800"), "es-drain.txt": "status=drained\nmissing=0\n"})) - md = render(self.root, ["sqlite-elasticsearch", "postgres-elasticsearch"]) - self.assertEqual(row(md, "Throughput", REINDEX_ROW), "| " + REINDEX_ROW + " | 1,200 † | 800 |") - # crud on the same undrained leg keeps its own rule: no drain check outside search - self.assertEqual(row(md, "Throughput", "crud"), "| crud | **100** | **100** |") def test_loading_rows_together_and_named(self): for leg in ("sqlite", "postgres"): put_dir(self.root, leg, leg_files(leg, **{ - "indexing.txt": indexing(), "bulk-import.txt": bulk_txt(), + "bulk-import.txt": bulk_txt(), "insert.json": summary(800.0, 90.0), "insert.log": "k6\n"})) md = render(self.root, ["sqlite", "postgres"]) self.assertEqual(labels(md, "Throughput"), - ["prewarm", IMPORT_ROW, BULK_ROW, INGEST_ROW, INDEX_ROW, REINDEX_ROW, - "crud", "search", INSERT_ROW]) - self.assertEqual(labels(md, "p95"), ["prewarm", IMPORT + " (per Bundle)", BULK, REINDEX, - "crud", "search", "insert"]) - self.assertEqual(labels(md, "Errors"), ["prewarm", IMPORT, BULK, REINDEX, - "crud", "search", "insert"]) + ["prewarm", IMPORT_ROW, BULK_ROW, INGEST_ROW, INDEX_ROW, + "crud", "search", SQL_ROW, SQL_ROWS_ROW, INSERT_ROW]) + self.assertEqual(labels(md, "p95"), ["prewarm", IMPORT + " (per Bundle)", BULK, + "crud", "search", SQL, "insert"]) + self.assertEqual(labels(md, "Errors"), ["prewarm", IMPORT, BULK, + "crud", "search", SQL, "insert"]) self.assertNotIn("$import", md) # HFS has none; no label may suggest it - self.assertIn("`†` crud/search/reindex ran on an incomplete corpus", md) - self.assertIn("on reindex, any reindex error or a failed job", md) + # the four import rows sit right after prewarm, in this order, under the UI names + t = labels(md, "Throughput") + self.assertEqual(t[:5], ["prewarm", IMPORT_ROW, BULK_ROW, INGEST_ROW, INDEX_ROW]) + self.assertNotIn("20 concurrent clients", IMPORT_ROW) + self.assertIn("k6 drives it with 20 concurrent clients.", cl.IMPORT_NOTE) + self.assertTrue(INGEST_ROW.startswith("↳ ") and INDEX_ROW.startswith("↳ ")) + # one vocabulary: "search indexing", never "initial index" + self.assertNotIn("initial index", md) + self.assertNotIn("initial-index", md) + self.assertIn("search indexing", md) + self.assertNotIn("search-index rebuild after Completed", md) + self.assertIn("`†` crud/search ran on an incomplete corpus", md) self.assertIn("shown only when no leg in that row carries a marker or `(partial)`", md) def test_display_order_keeps_run_order_markers(self): # tests in run order crud, search, import: crud and search ran before import for leg in ("sqlite", "postgres"): - put_dir(self.root, leg, leg_files(leg, **{"indexing.txt": indexing(), - "bulk-import.txt": bulk_txt()})) + put_dir(self.root, leg, leg_files(leg, **{"bulk-import.txt": bulk_txt()})) md = render(self.root, ["sqlite", "postgres"], - tests="prewarm,crud,bulk-import,search,import,indexing") + tests="prewarm,crud,bulk-import,search,import") self.assertEqual(labels(md, "Throughput"), ["prewarm", "crud", IMPORT_ROW, BULK_ROW, INGEST_ROW, INDEX_ROW, - REINDEX_ROW, "search"]) + "search", SQL_ROW, SQL_ROWS_ROW]) for suite in ("crud", "search"): # shown after import, still marked as run before it self.assertTrue(row(md, "Throughput", suite).endswith("100 † |"), suite) - self.assertEqual(row(md, "Throughput", REINDEX_ROW), "| " + REINDEX_ROW + " | **1,200** | **1,200** |") def test_bulk_import_row_and_table(self): put_dir(self.root, "sqlite", leg_files("sqlite", **{"bulk-import.txt": bulk_txt()})) @@ -539,7 +411,7 @@ def test_bulk_phase_rows_deferred(self): "| " + INDEX_ROW + " | 1,800 s | **587 s** |") self.assertEqual(labels(md, "Throughput"), ["prewarm", IMPORT_ROW, BULK_ROW, INGEST_ROW, INDEX_ROW, - "crud", "search", INSERT_ROW]) + "crud", "search", SQL_ROW, SQL_ROWS_ROW, INSERT_ROW]) for heading in ("p95", "Errors"): self.assertNotIn(INGEST_ROW, labels(md, heading)) self.assertNotIn(INDEX_ROW, labels(md, heading)) @@ -556,7 +428,7 @@ def test_bulk_phase_rows_inline(self): "bulk-import.txt": bulk_txt(**inline)})) md = render(self.root, ["sqlite", "postgres"]) index = row(md, "Throughput", INDEX_ROW) - self.assertEqual(index, "| " + INDEX_ROW + " | 1,800 s | inline (during ingest) |") + self.assertEqual(index, "| " + INDEX_ROW + " | 1,800 s | 600 s (= ingest) |") self.assertNotIn("**", index) self.assertNotIn("**", row(md, "Throughput", INGEST_ROW)) # mixed: no best either self.assertEqual(row(md, "Throughput", BULK_ROW), "| " + BULK_ROW + " | 680 | **2,718** |") @@ -573,7 +445,7 @@ def test_bulk_phase_rows_inline(self): self.assertEqual(row(md, "Throughput", INGEST_ROW), "| " + INGEST_ROW + " | 2,000 (600 s) | **2,718** (600 s) |") self.assertEqual(row(md, "Throughput", INDEX_ROW), - "| " + INDEX_ROW + " | inline (during ingest) | inline (during ingest) |") + "| " + INDEX_ROW + " | 600 s (= ingest) | 600 s (= ingest) |") # indexing off in the ingest, but a follow-up rebuild of the types the index rejected rebuild = os.path.join(self.root, "rebuild") put_dir(rebuild, "sqlite", leg_files("sqlite", **{"bulk-import.txt": bulk_txt( @@ -585,6 +457,22 @@ def test_bulk_phase_rows_inline(self): self.assertIn("| inline (during ingest) + 12 s rebuild |", md.split("### Bulk import", 1)[1]) + def test_sql_run_rows(self): + for leg in ("sqlite", "postgres"): + put_dir(self.root, leg, leg_files(leg)) + md = render(self.root, ["sqlite", "postgres"]) + t = labels(md, "Throughput") + self.assertEqual(t[t.index("search"):t.index("search") + 3], + ["search", SQL_ROW, SQL_ROWS_ROW]) + self.assertLess(t.index(SQL_ROWS_ROW), t.index(INSERT_ROW)) + self.assertEqual(row(md, "Throughput", SQL_ROWS_ROW), "| " + SQL_ROWS_ROW + " | **2,500** | **2,500** |") + for heading in ("p95", "Errors"): + l = labels(md, heading) + self.assertLess(l.index("search"), l.index(SQL)) + self.assertLess(l.index(SQL), l.index("insert")) + self.assertNotIn(SQL_ROWS_ROW, labels(md, "p95")) + self.assertIn(cl.SQL_RUN_NOTE, md) + def test_bulk_phase_rows_na_and_markers(self): legs = ["sqlite", "postgres", "mongodb", "sqlite-elasticsearch", "postgres-elasticsearch", "mongodb-elasticsearch"] @@ -681,6 +569,32 @@ def test_never_raises(self): self.assertIn("Leg comparison failed", out.getvalue()) self.assertIn("::warning", err.getvalue()) + def _main_out(self, *args): + out = io.StringIO() + with contextlib.redirect_stdout(out), contextlib.redirect_stderr(io.StringIO()): + self.assertEqual(cl.main(["x", self.root] + list(args)), 0) + return out.getvalue() + + def test_timing_block(self): + self.two_legs() + base = self._main_out() + gone = os.path.join(self.root, "no-such-timing.md") + empty = os.path.join(self.root, "empty-timing.md") + open(empty, "w").close() + self.assertEqual(self._main_out("--timing", gone), base) + self.assertEqual(self._main_out("--timing", empty), base) + block = "\n### Run time\n\n| Phase | Seconds |\n|---|---|\n| total | 12 |\n" + path = os.path.join(self.root, "timing.md") + with open(path, "w", encoding="utf-8") as f: + f.write(block) + md = self._main_out("--timing", path) + self.assertEqual(md.count("### Run time"), 1) + head, rest = md.split("### Run time", 1) + self.assertIn("legs have results", head) + self.assertNotIn("###", head) + self.assertIn("| total | 12 |", rest.split("### Throughput", 1)[0]) + self.assertEqual(md.replace(block.strip("\n") + "\n\n", "", 1), base) + if __name__ == "__main__": unittest.main() diff --git a/.github/scripts/fhir-bench/test_history.py b/.github/scripts/fhir-bench/test_history.py new file mode 100644 index 0000000000..2c3f86eb27 --- /dev/null +++ b/.github/scripts/fhir-bench/test_history.py @@ -0,0 +1,237 @@ +import types +import unittest + +import history + +FIXTURE = """## FHIR Benchmark — leg comparison + +run 39657850695 · suites: all · 6 of 6 legs have results + +### Throughput (requests/s unless the row names its unit) + +| Suite | sqlite | postgres | mongodb | sqlite+ES | postgres+ES | mongodb+ES | +|---|---:|---:|---:|---:|---:|---:| +| prewarm | 1,475 | **1,867** | 1,232 | 90 | 102 | 97 | +| Batch/Transaction Import, `POST /` Bundles (resources/s) | 1,122 ‡ | 4,369 | 1,201 ‡ | 6,325 | 6,141 | 4,972 ‡ | +| Bulk Import, `$bulk-submit` (resources/s) | 1,122 | 1,042 | 620 | **3,057** | 2,565 | 1,638 | +| Bulk Import: ingest (resources/s, seconds) | 4,591 (355 s) | 3,196 (510 s) | 1,752 (930 s) | **7,409** (220 s) | 5,175 (315 s) | 2,527 (645 s) | +| Bulk Import: index rebuild (seconds) | 1,099 s | 1,054 s | 1,698 s | **313 s** | 321 s | 350 s | +| crud | 1,132 † | 2,175 | 1,539 † | 995 | 879 | 875 † | +| search | 4 † | 2,186 | 22 † | 920 | 869 | 1,081 † | +| insert (creates/s) | 827 | **1,425** | 1,167 | 267 | 263 | 261 | + +### p95 latency (ms) + +| Suite | sqlite | postgres | mongodb | sqlite+ES | postgres+ES | mongodb+ES | +|---|---:|---:|---:|---:|---:|---:| +| prewarm | 20.6 | **11.6** | 19.9 | 292.3 | 287.7 | 304.3 | +| Bulk Import, `$bulk-submit` | n/a (one async job) | n/a (one async job) | n/a (one async job) | n/a (one async job) | n/a (one async job) | n/a (one async job) | +| crud | 902.2 † | 290.0 | 380.0 † | 749.2 | 798.6 | 825.6 † | + +### Errors (Err% · failed checks) + +| Suite | sqlite | +|---|---:| +| crud | 0.0% | +""" + + +def run(n, date="2026-10-0%d", branch="feat"): + return {"id": 1000 + n, "number": n, "date": date % n, "branch": branch, + "url": f"https://example/runs/{1000 + n}"} + + +def args(**kw): + d = dict(repo="o/r", workflow="w.yml", branch="feat", run_id="999", + artifact_name="a", max_runs=5) + d.update(kw) + d["artifact_name"] = d.get("artifact_name") + return types.SimpleNamespace(**d) + + +def scaled(k): + # scale every number in the throughput table by k via crude replace + return FIXTURE.replace("| crud | 1,132 † |", f"| crud | {int(1132 * k):,} † |") + + +class T(unittest.TestCase): + def test_parse_cells(self): + p = history.parse_cell + self.assertEqual(p("1,122 ‡"), 1122.0) + self.assertEqual(p("**3,057**"), 3057.0) + self.assertEqual(p("4 †"), 4.0) + self.assertEqual(p("4,591 (355 s)"), 4591.0) + self.assertEqual(p("1,099 s"), 1099.0) + self.assertIsNone(p("n/a (one async job)")) + self.assertIsNone(p("")) + + def test_parse_tables(self): + t = history.parse_tables(FIXTURE) + self.assertEqual(len(t["throughput"]["legs"]), 6) + self.assertEqual(len(t["throughput"]["rows"]), 8) + self.assertEqual(t["throughput"]["rows"][1][1][0], 1122.0) + self.assertIn("p95", t) + self.assertIsNone(t["p95"]["rows"][1][1][0]) + + def _fetch(self, missing=()): + def fr(*a): + return [run(i) for i in (1, 2, 3)] + + def fc(repo, r, name): + if r["number"] in missing: + return None + return scaled(r["number"]) + return fr, fc + + def test_missing_artifact_skipped(self): + fr, fc = self._fetch(missing=(1, 2)) + out = history.build(args(), fr, fc, FIXTURE) + self.assertIn("Progress over the last 2 runs", out) + self.assertNotIn("#1,", out) + + def test_fewer_than_two(self): + fr, fc = self._fetch(missing=(1, 2, 3)) + out = history.build(args(), fr, fc, None) + self.assertIn("fewer than 2", out) + self.assertNotIn("
", out) + out = history.build(args(), lambda *a: [], fc, FIXTURE) + self.assertIn("fewer than 2", out) + + def test_fetch_errors_swallowed(self): + def boom(*a): + raise RuntimeError("net") + out = history.build(args(), boom, boom, FIXTURE) + self.assertIn("fewer than 2", out) + fr, _ = self._fetch() + out = history.build(args(), fr, boom, FIXTURE) + self.assertIn("fewer than 2", out) + + def test_charts_capped_and_shape(self): + fr, fc = self._fetch() + out = history.build(args(), fr, fc, FIXTURE) + n = out.count("```mermaid") + self.assertTrue(1 <= n <= history.MAX_CHARTS) + self.assertEqual(n, 5) # prewarm, sub-row and seconds row excluded + self.assertIn("xychart-beta", out) + self.assertNotIn('title "prewarm', out) + self.assertIn("(+", out) # change vs previous run + self.assertLess(len(out.encode()), history.MAX_BYTES) + + def test_chart_cap_many_rows(self): + rows = "\n".join(f"| row{i} | {i + 1} | {i + 2} |" for i in range(12)) + md = "### Throughput\n\n| Suite | a | b |\n|---|---:|---:|\n" + rows + "\n" + out = history.build(args(), lambda *a: [run(1), run(2)], + lambda *a: md, md) + self.assertEqual(out.count("```mermaid"), history.MAX_CHARTS) + + def test_deterministic(self): + fr, fc = self._fetch() + a = history.build(args(), fr, fc, FIXTURE) + b = history.build(args(), fr, fc, FIXTURE) + self.assertEqual(a, b) + + def test_artifact_name_gets_run_id_suffix(self): + import unittest.mock as m + calls = [] + + def fake(a): + calls.append(a) + return types.SimpleNamespace(returncode=1, stdout="", stderr="") + with m.patch.object(history, "_gh", fake): + self.assertIsNone(history.fetch_comparison("o/r", run(7), "pre")) + self.assertIn("pre-1007", calls[0]) + self.assertIn("1007", calls[0]) + + def test_alias_join_and_cell(self): + old = FIXTURE + new = FIXTURE.replace( + "Batch/Transaction Import, `POST /` Bundles (resources/s)", history.NEW_BATCH + ).replace("| Bulk Import: index rebuild (seconds) | 1,099 s", + "| ↳ search indexing (seconds) | 195 s (= ingest)") + t = history.parse_tables(old)["throughput"]["rows"] + self.assertIn(history.NEW_BATCH, [r[0] for r in t]) + self.assertIn(history.OLD_REBUILD, [r[0] for r in t]) + self.assertNotIn(history.NEW_INDEX, [r[0] for r in t]) + self.assertEqual(history.parse_cell("195 s (= ingest)"), 195.0) + runs = [run(1), run(2)] + out = history.build(args(), lambda *a: runs, + lambda repo, r, n: old if r["number"] == 1 else new, new) + self.assertEqual(out.count("**" + history.NEW_BATCH + "**"), 1) + self.assertNotIn("Bundles (resources/s)**\n\n| Leg" + "x", out) + self.assertNotIn("**Batch/Transaction Import, `POST", out) + self.assertIn("1,122 (", out) + # old rebuild row and new indexing row stay separate: no delta across them + self.assertIn("**" + history.OLD_REBUILD + "**", out) + self.assertIn("**" + history.NEW_INDEX + "**", out) + sec = out.split("**" + history.NEW_INDEX + "**")[1].split("**")[0] + self.assertIn("| `sqlite` | – | 195 | 195 (+0%) |", sec) # delta only new vs new + self.assertNotIn("1,099", sec) + + def test_pct_sign_and_missing(self): + self.assertEqual(history.pct(100, 80), "-20%") # seconds: lower is better + self.assertEqual(history.pct(None, 5), "") + self.assertEqual(history.pct(0, 5), "") + + def test_truncation_keeps_fences_balanced(self): + secs = ["head"] + ["```mermaid\nx\n```\n" + "y" * 300 for _ in range(50)] + text = history._finish(secs, max_bytes=3000) + self.assertEqual(text.count("```") % 2, 0) + self.assertIn("output cut", text) + self.assertTrue(text.rstrip().endswith("
")) + self.assertLess(len(text.encode()), 3000) + self.assertTrue(history._finish(["```a", "b"]).count("```") % 2 == 0) + + def test_failed_run_with_artifact_included(self): + import unittest.mock as m + payload = {"workflow_runs": [ + {"id": 5, "conclusion": "failure", "head_branch": "feat"}, + {"id": 6, "conclusion": "cancelled", "head_branch": "feat"}, + {"id": 7, "conclusion": "success", "head_branch": "feat"}]} + fake = lambda a: types.SimpleNamespace(returncode=0, stdout=__import__("json").dumps(payload)) + with m.patch.object(history, "_gh", fake): + got = history._list_runs("o/r", "w.yml", "feat", 5) + self.assertEqual([x["id"] for x in got], [5, 7]) + + def test_suites_mismatch_skipped_unparseable_kept(self): + other = FIXTURE.replace("suites: all", "suites: crud") + fr = lambda *a: [run(1), run(2, branch="main"), run(3)] + fc = lambda repo, r, n: other if r["number"] != 3 else FIXTURE + out = history.build(args(), fr, fc, FIXTURE) + self.assertIn("last 3 runs", out) # run 1 skipped, main kept, 3 + current + nohdr = FIXTURE.replace("suites: all", "") + out = history.build(args(), lambda *a: [run(1)], lambda *a: other, nohdr) + self.assertIn("last 2 runs", out) + + def test_data_dir_downloads_each_run(self): + calls = [] + fr, fc = self._fetch() + history.build(args(data_dir="D"), fr, fc, FIXTURE, + lambda repo, r, d: calls.append((r["id"], d))) + self.assertEqual(calls, [(1001, "D"), (1002, "D"), (1003, "D")]) + + def test_single_series_chart_shape(self): + fr, fc = self._fetch() + out = history.build(args(), fr, fc, FIXTURE) + self.assertNotIn("Lines in order", out) + self.assertEqual(out.count(" line ["), out.count("```mermaid")) + self.assertIn('title "crud - sqlite"', out) + c = history.render_chart("r", "leg", [1.0, None], ["a", "b"]) + self.assertEqual(c, "") + + def test_main_exit_zero(self): + self.assertEqual(history.main(["--bogus"]), 0) + + + +class YAxisUnit(unittest.TestCase): + def test_unit_from_row_label(self): + for lab, u in (("Batch/Transaction Import (`/ui/batch`: `POST /` Bundles) (resources/s)", "resources/s"), + ("insert (creates/s)", "creates/s"), ("crud", "requests/s"), + ("x (seconds)", "seconds")): + c = history.render_chart(lab, "sqlite", [1.0, 2.0], ["#1", "#2"]) + self.assertIn('y-axis "%s"' % u, c) + self.assertNotIn('y-axis "value"', c) + self.assertNotIn("`", c.split("title")[1].split("\n")[0]) + +if __name__ == "__main__": + unittest.main() diff --git a/.github/scripts/fhir-bench/test_md_charts.py b/.github/scripts/fhir-bench/test_md_charts.py new file mode 100644 index 0000000000..3321861884 --- /dev/null +++ b/.github/scripts/fhir-bench/test_md_charts.py @@ -0,0 +1,378 @@ +"""Tests for md_charts.py (stdlib unittest): python3 -m unittest -q test_md_charts""" +import contextlib +import io +import os +import re +import tempfile +import unittest + +import md_charts as mc + +# Trimmed from the real comparison.md of run 40335047310 (one leg, Elasticsearch: indexing +# runs during ingest). +ONE_LEG = """## FHIR Benchmark — `tmp/bench-steve-ci-test` (leg comparison) + +Commit `a4f41e7` · run 40335047310 · suites: all · 1 of 1 legs have results + +### Throughput (requests/s unless the row names its unit) + +| Suite | postgres+ES | +|---|---:| +| prewarm | 100 | +| Batch/Transaction Import (`/ui/batch`: `POST /` Bundles) (resources/s) | 6,178 | +| Bulk Import (`/ui/bulk-import`: `$bulk-submit`, until searchable) (resources/s) | 7,758 | +| ↳ ingest, until Completed (resources/s, seconds) | 7,758 (210 s) | +| ↳ search indexing (seconds) | 210 s (= ingest) | +| crud | 961 | +| search | 948 | +| SQL-on-FHIR `$sql-run` (requests/s) | 160 | +| SQL-on-FHIR `$sql-run` (rows/s) | 419,202 | +| insert (creates/s) | 259 | + +### p95 latency (ms) + +| Suite | postgres+ES | +|---|---:| +| prewarm | 286.8 | +| Batch/Transaction Import (`/ui/batch`: `POST /` Bundles) (per Bundle) | 11064.5 | +| Bulk Import (`/ui/bulk-import`: `$bulk-submit`) | n/a (one async job) | +| crud | 697.4 | +| search | 68.0 | +| SQL-on-FHIR `$sql-run` | 88.2 | +| insert | 248.7 | + +### Errors (Err% · failed checks) + +| Suite | postgres+ES | +|---|---:| +| prewarm | 0.0% | + +`†` crud/search ran on an incomplete corpus · `‡` more than 1% errors + +### Bulk import (`$bulk-submit`) + +| Leg | Result | Resources ingested | Ingest | Index | Total | Search check | +|---|---|---:|---:|---:|---:|---| +| `postgres-elasticsearch` | ✓ | 1,630,685/1,630,685 | 210 s · 7,758/s | inline (during ingest) | 210 s | ✓ Patient 1,000 | + +_Per-leg detail is in each `Benchmark ()` job summary._ +""" + +SIX = ["sqlite", "postgres", "mongodb", "sqlite+ES", "postgres+ES", "mongodb+ES"] + + +def many(legs, rebuild_for=("sqlite", "postgres", "mongodb"), marks=True): + """A comparison with one column per leg; non-ES legs have a real deferred rebuild.""" + n = len(legs) + + def row(label, f): + return "| %s | %s |" % (label, " | ".join(f(i, l) for i, l in enumerate(legs))) + + head = "| Suite | %s |\n|---|%s\n" % (" | ".join(legs), "---:|" * n) + mark = lambda i: " †" if marks and i == 1 else "" + thr = [ + row("prewarm", lambda i, l: "%d" % (100 + i)), + row("Batch/Transaction Import (`/ui/batch`: `POST /` Bundles) (resources/s)", + lambda i, l: "**%s**" % format(6000 + 100 * i, ",") if i == 0 else format(6000 + 100 * i, ",") + mark(i)), + row("Bulk Import (`/ui/bulk-import`: `$bulk-submit`, until searchable) (resources/s)", + lambda i, l: format(1000 * (i + 1), ",")), + row("↳ ingest, until Completed (resources/s, seconds)", + lambda i, l: "%s (%d s)" % (format(1000 * (i + 1), ","), 200 + i)), + row("↳ search indexing (seconds)", + lambda i, l: ("%d s" % (60 + i)) if l in rebuild_for else "%d s (= ingest)" % (200 + i)), + row("crud", lambda i, l: "n/a (no results)" if i == 2 else format(900 + i, ",")), + row("SQL-on-FHIR `$sql-run` (requests/s)", lambda i, l: "%d" % (160 + i)), + row("SQL-on-FHIR `$sql-run` (rows/s)", lambda i, l: format(419202 + i, ",")), + ] + p95 = [ + row("crud", lambda i, l: "%.1f" % (600 + i)), + row("Bulk Import (`/ui/bulk-import`: `$bulk-submit`)", lambda i, l: "n/a (one async job)"), + ] + return ("## FHIR Benchmark — `main` (leg comparison)\n\n### Throughput (requests/s unless the row names its unit)\n\n" + + head + "\n".join(thr) + "\n\n### p95 latency (ms)\n\n" + head + "\n".join(p95) + + "\n\n### Bulk import (`$bulk-submit`)\n\n| Leg | Result | Resources ingested | Ingest | Index | Total | Search check |\n" + "|---|---|---:|---:|---:|---:|---|\n" + + "\n".join("| `%s` | ✓ | 1/1 | 210 s · 7,758/s | inline (during ingest) | 210 s | ✓ |" % l for l in legs) + + "\n\nfooter text\n") + + +LEG_BOX = """### Postgres tuning (postgres) + +| setting | value | +|---|---| +| shared_buffers | `2GB` | + +## FHIR Benchmark — `main` (postgres) + +| | | +|---|---| +| **Commit** | `e0bd5cb` | + +### Results + +| Suite | Throughput | p50 ms | p95 ms | p99 ms | Err% | Checks ✓/✗ | +|-------|----:|-------:|-------:|-------:|-----:|-----------:| +| crud | 2,175 | 122.7 | 290.0 | 415.7 | 0.0% | 526,680/0 | +| Batch/Transaction Import (`/ui/batch`: `POST /` Bundles) (resources/s; latency per Bundle) | 4,369 | 2673.3 | 26629.8 | 66378.2 | 0.0% | 1,000/0 | +| Bulk Import (`/ui/bulk-import`: `$bulk-submit`, until searchable) (resources/s) | 1,042 | n/a | n/a | n/a | 0.0% | 1,630,685/0 | +| insert | 1,425 | 31.9 | 57.7 | 102.9 | 0.0% | 171,220/0 | +| search | 2,186 | 7.7 | 40.4 | 114.4 | 0.0% | 262,872/0 | + +_Throughput is requests/s._ +""" + + +def run_cli(*args): + out = io.StringIO() + with contextlib.redirect_stdout(out), contextlib.redirect_stderr(io.StringIO()): + rc = mc.main(list(args)) + return rc, out.getvalue() + + +def write(d, name, text): + p = os.path.join(d, name) + with open(p, "w", encoding="utf-8") as fh: + fh.write(text) + return p + + +def mermaid_blocks(text): + return re.findall(r"```mermaid\n(.*?)```", text, re.S) + + +class Compare(unittest.TestCase): + def setUp(self): + self.tmp = tempfile.TemporaryDirectory() + self.addCleanup(self.tmp.cleanup) + + def compare(self, text, layout="sidebyside"): + p = write(self.tmp.name, "comparison.md", text) + rc, out = run_cli("compare", "--in", p, "--layout", layout) + self.assertEqual(rc, 0) + return out + + def test_one_leg_sections_and_charts(self): + out = self.compare(ONE_LEG) + self.assertTrue(out.startswith("\n### Charts\n")) + self.assertIn("
Chart: throughput by leg", out) + self.assertIn("", out) + titles = re.findall(r"^\*\*(.+)\*\*$", out, re.M) + for want in ("prewarm (requests/s)", "Batch/Transaction Import (resources/s)", + "Bulk Import (resources/s)", "Bulk Import ingest (resources/s, seconds)", + "Bulk Import search indexing (seconds)", "SQL-on-FHIR sql-run (requests/s)", + "SQL-on-FHIR sql-run (rows/s)", "insert (creates/s)", + "Batch/Transaction Import p95 (ms)", "crud p95 (ms)"): + self.assertIn(want, titles) + self.assertNotIn("Errors", out) + self.assertNotIn("Bulk Import p95 (ms)", titles) # n/a: one async job + for t in titles: + self.assertNotRegex(t, r"[`$]") + + def test_numbers_parse_through_markers_and_commas(self): + out = self.compare(ONE_LEG) + self.assertIn('"postgres+ES · 419,202"', out) + self.assertIn("bar [419202]", out) + self.assertIn("bar [7758]", out) # "7,758 (210 s)" on the ingest row + self.assertIn("bar [11064.5]", out) + + def test_inline_indexing_has_no_rebuild_phase(self): + out = self.compare(ONE_LEG) + gantts = [b for b in mermaid_blocks(out) if b.split("\n", 2)[1].startswith("gantt")] + self.assertEqual(len(gantts), 1) + self.assertIn("ingest 210 s", gantts[0]) + self.assertNotIn("rebuild", gantts[0]) + self.assertNotIn("rebuild", out.lower().replace("search indexing", "")) + self.assertNotIn("deferred", out) + + def test_old_wording_bulk_table_fallback(self): + old = ONE_LEG.replace("| ↳ ingest, until Completed (resources/s, seconds) | 7,758 (210 s) |\n", "") \ + .replace("| ↳ search indexing (seconds) | 210 s (= ingest) |\n", "") + out = self.compare(old) + self.assertIn("Bulk Import phases by leg", out) + self.assertIn("values in the Bulk import table above", out) + + def test_six_legs_colours_and_rebuild_only_where_real(self): + out = self.compare(many(SIX)) + pal = re.findall(r'"plotColorPalette": "([^"]+)"', out) + self.assertTrue(any(len(p.split(", ")) == 6 for p in pal)) + known = mc.leg_colours(SIX) + for p in pal: + for c in p.split(", "): + self.assertIn(c, known.values()) + g = [b for b in mermaid_blocks(out) if "gantt" in b.split("\n")[1:3][0]][0] + for leg in ("sqlite", "postgres", "mongodb"): + self.assertRegex(g, r"section %s\n ingest \d+ s :i\d+, [^\n]+\n rebuild" % re.escape(leg)) + for leg in ("sqlite+ES", "postgres+ES", "mongodb+ES"): + self.assertRegex(g, r"section %s\n ingest \d+ s :i\d+, [^\n]+\n( section|\Z)" % re.escape(leg)) + self.assertEqual(g.count("rebuild"), 3) + self.assertIn("Bulk Import: ingest until Completed, then search-index rebuild", out) + + def test_n_a_cell_gives_zero_bar_but_keeps_label(self): + out = self.compare(many(SIX)) + self.assertIn("mongodb · n/a (no results)", out) + + def test_each_bar_has_its_own_series_and_colour(self): + out = self.compare(many(SIX)) + blk = [b for b in mermaid_blocks(out) if '"crud' not in b and "x-axis" in b][0] + self.assertEqual(blk.count(" bar ["), 6) + + def test_more_than_six_legs_get_colours(self): + legs = ["leg%d" % i for i in range(1, 13)] + cols = mc.leg_colours(legs) + self.assertEqual(len(cols), 12) + self.assertTrue(all(re.match(r"^#[0-9a-f]{6}$", c) for c in cols.values())) + self.assertEqual(len(set(list(cols.values())[:len(mc.EXTRA)])), len(mc.EXTRA)) + self.assertEqual(mc.leg_colours(["leg3"])["leg3"], mc.leg_colours(["leg3", "leg9"])["leg3"]) + out = self.compare(many(legs, rebuild_for=())) + self.assertTrue(any(len(p.split(", ")) == 12 for p in re.findall(r'"plotColorPalette": "([^"]+)"', out))) + + def test_known_legs_keep_prototype_colours_for_short_labels(self): + c = mc.leg_colours(["postgres+ES", "sqlite", "mongodb-elasticsearch"]) + self.assertEqual(c["postgres+ES"], "#4a91f8") + self.assertEqual(c["sqlite"], "#008622") + self.assertEqual(c["mongodb-elasticsearch"], "#b96dd8") + + def test_prefix_invariant(self): + for text in (ONE_LEG, many(SIX), many(SIX[:2]), ONE_LEG.rstrip("\n")): + out = self.compare(text) + self.assertTrue(out) + self.assertTrue((text + out).startswith(text)) + self.assertEqual((text + out)[:len(text)].encode(), text.encode()) + self.assertTrue(out.startswith("\n")) # a blank line separates it from the report text + + def test_stacked_layout_has_no_table(self): + out = self.compare(ONE_LEG, "stacked") + self.assertNotIn("
", out) + self.assertIn("```mermaid", out) + + def test_no_backticks_or_dollars_in_mermaid(self): + for b in mermaid_blocks(self.compare(many(SIX))): + self.assertNotIn("`", b) + self.assertNotIn("$", b) + + +class Leg(unittest.TestCase): + def setUp(self): + self.tmp = tempfile.TemporaryDirectory() + self.addCleanup(self.tmp.cleanup) + self.d = os.path.join(self.tmp.name, "bench-results") + os.makedirs(self.d) + write(self.d, "host-contention.txt", + "14:11:46Z suite=prewarm phase=start host_loadavg=0.9\n14:12:21Z suite=prewarm phase=end x\n" + "23:59:00Z suite=crud phase=start x\n00:03:00Z suite=crud phase=end x\n") + + def leg(self, box_text, leg="postgres", bulk=None): + if bulk is not None: + write(self.d, "bulk-import.txt", bulk) + box = write(self.tmp.name, "box.md", box_text) + rc, out = run_cli("leg", "--box", box, "--leg", leg, "--run-dir", self.d, "--layout", "sidebyside") + self.assertEqual(rc, 0) + return out + + def test_leg_charts_and_header_not_first(self): + out = self.leg(LEG_BOX) + self.assertTrue(out.startswith("\n### Charts\n")) + self.assertIn("postgres: k6 suites throughput (requests/s)", out) + self.assertIn("postgres: Import throughput (resources/s)", out) + self.assertIn("postgres: latency per suite (ms)", out) + self.assertIn("bar [2175, 1425, 2186]", out) + self.assertIn('"plotColorPalette": "#236bcf"', out) + self.assertIn("section Suites", out) + self.assertIn("2000-01-02 00:03:00", out) # crossed midnight UTC + + def test_leg_prefix_invariant(self): + out = self.leg(LEG_BOX) + self.assertTrue((LEG_BOX + out).startswith(LEG_BOX)) + + def test_leg_inline_vs_rebuild(self): + inline = self.leg(LEG_BOX, bulk="ingest_seconds=210.2\nindex_status=inline\nindex_seconds=0\n") + g = [b for b in mermaid_blocks(inline) if "ingest 210 s" in b][0] + self.assertNotIn("rebuild", g) + real = self.leg(LEG_BOX, bulk="ingest_seconds=210.2\nindex_status=completed\nindex_seconds=120.4\n") + g = [b for b in mermaid_blocks(real) if "ingest 210 s" in b][0] + self.assertIn("rebuild 120 s", g) + + def test_leg_bulk_status_and_index_status(self): + for st in ("timeout", "error", "incomplete"): + out = self.leg(LEG_BOX, bulk="status=%s\ningest_seconds=210.2\nindex_status=completed\nindex_seconds=9\n" % st) + self.assertFalse([b for b in mermaid_blocks(out) if "ingest " in b], st) + out = self.leg(LEG_BOX, bulk="status=complete\ningest_seconds=210.2\nindex_status=error\nindex_seconds=9\n") + g = [b for b in mermaid_blocks(out) if "ingest 210 s" in b][0] + self.assertNotIn("rebuild", g) + + def test_gantt_axis_has_units(self): + out = self.leg(LEG_BOX, bulk="status=complete\ningest_seconds=210.2\nindex_status=completed\nindex_seconds=120\n") + g = [b for b in mermaid_blocks(out) if "ingest 210 s" in b][0] + self.assertIn("axisFormat %Mm %Ss", g) + self.assertIn("bulk-import.txt", out) + long = self.leg(LEG_BOX, bulk="status=complete\ningest_seconds=5000\nindex_status=completed\nindex_seconds=900\n") + self.assertIn("axisFormat %Hh %Mm", [b for b in mermaid_blocks(long) if "ingest 5000 s" in b][0]) + + def test_na_in_box_is_not_plotted(self): + box = LEG_BOX.replace("| insert | 1,425 |", "| insert | n/a |") + out = self.leg(box) + self.assertNotIn("insert", "".join(b for b in mermaid_blocks(out) if "k6 suites" in out and "2175" in b)) + self.assertIn("bar [2175, 2186]", out) + + def test_compare_skips_na_bulk_leg(self): + txt = many(["sqlite", "postgres"]).replace( + "(`/ui/bulk-import`: `$bulk-submit`, until searchable) (resources/s) | 1,000 | 2,000 |", + "(`/ui/bulk-import`: `$bulk-submit`, until searchable) (resources/s) | 1,000 | n/a (timeout) |") + self.assertIn("n/a (timeout)", txt) + g = [b for b in mermaid_blocks("\n".join(mc.compare_section(txt.split("\n"), "stacked"))) if "ingest " in b][0] + self.assertIn("section sqlite", g) + self.assertNotIn("section postgres", g) + both = txt.replace("| 1,000 | n/a (timeout) |", "| n/a (x) | n/a (timeout) |") + self.assertFalse([b for b in mermaid_blocks("\n".join(mc.compare_section(both.split("\n"), "stacked"))) if "ingest " in b]) + + def test_missing_files_still_charts_from_table(self): + out = self.leg(LEG_BOX) + self.assertIn("throughput and latency", out) + empty = os.path.join(self.tmp.name, "nothing") + box = write(self.tmp.name, "b2.md", LEG_BOX) + rc, out = run_cli("leg", "--box", box, "--leg", "postgres", "--run-dir", empty) + self.assertEqual(rc, 0) + self.assertIn("throughput and latency", out) + + +class Robust(unittest.TestCase): + GARBAGE = ["", "\n", "garbage", "### Throughput\n| a |\n", "### Throughput\n\n| Suite | x |\n|---|\n| a |\n", + "### Throughput\n\n| Suite | a | b |\n|---|---|---|\n| row | ** | †⚠ |\n| | | |\n", + "### p95 latency (ms)\n\n| Suite |\n|---|\n| crud |\n", "\x00\xff||||\n|--|\n", + "### Bulk import\n\n| Leg |\n|---|\n| `x` |\n", "### Results\n\n| Suite |\n|---|\n| crud |\n"] + + def test_never_raises_on_garbage(self): + with tempfile.TemporaryDirectory() as t: + for g in self.GARBAGE: + p = write(t, "g.md", g) + for args in (("compare", "--in", p), ("leg", "--box", p, "--leg", "x", "--run-dir", t)): + rc, out = run_cli(*args) + self.assertEqual(rc, 0) + self.assertLess(len(out), 2000, out[:200]) + + def test_missing_files_and_bad_args_exit_zero(self): + for args in (("compare", "--in", "/nonexistent/x.md"), + ("leg", "--box", "/nonexistent", "--leg", "a", "--run-dir", "/nonexistent"), + ("bogus",), ("compare",), ()): + rc, out = run_cli(*args) + self.assertEqual(rc, 0) + self.assertLess(len(out), 200) + + def test_binary_file(self): + with tempfile.TemporaryDirectory() as t: + p = os.path.join(t, "b.md") + with open(p, "wb") as fh: + fh.write(bytes(range(256)) * 20) + self.assertEqual(run_cli("compare", "--in", p)[0], 0) + + def test_num_parsing(self): + self.assertEqual(mc.num("**1,042** †"), 1042) + self.assertEqual(mc.num("⚠ 7,758 (210 s)"), 7758) + self.assertEqual(mc.num("0.0%"), 0.0) + self.assertIsNone(mc.num("n/a (one async job)")) + self.assertIsNone(mc.num("inline (during ingest)")) + self.assertEqual(mc.num("210 s (= ingest)"), 210) + + +if __name__ == "__main__": + unittest.main() diff --git a/.github/scripts/fhir-bench/test_report_html.py b/.github/scripts/fhir-bench/test_report_html.py new file mode 100644 index 0000000000..57b56357a6 --- /dev/null +++ b/.github/scripts/fhir-bench/test_report_html.py @@ -0,0 +1,358 @@ +"""Tests of report_html.py (python3 -m unittest -q test_report_html, from this folder).""" +import json +import os +import re +import subprocess +import sys +import tempfile +import unittest + +HERE = os.path.dirname(os.path.abspath(__file__)) +SCRIPT = os.path.join(HERE, "report_html.py") +REAL = os.environ.get("FHIR_BENCH_REAL_RUN_DIR", "") + + +def k6(rps=100.0, extra=None): + m = {"http_reqs": {"count": 1000, "rate": rps}, + "http_req_failed": {"value": 0.0}, + "http_req_duration": {"med": 10.0, "p(95)": 40.0, "p(99)": 80.0, "max": 120.0}, + "iteration_duration": {"med": 500.0, "p(95)": 900.0, "p(99)": 1200.0, "max": 1500.0}, + "checks": {"passes": 1000, "fails": 0}, "vus_max": {"max": 10}} + m.update(extra or {}) + return json.dumps({"metrics": m}) + + +def put(d, name, text): + os.makedirs(d, exist_ok=True) + with open(os.path.join(d, name), "w", encoding="utf-8") as fh: + fh.write(text) + + +def make_leg(root, leg, es): + d = os.path.join(root, "fhir-benchmark-%s-777" % leg, leg) + put(d, "runner-info.txt", "runner_name: r1\nrunner_cpus: 8\nrunner_ram: 16G\ngithub_run: 777\n" + "git_sha: abcdef1234567\ngit_ref: feature/x\n") + for s in ("prewarm", "import", "crud", "search", "insert"): + put(d, s + ".json", k6()) + views = {} + for v in ("claim", "eob"): + views["http_req_duration{view:%s}" % v] = {"med": 20.0, "p(95)": 50.0, "p(99)": 70.0, "max": 90.0, "count": 5} + views["sql_run_rows"] = {"count": 5000, "rate": 1234.5} + put(d, "sql-run.json", k6(160.0, views)) + put(d, "import-completeness.txt", "bundles_ok=1000\nentries=100000\nscenario_seconds=100\nsetup_seconds=50\nwall_seconds=160\n") + put(d, "bulk-import.txt", "status=complete\nphase=done\nconvert_seconds=40\ningest_seconds=200\n" + "index_status=%s\nindex_seconds=%s\ntotal_seconds=200\nresources_per_s=5000\n" + "ingest_resources_per_s=5000\nresources_ok=1000\nresources_submitted=1000\nresources_failed=0\nsearchable=yes\n" + % (("inline", "0.0") if es else ("deferred", "35.5"))) + put(d, "containers-state.txt", "hfs-bench-%s-1 Status=running OOMKilled=false\n" % leg) + put(d, "host-contention.txt", + "10:00:00Z suite=import phase=start host_loadavg=1.0 0.5 0.2 host_containers=3 host_mem_avail_mb=9000\n" + "10:05:00Z suite=import phase=end host_loadavg=4.0 2.0 1.0 host_containers=3 host_mem_avail_mb=8000\n") + if es: + put(d, "es-drain.txt", "status=drained\nmissing=0\nsync_mode=synchronous\n") + return d + + +def run(args): + return subprocess.run([sys.executable, "-I", SCRIPT] + args, capture_output=True, text=True, timeout=300) + + +class SyntheticRun(unittest.TestCase): + @classmethod + def setUpClass(cls): + cls.tmp = tempfile.TemporaryDirectory() + t = cls.tmp.name + make_leg(t, "sqlite", False) + make_leg(t, "sqlite-elasticsearch", True) + make_leg(t, "weird-backend", False) # not a known leg: must still be discovered + cls.out, cls.dump = os.path.join(t, "r.html"), os.path.join(t, "d.json") + cls.p = run(["--run-dir", t, "--run-id", "777", "--repo", "o/r", "--branch", "feature/x", + "--sha", "abcdef1234567", "--out", cls.out, "--dump-json", cls.dump, "--no-shapes"]) + with open(cls.out, encoding="utf-8") as fh: + cls.html = fh.read() + with open(cls.dump, encoding="utf-8") as fh: + cls.data = json.load(fh) + + @classmethod + def tearDownClass(cls): + cls.tmp.cleanup() + + def test_exit_and_valid_page(self): + self.assertEqual(self.p.returncode, 0, self.p.stderr) + self.assertTrue(self.html.startswith("")) + self.assertTrue(self.html.rstrip().endswith("")) + self.assertNotIn("/*__DATA__*/", self.html) + self.assertNotRegex(self.html, r"(src|href)=\"https?://(?!github\.com)") + + def test_embedded_json_parses(self): + m = re.search(r"const D = (\{.*?\});\nconst LEGS", self.html, re.S) + self.assertIsNotNone(m) + d = json.loads(m.group(1).replace("<\\/", "")[-1].split("const D =")[0]) + + def test_dump_is_slim_and_trend_needs_no_history(self): + pt = self.data["legs"]["sqlite"]["point"] + self.assertIn("sql_rows", pt["suites"]) + self.assertNotIn("shapes", self.data["legs"]["sqlite"]) + self.assertEqual(self.data["history_runs"], 0) + + +class MissingInputs(unittest.TestCase): + def build(self, mutate, vus=None): + tmp = tempfile.TemporaryDirectory() + self.addCleanup(tmp.cleanup) + d = make_leg(tmp.name, "sqlite", False) + mutate(d) + out, dump = os.path.join(tmp.name, "r.html"), os.path.join(tmp.name, "d.json") + p = run(["--run-dir", tmp.name, "--run-id", "777", "--out", out, "--dump-json", dump, "--no-shapes"]) + self.assertEqual(p.returncode, 0, p.stderr) + with open(out, encoding="utf-8") as fh: + html = fh.read() + with open(dump, encoding="utf-8") as fh: + return html, json.load(fh) + + def leg(self, data): + return data["legs"]["sqlite"] + + def test_missing_checks_is_na_not_ok(self): + def m(d): + put(d, "crud.json", json.dumps({"metrics": {k: v for k, v in json.loads(k6())["metrics"].items() if k != "checks"}})) + _, data = self.build(m) + self.assertIsNone(self.leg(data)["suites"]["crud"]["fail"]) + st, txt = self.leg(data)["checks"]["err"] + self.assertEqual(st, "na") + self.assertIn("n/a", txt) + self.assertNotEqual(txt, "0 %") + + def test_missing_resources_failed_is_na(self): + def m(d): + p = os.path.join(d, "bulk-import.txt") + with open(p) as fh: + t = fh.read().replace("resources_failed=0\n", "") + put(d, "bulk-import.txt", t) + _, data = self.build(m) + self.assertIsNone(self.leg(data)["bulk"]["failed"]) + self.assertEqual(self.leg(data)["checks"]["err"][0], "na") + + def test_measured_zero_checks_stay_ok(self): + _, data = self.build(lambda d: None) + self.assertEqual(self.leg(data)["suites"]["crud"]["fail"], 0) + self.assertEqual(self.leg(data)["checks"]["err"], ["ok", "0 %"]) + + def test_no_host_contention_no_fake_midnight(self): + _, data = self.build(lambda d: os.remove(os.path.join(d, "host-contention.txt"))) + self.assertIsNone(self.leg(data)["start"]) + self.assertIsNone(data["date"]) + html, _ = self.build(lambda d: os.remove(os.path.join(d, "host-contention.txt"))) + self.assertNotIn("T00:00:00Z", html) + self.assertIn('D.date?fdate(D.date,true):"unknown"', html) + + def test_prose_numbers_not_literals(self): + html, data = self.build(lambda d: put(d, "import.json", k6(extra={"vus_max": {"max": 37}}))) + self.assertEqual(self.leg(data)["suites"]["import"]["vus"], 37) + for lit in ("out of 1,000", "20 concurrent", "300 VUs"): + self.assertNotIn(lit, html) + self.assertIn('id="proseImpVus"', html) + self.assertIn("sv(\"import\")", html) + + +class PgContention(unittest.TestCase): + PGSTAT = " total_s | mean_ms | calls\n 3500.0 | 1.0 | 1000000\n" + + def test_rule_applies_only_to_leg_named_postgres(self): + with tempfile.TemporaryDirectory() as t: + for leg, es in (("postgres", False), ("postgres-elasticsearch", True)): + d = make_leg(t, leg, es) + put(d, "crud-pgstat.txt", self.PGSTAT) # 3.5 ms/call + out, dump = os.path.join(t, "r.html"), os.path.join(t, "d.json") + p = run(["--run-dir", t, "--run-id", "777", "--out", out, "--dump-json", dump, "--no-shapes"]) + self.assertEqual(p.returncode, 0, p.stderr) + with open(dump, encoding="utf-8") as fh: + legs = json.load(fh)["legs"] + with open(out, encoding="utf-8") as fh: + html = fh.read() + self.assertNotIn("39657850695", html) + pg, pe = legs["postgres"], legs["postgres-elasticsearch"] + self.assertEqual(pg["checks"]["load"][0], "bad") + self.assertIn("⚠", pg["markers"].get("crud", "")) + self.assertIn("3.50 ms/call", pe["checks"]["load"][1]) # value still shown + self.assertNotEqual(pe["checks"]["load"][0], "bad") + self.assertNotIn("⚠", pe["markers"].get("crud", "")) + + +class TrendAndFailures(unittest.TestCase): + def test_trend_dir_is_used(self): + with tempfile.TemporaryDirectory() as t: + cur, hist = os.path.join(t, "cur"), os.path.join(t, "hist") + make_leg(cur, "sqlite", False) + first = os.path.join(t, "first.json") + r = run(["--run-dir", cur, "--run-id", "700", "--branch", "feature/x", "--out", os.path.join(t, "a.html"), + "--dump-json", first, "--no-shapes"]) + self.assertEqual(r.returncode, 0) + os.makedirs(os.path.join(hist, "700")) + os.replace(first, os.path.join(hist, "700", "report-data.json")) + out, dump = os.path.join(t, "b.html"), os.path.join(t, "b.json") + run(["--run-dir", cur, "--run-id", "777", "--branch", "feature/x", "--out", out, "--dump-json", dump, + "--trend-dir", hist, "--no-shapes"]) + d = json.load(open(dump)) + self.assertEqual(d["history_runs"], 1) + with open(out, encoding="utf-8") as fh: + self.assertIn('"trend":[', fh.read()) + + def test_garbage_input_still_yields_page(self): + with tempfile.TemporaryDirectory() as t: + junk = os.path.join(t, "fhir-benchmark-x-1", "x") + put(junk, "crud.json", "{not json") + put(junk, "bulk-import.txt", "\x00\xff garbage\n===") + put(junk, "host-contention.txt", "nonsense") + out = os.path.join(t, "o.html") + r = run(["--run-dir", t, "--run-id", "1", "--out", out, "--dump-json", os.path.join(t, "o.json")]) + self.assertEqual(r.returncode, 0, r.stderr) + html = open(out, encoding="utf-8").read() + self.assertTrue(html.startswith("")) + self.assertTrue(html.rstrip().endswith("")) + + def test_missing_run_dir_and_bad_args(self): + with tempfile.TemporaryDirectory() as t: + out = os.path.join(t, "o.html") + r = run(["--run-dir", os.path.join(t, "nope"), "--out", out]) + self.assertEqual(r.returncode, 0) + self.assertIn("no leg artifacts", open(out, encoding="utf-8").read()) + r = run(["--bogus-flag", "--out", out]) + self.assertEqual(r.returncode, 0) + + def test_render_failure_writes_minimal_page(self): + import importlib.util + spec = importlib.util.spec_from_file_location("report_html", SCRIPT) + mod = importlib.util.module_from_spec(spec) + spec.loader.exec_module(mod) + page = mod.minimal_page("9", "boom ") + self.assertIn("<b>", page) + self.assertTrue(page.rstrip().endswith("")) + + +@unittest.skipUnless(bool(REAL) and os.path.isdir(REAL), + "set FHIR_BENCH_REAL_RUN_DIR to a downloaded CI run directory") +class RealRun(unittest.TestCase): + def test_smoke(self): + with tempfile.TemporaryDirectory() as t: + out, dump = os.path.join(t, "r.html"), os.path.join(t, "d.json") + r = run(["--run-dir", REAL, "--run-id", "40335047310", "--repo", "HeliosSoftware/hfs", + "--branch", "tmp/bench-steve-ci-test", "--sha", "a4f41e7", "--out", out, + "--dump-json", dump, "--no-shapes"]) + self.assertEqual(r.returncode, 0, r.stderr) + html = open(out, encoding="utf-8").read() + d = json.load(open(dump)) + self.assertIn("postgres-elasticsearch", d["order"]) + b = d["legs"]["postgres-elasticsearch"]["bulk"] + self.assertTrue(b["index_inline"]) + self.assertEqual(len(d["legs"]["postgres-elasticsearch"]["suites"]["sql-run"]["views"]), 5) + self.assertIn("inline (during ingest)", html) + self.assertLess(len(html), 400_000) + + +class Timing(unittest.TestCase): + @classmethod + def setUpClass(cls): + cls.tmp = tempfile.TemporaryDirectory() + cls.t = cls.tmp.name + make_leg(cls.t, "sqlite", False) + + @classmethod + def tearDownClass(cls): + cls.tmp.cleanup() + + def timing(self, waiting, working): + job = {"name": "leg sqlite", "kind": "leg", "leg": "sqlite", "queued_s": 5, "behind_legs_s": 77, + "capacity_wait_s": 3, "host_wait_s": 0, "waiting_s": waiting, "working_s": working, + "created": "2026-10-26T10:00:00Z", "started": "2026-10-26T10:01:00Z", + "completed": "2026-10-26T11:00:00Z", "running": False} + return {"run_id": "777", "total_s": waiting + working, "waiting_s": waiting, "working_s": working, + "jobs": [job]} + + def build(self, tag, timing=None, raw=None): + out, dump = os.path.join(self.t, tag + ".html"), os.path.join(self.t, tag + ".json") + args = ["--run-dir", self.t, "--run-id", "777", "--out", out, "--dump-json", dump, "--no-shapes"] + if timing is not None or raw is not None: + tj = os.path.join(self.t, tag + "-t.json") + with open(tj, "w", encoding="utf-8") as fh: + fh.write(raw if raw is not None else json.dumps(timing)) + args += ["--timing-json", tj] + r = run(args) + self.assertEqual(r.returncode, 0, r.stderr) + return open(out, encoding="utf-8").read(), json.load(open(dump)) + + def test_tile_from_data(self): + html, d = self.build("ok", self.timing(11, 3195)) + self.assertIn("Waiting 11 s", html) + self.assertIn("Working 53 min 15 s", html) + self.assertIn("of 53 min 26 s total", html) + self.assertEqual(d["timing"]["waiting_s"], 11) + self.assertNotIn("waited", json.dumps(d["verdict_all"])) + self.assertNotIn("timing_view", d) + + def test_warning_sentence(self): + html, d = self.build("warn", self.timing(3900, 3195)) + self.assertIn("This run waited 1 h 05 min for resources: it is slower to finish, not slower to run.", html) + self.assertTrue(any("waited 1 h 05 min" in i[1] for i in d["verdict_all"]["items"])) + + def test_invalid_or_absent_is_identical(self): + base, bd = self.build("base") + for tag, raw in (("bad1", "{not json"), ("bad2", json.dumps({"run_id": "1"}))): + html, d = self.build(tag, raw=raw) + self.assertEqual(html, base) + self.assertNotIn("timing", d) + self.assertNotIn("timing", bd) + + def test_template_has_no_fixture_numbers(self): + with open(os.path.join(HERE, "report_template.html"), encoding="utf-8") as fh: + tpl = fh.read() + for lit in ("3195", "3206", "53 min", "1 h 05", "Waiting 11"): + self.assertNotIn(lit, tpl) + + +if __name__ == "__main__": + unittest.main() diff --git a/.github/scripts/fhir-bench/test_run_timing.py b/.github/scripts/fhir-bench/test_run_timing.py new file mode 100644 index 0000000000..f158b289d0 --- /dev/null +++ b/.github/scripts/fhir-bench/test_run_timing.py @@ -0,0 +1,138 @@ +import json +import os +import tempfile +import unittest + +import run_timing as rt + +D = "2026-10-26T" + + +def job(name, c, s, e): + return {"name": name, "created_at": D + c + "Z", "started_at": D + s + "Z", + "completed_at": (D + e + "Z") if e else None} + + +def make_fetcher(run, jobs): + def f(kind, repo, rid): + return run if kind == "run" else jobs + return f + + +def write_info(root, leg, cap, host=None): + d = os.path.join(root, f"fhir-benchmark-{leg}-1", leg) + os.makedirs(d) + with open(os.path.join(d, "runner-info.txt"), "w") as f: + f.write(f"runner_name: r1\ncapacity_wait_s: {cap}\n") + if host is not None: + f.write(f"host_wait_s: {host}\n") + + +REAL_RUN = {"id": 40353889556, "created_at": D + "15:54:17Z"} +REAL_JOBS = [ + job("Resolve backend matrix", "15:54:19", "15:54:20", "15:54:25"), + job("Build HFS binary", "15:54:25", "15:54:27", "16:07:50"), + job("Benchmark (postgres-elasticsearch)", "16:07:50", "16:07:51", "16:47:25"), + job("Compare legs", "16:47:25", "16:47:28", "16:47:43"), +] + + +class T(unittest.TestCase): + def test_humanize(self): + self.assertEqual(rt.humanize(11), "11 s") + self.assertEqual(rt.humanize(3206), "53 min 26 s") + self.assertEqual(rt.humanize(4 * 3600 + 27 * 60), "4 h 27 min") + + def test_real_fixture(self): + with tempfile.TemporaryDirectory() as d: + write_info(d, "postgres-elasticsearch", 2) + rep = rt.build("o/r", "1", d, make_fetcher(REAL_RUN, REAL_JOBS)) + self.assertEqual(rep["total_s"], 3206) + self.assertEqual(rep["waiting_s"], 11) + self.assertEqual(rep["working_s"], 3195) + self.assertEqual(rep["total_s"], rep["waiting_s"] + rep["working_s"]) + md = rt.to_markdown(rep) + self.assertTrue(md.startswith("\n### Run time\n")) + self.assertIn("**Total 53 min 26 s** · waiting for resources **11 s** " + "· working **53 min 15 s**", md) + self.assertIn("| Resolve backend matrix | 3 s | – | 5 s |", md) + self.assertIn("| Build HFS binary | 2 s | – | 13 min 23 s |", md) + self.assertIn("| `postgres-elasticsearch` | 3 s (runner 1 s + capacity " + "gate 2 s) | – | 39 min 32 s |", md) + self.assertIn("| Compare legs | 3 s | – | 15 s |", md) + self.assertTrue(md.endswith("\n")) + js = rt.to_json(rep) + self.assertEqual([j["kind"] for j in js["jobs"]], + ["setup", "build", "leg", "compare"]) + self.assertEqual(js["jobs"][2]["leg"], "postgres-elasticsearch") + self.assertEqual(js["jobs"][2]["capacity_wait_s"], 2) + self.assertFalse(js["jobs"][0]["running"]) + + def test_three_sequential_legs(self): + run = {"id": 1, "created_at": D + "10:00:00Z"} + jobs = [ + job("Build HFS binary", "10:00:00", "10:00:00", "10:10:00"), + job("Benchmark (a)", "10:10:00", "10:10:00", "10:30:00"), + job("Benchmark (b)", "10:10:00", "10:30:00", "10:50:00"), + job("Benchmark (c)", "10:10:00", "10:50:00", "11:10:00"), + ] + with tempfile.TemporaryDirectory() as d: + rep = rt.build("o/r", "1", d, make_fetcher(run, jobs)) + by = {r["leg"]: r for r in rep["rows"] if r["leg"]} + self.assertEqual(by["a"]["behind"], 0) + self.assertEqual(by["b"]["behind"], 1200) + self.assertEqual(by["c"]["behind"], 2400) + self.assertEqual(by["b"]["waiting"], 0) + self.assertEqual(by["c"]["waiting"], 0) + self.assertEqual(rep["total_s"], 4200) + self.assertEqual(rep["waiting_s"], 0) + self.assertEqual(rep["working_s"], 4200) + md = rt.to_markdown(rep) + self.assertIn("| `c` | 0 s | 40 min | 20 min |", md) + + def test_running_job(self): + now = rt.parse_ts(D + "16:48:00Z") + jobs = REAL_JOBS[:3] + [job("Compare legs", "16:47:25", "16:47:28", None)] + rep = rt.build("o/r", "1", "", make_fetcher(REAL_RUN, jobs), now=now) + last = rep["rows"][-1] + self.assertTrue(last["running"]) + self.assertEqual(last["working"], 32) + self.assertEqual(rep["total_s"], 3223) + self.assertEqual(rep["total_s"], rep["waiting_s"] + rep["working_s"]) + self.assertIn("(running)", rt.to_markdown(rep)) + self.assertIsNone(rt.to_json(rep)["jobs"][-1]["completed"]) + + def test_missing_runner_info_and_host_wait(self): + with tempfile.TemporaryDirectory() as d: + rep = rt.build("o/r", "1", d, make_fetcher(REAL_RUN, REAL_JOBS)) + self.assertEqual(rep["waiting_s"], 9) + with tempfile.TemporaryDirectory() as d: + write_info(d, "postgres-elasticsearch", 2, host=10) + rep = rt.build("o/r", "1", d, make_fetcher(REAL_RUN, REAL_JOBS)) + self.assertEqual(rep["waiting_s"], 21) + self.assertIn("quiet host 10 s", rt.to_markdown(rep)) + + def test_api_failure_exits_zero_no_output(self): + def boom(*a): + raise RuntimeError("api down") + with tempfile.TemporaryDirectory() as d: + out, js = os.path.join(d, "o.md"), os.path.join(d, "o.json") + rc = rt.main(["--repo", "o/r", "--run-id", "1", "--run-dir", d, + "--out", out, "--dump-json", js], fetcher=boom) + self.assertEqual(rc, 0) + self.assertFalse(os.path.exists(out)) + self.assertFalse(os.path.exists(js)) + + def test_main_writes_files(self): + with tempfile.TemporaryDirectory() as d: + out, js = os.path.join(d, "o.md"), os.path.join(d, "o.json") + rc = rt.main(["--repo", "o/r", "--run-id", "1", "--run-dir", d, + "--out", out, "--dump-json", js], + fetcher=make_fetcher(REAL_RUN, REAL_JOBS)) + self.assertEqual(rc, 0) + self.assertEqual(json.load(open(js))["total_s"], 3206) + self.assertIn("### Run time", open(out).read()) + + +if __name__ == "__main__": + unittest.main() diff --git a/.github/scripts/fhir-bench/test_summary_backends.py b/.github/scripts/fhir-bench/test_summary_backends.py index 4e29518c21..a2297c9352 100644 --- a/.github/scripts/fhir-bench/test_summary_backends.py +++ b/.github/scripts/fhir-bench/test_summary_backends.py @@ -1,6 +1,6 @@ #!/usr/bin/env python3 # -# Unit tests for summary_backends.py's indexing-suite and bulk-import lines: stdlib unittest, +# Unit tests for summary_backends.py's bulk-import lines: stdlib unittest, # synthetic bench-results// files built in code, the script run as the # workflow runs it (its own python process, GITHUB_WORKSPACE + BACKEND set). # Not wired into CI. Run from the repo root: @@ -13,12 +13,6 @@ import unittest SCRIPT = os.path.join(os.path.dirname(os.path.abspath(__file__)), "summary_backends.py") -FINISHED = ("2026-10-09T13:19:08.201143Z INFO helios_persistence::search::reindex: reindex job " - "finished tenant=default job_id=j outcome=completed types_done=1 types=1 " - "processed=5000 total=5000 elapsed_ms=8018 resources_per_s=623.6 entries=45000 " - "failed=0 pages=6 fetch_ms=512 write_ms=7401 extract_ms=0 delete_ms=0 insert_ms=0 " - "writer_other_ms=7401 yield_ms=31 other_ms=74 db_wait_ms=0\n") - class SummaryRunMixin(object): def summary(self, files, backend="sqlite"): @@ -48,14 +42,14 @@ def bulk_txt(**kv): class SummaryBulkImportTest(SummaryRunMixin, unittest.TestCase): def test_bulk_line_deferred_unchanged(self): out = self.summary({"bulk-import.txt": bulk_txt()}) - self.assertIn("resources in 2400 s (Bulk Import: ingest 600 s + Bulk Import: index rebuild 1800 s, " + self.assertIn("resources in 2400 s (ingest until Completed 600 s + search-index rebuild 1800 s, " "`completed`) = **679.5 resources/s** end to end, 2717.8 resources/s " "ingest only; fresh database, `defer_indexing=true`.", out) def test_bulk_line_inline(self): out = self.summary({"bulk-import.txt": bulk_txt( defer_indexing="false", index_status="inline", index_seconds=0, total_seconds=600)}) - self.assertIn("(Bulk Import: ingest 600 s, search index built inline during ingest)", out) + self.assertIn("(ingest until Completed 600 s, search index built inline during ingest)", out) self.assertNotIn("rebuild 0 s", out) self.assertNotIn("search-index rebuild", out) @@ -63,51 +57,50 @@ def test_bulk_line_inline_with_rebuild_of_rejected_types(self): out = self.summary({"bulk-import.txt": bulk_txt( defer_indexing="false", index_status="completed", index_seconds=12, total_seconds=612)}) - self.assertIn("(Bulk Import: ingest 600 s, search index built inline during ingest + 12 s rebuild " + self.assertIn("(ingest until Completed 600 s, search index built inline during ingest + 12 s rebuild " "of rejected types, `completed`)", out) self.assertNotIn("search-index rebuild", out) -class SummaryIndexingTest(SummaryRunMixin, unittest.TestCase): - def test_completed_with_phase_split(self): - out = self.summary({ - "indexing.txt": "status=completed\nreason=\nresource_type=Encounter\ntotal=5000\n" - "processed=5000\nentries=45000\nerrors=0\nseconds=8.028\n" - "resources_per_s=622.8\nentries_per_resource=9.00\nbatch_size=1000\n" - "budget_s=180\nes_refresh=n/a\n", - "indexing-hfs-log.txt": FINISHED}) - self.assertIn("**Indexing (`$reindex` of Encounter):** completed — 5,000/5,000 resources " - "in 8.0 s = **623 resources/s**", out) - self.assertIn("fetch 0.5 s · write 7.4 s", out) - self.assertIn("budget 180 s", out) - self.assertNotIn("⚠", out) - - def test_partial_es_and_failed_kickoff(self): - out = self.summary({ - "indexing.txt": "status=partial\nreason=time-cap\nresource_type=Encounter\n" - "total=67692\nprocessed=30000\nentries=450000\nerrors=0\n" - "seconds=180.4\nresources_per_s=166.3\nentries_per_resource=15.00\n" - "batch_size=1000\nbudget_s=180\nes_refresh=wait_for\n"}, - backend="sqlite-elasticsearch") - self.assertIn("30,000/67,692", out) - self.assertIn("Elasticsearch refresh `wait_for`", out) - self.assertIn("⚠ partial (time-cap)", out) - self.assertIn("budget 180 s", out) - out = self.summary({"indexing.txt": "status=kickoff-failed\nreason=http-501\n" - "resource_type=Encounter\nkickoff_http=501\n"}) - self.assertIn("answered HTTP 501", out) - - def test_no_indexing_file_prints_nothing(self): - out = self.summary({"runner-info.txt": "runner_name: agent-sqlite\nrunner_cpus: 8\n"}) - self.assertNotIn("Indexing", out) - - def test_budget_other_value(self): - out = self.summary({"indexing.txt": "status=completed\nresource_type=Encounter\n" - "total=10\nprocessed=10\nentries=90\nerrors=0\n" - "seconds=1.0\nresources_per_s=10.0\n" - "entries_per_resource=9.00\nbatch_size=1000\n" - "budget_s=240\nes_refresh=n/a\n"}) - self.assertIn("budget 240 s", out) +def sql_run_json(views=("observation_page", "observation_large", "observation_filter", "claim"), + fails=0): + """A small sql-run.json (k6 --summary-export); `eob` has no samples by default.""" + import json + m = {"sql_run_rows": {"count": 120000, "rate": 2000.0}, + "http_req_failed": {"value": 0.0125, "passes": 1, "fails": 80}} + for v in views: + m["http_req_duration{view:%s}" % v] = {"avg": 10.0, "min": 1.0, "med": 8.5, + "max": 99.0, "p(90)": 20.0, "p(95)": 30.25, + "count": 500} + checks = {"sql-run 200": {"passes": 500, "fails": fails}, + "sql-run rows > 0": {"passes": 500, "fails": 0}} + return json.dumps({"metrics": m, "root_group": {"checks": checks}}) + + +class SummarySqlRunTest(SummaryRunMixin, unittest.TestCase): + def test_section_absent_without_file(self): + self.assertNotIn("$sql-run", self.summary({})) + + def test_table_rows_and_totals(self): + out = self.summary({"sql-run.json": sql_run_json()}) + self.assertIn("**SQL-on-FHIR `$sql-run` by view**", out) + self.assertIn("| View | Requests | avg ms | p50 ms | p90 ms | p95 ms | max ms |", out) + self.assertIn("| observation_filter | 500 | 10.0 | 8.5 | 20.0 | 30.2 | 99.0 |", out) + self.assertNotIn("p99", out) + self.assertIn("Rows returned: 120,000 total, 2,000 rows/s · errors 1.25%", out) + self.assertIn("sql-run 200 ✓; sql-run rows > 0 ✓", out) + self.assertIn("the filtered view is the scan", out) + + def test_view_without_samples(self): + out = self.summary({"sql-run.json": sql_run_json()}) + self.assertIn("| eob | ? | ? | ? | ? | ? | ? |", out) + + def test_failed_check_flagged(self): + out = self.summary({"sql-run.json": sql_run_json(fails=7)}) + self.assertIn("sql-run 200 ✗ 7", out) + + def test_invalid_json_omits_section(self): + self.assertNotIn("$sql-run", self.summary({"sql-run.json": "{not json"})) if __name__ == "__main__": diff --git a/.github/workflows/fhir-bench-tests.yml b/.github/workflows/fhir-bench-tests.yml new file mode 100644 index 0000000000..4733565af7 --- /dev/null +++ b/.github/workflows/fhir-bench-tests.yml @@ -0,0 +1,61 @@ +name: FHIR benchmark scripts + +# ────────────────────────────────────────────────────────────────────────────── +# Unit tests and a syntax gate for the FHIR Server Benchmark helper scripts +# (.github/scripts/fhir-bench/). Runs on pull requests that touch them so a +# change cannot silently break the benchmark report. +# +# Kept out of ci.yml on purpose: ci.yml has no per-path filter, and a +# workflow-level `paths:` there would restrict the whole CI. +# +# stdlib unittest only; no Docker, no network, runs in about a second. The +# real-data smoke tests read local sample data and skip on a clean runner. +# ────────────────────────────────────────────────────────────────────────────── + +on: + pull_request: + paths: + - ".github/scripts/fhir-bench/**" + - ".github/workflows/fhir-benchmark.yml" + - ".github/workflows/fhir-bench-tests.yml" + workflow_dispatch: + +permissions: + contents: read + +concurrency: + group: ${{ github.workflow }}-${{ github.ref }} + cancel-in-progress: true + +jobs: + bench-scripts: + name: Benchmark script tests + runs-on: ubuntu-latest + timeout-minutes: 10 + steps: + - name: Checkout + uses: actions/checkout@v5 + + - name: Python version + run: python3 --version + + - name: Unit tests + run: python3 -m unittest discover -s .github/scripts/fhir-bench -p 'test_*.py' -v + + - name: Syntax gate + run: | + set -euo pipefail + for f in .github/scripts/fhir-bench/*.sh; do + echo "bash -n $f" + bash -n "$f" + done + for f in .github/scripts/fhir-bench/*.py; do + echo "py_compile $f" + python3 -m py_compile "$f" + done + python3 -c 'import yaml' 2>/dev/null || python3 -m pip install --break-system-packages pyyaml + python3 - <<'PY' + import yaml + yaml.safe_load(open(".github/workflows/fhir-benchmark.yml")) + print("fhir-benchmark.yml: YAML OK") + PY diff --git a/.github/workflows/fhir-benchmark.yml b/.github/workflows/fhir-benchmark.yml index 1c70112609..7bd998cb0c 100644 --- a/.github/workflows/fhir-benchmark.yml +++ b/.github/workflows/fhir-benchmark.yml @@ -10,6 +10,11 @@ name: FHIR Server Benchmark # (which drives the terminology `tx-benchmark` suite against HTS). It reuses the # same self-hosted-runner + remote-Docker plumbing. # +# Artifacts: fhir-benchmark-- (results per leg), +# fhir-bench-comparison- (comparison.md), fhir-bench-report- +# (single dark HTML report, not zipped) and fhir-bench-report-data- +# (report-data.json, read by later runs for the trend). +# # Topology (mirrors hts-benchmark.yml — HFS and k6 run natively ON the runner; # only the stateful dependencies live in containers on the REMOTE Docker daemon): # @@ -55,18 +60,23 @@ name: FHIR Server Benchmark # hfs_bulk_import, the mongo database _bulk_import, or the ES index # prefix hfsbulk. So crud/search, the result-size counts and the crud # residue are untouched, and the bulk load starts from the same empty -# state import does. HFS's bulk defaults (deferred indexing, batch 100, -# file concurrency 1); the clock runs from kick-off until the deferred +# state import does. The per-leg indexing recipe below +# replaces HFS's bulk defaults; the clock runs from kick-off until the deferred # search-index rebuild has finished, capped by BULK_IMPORT_TIMEOUT_S and by # what is left of the leg budget; the bulk database is dropped afterwards. # The comparison reports the one load as three Throughput rows: -# `Bulk Import, $bulk-submit (resources/s)` (over both phases), -# `Bulk Import: ingest (resources/s, seconds)` (resources/s and the +# `Bulk Import (`/ui/bulk-import`: `$bulk-submit`, until searchable) (resources/s)` (over both phases), +# `↳ ingest, until Completed (resources/s, seconds)` (resources/s and the # seconds from kick-off until the status manifest is final: how long -# loading the corpus takes) and `Bulk Import: index rebuild (seconds)` +# loading the corpus takes) and `↳ search indexing (seconds)` # (seconds of the deferred search-index rebuild that follows: how -# long until that freshly loaded data is indexed; `inline (during ingest)` +# long until that freshly loaded data is indexed; ` s (= ingest)` # when HFS indexed while ingesting, HFS_BULK_SUBMIT_DEFER_INDEXING=false). +# Indexing mode per leg (bulk-import.sh sets it, a caller env var wins): +# standalone legs defer indexing (HFS_BULK_SUBMIT_DEFER_INDEXING=true); +# *-elasticsearch legs index inline with file concurrency 4 (HFS uses 1 on +# sqlite-elasticsearch, whose primary is SQLite), batch 1000 and ES bulk +# concurrency 4. Both are recorded in the leg configuration lines. # It starts no containers, so the capacity gate is unchanged. Logic in # .github/scripts/fhir-bench/bulk-import.sh and bulk_import.py. # • Every named volume this workflow creates is @@ -81,8 +91,14 @@ name: FHIR Server Benchmark # overrides for a script that defines none. Change the scenarios upstream (or # fork the scripts) if you need a different load shape for a comparable run. # -# One suite is HFS's own, `insert` (.github/scripts/fhir-bench/k6/insert.js, -# 50 VUs / 2m). It measures single-resource creates (per iteration POST +# Two suites are HFS's own. `sql-run` (.github/scripts/fhir-bench/k6/sql-run.js, +# 10 VUs x 1 min) runs SQL-on-FHIR ViewDefinitions (GET /$sql-run): +# read-only, five views, never patient/group. With tests=all it runs after +# search (CANONICAL order); with an explicit tests list it runs where listed, +# and on an empty database (no import/search before it) it returns nothing useful. +# It writes sql-run.json into the +# leg artifact like the other suites. The other is `insert` +# (.github/scripts/fhir-bench/k6/insert.js, 50 VUs / 2m). It measures single-resource creates (per iteration POST # Patient, then four POST Observation referencing it), which crud's mixed # 300-VU loop cannot isolate. "Run benchmark suites" runs a suite file found # under .github/scripts/fhir-bench/k6/ in place of upstream's k6/.js. @@ -90,24 +106,6 @@ name: FHIR Server Benchmark # after the result-size snapshot (search-counts.txt), wherever it appears in # `tests`. Its matrix throughput row is creates/s. # -# A second suite is this repository's own, not upstream's: `indexing`. It is -# opt-in and NOT part of `all`: it runs only when `tests` names it, listed -# after search (for example -# tests=prewarm,import,crud,search,indexing,insert,bulk-import); insert and -# bulk-import still run after it. It times one `POST /Encounter/$reindex` -# (batchSize 1000) of the corpus import loaded — HFS re-extracts every -# Encounter's search parameters and rewrites the index that serves search (the -# primary's own on sqlite/postgres/mongodb, Elasticsearch on the -# *-elasticsearch legs). Users never run a $reindex when they load data, and it -# rewrites the search index right before insert and bulk-import, so a run that -# includes it may skew both. How long freshly loaded data takes to become -# indexed is the `Bulk Import: index rebuild (seconds)` row instead. Past a 240 s budget the -# job is cancelled and reported partial, so it adds at most ~5 min to a leg. See -# run_indexing_suite in .github/scripts/fhir-bench/suite-lib.sh. Its matrix row -# is labelled `reindex, $reindex Encounter` (resources/s) and sits with the -# Batch/Transaction Import (`POST /` Bundles; suite `import`) and Bulk Import -# (`$bulk-submit`; suite `bulk-import`) rows. -# # The Batch/Transaction Import and Bulk Import rows are not comparable: they # differ in numerator and denominator (committed Bundle entries per second of # the k6 scenario vs resources until the search index covers them). @@ -145,7 +143,7 @@ on: - postgres-elasticsearch - mongodb-elasticsearch tests: - description: "Suites to run: 'all' = prewarm,import,crud,search,insert,bulk-import | comma-separated from those plus indexing (a timed $reindex; opt-in only, never part of 'all', list it after search; it rewrites the index before insert and bulk-import and may skew both). insert runs after the other k6 suites; bulk-import ($bulk-submit into a fresh database: total, ingest and index-rebuild rows) always runs last and can add up to ~70 min per leg; 'prewarm,import,crud,search,insert' skips it" + description: "Suites to run: 'all' = prewarm,import,crud,search,sql-run,insert,bulk-import | comma-separated from those. sql-run is HFS's own read-only SQL-on-FHIR suite (10 VUs x 1 min, five views, never patient/group); it follows search only with 'all', and with an explicit list it runs where listed (useless on an empty database). insert runs after the other k6 suites; bulk-import ($bulk-submit into a fresh database: total, ingest and search-index rebuild rows) always runs last and can add up to ~70 min per leg; 'prewarm,import,crud,search,sql-run,insert' skips it" required: false default: "all" vus: @@ -197,7 +195,7 @@ on: required: false default: "32" max_parallel: - description: "Backend legs running at once (1..2 — every leg shares one 4-CPU / 11 GB Docker host, so 2 skews both legs' numbers)" + description: "Backend legs running at once (1..2 — every leg shares one 4-CPU Docker host with the rest of CI (its memory is printed by the capacity gate), so 2 skews both legs' numbers)" type: number required: false default: 1 @@ -248,7 +246,7 @@ jobs: # ──────────────────────────────────────────────────────────────────────────── # Resolve the `backend` input into a job matrix. Each leg carries a fixed HFS # port (8081-8086), distinct per backend so legs never collide even with - # max_parallel > 1 (clamped to 1..2 below — the shared 4-CPU / 11 GB Docker + # max_parallel > 1 (clamped to 1..2 below — the shared 4-CPU Docker # host). Include order = intended run order: bare backends first. Also # validates the free-text tuning inputs here, in one place, before the # ~13-minute build. @@ -302,10 +300,10 @@ jobs: run: bash "$GITHUB_WORKSPACE/.fhir-bench-setup/.github/scripts/fhir-bench/resolve-matrix.sh" # ──────────────────────────────────────────────────────────────────────────── - # Compile one debug `hfs` binary with every benchmarked backend (sqlite, - # postgres, mongodb, elasticsearch) linked in — the backend is selected at - # runtime via HFS_STORAGE_BACKEND, so a single build serves every matrix - # leg. `ui` is dropped so the benchmark exercises the FHIR API only. + # Compile one release `hfs` binary with the backends the selected legs need + # (sqlite, postgres, mongodb, elasticsearch) linked in — the backend is + # selected at runtime via HFS_STORAGE_BACKEND, so a single build serves every + # matrix leg. `ui` is dropped so the benchmark exercises the FHIR API only. # ──────────────────────────────────────────────────────────────────────────── build: name: Build HFS binary @@ -320,6 +318,7 @@ jobs: clean: false - name: Install Rust toolchain + id: rust uses: dtolnay/rust-toolchain@stable with: toolchain: stable @@ -347,11 +346,60 @@ jobs: # mongodb pulls in mongocrypt-sys (native libmongocrypt, needs cmake); # these runners already build it via ci.yml's --all-features. s3 is not # compiled: no s3 leg is benchmarked (see header). - - name: Build release binary (R4 + sqlite + postgres + mongodb + elasticsearch) + # Compile only the backends the selected legs need (FHIR R4 only, always). + # build_features.py maps the setup job's matrix to the feature list: + # sqlite -> sqlite, postgres -> postgres, mongodb -> mongodb, + # -elasticsearch -> x + elasticsearch; core/all gives the full set. + - name: Resolve build features + id: features + env: + MATRIX: ${{ needs.setup.outputs.matrix }} + run: | + FEATURES=$(python3 .github/scripts/fhir-bench/build_features.py "$MATRIX") + echo "features=$FEATURES" >> "$GITHUB_OUTPUT" + # actions/cache keys cannot contain commas (run 40415264411 failed with + # "Key Validation Error"), so the cache key uses the list joined with +. + echo "key=${FEATURES//,/+}" >> "$GITHUB_OUTPUT" + echo "Building with features: $FEATURES" + + # Rust cache. The repo has no cache action; its convention is a warm + # target/ kept on the self-hosted runner (checkout clean: false plus + # .github/actions/cargo-target-gc). That never helped this job: ci.yml + # builds the debug profile, so the release profile starts cold on every + # runner that has not built it (485 crates, 14 min). actions/cache is the + # first-party action (pinned by major tag like the others). Key = lockfile + # + feature list (different features compile different crates); the + # restore-keys fallbacks reuse a close cache and cargo rebuilds only the + # difference. Saved after a successful build on any branch (keys are + # immutable, so no clash); a branch reads its own and main's caches. + # Only target/release/{deps,build,.fingerprint} are cached, not + # incremental/ or the linked binary. The first run per key is still cold. + # Key includes the rustc version (steps.rust.outputs.cachekey) so a toolchain + # bump gets a fresh key. This job does not run cargo-target-gc and release + # deps/ can be 2-3.5 GB, so key churn can evict other entries. + - name: Cache Rust build (release) + uses: actions/cache@v5 + with: + path: | + ${{ env.CARGO_HOME }}/registry/index + ${{ env.CARGO_HOME }}/registry/cache + ${{ env.CARGO_HOME }}/git/db + target/release/deps + target/release/build + target/release/.fingerprint + key: bench-release-${{ runner.os }}-${{ steps.features.outputs.key }}-${{ steps.rust.outputs.cachekey }}-${{ hashFiles('Cargo.lock') }} + restore-keys: | + bench-release-${{ runner.os }}-${{ steps.features.outputs.key }}-${{ steps.rust.outputs.cachekey }}- + bench-release-${{ runner.os }}-${{ steps.features.outputs.key }}- + bench-release-${{ runner.os }}- + + - name: Build release binary + env: + FEATURES: ${{ steps.features.outputs.features }} run: | cargo build --release -p helios-hfs \ --no-default-features \ - --features "R4,sqlite,postgres,mongodb,elasticsearch" + --features "$FEATURES" - name: Upload binary uses: actions/upload-artifact@v7 @@ -1244,7 +1292,7 @@ jobs: # above and are read back here as plain environment variables. set -uo pipefail # es_drain_gate, capture_backend_stats, write_import_completeness, - # write_mongo_txn_errors, write_search_counts, run_indexing_suite, + # write_mongo_txn_errors, write_search_counts, # write_containers_state, inspect_running and # check_leg_containers_alive (issue #1475's ES/Mongo/composite # per-suite instrumentation) live in suite-lib.sh, sourced here so @@ -1338,17 +1386,10 @@ jobs: cat "$RESULTS_DIR/runner-info.txt" # Resolve suite list. 'search' needs data, so 'import' must precede it. - # 'indexing' (a timed $reindex, not a k6 suite — run_indexing_suite) - # is opt-in and not in CANONICAL, so 'all' never runs it: users do - # not run $reindex when they load data, and rewriting the index here - # would skew insert and bulk-import, whose Bulk Import index-rebuild row measures - # indexing instead. Named explicitly, it runs where `tests` lists it - # (put it after search so it cannot disturb crud/search) and always - # before insert and bulk-import, which are moved last below. # bulk-import is last and is not a k6 suite: it is taken out of the # list wherever it was listed and runs once after the result-size # snapshot (below). - CANONICAL="prewarm import crud search insert bulk-import" + CANONICAL="prewarm import crud search sql-run insert bulk-import" INPUT_TESTS="${BENCH_IN_TESTS:-all}" if [ "$INPUT_TESTS" = "all" ]; then SUITES="$CANONICAL" @@ -1418,19 +1459,6 @@ jobs: # still runs against a possibly-incomplete index. ES_DRAIN_TIMEOUT_S=600 - # The indexing suite (opt-in: only when tests names it) times one - # `POST /$INDEXING_TYPE/$reindex` after - # search (run_indexing_suite in suite-lib.sh). Encounter is the - # largest type that fits the budget on every leg (67,692 on a - # 1000/1000 import in run 37782202746; Observation's 689,080 would - # need ~2,900 resources/s). batchSize 1000 is - # HFS_REINDEX_BATCH_SIZE's default for the automatic post-import - # rebuild (a bare $reindex pages 100). Past INDEXING_BUDGET_S the job - # is cancelled and its rate covers the part that ran. - INDEXING_TYPE=Encounter - INDEXING_BATCH_SIZE=1000 - INDEXING_BUDGET_S=240 - if [ "$PG_FAMILY" = true ] && [ -n "${PG_CONTAINER:-}" ]; then docker exec "$PG_CONTAINER" psql -U postgres -d postgres -q \ -c "CREATE EXTENSION IF NOT EXISTS pg_stat_statements" >/dev/null 2>&1 \ @@ -1505,7 +1533,7 @@ jobs: SUITE="${SUITE// /}" [ -z "$SUITE" ] && continue SCRIPT="k6/${SUITE}.js" - # HFS-owned suites (insert) live in this repository, not in the + # HFS-owned suites (sql-run, insert) live in this repository, not in the # upstream checkout this step runs from; a file there wins. HFS_SUITE_JS="$GITHUB_WORKSPACE/.github/scripts/fhir-bench/k6/${SUITE}.js" if [ -f "$HFS_SUITE_JS" ]; then @@ -1527,22 +1555,6 @@ jobs: fi fi - # indexing on an ES leg with no drain earlier in this leg (tests - # without search, e.g. import,indexing): drain first, as - # write_search_counts does, so the timed $reindex does not race the - # sync worker's import/crud backlog (asynchronous es_sync_mode) and - # the matrix's reindex-row † (ES index not drained) has an - # es-drain.txt to read. Before probe_host/SUITE_START like the - # search gate above, with the same pgstat reset after it. - if [ "$SUITE" = indexing ] && [ -n "${ES_PORT:-}" ] \ - && [ ! -f "$RESULTS_DIR/es-drain.txt" ]; then - es_drain_gate || echo '::warning::drain gate errored' - if [ "$PG_FAMILY" = true ] && [ -n "${PG_CONTAINER:-}" ]; then - timeout 60 docker exec "$PG_CONTAINER" psql -U postgres -d postgres -q \ - -c "SELECT pg_stat_statements_reset()" >/dev/null 2>&1 || true - fi - fi - # insert keeps what it creates, so the result-size cross-check # (write_search_counts, suite-lib.sh) is taken here, before it: its # totals are compared across legs and must not include insert's @@ -1566,8 +1578,7 @@ jobs: # pg_exec-vs-wall attribution below. probe_host start "$SUITE" SUITE_START=$(date +%s) - # indexing has no k6/indexing.js upstream (see run_indexing_suite below) - if [ "$SUITE" != indexing ] && [ ! -f "$SCRIPT" ]; then + if [ ! -f "$SCRIPT" ]; then echo "Skip '$SUITE' — $SCRIPT not found" continue fi @@ -1627,26 +1638,18 @@ jobs: unset K6_SETUP_TIMEOUT fi - # indexing is not a k6 suite: run_indexing_suite (suite-lib.sh) - # times a $reindex and writes indexing.txt; the bookends around it - # (probe_host, SUITE_WALL, the pgstat dump/reset, - # capture_backend_stats) are the same as for the k6 suites. - if [ "$SUITE" = indexing ]; then - run_indexing_suite || echo "::warning::indexing suite errored" - else - k6 run \ - --no-usage-report \ - --tag runid="$RUN_ID" \ - --tag fhirimpl=hfs \ - --env BASE_URL="http://localhost:$BENCH_PORT" \ - --env BUNDLE_URL="$BUNDLE_URL" \ - --env FHIRIMPL=hfs \ - --summary-trend-stats "avg,min,med,p(90),p(95),p(99),max" \ - --summary-export "$RESULTS_DIR/${SUITE}.json" \ - $POINTS_ARG \ - $EXTRA_ARGS \ - "$SCRIPT" 2>&1 | tee "$RESULTS_DIR/${SUITE}.log" || true - fi + k6 run \ + --no-usage-report \ + --tag runid="$RUN_ID" \ + --tag fhirimpl=hfs \ + --env BASE_URL="http://localhost:$BENCH_PORT" \ + --env BUNDLE_URL="$BUNDLE_URL" \ + --env FHIRIMPL=hfs \ + --summary-trend-stats "avg,min,med,p(90),p(95),p(99),max,count" \ + --summary-export "$RESULTS_DIR/${SUITE}.json" \ + $POINTS_ARG \ + $EXTRA_ARGS \ + "$SCRIPT" 2>&1 | tee "$RESULTS_DIR/${SUITE}.log" || true SUITE_WALL=$(( $(date +%s) - SUITE_START )) probe_host end "$SUITE" @@ -1745,11 +1748,9 @@ jobs: # The plan capture above runs before the load, so its idx_scan counters # only reflect import. This one runs after every suite, so a zero here # means no shape in the whole run touched that index — while every - # write still maintained it and it still occupied cache on an 11G host. + # write still maintained it and it still occupied cache on the shared Docker host. # Evidence for the next round of index pruning; nothing reads it in - # this run. When the indexing suite ran, its $reindex per-resource - # deletes (DELETE FROM search_index WHERE tenant_id/resource_type/ - # resource_id) add idx_search_resource scans to this table. + # this run. if [ "$BACKEND" = "postgres" ] && [ -n "${PG_CONTAINER:-}" ]; then docker exec "$PG_CONTAINER" psql -U postgres -d postgres \ -c "SELECT s.indexrelname AS index_name, s.idx_scan AS scans, @@ -1799,6 +1800,7 @@ jobs: # that most needed diagnosing. Everything after this point is derived data # that can be recomputed from these artifacts; the artifacts cannot be # recovered from anything. Upload first, analyse second. + # The shape-attribution step must stay after this upload, never before it. # # Teardown (Diagnose backend container failure, then Stop HFS server / # Stop tgz bundle server / Stop ephemeral Postgres / Stop ephemeral @@ -1990,6 +1992,9 @@ jobs: # below) — that script cannot use ${{ }} itself. BACKEND: ${{ matrix.backend }} run: | + # GitHub's default shell has no pipefail: without it the step status + # would be tee's, hiding a crash in the python summary below. + set -o pipefail { echo "## FHIR Benchmark — \`${{ github.ref_name }}\` (${{ matrix.backend }})" echo "" @@ -2054,12 +2059,48 @@ jobs: except (KeyError, ValueError, ZeroDivisionError): rate = None it = m.get('iteration_duration', {}) - return rate, it.get('med', 0), it.get('p(95)', 0), it.get('p(99)', 0) + return rate, it.get('med'), it.get('p(95)'), it.get('p(99)') + + def bulk_import_row(): + kv = {} + try: + for line in open(f"{results_dir}/bulk-import.txt"): + if "=" in line: + k, v = line.strip().split("=", 1) + kv[k] = v + if kv.get("status") != "complete": + return None + rate = float(kv["resources_per_s"]) + except (OSError, KeyError, ValueError): + return None + try: + failed, sub = float(kv["resources_failed"]), float(kv["resources_submitted"]) + err = 100.0 * max(failed, 0) / sub + err_fmt = f"**{err:.1f}%**" if err > 1 else f"{err:.1f}%" + except (KeyError, ValueError, ZeroDivisionError): + err_fmt = "n/a" + # Checks column: resources loaded / resources that failed, the counterpart of the + # Batch/Transaction Import row's Bundles passed / failed. + try: + ok, bad = float(kv["resources_ok"]), max(float(kv["resources_failed"]), 0) + chk_fmt = f"{ok:,.0f}/{bad:,.0f}" + if bad > 0: + chk_fmt = f"**{chk_fmt}**" + except (KeyError, ValueError): + chk_fmt = "n/a" + # A job that completed but whose data is not searchable (or whose index rebuild + # failed) must not look healthy: compare_legs.py marks it with the dagger. + if kv.get("searchable") == "no" or kv.get("index_status") == "error": + chk_fmt = "**" + chk_fmt.strip("*") + " · not searchable**" + return (f"| Bulk Import (`/ui/bulk-import`: `$bulk-submit`, until searchable) (resources/s) " + f"| {rate:,.0f} | n/a | n/a | n/a | {err_fmt} | {chk_fmt} |") print("### Results\n") print("| Suite | Throughput | p50 ms | p95 ms | p99 ms | Err% | Checks ✓/✗ |") print("|-------|----:|-------:|-------:|-------:|-----:|-----------:|") has_import = False + has_bulk = False + bulk_row = bulk_import_row() for f in files: suite = os.path.basename(f).replace('.json', '') try: @@ -2069,11 +2110,11 @@ jobs: print(f"| {suite} | _parse error: {e}_ | | | | | |") continue m = d.get('metrics', {}) - rps = m.get('http_reqs', {}).get('rate', 0) + rps = m.get('http_reqs', {}).get('rate') dur = m.get('http_req_duration', {}) - p50 = dur.get('med', 0) - p95 = dur.get('p(95)', 0) - p99 = dur.get('p(99)', 0) + p50 = dur.get('med') # absent key -> None -> printed as n/a, not a fake 0 + p95 = dur.get('p(95)') + p99 = dur.get('p(99)') # http_req_failed is a k6 Rate metric: the fraction lives in `value`, # NOT `rate` (which only exists on Counter metrics like http_reqs). err = m.get('http_req_failed', {}).get('value', 0) * 100 @@ -2084,14 +2125,34 @@ jobs: chk_fmt = f"**{chk_fmt}**" label = suite if suite == "import": - label = "Batch/Transaction Import, `POST /` Bundles (resources/s; latency per Bundle)" + label = "Batch/Transaction Import (`/ui/batch`: `POST /` Bundles) (resources/s; latency per Bundle)" rps, p50, p95, p99 = import_row(m) has_import = True rps_fmt = "n/a" if rps is None else f"{rps:,.0f}" - print(f"| {label} | {rps_fmt} | {p50:.1f} | {p95:.1f} | {p99:.1f} | {err_fmt} | {chk_fmt} |") - if has_import: - print("\n_Throughput is requests/s and latency is per request, except on the Batch/Transaction Import row " - "(resources/s and per-Bundle latency, see the **Import** line above)._") + p50_f, p95_f, p99_f = ("n/a" if v is None else f"{v:.1f}" for v in (p50, p95, p99)) + print(f"| {label} | {rps_fmt} | {p50_f} | {p95_f} | {p99_f} | {err_fmt} | {chk_fmt} |") + if suite == "import": + # Bulk import is not a k6 suite: its result is bulk-import.txt (bulk_import.py). + # Row only for a complete job with a numeric resources_per_s (compare_legs.py + # _load_bulk_import is more lenient); missing/skipped/partial/timeout/error: no row. + if bulk_row: + print(bulk_row) + has_bulk = True + if bulk_row and not has_bulk: + # Some k6 suites ran but not `import`: still show the bulk job, after them. + print(bulk_row) + has_bulk = True + if has_import or has_bulk: + note = "Throughput is requests/s and latency is per request" + if has_import: + note += (", except on the Batch/Transaction Import row (resources/s and per-Bundle latency, " + "see the **Batch/Transaction Import** line above; k6 drives it with 20 concurrent clients)") + if has_bulk: + note += ("; the Bulk Import row is resources/s end to end until searchable, with no per-request " + "latency (see the **Bulk Import** line above)" if has_import else + ", except on the Bulk Import row (resources/s end to end until searchable, with no " + "per-request latency, see the **Bulk Import** line above)") + print(f"\n_{note}._") # ── How loaded the shared Docker host was ────────────────────────── # @@ -2137,7 +2198,19 @@ jobs: print(f"\n**Environment:** crud Postgres cost **{per_call:.2f} ms/call** " f"({exec_s:,.0f} s over {calls:,} statements{load}).{flag}") PYEOF - } >> "$GITHUB_STEP_SUMMARY" + } | tee "$RUNNER_TEMP/leg-box.md" >> "$GITHUB_STEP_SUMMARY" + + # Charts for this leg, from the box captured above and the results dir. + # Display only: guarded so it can never fail the job. + - name: Leg charts + if: always() + continue-on-error: true + timeout-minutes: 3 + env: + LEG: ${{ matrix.backend }} + run: | + RESULTS_DIR="$GITHUB_WORKSPACE/bench-results/$LEG" + python3 "$GITHUB_WORKSPACE/.github/scripts/fhir-bench/md_charts.py" leg --box "$RUNNER_TEMP/leg-box.md" --leg "$LEG" --run-dir "$RESULTS_DIR" --layout sidebyside >> "$GITHUB_STEP_SUMMARY" || true # ── Final verification ─────────────────────────────────────────────── # The only way to confirm cleanup actually reclaimed this leg's @@ -2183,10 +2256,9 @@ jobs: # ──────────────────────────────────────────────────────────────────────────── # Cross-leg comparison: suites as rows, legs as columns (throughput, p95, - # errors; the Batch/Transaction Import, Bulk Import and reindex rows name the + # errors; the Batch/Transaction Import and Bulk Import rows name the # operation each times and sit together; the Throughput table also splits - # Bulk Import into its ingest and index-rebuild rows right under it; the reindex row appears - # only when a leg ran the opt-in indexing suite) and a leg-health table, so + # Bulk Import into its ingest and search-indexing rows right under it) and a leg-health table, so # a reader does not have to scroll six stacked per-leg summaries. # Display only: the job is continue-on-error and # compare_legs.py always exits 0, so it can never change the run's @@ -2210,10 +2282,15 @@ jobs: needs: [setup, benchmark] if: ${{ always() && needs.benchmark.result != 'skipped' }} runs-on: ubuntu-latest - timeout-minutes: 10 + # 20, was 10: the steps added after the summary (unzip the leg results, + # history, the HTML report) can take a few minutes on top of the original + # summary + uploads. All of them are continue-on-error with their own + # timeouts, so this is headroom, not a new way to fail the run. + timeout-minutes: 20 continue-on-error: true permissions: contents: read + actions: read steps: - name: Check out benchmark scripts continue-on-error: true @@ -2237,6 +2314,34 @@ jobs: path: bench-artifacts skip-decompress: true + # The leg artifacts were downloaded as zips (skip-decompress above). Unzip + # each into report-input// (the layout report_html.py reads: + # fhir-benchmark--//...), leaving out search-points.json, + # which can be hundreds of MB and which the report does not use. + - name: Unpack leg results for the report + if: always() + continue-on-error: true + timeout-minutes: 5 + run: | + mkdir -p report-input + find bench-artifacts -name '*.zip' -print0 2>/dev/null | while IFS= read -r -d '' z; do + n=$(basename "$z" .zip) + case "$n" in fhir-benchmark-*) ;; *) n=$(basename "$(dirname "$z")") ;; esac + unzip -q -o "$z" -x '*search-points.json' -d "report-input/$n" || echo "::warning::could not unzip $z" + done + ls report-input + + # Wall-clock of the run (jobs API + capacity_wait_s from the unpacked legs). + # Display only; a missing run-time.md leaves the comparison unchanged. + - name: Compute run time + if: always() + continue-on-error: true + timeout-minutes: 3 + env: + GH_TOKEN: ${{ github.token }} + run: | + python3 .github/scripts/fhir-bench/run_timing.py --repo "$GITHUB_REPOSITORY" --run-id "$GITHUB_RUN_ID" --run-dir report-input --out run-time.md --dump-json run-timing.json + - name: Write comparison summary if: always() env: @@ -2248,14 +2353,19 @@ jobs: DOWNLOAD_OUTCOME: ${{ steps.download.outcome }} run: | PY="$GITHUB_WORKSPACE/.github/scripts/fhir-bench/compare_legs.py" + TIMING_ARGS=() + if [ -s run-time.md ]; then TIMING_ARGS=(--timing run-time.md); fi if [ -f "$PY" ]; then - python3 "$PY" bench-artifacts > comparison.md \ + python3 "$PY" bench-artifacts "${TIMING_ARGS[@]}" > comparison.md \ || echo "::warning::compare_legs.py exited non-zero" else echo "::warning::compare_legs.py missing (checkout failed); no comparison written" printf '## FHIR Benchmark — leg comparison\n\n_Not available: the comparison script could not be checked out._\n' > comparison.md fi cat comparison.md >> "$GITHUB_STEP_SUMMARY" + # Collapsed "### Charts" section, appended right after the tables. + # Display only: never fails the step. + python3 .github/scripts/fhir-bench/md_charts.py compare --in comparison.md --layout sidebyside >> "$GITHUB_STEP_SUMMARY" || true # Raw Markdown for pasting into an issue or PR (the summary page only # offers rendered tables). Named fhir-bench-*, NOT fhir-benchmark-*, so a @@ -2269,3 +2379,90 @@ jobs: path: comparison.md retention-days: 90 if-no-files-found: ignore + + # Trend over the last runs of this branch. Display only: it can never + # fail the run (continue-on-error, a 5 minute timeout, and the summary append is guarded). + # It runs after "Upload comparison" so a slow `gh` call can never cost the run its artifact. + # history.md is NOT appended here any more: the last step does it, so the + # report link lands after it. --data-dir receives the report-data.json of + # earlier runs (artifact fhir-bench-report-data-) for the HTML trend. + - name: Write run history + if: always() + continue-on-error: true + timeout-minutes: 5 + env: + GH_TOKEN: ${{ github.token }} + run: | + python3 .github/scripts/fhir-bench/history.py --repo "$GITHUB_REPOSITORY" --branch "$GITHUB_REF_NAME" --run-id "$GITHUB_RUN_ID" --current comparison.md --artifact-name fhir-bench-comparison --out history.md --max-runs 5 --data-dir "$RUNNER_TEMP/trend" + + # comparison.md exists only after the summary step, so it is staged here. + - name: Stage comparison for the report + if: always() + continue-on-error: true + run: | + mkdir -p report-input + # report_html.py finds comparison.md inside --run-dir (or its parent). + cp comparison.md report-input/ 2>/dev/null || true + + - name: Build HTML report + if: always() + continue-on-error: true + timeout-minutes: 5 + env: + MATRIX_JSON: ${{ needs.setup.outputs.matrix }} + run: | + EXPECT_LEGS=$(python3 -c 'import json,os;print(",".join(i["backend"] for i in json.loads(os.environ["MATRIX_JSON"])["include"]))' 2>/dev/null || true) + TIMING_JSON_ARGS=() + if [ -s run-timing.json ]; then TIMING_JSON_ARGS=(--timing-json run-timing.json); fi + python3 .github/scripts/fhir-bench/report_html.py \ + "${TIMING_JSON_ARGS[@]}" \ + --run-dir report-input \ + --expect-legs "$EXPECT_LEGS" \ + --run-id "$GITHUB_RUN_ID" \ + --repo "$GITHUB_REPOSITORY" \ + --branch "$GITHUB_REF_NAME" \ + --sha "$GITHUB_SHA" \ + --out "fhir-bench-report-$GITHUB_RUN_ID.html" \ + --dump-json report-data.json \ + --trend-dir "$RUNNER_TEMP/trend" \ + --no-shapes + + # archive: false uploads the single .html as-is (not zipped), so it opens + # in the browser from the artifact link. + - name: Upload HTML report + id: report + if: always() + continue-on-error: true + uses: actions/upload-artifact@v7 + with: + name: fhir-bench-report-${{ github.run_id }} + path: fhir-bench-report-${{ github.run_id }}.html + archive: false + retention-days: 90 + if-no-files-found: ignore + + # The data the next runs read through history.py --data-dir. + - name: Upload report data + if: always() + continue-on-error: true + uses: actions/upload-artifact@v7 + with: + name: fhir-bench-report-data-${{ github.run_id }} + path: | + report-data.json + run-timing.json + retention-days: 90 + if-no-files-found: ignore + + # LAST on purpose: history table, then the link to the full report. + # The artifact link works for signed-in viewers of the repository only. + - name: Append history and report link + if: always() + continue-on-error: true + env: + REPORT_URL: ${{ steps.report.outputs.artifact-url }} + run: | + if [ -f history.md ]; then cat history.md >> "$GITHUB_STEP_SUMMARY"; fi + if [ -n "$REPORT_URL" ]; then + printf '\n[Full report (HTML)](%s)\n' "$REPORT_URL" >> "$GITHUB_STEP_SUMMARY" + fi diff --git a/MANUAL_TESTING_MATRIX.md b/MANUAL_TESTING_MATRIX.md index 4be6720dc1..e1f1ef3854 100644 --- a/MANUAL_TESTING_MATRIX.md +++ b/MANUAL_TESTING_MATRIX.md @@ -295,11 +295,9 @@ Use these settings for the whole pass; do not restart HFS between T3 and T4: Without `REINDEX_REFRESH=false` the search rebuild in 7.4 is several times slower. -Leave `HFS_BULK_SUBMIT_DEFER_INDEXING` at its default (`true`) on rows without -Elasticsearch: the import stores first and the search index is rebuilt afterwards -(7.4). On `*-es` rows set `HFS_BULK_SUBMIT_DEFER_INDEXING=false` with -`HFS_BULK_SUBMIT_INDEX_QUEUE=64`, `HFS_BULK_SUBMIT_INDEX_CONCURRENCY=8` and -`HFS_BULK_SUBMIT_INDEX_COALESCE=4`, the settings of the #937 reference run (§14). +Set `HFS_BULK_SUBMIT_DEFER_INDEXING` and the related settings for each row as the +[indexing-mode table](crates/rest/README.md#bulk-submit-indexing-mode-per-storage-backend) +says (deferred on standalone rows, inline on `*-es` rows). Record the mode in the matrix cell, because it changes what 7.4 and §14 measure. ### Cost of the status page during T3 @@ -1370,7 +1368,9 @@ For each backend row, attach to the release issue: - **The T3 searchable time**: from the same start to the rebuild reaching `completed` (7.4), plus the rebuild's own elapsed time and its `$reindex-status` summary. - Reference (#937, `sqlite-es`): 18,955,865 resources in 4 h 36 m 47 s from creation - to Completed, searchable at that point, with the section 5 `*-es` settings. + to Completed, searchable at that point, run inline with `HFS_BULK_SUBMIT_INDEX_QUEUE=64`, + `HFS_BULK_SUBMIT_INDEX_CONCURRENCY=8` and `HFS_BULK_SUBMIT_INDEX_COALESCE=4`; the current + settings are in the section 5 pointer table. - **The final database size** and the resource count it holds: ```bash diff --git a/crates/hfs/README.md b/crates/hfs/README.md index 980ccde66d..9e72423815 100644 --- a/crates/hfs/README.md +++ b/crates/hfs/README.md @@ -136,6 +136,8 @@ recorded by `Type/id`, with Elasticsearch's `error.type` and `reason` when it gave one, in `GET /$reindex-status/{job_id}`. See [Bulk writes and rebuilds on Elasticsearch-backed composites](../persistence/README.md#bulk-writes-and-rebuilds-on-elasticsearch-backed-composites). +For `$bulk-submit`, which indexing mode and settings to run per backend are in the [indexing-mode table](../rest/README.md#bulk-submit-indexing-mode-per-storage-backend); the paragraph below is only about the `$reindex` rebuild. + On `sqlite-elasticsearch`, the recommended pair for a bulk import is `HFS_ELASTICSEARCH_WRITE_REFRESH=wait_for` with `HFS_ELASTICSEARCH_REINDEX_REFRESH=false`: ordinary writes stay diff --git a/crates/rest/README.md b/crates/rest/README.md index a7cee0d826..061dc9da91 100644 --- a/crates/rest/README.md +++ b/crates/rest/README.md @@ -459,7 +459,7 @@ Configured via `HFS_BULK_SUBMIT_*` environment variables: | `HFS_BULK_SUBMIT_FILE_CONCURRENCY` | `1` | How many of a single manifest's files one worker ingests at once (fan-out). **SQLite always runs at `1` regardless of the configured value** because it serialises writers; a higher fan-out queues batch writes behind one lock until they outlast `busy_timeout` and abort the import (#942). On standalone PostgreSQL, an effective value above `1` runs admitted output files in independent Tokio tasks. Existing standalone PostgreSQL deployments configured above `1` change scheduling on upgrade. Setting `1` restores inline scheduling and also reduces concurrency to one; there is no switch that keeps inline scheduling above `1`. Every other mode, including PostgreSQL plus Elasticsearch, keeps inline scheduling at its current effective concurrency. | | `HFS_BULK_SUBMIT_DISABLE_LOCAL_WORKER` | `false` | Disable in-pod workers. | | `HFS_BULK_SUBMIT_MAX_CONCURRENT_PER_TENANT` | `4` | Per-tenant active-submission cap (kick-off returns `429` if exceeded). | -| `HFS_BULK_SUBMIT_BATCH_SIZE` | `100` | Resources per ingestion batch, one database transaction each. Honoured by the worker since #1127 (before, every run used `100` whatever this said). With index-during-ingest on, `1000` measured slower than `100`. | +| `HFS_BULK_SUBMIT_BATCH_SIZE` | `100` | Resources per ingestion batch, one database transaction each. Honoured by the worker since #1127 (before, every run used `100` whatever this said). An older measurement (index-during-ingest on, before the Elasticsearch recipe below) found `1000` slower than `100`. The recipe below, measured later on the same 133,527-resource slice, uses `1000` as part of a combined setting and was the better combination; batch size alone was not isolated again. | | `HFS_BULK_SUBMIT_FETCH_READ_TIMEOUT` | `60` | Seconds the input-file fetcher waits for the next bytes before treating the body as broken and resuming it with `Range`. Connecting is capped at 10 s. | | `HFS_BULK_SUBMIT_SKIP_UNCHANGED` | `false` | SQLite and PostgreSQL: leave a stored resource untouched when the submitted one is identical apart from `meta.versionId`/`meta.lastUpdated`, so replaying a manifest writes no new versions. | | `HFS_BULK_SUBMIT_INDEX_QUEUE` | `16` | Committed batches each index-during-ingest writer may hold queued. | @@ -467,7 +467,7 @@ Configured via `HFS_BULK_SUBMIT_*` environment variables: | `HFS_BULK_SUBMIT_INDEX_COALESCE` | `4` | Queued batches one writer merges into a single write to the secondary. Raising it to `16` measured 34 % slower. | | `HFS_BULK_SUBMIT_INDEX_MAX_WAIT` | `30` | Seconds the ingest waits for room in a writer queue; past it the batch is marked unindexed and repaired by the deferred reindex, so a slow secondary never stalls the ingest or its lease. | | `HFS_BULK_SUBMIT_INDEX_PAGE_BYTES` | `33554432` | Most bytes of resource content one write to the secondary carries; a larger coalesced page goes out in several writes, each within its own `HFS_BULK_SUBMIT_INDEX_MAX_WAIT`. `0` = unbounded. Measured (#939): 4 × 1,000 Provenance (~100 KB each) made one 400 MB page that timed out although Elasticsearch applied it. | -| `HFS_BULK_SUBMIT_DEFER_INDEXING` | `true` | Bulk fast-load (#903): ingest without search-index/FTS writes, then rebuild them after each manifest. Compatible automatic requests for one tenant share one active generation and one pending type set (#1087), so manifest overlap does not start concurrent full-type scans. The coordination is process-local and does not include explicit `$reindex`; a restart can still leave stored resources unsearchable until manual repair. See [`docs/deferred-reindex-coordination-benchmark.md`](../../docs/deferred-reindex-coordination-benchmark.md) for the exact lifecycle, limits, and PostgreSQL measurement protocol. Set `false` to close the post-publication window at the cost measured by `crates/hfs/tests/bulk_submit/run_defer_indexing_benchmark.sh`. On a composite with Elasticsearch, `false` selects index-during-ingest (#1127): each committed batch reaches the secondary through the `HFS_BULK_SUBMIT_INDEX_*` writers below, and the deferred reindex runs only for types with rejected entries. The former `HFS_BULK_SUBMIT_INDEX_DURING_INGEST` was folded into this switch (#1242); a server started with it set refuses to start and names the replacement. | +| `HFS_BULK_SUBMIT_DEFER_INDEXING` | `true` | Bulk fast-load (#903): ingest without search-index/FTS writes, then rebuild them after each manifest. Compatible automatic requests for one tenant share one active generation and one pending type set (#1087), so manifest overlap does not start concurrent full-type scans. The coordination is process-local and does not include explicit `$reindex`; a restart can still leave stored resources unsearchable until manual repair. See [`docs/deferred-reindex-coordination-benchmark.md`](../../docs/deferred-reindex-coordination-benchmark.md) for the exact lifecycle, limits, and PostgreSQL measurement protocol. Which value to run per backend: see [`$bulk-submit` indexing mode per storage backend](#bulk-submit-indexing-mode-per-storage-backend). Set `false` to close the post-publication window at the cost measured by `crates/hfs/tests/bulk_submit/run_defer_indexing_benchmark.sh`. On a composite with Elasticsearch, `false` selects index-during-ingest (#1127): each committed batch reaches the secondary through the `HFS_BULK_SUBMIT_INDEX_*` writers below, and the deferred reindex runs only for types with rejected entries. The former `HFS_BULK_SUBMIT_INDEX_DURING_INGEST` was folded into this switch (#1242); a server started with it set refuses to start and names the replacement. | | `HFS_BULK_SUBMIT_LEASE_DURATION` | `60` | Initial manifest lease length, seconds. Must exceed the heartbeat interval. | | `HFS_WORKER_SHUTDOWN_TIMEOUT` | `20` | Seconds a graceful shutdown waits for the bulk export and submit workers to stop and release their leases (#1531). A released manifest is claimable by another instance at once; the next run skips the output files this one walked to their end and re-walks only the rest (#1610), whose committed entries upsert idempotently. Past the deadline, leases lapse after the lease duration as before. | | `HFS_BULK_SUBMIT_HEARTBEAT_INTERVAL` | `20` | Worker heartbeat cadence, seconds. | @@ -478,20 +478,33 @@ Configured via `HFS_BULK_SUBMIT_*` environment variables: | `HFS_BULK_SUBMIT_OUTBOUND_SCOPE` | `system/*.rs` | Read scope requested for file-retrieval tokens (never `system/bulk-submit`). | | `HFS_BULK_SUBMIT_DECRYPTION_KEY` | *(none)* | P-256/P-384 private key(s) for `ECDH-ES*` JWE key management — PEM (PKCS#8/SEC1) or a JWK / JWK Set. | -**Recommended for bulk loads on an Elasticsearch composite (`pg-es`, `sqlite-es`, `mongo-es`).** Measured on the full Synthea corpus (18.96 M resources, 6 cores): 1 h 45 min until every resource is searchable, against more than 7 h with the deferred rebuild (#939). +##### `$bulk-submit` indexing mode per storage backend + +This is the single source of truth for which indexing mode to run; other documents point here. Deferred = ingest first, then one search-index rebuild. Inline = each committed batch is indexed while it is ingested. Every figure below is the seconds or ratio until all resources are searchable, on one slice of 133,527 resources, from single runs (except the cells that list two or three runs; run-to-run spread is large, e.g. 18-52 s for identical Elasticsearch settings). + +| Backend | Mode | Settings | Measured | +|---|---|---|---| +| `sqlite` | deferred | `HFS_BULK_SUBMIT_DEFER_INDEXING=true` (the default). `HFS_BULK_SUBMIT_FILE_CONCURRENCY` has no effect: SQLite always ingests one file at a time | 26-27 % faster than inline | +| `postgres` | deferred | `HFS_BULK_SUBMIT_DEFER_INDEXING=true` (the default) | 26-27 % faster than inline | +| `mongodb` | deferred | `HFS_BULK_SUBMIT_DEFER_INDEXING=true` (the default) | a tie with inline | +| `sqlite` + Elasticsearch | inline | recipe below (`HFS_BULK_SUBMIT_FILE_CONCURRENCY` has no effect here either: the primary is SQLite) | 24.0 s and 18.0 s in two runs (defaults inline: ~80-82 s) | +| `postgres` + Elasticsearch | inline | recipe below | 24.1 s and 24.1 s in two runs (defaults inline: ~80-82 s); a 3.7x larger slice: 203.5 s, peak RSS 2.97 GB against 2.15 GB | +| `mongodb` + Elasticsearch | inline | recipe below | 32.2 s and 52.1 s in two runs (defaults inline: ~80-82 s) | + +The Elasticsearch recipe (code defaults in parentheses): ```bash -HFS_BULK_SUBMIT_DEFER_INDEXING=false # index each committed batch during ingest -HFS_ELASTICSEARCH_REINDEX_REFRESH=false -HFS_ELASTICSEARCH_BULK_CONCURRENCY=4 -HFS_BULK_SUBMIT_BATCH_SIZE=1000 -HFS_BULK_SUBMIT_FILE_CONCURRENCY=4 -HFS_BULK_SUBMIT_INDEX_CONCURRENCY=4 # about one core each; 8 on 8+ cores -HFS_BULK_SUBMIT_INDEX_QUEUE=16 # bounds HFS memory -HFS_PG_MAX_CONNECTIONS=32 +HFS_BULK_SUBMIT_DEFER_INDEXING=false # (true) index inline with the ingest +HFS_BULK_SUBMIT_FILE_CONCURRENCY=4 # (1) +HFS_BULK_SUBMIT_BATCH_SIZE=1000 # (100) +HFS_ELASTICSEARCH_BULK_CONCURRENCY=4 # (1) ``` -Leave `HFS_ELASTICSEARCH_REFRESH_INTERVAL` at its `1s` default. An earlier version of this block set it to `30s`, but the 1 h 45 min figure above came from a run that also carried other import fixes, so it was never isolated. Measured in isolation (#1749; `pg-es`, PostgreSQL 16, Elasticsearch 8.15.0, 8 CPU / 23 GB, 919,752 resources, 3 runs per value), the interval does not change the import time: `1s` 223 s, `5s` 220 s, `30s` 220 s on average (under 2 % apart, which is within run-to-run noise). It only lowers Elasticsearch's CPU (about 95 % at `1s`, about 40 % at `30s`). A long interval has a cost: with `HFS_ELASTICSEARCH_WRITE_REFRESH=wait_for` every interactive write waits for the next refresh, and the server itself takes about 200 s to start on an empty cluster at `30s`, against 10 s at `1s`, because seeding the search parameters waits for refreshes too. `-1` together with `wait_for` never became ready in 10 minutes (three runs). The measurement at the full 18.96 M-resource scale is still open on #1749. Leave `HFS_BULK_SUBMIT_INDEX_COALESCE`, `HFS_BULK_SUBMIT_INDEX_MAX_WAIT` and `HFS_BULK_SUBMIT_INDEX_PAGE_BYTES` at their defaults. Plan for ~15 GB of HFS memory while a file of large resources (~100 KB each) is ingested. Resources the index rejects under load are marked unindexed and rebuilt one by one when the manifest completes. They are stored, so the completion manifest lists them in its `outcome` file as `warning`s (`incomplete`, "HFS starts a reindex that rebuilds its search index entries once the manifest completes; no manual $reindex is needed"), not as errors, and they are not counted in `failed_entries`; only a server without an automatic reindex reports them as `error`s asking for `POST /{type}/$reindex` (#1666). The warning points at `GET /$reindex-status/{job_id}` to follow that repair; the job id is in the `deferred reindex generation started` log line. Only if no such job started is a manual `POST /{type}/$reindex` needed. The log says `rebuilding search index entries for the resources the index rejected during ingest`, or `indexed every resource during ingest; no deferred reindex needed` when there were none. +The measurements and the CI benchmark also keep `HFS_ELASTICSEARCH_WRITE_REFRESH=wait_for`, a 200 ms refresh interval, `HFS_ELASTICSEARCH_REINDEX_REFRESH=false` for the rebuild and 32-connection database pools; those are the benchmark's own settings, not part of the recipe. + +What was measured and did **not** help: raising the Elasticsearch refresh interval from the benchmark's 200 ms to 1 s (about twice as slow with `HFS_ELASTICSEARCH_WRITE_REFRESH=wait_for`, about equal with `false`); a longer index queue with 8 index workers (unstable on `postgres` + Elasticsearch: 18, 132 and 64 s in three runs); and the earlier #941 recipe on `mongodb` + Elasticsearch (40 s). Deferred indexing also exists on Elasticsearch composites (`HFS_BULK_SUBMIT_DEFER_INDEXING=true`), but it is not recommended there. An earlier full-corpus measurement (18.96 M resources, #939) took 1 h 45 min inline against more than 7 h deferred. Leave `HFS_BULK_SUBMIT_INDEX_COALESCE`, `HFS_BULK_SUBMIT_INDEX_MAX_WAIT` and `HFS_BULK_SUBMIT_INDEX_PAGE_BYTES` at their defaults. Plan for about 15 GB of HFS memory while a file of large resources (~100 KB each) is ingested. + +Leave `HFS_ELASTICSEARCH_REFRESH_INTERVAL` at its `1s` code default (the benchmark sets 200 ms together with `HFS_ELASTICSEARCH_WRITE_REFRESH=wait_for` in synchronous mode; `1s` with `wait_for` was slower, 46-50 s against 24 s, and `1s` with `false` was about equal to the recipe; the recommendation stands: do not tune it for bulk submit). An earlier version of this block set it to `30s`, but the 1 h 45 min figure above came from a run that also carried other import fixes, so it was never isolated. Measured in isolation (#1749; `pg-es`, PostgreSQL 16, Elasticsearch 8.15.0, 8 CPU / 23 GB, 919,752 resources, 3 runs per value), the interval does not change the import time: `1s` 223 s, `5s` 220 s, `30s` 220 s on average (under 2 % apart, which is within run-to-run noise). It only lowers Elasticsearch's CPU (about 95 % at `1s`, about 40 % at `30s`). A long interval has a cost: with `HFS_ELASTICSEARCH_WRITE_REFRESH=wait_for` every interactive write waits for the next refresh, and the server itself takes about 200 s to start on an empty cluster at `30s`, against 10 s at `1s`, because seeding the search parameters waits for refreshes too. `-1` together with `wait_for` never became ready in 10 minutes (three runs). The measurement at the full 18.96 M-resource scale is still open on #1749. Resources the index rejects under load are marked unindexed and rebuilt one by one when the manifest completes. They are stored, so the completion manifest lists them in its `outcome` file as `warning`s (`incomplete`, "HFS starts a reindex that rebuilds its search index entries once the manifest completes; no manual $reindex is needed"), not as errors, and they are not counted in `failed_entries`; only a server without an automatic reindex reports them as `error`s asking for `POST /{type}/$reindex` (#1666). The warning points at `GET /$reindex-status/{job_id}` to follow that repair; the job id is in the `deferred reindex generation started` log line. Only if no such job started is a manual `POST /{type}/$reindex` needed. The log says `rebuilding search index entries for the resources the index rejected during ingest`, or `indexed every resource during ingest; no deferred reindex needed` when there were none. For protected provider files (`requiresAccessToken`), HFS acquires a read-scoped token via SMART Backend Services (`client_credentials` + `private_key_jwt`) when diff --git a/crates/rest/src/bulk_submit_fetcher.rs b/crates/rest/src/bulk_submit_fetcher.rs index 00c9684652..707376b22b 100644 --- a/crates/rest/src/bulk_submit_fetcher.rs +++ b/crates/rest/src/bulk_submit_fetcher.rs @@ -635,6 +635,8 @@ impl ResumableBody { Err(e) => Some((Err(e), None)), } }) + // StreamReader re-polls after EOF and `unfold` panics when polled after None. + .fuse() } async fn next_chunk(&mut self) -> std::io::Result> { diff --git a/crates/rest/src/handlers/sof/run.rs b/crates/rest/src/handlers/sof/run.rs index 86d22dd338..b2840c8a1d 100644 --- a/crates/rest/src/handlers/sof/run.rs +++ b/crates/rest/src/handlers/sof/run.rs @@ -1265,9 +1265,13 @@ fn channel_body_response( content_type: &'static str, runner_label: Option<&str>, ) -> Response { + // `unfold` panics if polled again after it ends. The compression layer's + // body reader does exactly that when the client sends `Accept-Encoding`, + // which aborted the response with an empty gzip body — so fuse it. let body_stream = futures::stream::unfold(rx, |mut rx| async move { rx.recv().await.map(|chunk| (chunk, rx)) - }); + }) + .fuse(); let body = axum::body::Body::from_stream(body_stream); let mut response = Response::new(body); diff --git a/crates/rest/tests/http_compression.rs b/crates/rest/tests/http_compression.rs index 1db7d51f3d..8b30a0b522 100644 --- a/crates/rest/tests/http_compression.rs +++ b/crates/rest/tests/http_compression.rs @@ -393,3 +393,57 @@ async fn test_cors_preflight_allows_content_encoding() { "Access-Control-Allow-Headers was: {allow_headers}" ); } + +/// A streamed NDJSON `$sql-run` body (chunked, no `Content-Length`) must come +/// back as a valid gzip stream when the client asks for gzip. +#[tokio::test] +async fn test_streamed_ndjson_sql_run_is_gzip_compressed() { + let server = create_test_server(test_config()); + + for family in ["Alpha", "Beta", "Gamma"] { + let response = server + .post("/Patient") + .add_header("x-tenant-id", "test-tenant") + .json(&json!({"resourceType": "Patient", "name": [{"family": family}]})) + .await; + assert_eq!(response.status_code(), StatusCode::CREATED); + } + let response = server + .put("/ViewDefinition/gz-vd") + .add_header("x-tenant-id", "test-tenant") + .json(&json!({ + "resourceType": "ViewDefinition", + "id": "gz-vd", + "resource": "Patient", + "status": "active", + "select": [{"column": [{"name": "family", "path": "name.family", "type": "string"}]}] + })) + .await; + assert!(response.status_code().is_success(), "{}", response.text()); + + let response = server + .get("/$sql-run?subjectReference=ViewDefinition/gz-vd&_format=ndjson&_limit=100") + .add_header("x-tenant-id", "test-tenant") + .add_header("accept-encoding", "gzip") + .await; + + assert_eq!( + response.status_code(), + StatusCode::OK, + "{}", + response.text() + ); + assert_eq!( + response.headers().get("content-encoding").unwrap(), + "gzip", + "streamed ndjson must be gzip-encoded when requested" + ); + let body = gunzip_bytes(response.as_bytes()); + let mut families: Vec = String::from_utf8(body) + .unwrap() + .lines() + .map(|l| serde_json::from_str::(l).unwrap()["family"].to_string()) + .collect(); + families.sort(); + assert_eq!(families, ["\"Alpha\"", "\"Beta\"", "\"Gamma\""]); +}