From 91901f0ee8e336af61fb54e559aadb479a7cc1c9 Mon Sep 17 00:00:00 2001 From: Edson Terceros Date: Fri, 23 Oct 2026 12:46:35 +0000 Subject: [PATCH 01/12] ci(bench): present import as the two UI processes and add a Bulk Import row The web UI exposes two import processes: Batch/Transaction (/ui/batch) and Bulk Import (/ui/bulk-import, $bulk-submit). The benchmark report showed four import rows named after internal phases, and the per-leg Results table had no Bulk Import row at all (it only lists k6 suites). - Name the rows after the UI: "Batch/Transaction Import (`/ui/batch`: ...)" and "Bulk Import (`/ui/bulk-import`: `$bulk-submit`, until searchable)", with the two phases as indented sub-rows (ingest until Completed, search-index rebuild after Completed). - Add the Bulk Import row to the per-leg Results table from bulk-import.txt: resources/s end to end, Err% = failed/submitted, Checks = resources ok/failed; p50/p95/p99 are n/a because it is a single async job. The row is only printed for a complete job, so reports of runs without bulk import are unchanged. - Move "k6 drives it with 20 concurrent clients" from the row labels to the legend, and use "search-index rebuild" consistently (it was also called "initial index" / "index rebuild"). Numbers, formulas, row order, best-value bolding and markers are unchanged. Co-Authored-By: Claude Sonnet 5.5 --- .github/scripts/fhir-bench/compare_legs.py | 49 +++++++------ .github/scripts/fhir-bench/suite-lib.sh | 2 +- .../scripts/fhir-bench/summary_backends.py | 4 +- .../scripts/fhir-bench/test_compare_legs.py | 20 +++-- .../fhir-bench/test_summary_backends.py | 6 +- .github/workflows/fhir-benchmark.yml | 73 ++++++++++++++++--- 6 files changed, 110 insertions(+), 44 deletions(-) diff --git a/.github/scripts/fhir-bench/compare_legs.py b/.github/scripts/fhir-bench/compare_legs.py index 2dbfcd20a2..2417b470e3 100644 --- a/.github/scripts/fhir-bench/compare_legs.py +++ b/.github/scripts/fhir-bench/compare_legs.py @@ -15,7 +15,7 @@ # and indexing.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 +# seconds, how long loading the corpus takes) and search-index rebuild (seconds of the # deferred search-index rebuild after it, `inline (during 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` @@ -119,16 +119,16 @@ 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 " + "run before it, or the ES index not drained); on Bulk Import and its search-index rebuild, 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 " + "that suite (on Bulk Import and its ingest, any resource not ingested; on its search-index " + "rebuild, 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 " "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-index rebuild 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 " + "fresh database, kick-off until the search index covers it, and its ingest and search-index " + "rebuild 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 · " @@ -145,15 +145,15 @@ # 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)", # 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`", + ("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`)", # 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", @@ -161,8 +161,8 @@ } # 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-index rebuild after Completed (seconds)" # index_seconds is 0 when HFS indexed while ingesting; that is not a free index. INLINE_INDEX = "inline (during ingest)" # bulk_import.py index_status values that mean the deferred rebuild did not finish cleanly. @@ -175,18 +175,19 @@ "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-index rebuild 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 " + "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-index rebuild** = seconds from Completed 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 " + "— it is not a zero-second rebuild; `+ 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)." @@ -206,7 +207,7 @@ "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 " + "data, which is the Bulk Import search-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 " @@ -1026,7 +1027,7 @@ def _health_row(d, rows): "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); " "**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-index rebuild 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 +1052,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") @@ -1124,7 +1125,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-index rebuild 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.""" diff --git a/.github/scripts/fhir-bench/suite-lib.sh b/.github/scripts/fhir-bench/suite-lib.sh index 1a9f95d6e7..5c667ee919 100644 --- a/.github/scripts/fhir-bench/suite-lib.sh +++ b/.github/scripts/fhir-bench/suite-lib.sh @@ -497,7 +497,7 @@ write_search_counts() { # 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 +# may skew both; bulk-import's search-index rebuild row is the default # indexing number. # # Timing is the job's own `$reindex-status` startedAt → completedAt diff --git a/.github/scripts/fhir-bench/summary_backends.py b/.github/scripts/fhir-bench/summary_backends.py index efdb8509db..e2f464c555 100755 --- a/.github/scripts/fhir-bench/summary_backends.py +++ b/.github/scripts/fhir-bench/summary_backends.py @@ -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}) = " diff --git a/.github/scripts/fhir-bench/test_compare_legs.py b/.github/scripts/fhir-bench/test_compare_legs.py index 67d8ca0891..b2cf6a5469 100644 --- a/.github/scripts/fhir-bench/test_compare_legs.py +++ b/.github/scripts/fhir-bench/test_compare_legs.py @@ -21,12 +21,12 @@ RUN = "100" SUITES = ("prewarm", "import", "crud", "search") 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)" +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-index rebuild after Completed (seconds)" REINDEX = "reindex, `$reindex` Encounter" REINDEX_ROW = REINDEX + " (resources/s)" _guard = {"on": False} @@ -450,6 +450,16 @@ def test_loading_rows_together_and_named(self): self.assertEqual(labels(md, "Errors"), ["prewarm", IMPORT, BULK, REINDEX, "crud", "search", "insert"]) self.assertNotIn("$import", md) # HFS has none; no label may suggest it + # 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-index rebuild", never "initial index" + self.assertNotIn("initial index", md) + self.assertNotIn("initial-index", md) + self.assertIn("search-index rebuild", md) self.assertIn("`†` crud/search/reindex ran on an incomplete corpus", md) self.assertIn("on reindex, any reindex error or a failed job", md) self.assertIn("shown only when no leg in that row carries a marker or `(partial)`", md) diff --git a/.github/scripts/fhir-bench/test_summary_backends.py b/.github/scripts/fhir-bench/test_summary_backends.py index 4e29518c21..db65944ed4 100644 --- a/.github/scripts/fhir-bench/test_summary_backends.py +++ b/.github/scripts/fhir-bench/test_summary_backends.py @@ -48,14 +48,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,7 +63,7 @@ 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) diff --git a/.github/workflows/fhir-benchmark.yml b/.github/workflows/fhir-benchmark.yml index 1c70112609..a4a0672a2a 100644 --- a/.github/workflows/fhir-benchmark.yml +++ b/.github/workflows/fhir-benchmark.yml @@ -60,10 +60,10 @@ name: FHIR Server Benchmark # 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-index rebuild after Completed (seconds)` # (seconds of the deferred search-index rebuild that follows: how # long until that freshly loaded data is indexed; `inline (during ingest)` # when HFS indexed while ingesting, HFS_BULK_SUBMIT_DEFER_INDEXING=false). @@ -101,7 +101,7 @@ name: FHIR Server Benchmark # *-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 +# indexed is the `↳ search-index rebuild after Completed (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 @@ -145,7 +145,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,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 search-index rebuild rows) always runs last and can add up to ~70 min per leg; 'prewarm,import,crud,search,insert' skips it" required: false default: "all" vus: @@ -2056,10 +2056,46 @@ jobs: it = m.get('iteration_duration', {}) return rate, it.get('med', 0), it.get('p(95)', 0), it.get('p(99)', 0) + 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: @@ -2084,14 +2120,33 @@ 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)._") + 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 ────────────────────────── # From 7f4addbdd38e4d452cc93a4d0b30264184c3cba4 Mon Sep 17 00:00:00 2001 From: Edson Terceros Date: Mon, 26 Oct 2026 10:59:54 +0000 Subject: [PATCH 02/12] ci(bench): indexing recipe per leg, search indexing row, sql-run suite, run history - Remove the opt-in `indexing` ($reindex) suite and its report row. - Set the bulk-import indexing mode explicitly per leg: deferred on the standalone backends; inline with 4 files x 4 ES bulk workers and batches of 1000 on every Elasticsearch leg. Document it in one table in crates/rest/README.md. - Rename the Bulk Import sub-row to `search indexing (seconds)`; Elasticsearch legs show `N s (= ingest)`. - Add the `sql-run` k6 suite (five views on Observation, Claim and ExplanationOfBenefit) with a per-view table in the leg summary. - Append a collapsed run history with Mermaid charts to the compare summary. Co-Authored-By: Claude Sonnet 5.5 --- .github/scripts/fhir-bench/README.md | 32 ++ .github/scripts/fhir-bench/bulk-import.sh | 13 + .github/scripts/fhir-bench/compare_legs.py | 217 ++++-------- .github/scripts/fhir-bench/history.py | 330 ++++++++++++++++++ .github/scripts/fhir-bench/k6/sql-run.js | 151 ++++++++ .github/scripts/fhir-bench/suite-lib.sh | 173 +-------- .../scripts/fhir-bench/summary_backends.py | 112 +++--- .../scripts/fhir-bench/test_compare_legs.py | 200 +++-------- .github/scripts/fhir-bench/test_history.py | 150 ++++++++ .../fhir-bench/test_summary_backends.py | 87 +++-- .github/workflows/fhir-benchmark.yml | 137 +++----- MANUAL_TESTING_MATRIX.md | 12 +- crates/hfs/README.md | 2 + crates/rest/README.md | 33 +- 14 files changed, 952 insertions(+), 697 deletions(-) create mode 100644 .github/scripts/fhir-bench/README.md create mode 100644 .github/scripts/fhir-bench/history.py create mode 100644 .github/scripts/fhir-bench/k6/sql-run.js create mode 100644 .github/scripts/fhir-bench/test_history.py diff --git a/.github/scripts/fhir-bench/README.md b/.github/scripts/fhir-bench/README.md new file mode 100644 index 0000000000..82fdf451fc --- /dev/null +++ b/.github/scripts/fhir-bench/README.md @@ -0,0 +1,32 @@ +# 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. diff --git a/.github/scripts/fhir-bench/bulk-import.sh b/.github/scripts/fhir-bench/bulk-import.sh index 19b592d1b4..f147a6a219 100755 --- a/.github/scripts/fhir-bench/bulk-import.sh +++ b/.github/scripts/fhir-bench/bulk-import.sh @@ -127,6 +127,19 @@ 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-32 s for this recipe + # (index while ingesting, 4 files x 4 ES bulk workers, batches of 1000). + # 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/compare_legs.py b/.github/scripts/fhir-bench/compare_legs.py index 2417b470e3..00c6722017 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 search-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 search-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 search-index " - "rebuild, 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 search-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 search-index " - "rebuild 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 = ( @@ -150,21 +137,23 @@ ("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 (`/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`)", - # 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", } # The two phases of the bulk-import job, as Throughput rows right under the # combined bulk-import row (_bulk_phase_lines). BULK_INGEST_LABEL = "↳ ingest, until Completed (resources/s, seconds)" -BULK_INDEX_LABEL = "↳ search-index rebuild after Completed (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 = ( @@ -178,20 +167,26 @@ "scenario, against resources until the search index covers them. k6 drives it with 20 concurrent clients." ) BULK_PHASES_NOTE = ( - "Bulk Import ingest and search-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 (the web UI then " "shows the submission as Completed), those seconds in brackets: how long loading the " - "corpus takes. **Search-index rebuild** = seconds from Completed 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 rebuild; `+ N s rebuild` is a follow-up rebuild of the types 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 " @@ -199,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 search-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 ────────────────────────────────────── @@ -581,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")), @@ -613,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:]: @@ -688,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" @@ -762,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 `†`. @@ -804,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)) @@ -828,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"): @@ -856,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") @@ -1025,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 search-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 " @@ -1117,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): @@ -1125,7 +1045,7 @@ def _fmt_secs(v): def _bulk_phase_lines(datas, loaded, nocrown): - """The ingest and search-index rebuild 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.""" @@ -1283,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 @@ -1354,7 +1272,8 @@ 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) diff --git a/.github/scripts/fhir-bench/history.py b/.github/scripts/fhir-bench/history.py new file mode 100644 index 0000000000..fac9bcf7b6 --- /dev/null +++ b/.github/scripts/fhir-bench/history.py @@ -0,0 +1,330 @@ +#!/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+)?") + + +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 = cells[0] + 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=success&per_page={per_page}"]) + if r.returncode != 0: + return [] + return json.loads(r.stdout).get("workflow_runs", []) + + +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 + + +# ---- 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 _fill(vals): + """Fill gaps with nearest known value so the line stays continuous.""" + known = [v for v in vals if v is not None] + if not known: + return None + out, last = [], None + for v in vals: + last = v if v is not None else last + out.append(last) + first = known[0] + return [first if v is None else v for v in out] + + +def _clean(s): + return re.sub(r'["\[\]\n|`]', "", s).strip() + + +def render_chart(label, legs, series, xlabels): + lines = ["```mermaid", "xychart-beta", + f' title "{_clean(label)[:70]}"', + " x-axis [" + ", ".join(f'"{x}"' for x in xlabels) + "]", + f' y-axis "{_clean(label)[:20]}" 0'] + # y-axis with only a label keeps min auto; drop the stray 0 form + lines[-1] = ' y-axis "value"' + used = [] + for leg, vals in zip(legs, series): + f = _fill(vals) + if f is None: + continue + used.append(leg) + lines.append(" line [" + ", ".join(f"{v:.1f}" for v in f) + "]") + lines.append("```") + if not used: + return "" + return "\n".join(lines) + "\n\nLines in order: " + ", ".join(f"`{u}`" for u in used) + "\n" + + +def build(args, fetch_runs_fn, fetch_comparison_fn, current_text=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 = [] + 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 + 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 + out.append(f"**{lab}**\n") + out.append("| Leg | " + " | ".join(xlabels) + " |") + out.append("|---|" + "---:|" * 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) + out.append(f"| `{lg}` | " + " | ".join(cells) + " |") + out.append("") + if _is_chart_row(lab) and len(charts) < MAX_CHARTS: + c = render_chart(lab, legs, [data[g] for g in legs], xlabels) + if c: + charts.append(c) + + if charts: + out.append("Charts (one line per leg, runs oldest to newest):\n") + out.extend(c + "\n" for c in charts) + out.append("
\n") + text = "\n".join(out) + if len(text.encode("utf-8")) > MAX_BYTES: + text = text.encode("utf-8")[:MAX_BYTES - 200].decode("utf-8", "ignore") + text += "\n\n_(truncated)_\n\n" + return text + + +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") + 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) + 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..f84ea226ef --- /dev/null +++ b/.github/scripts/fhir-bench/k6/sql-run.js @@ -0,0 +1,151 @@ +// 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. +// +// 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') + +const FILTER_CODES = ['8302-2', '29463-7', '8867-4', '8480-6'] + +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/suite-lib.sh b/.github/scripts/fhir-bench/suite-lib.sh index 5c667ee919..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 search-index rebuild 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 e2f464c555..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). @@ -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_compare_legs.py b/.github/scripts/fhir-bench/test_compare_legs.py index b2cf6a5469..21fe649146 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 (`/ui/batch`: `POST /` Bundles)" # Errors label; Throughput and p95 add a unit IMPORT_ROW = IMPORT + " (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-index rebuild after Completed (seconds)" -REINDEX = "reindex, `$reindex` Encounter" -REINDEX_ROW = REINDEX + " (resources/s)" +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,57 +299,20 @@ 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 # the four import rows sit right after prewarm, in this order, under the UI names t = labels(md, "Throughput") @@ -456,27 +320,25 @@ def test_loading_rows_together_and_named(self): 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-index rebuild", never "initial index" + # one vocabulary: "search indexing", never "initial index" self.assertNotIn("initial index", md) self.assertNotIn("initial-index", md) - self.assertIn("search-index rebuild", md) - self.assertIn("`†` crud/search/reindex ran on an incomplete corpus", md) - self.assertIn("on reindex, any reindex error or a failed job", 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()})) @@ -549,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)) @@ -566,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** |") @@ -583,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( @@ -595,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"] diff --git a/.github/scripts/fhir-bench/test_history.py b/.github/scripts/fhir-bench/test_history.py new file mode 100644 index 0000000000..6ecf4a19fd --- /dev/null +++ b/.github/scripts/fhir-bench/test_history.py @@ -0,0 +1,150 @@ +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_main_exit_zero(self): + self.assertEqual(history.main(["--bogus"]), 0) + + +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 db65944ed4..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"): @@ -68,46 +62,45 @@ def test_bulk_line_inline_with_rebuild_of_rejected_types(self): 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-benchmark.yml b/.github/workflows/fhir-benchmark.yml index a4a0672a2a..32f5424636 100644 --- a/.github/workflows/fhir-benchmark.yml +++ b/.github/workflows/fhir-benchmark.yml @@ -55,18 +55,22 @@ 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 above +# 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 (`/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 `↳ search-index rebuild after Completed (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, 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 +85,11 @@ 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; 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 +97,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 `↳ search-index rebuild after Completed (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 +134,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 search-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). 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: @@ -1244,7 +1233,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 +1327,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 +1400,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 +1474,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 +1496,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 +1519,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 +1579,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" @@ -1747,9 +1691,7 @@ jobs: # 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. # 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, @@ -2238,10 +2180,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 index-rebuild 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 @@ -2269,6 +2210,7 @@ jobs: continue-on-error: true permissions: contents: read + actions: read steps: - name: Check out benchmark scripts continue-on-error: true @@ -2312,6 +2254,17 @@ jobs: fi cat comparison.md >> "$GITHUB_STEP_SUMMARY" + # Trend over the last runs of this branch. Display only: it can never + # fail the run (continue-on-error, and the summary append is guarded). + - name: Write run history + if: always() + continue-on-error: true + 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 + if [ -f history.md ]; then cat history.md >> "$GITHUB_STEP_SUMMARY"; fi + # Raw Markdown for pasting into an issue or PR (the summary page only # offers rendered tables). Named fhir-bench-*, NOT fhir-benchmark-*, so a # re-run of this job can never pick it up as a leg. 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..a37235fb0b 100644 --- a/crates/rest/README.md +++ b/crates/rest/README.md @@ -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,31 @@ 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 (one run per cell; 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 | 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. +What was measured and did **not** help: a 1 s Elasticsearch refresh interval; 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` 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. 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 From b6c71d63f1b9b382247c53fb6907d293d2699e22 Mon Sep 17 00:00:00 2001 From: Edson Terceros Date: Mon, 26 Oct 2026 11:07:34 +0000 Subject: [PATCH 03/12] ci(bench): fix review findings (sql-run filter code, history order and gaps, docs) - sql-run: replace filter code 8480-6 (only a panel component in the corpus, matched no row) with 39156-5. - history: run the step after "Upload comparison" with a 5 minute timeout; do not invent chart points for missing values. - Document that sqlite-elasticsearch ingests one file at a time, clarify the refresh-interval wording and the benchmark's own settings. Co-Authored-By: Claude Sonnet 5.5 --- .github/scripts/fhir-bench/bulk-import.sh | 3 ++- .github/scripts/fhir-bench/history.py | 14 ++++------- .github/scripts/fhir-bench/k6/sql-run.js | 4 +++- .github/workflows/fhir-benchmark.yml | 29 +++++++++++++---------- crates/rest/README.md | 6 +++-- 5 files changed, 30 insertions(+), 26 deletions(-) diff --git a/.github/scripts/fhir-bench/bulk-import.sh b/.github/scripts/fhir-bench/bulk-import.sh index f147a6a219..ba6a3fef8c 100755 --- a/.github/scripts/fhir-bench/bulk-import.sh +++ b/.github/scripts/fhir-bench/bulk-import.sh @@ -129,7 +129,8 @@ case "$BACKEND" in 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-32 s for this recipe - # (index while ingesting, 4 files x 4 ES bulk workers, batches of 1000). + # (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}" diff --git a/.github/scripts/fhir-bench/history.py b/.github/scripts/fhir-bench/history.py index fac9bcf7b6..801a757fa6 100644 --- a/.github/scripts/fhir-bench/history.py +++ b/.github/scripts/fhir-bench/history.py @@ -158,16 +158,12 @@ def _is_chart_row(label): def _fill(vals): - """Fill gaps with nearest known value so the line stays continuous.""" - known = [v for v in vals if v is not None] - if not known: + """The series as plotted: only a leg with a value in every run gets a line. + A gap is never filled with a neighbouring value (a renamed row or a leg that + did not run would otherwise draw a flat line); the tables show the gap as a dash.""" + if not vals or any(v is None for v in vals): return None - out, last = [], None - for v in vals: - last = v if v is not None else last - out.append(last) - first = known[0] - return [first if v is None else v for v in out] + return list(vals) def _clean(s): diff --git a/.github/scripts/fhir-bench/k6/sql-run.js b/.github/scripts/fhir-bench/k6/sql-run.js index f84ea226ef..01ba9960e8 100644 --- a/.github/scripts/fhir-bench/k6/sql-run.js +++ b/.github/scripts/fhir-bench/k6/sql-run.js @@ -66,7 +66,9 @@ const BASE_URL = __ENV.BASE_URL const JSON_HEADERS = { 'Accept': 'application/json', 'Content-Type': 'application/json' } const rows = new Counter('sql_run_rows') -const FILTER_CODES = ['8302-2', '29463-7', '8867-4', '8480-6'] +// 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 = { diff --git a/.github/workflows/fhir-benchmark.yml b/.github/workflows/fhir-benchmark.yml index 32f5424636..e88bcb3616 100644 --- a/.github/workflows/fhir-benchmark.yml +++ b/.github/workflows/fhir-benchmark.yml @@ -69,8 +69,9 @@ name: FHIR Server Benchmark # 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, batch 1000 and -# ES bulk concurrency 4. Both are recorded in the leg configuration lines. +# *-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 @@ -2254,17 +2255,6 @@ jobs: fi cat comparison.md >> "$GITHUB_STEP_SUMMARY" - # Trend over the last runs of this branch. Display only: it can never - # fail the run (continue-on-error, and the summary append is guarded). - - name: Write run history - if: always() - continue-on-error: true - 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 - if [ -f history.md ]; then cat history.md >> "$GITHUB_STEP_SUMMARY"; fi - # Raw Markdown for pasting into an issue or PR (the summary page only # offers rendered tables). Named fhir-bench-*, NOT fhir-benchmark-*, so a # re-run of this job can never pick it up as a leg. @@ -2277,3 +2267,16 @@ 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. + - 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 + if [ -f history.md ]; then cat history.md >> "$GITHUB_STEP_SUMMARY"; fi diff --git a/crates/rest/README.md b/crates/rest/README.md index a37235fb0b..9f03836b69 100644 --- a/crates/rest/README.md +++ b/crates/rest/README.md @@ -487,7 +487,7 @@ This is the single source of truth for which indexing mode to run; other documen | `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 | 24.0 s and 18.0 s in two runs (defaults inline: ~80-82 s) | +| `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) | @@ -500,7 +500,9 @@ HFS_BULK_SUBMIT_BATCH_SIZE=1000 # (100) HFS_ELASTICSEARCH_BULK_CONCURRENCY=4 # (1) ``` -What was measured and did **not** help: a 1 s Elasticsearch refresh interval; 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. +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 (twice as slow with `HFS_ELASTICSEARCH_WRITE_REFRESH=wait_for`, no faster 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` 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. 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. From ec022b2836e65a7d85d02878f4bdcd5b0647b256 Mon Sep 17 00:00:00 2001 From: Edson Terceros Date: Mon, 26 Oct 2026 13:26:34 +0000 Subject: [PATCH 04/12] ci(bench): document why sql-run asks for gzip HFS used to answer a gzip-encoded $sql-run `_format=ndjson` request with 200 and an empty body (fixed in channel_body_response); the script asks for gzip like any real client and says why. Co-Authored-By: Claude Sonnet 5.5 --- .github/scripts/fhir-bench/k6/sql-run.js | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/.github/scripts/fhir-bench/k6/sql-run.js b/.github/scripts/fhir-bench/k6/sql-run.js index 01ba9960e8..fd50cddfe8 100644 --- a/.github/scripts/fhir-bench/k6/sql-run.js +++ b/.github/scripts/fhir-bench/k6/sql-run.js @@ -36,6 +36,11 @@ // 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). From 9739f2a583a21b3896728c2966fe730b85ffd2b7 Mon Sep 17 00:00:00 2001 From: Edson Terceros Date: Mon, 26 Oct 2026 14:02:08 +0000 Subject: [PATCH 05/12] fix(rest): `$sql-run` streamed bodies no longer come back empty under gzip `channel_body_response` built its body with `futures::stream::unfold`, which panics when polled again after it returned `None`. tower-http's compression layer polls the body once more at the end, so a client sending `Accept-Encoding: gzip` got `200` with `content-encoding: gzip` and a zero-byte body. Fuse the stream. Covers every streamed `$sql-run` format (ndjson, csv, json, fhir, parquet, arrow). Co-Authored-By: Claude Sonnet 5.5 --- crates/rest/src/handlers/sof/run.rs | 6 ++- crates/rest/tests/http_compression.rs | 54 +++++++++++++++++++++++++++ 2 files changed, 59 insertions(+), 1 deletion(-) 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\""]); +} From ed7a28eb69d95110b76a10fd863eccc189ae9809 Mon Sep 17 00:00:00 2001 From: Edson Terceros Date: Mon, 26 Oct 2026 18:35:02 +0000 Subject: [PATCH 06/12] ci(bench): collapsed Mermaid charts, standalone dark HTML report and a joined run history - md_charts.py: collapsed `### Charts` section appended after the unchanged comparison and per-leg text (two charts per row, one colour per leg). - report_html.py + report_template.html: single-file dark HTML report with a summary at the top, uploaded with `archive: false` and linked as the last line of the summary. - history.py: joins renamed rows, single-series trend charts, safe truncation, `--data-dir` for the report trend. - workflow: capture the leg box, run the chart/report/history steps, never failing the run. Co-Authored-By: Claude Sonnet 5.5 --- .github/scripts/fhir-bench/history.py | 154 ++- .github/scripts/fhir-bench/md_charts.py | 564 ++++++++++ .github/scripts/fhir-bench/report_html.py | 803 +++++++++++++++ .../scripts/fhir-bench/report_template.html | 966 ++++++++++++++++++ .github/scripts/fhir-bench/test_history.py | 64 ++ .github/scripts/fhir-bench/test_md_charts.py | 345 +++++++ .../scripts/fhir-bench/test_report_html.py | 211 ++++ .github/workflows/fhir-benchmark.yml | 103 +- 8 files changed, 3162 insertions(+), 48 deletions(-) create mode 100644 .github/scripts/fhir-bench/md_charts.py create mode 100644 .github/scripts/fhir-bench/report_html.py create mode 100644 .github/scripts/fhir-bench/report_template.html create mode 100644 .github/scripts/fhir-bench/test_md_charts.py create mode 100644 .github/scripts/fhir-bench/test_report_html.py diff --git a/.github/scripts/fhir-bench/history.py b/.github/scripts/fhir-bench/history.py index 801a757fa6..5859687955 100644 --- a/.github/scripts/fhir-bench/history.py +++ b/.github/scripts/fhir-bench/history.py @@ -20,6 +20,25 @@ 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)" +# 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, + "Bulk Import: index rebuild (seconds)": NEW_INDEX, + "↳ search-index rebuild after Completed (seconds)": NEW_INDEX, +} + + +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() @@ -57,7 +76,10 @@ def parse_tables(md): i += 2 # skip separator while i < len(lines) and lines[i].strip().startswith("|"): cells = _split_row(lines[i]) - label = cells[0] + 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)) @@ -84,10 +106,13 @@ def _gh(args): def _list_runs(repo, workflow, branch, per_page): r = _gh(["api", f"repos/{repo}/actions/workflows/{workflow}/runs" - f"?branch={branch}&status=success&per_page={per_page}"]) + f"?branch={branch}&status=completed&per_page={per_page}"]) if r.returncode != 0: return [] - return json.loads(r.stdout).get("workflow_runs", []) + # 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): @@ -137,6 +162,22 @@ def fetch_comparison(repo, run, artifact_name): 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): @@ -157,52 +198,57 @@ def _is_chart_row(label): return not (l.startswith("prewarm") or l.startswith("↳") or "seconds)" in l) -def _fill(vals): - """The series as plotted: only a leg with a value in every run gets a line. - A gap is never filled with a neighbouring value (a renamed row or a leg that - did not run would otherwise draw a flat line); the tables show the gap as a dash.""" - if not vals or any(v is None for v in vals): - return None - return list(vals) - - def _clean(s): return re.sub(r'["\[\]\n|`]', "", s).strip() -def render_chart(label, legs, series, xlabels): - lines = ["```mermaid", "xychart-beta", - f' title "{_clean(label)[:70]}"', - " x-axis [" + ", ".join(f'"{x}"' for x in xlabels) + "]", - f' y-axis "{_clean(label)[:20]}" 0'] - # y-axis with only a label keeps min auto; drop the stray 0 form - lines[-1] = ' y-axis "value"' - used = [] - for leg, vals in zip(legs, series): - f = _fill(vals) - if f is None: - continue - used.append(leg) - lines.append(" line [" + ", ".join(f"{v:.1f}" for v in f) + "]") - lines.append("```") - if not used: +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 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(lines) + "\n\nLines in order: " + ", ".join(f"`{u}`" for u in used) + "\n" + return "\n".join([ + "```mermaid", "xychart-beta", + f' title "{_clean(label)[:80]} - {_clean(leg)}"', + " x-axis [" + ", ".join(f'"{_clean(x)}"' for x in xlabels) + "]", + ' y-axis "value"', + " line [" + ", ".join(f"{v:.1f}" for v in vals) + "]", + "```"]) + "\n" -def build(args, fetch_runs_fn, fetch_comparison_fn, current_text=None): +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)) @@ -263,9 +309,8 @@ def xl(run): data[lg].append(v) if all(v is None for vs in data.values() for v in vs): continue - out.append(f"**{lab}**\n") - out.append("| Leg | " + " | ".join(xlabels) + " |") - out.append("|---|" + "---:|" * len(xlabels)) + 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): @@ -275,22 +320,39 @@ def xl(run): c = fmt_num(v) d = pct(vs[i - 1], v) if i else "" cells.append(f"{c} ({d})" if d else c) - out.append(f"| `{lg}` | " + " | ".join(cells) + " |") - out.append("") + sec.append(f"| `{lg}` | " + " | ".join(cells) + " |") + out.append("\n".join(sec) + "\n") if _is_chart_row(lab) and len(charts) < MAX_CHARTS: - c = render_chart(lab, legs, [data[g] for g in legs], xlabels) + 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("Charts (one line per leg, runs oldest to newest):\n") - out.extend(c + "\n" for c in charts) - out.append("
\n") - text = "\n".join(out) - if len(text.encode("utf-8")) > MAX_BYTES: - text = text.encode("utf-8")[:MAX_BYTES - 200].decode("utf-8", "ignore") - text += "\n\n_(truncated)_\n\n" - return text + 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): @@ -303,6 +365,7 @@ def main(argv=None): 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: @@ -314,7 +377,8 @@ def main(argv=None): except OSError: cur = None text = build(args, lambda *a: fetch_runs(*a), - lambda repo, run, name: fetch_comparison(repo, run, name), cur) + 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 diff --git a/.github/scripts/fhir-bench/md_charts.py b/.github/scripts/fhir-bench/md_charts.py new file mode 100644 index 0000000000..a64f71811c --- /dev/null +++ b/.github/scripts/fhir-bench/md_charts.py @@ -0,0 +1,564 @@ +#!/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.""" + out = ["```mermaid", "%%{init: " + json.dumps(gantt_init(150)) + "}%%", "gantt", + " dateFormat YYYY-MM-DD HH:mm:ss", " axisFormat %H:%M", " 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.""" + 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 [] + out = [] + for i, leg in enumerate(head[1:], start=1): + 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): + 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; shorter is better; values in the table above.") + 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 not phases: + 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 {} + try: + a = float(kv["ingest_seconds"]) + except (KeyError, ValueError): + return [] + b = None + if kv.get("index_status") != "inline": + 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), "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..847f86bee9 --- /dev/null +++ b/.github/scripts/fhir-bench/report_html.py @@ -0,0 +1,803 @@ +#!/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")) or 0, "fail": inum(g("checks", "fails")) or 0, + "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: + return None + return "%sT%sZ" % (day, pts[0]["t"] if pts else "00:00:00") + + +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")) or 0, "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"] > 0: + m += "‡" + if d["died"] or (s == "crud" 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["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"] > 0: + soft.append("%s %s ✗" % (s, fmt_int(v["fail"]))) + b = d["bulk"] + if 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 + ["%s no data" % s for s in nodata])] + elif nodata: + c["err"] = ["na", ", ".join(soft + ["%s no data" % s for s 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"] + if d["pg_ms"] > PG_CONTENDED_MS: + c["load"][0] = "bad" + d["peak"] = pk + return c + + +def verdict_all(legs, order, cpus, missing): + """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)]) + 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"]) + sha = (a.sha or first.get("sha") or "")[:9] or None + return {"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), + "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 #39657850695

+
+
+
+ +
+
+
+ +
+

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 1,000 († 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 20 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; 300 VUs are 300 clients at once, not 300 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/test_history.py b/.github/scripts/fhir-bench/test_history.py index 6ecf4a19fd..bcd8e2f070 100644 --- a/.github/scripts/fhir-bench/test_history.py +++ b/.github/scripts/fhir-bench/test_history.py @@ -142,6 +142,70 @@ def fake(a): 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.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) + + 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) 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..d078abc93e --- /dev/null +++ b/.github/scripts/fhir-bench/test_md_charts.py @@ -0,0 +1,345 @@ +"""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_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..96e371b5d7 --- /dev/null +++ b/.github/scripts/fhir-bench/test_report_html.py @@ -0,0 +1,211 @@ +"""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.path.expanduser("~/tmp/ci-bench/40335047310") + + +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 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(os.path.isdir(REAL), "real CI run not downloaded") +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) + + +if __name__ == "__main__": + unittest.main() diff --git a/.github/workflows/fhir-benchmark.yml b/.github/workflows/fhir-benchmark.yml index e88bcb3616..c34510d6f9 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): # @@ -2135,7 +2140,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 @@ -2207,7 +2224,11 @@ 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 @@ -2254,6 +2275,9 @@ jobs: 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 @@ -2271,6 +2295,9 @@ jobs: # 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 @@ -2278,5 +2305,75 @@ jobs: 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 + 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" + + # 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 + + - name: Build HTML report + if: always() + continue-on-error: true + timeout-minutes: 5 + run: | + python3 .github/scripts/fhir-bench/report_html.py \ + --run-dir report-input \ + --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 + 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 From 9bba51d9ce231bcb37f8ebcff3935212faa4cdf8 Mon Sep 17 00:00:00 2001 From: Edson Terceros Date: Mon, 26 Oct 2026 18:55:04 +0000 Subject: [PATCH 07/12] ci(bench): fix review findings in the visual report (missing data, axes, summary, pipefail) - report_html.py: find comparison.md (copied into report-input), pass --expect-legs, apply the Postgres contention rule only to `postgres`, never show missing inputs as 0 or 00:00, fill prose numbers from data. - md_charts.py: no bulk bars for timed-out or failed Bulk Import, axes with units, n/a values are skipped. - history.py: the old "index rebuild" row no longer joins `search indexing`; the y axis carries a unit. - workflow: pipefail for the leg summary, `n/a` for absent latency keys. - README: report outputs. Co-Authored-By: Claude Sonnet 5.5 --- .github/scripts/fhir-bench/README.md | 33 +++++++ .github/scripts/fhir-bench/history.py | 17 +++- .github/scripts/fhir-bench/md_charts.py | 32 +++++-- .github/scripts/fhir-bench/report_html.py | 29 ++++--- .../scripts/fhir-bench/report_template.html | 27 ++++-- .github/scripts/fhir-bench/test_history.py | 25 +++++- .github/scripts/fhir-bench/test_md_charts.py | 33 +++++++ .../scripts/fhir-bench/test_report_html.py | 86 +++++++++++++++++++ .github/workflows/fhir-benchmark.yml | 45 ++++------ 9 files changed, 268 insertions(+), 59 deletions(-) diff --git a/.github/scripts/fhir-bench/README.md b/.github/scripts/fhir-bench/README.md index 82fdf451fc..2f64000c5c 100644 --- a/.github/scripts/fhir-bench/README.md +++ b/.github/scripts/fhir-bench/README.md @@ -30,3 +30,36 @@ The `indexing` (`$reindex`) suite was removed. Recover it from git history if ne ## 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 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/history.py b/.github/scripts/fhir-bench/history.py index 5859687955..5efea97a0a 100644 --- a/.github/scripts/fhir-bench/history.py +++ b/.github/scripts/fhir-bench/history.py @@ -24,14 +24,16 @@ 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, - "Bulk Import: index rebuild (seconds)": NEW_INDEX, - "↳ search-index rebuild after Completed (seconds)": NEW_INDEX, + # 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, } @@ -211,6 +213,15 @@ def headline_leg(legs, data): 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): @@ -219,7 +230,7 @@ def render_chart(label, leg, vals, xlabels): "```mermaid", "xychart-beta", f' title "{_clean(label)[:80]} - {_clean(leg)}"', " x-axis [" + ", ".join(f'"{_clean(x)}"' for x in xlabels) + "]", - ' y-axis "value"', + f' y-axis "{_clean(y_unit(label))}"', " line [" + ", ".join(f"{v:.1f}" for v in vals) + "]", "```"]) + "\n" diff --git a/.github/scripts/fhir-bench/md_charts.py b/.github/scripts/fhir-bench/md_charts.py index a64f71811c..00de31b27c 100644 --- a/.github/scripts/fhir-bench/md_charts.py +++ b/.github/scripts/fhir-bench/md_charts.py @@ -198,8 +198,13 @@ def gtext(s): 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 %H:%M", " todayMarker off"] + " 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)))) @@ -282,7 +287,7 @@ def _rebuild_from_text(text): def bulk_phases_from_throughput(head, rows): - """[(leg, ingest_s, rebuild_s|None)] from the `↳ ingest` / `↳ search indexing` 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("**", "") @@ -294,9 +299,17 @@ def bulk_phases_from_throughput(head, rows): elif "index" in low: idx = row if not ing: - return [] + 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 @@ -318,12 +331,13 @@ def bulk_phases_from_table(head, rows): return out -def bulk_gantt_block(phases): +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; shorter is better; values in the table above.") + + ", 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)) @@ -376,7 +390,7 @@ def compare_section(lines, layout): r = find_table(lines, "### Throughput") if r: phases = bulk_phases_from_throughput(r[0], r[1]) - if not phases: + if phases is None: r = find_table(lines, "### Bulk import") if r: phases, tname = bulk_phases_from_table(r[0], r[1]), "Bulk import" @@ -431,12 +445,14 @@ def phases(d): 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") != "inline": + if kv.get("index_status") == "completed": try: b = float(kv.get("index_seconds", "")) except ValueError: @@ -462,7 +478,7 @@ def leg_section(lines, leg, run_dir, layout): 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), "Results")) + 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)} diff --git a/.github/scripts/fhir-bench/report_html.py b/.github/scripts/fhir-bench/report_html.py index 847f86bee9..ffe753fb52 100644 --- a/.github/scripts/fhir-bench/report_html.py +++ b/.github/scripts/fhir-bench/report_html.py @@ -173,7 +173,7 @@ def g(name, key): "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")) or 0, "fail": inum(g("checks", "fails")) or 0, + "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) @@ -236,9 +236,9 @@ def leg_start(d, pts): break except OSError: pass - if day is None: - return None - return "%sT%sZ" % (day, pts[0]["t"] if pts else "00:00:00") + 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): @@ -340,7 +340,7 @@ def load_leg(leg, d): "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")) or 0, "index_status": status, + "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 {} @@ -379,15 +379,15 @@ def markers(d): inc = not d["drain"] or d["drain"]["status"] != "drained" if inc: m += "†" - if v["err"] > ERR_PCT_HIGH or v["fail"] > 0: + if v["err"] > ERR_PCT_HIGH or (v["fail"] or 0) > 0: m += "‡" - if d["died"] or (s == "crud" and d["pg_ms"] is not None and d["pg_ms"] > PG_CONTENDED_MS): + 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["submitted"] and (100.0 * b["failed"] / b["submitted"] > ERR_PCT_HIGH or b["failed"] > 0): + 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 += "⚠" @@ -424,17 +424,21 @@ def leg_checks(d, cpus): 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"]: + 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 + ["%s no data" % s for s in nodata])] + 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 + ["%s no data" % s for s in 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: @@ -457,7 +461,8 @@ def leg_checks(d, cpus): 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"] - if d["pg_ms"] > PG_CONTENDED_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 diff --git a/.github/scripts/fhir-bench/report_template.html b/.github/scripts/fhir-bench/report_template.html index a205828fcf..70dfdd60b6 100644 --- a/.github/scripts/fhir-bench/report_template.html +++ b/.github/scripts/fhir-bench/report_template.html @@ -49,6 +49,7 @@ th,td{padding:6px 8px;border-bottom:1px solid var(--grid);text-align:left;vertical-align:top} th{font-weight:600;color:var(--ink-2);white-space:nowrap} td.n,th.n{text-align:right;white-space:nowrap} +#full td:first-child{white-space:nowrap;min-width:9em} .st{display:inline-flex;align-items:center;gap:5px;padding:1px 7px;border-radius:6px;font-size:.82rem;white-space:nowrap;font-weight:500} .st i{font-style:normal;font-weight:800;width:1em;text-align:center} .st.ok{color:var(--good);background:var(--good-bg)} @@ -58,6 +59,7 @@ .validity td{min-width:110px} .validity td:first-child{min-width:0;font-weight:600} .kpis{display:grid;grid-template-columns:repeat(auto-fit,minmax(190px,1fr));gap:10px;margin-top:10px} +.kpi{min-width:0;overflow-wrap:anywhere} .kpi .lbl{font-size:.82rem;color:var(--ink-2)} .kpi .val{font-size:1.9rem;font-weight:700;line-height:1.15;margin:2px 0} .kpi .unit{font-size:.85rem;font-weight:500;color:var(--ink-2)} @@ -66,7 +68,8 @@ .kpi .delta b{color:var(--ink)} .grid2{display:grid;grid-template-columns:repeat(auto-fit,minmax(320px,1fr));gap:12px} .grid2.wide{grid-template-columns:repeat(auto-fit,minmax(min(440px,100%),1fr))} -.chart{min-height:40px} +.chart{min-height:40px;min-width:0;overflow:hidden} +.chart svg{max-width:100%;height:auto} .chart svg{display:block;overflow:visible} .chart text{font-family:system-ui,-apple-system,"Segoe UI",sans-serif} .panel h4{margin:0 0 2px;font-size:.92rem} @@ -129,7 +132,7 @@
-

FHIR Server Benchmark #39657850695

+

FHIR Server Benchmark

@@ -188,7 +191,7 @@

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

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 1,000 († if the corpus is incomplete) and the error rate (‡ above the threshold).

+

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)

@@ -199,7 +202,7 @@

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 20 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.

+

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)

@@ -242,7 +245,7 @@

Result size cross-check

Glossary

LegA storage combination tested separately (e.g. postgres + Elasticsearch).
-
VU (virtual user)A simulated client with a single request in flight; 300 VUs are 300 clients at once, not 300 req/s.
+
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).
@@ -322,7 +325,7 @@

Glossary

const runners = [...new Set(LEGS.map(l=>L[l].runner).filter(Boolean))]; const any = LEGS.length ? L[LEGS[0]] : {}; $("meta").innerHTML = [ - `Start ${fdate(D.date,true)}`, + `Start ${D.date?fdate(D.date,true):"unknown"}`, `Commit ${esc(D.sha||"n/a")} (${esc(D.ref||"n/a")})`, D.repo && D.run ? `Run ${esc(D.repo)}` : "", `Runners ${esc(runners.join(", ")||"n/a")}${any.cpus?" · "+esc(any.cpus)+" CPU / "+esc(any.ram):""}`, @@ -344,6 +347,12 @@

Glossary

const src = LEGS.length ? L[LEGS[0]] : null; const vus = s => src && src.suites[s] && src.suites[s].vus ? src.suites[s].vus+" VUs" : "n/a"; $("glossSuites").textContent = `Batch/Transaction Import ${vus("import")} · crud ${vus("crud")} · search ${vus("search")} · $sql-run ${vus("sql-run")} · insert ${vus("insert")} · Bulk Import: one $bulk-submit job, the clock runs until the data can be searched.`; + /* prose numbers come from the data, never from literals */ + const sv = s => { const x = src && src.suites && src.suites[s]; return x && x.vus ? x.vus : null; }; + const anyVus = sv("crud") || sv("import") || sv("search") || sv("sql-run") || sv("insert"); + $("proseTarget").textContent = ok(TH.import_target) ? NF.format(TH.import_target) : "the target"; + $("proseImpVus").textContent = sv("import") ? sv("import")+" concurrent" : "concurrent"; + $("proseVus").textContent = anyVus ? anyVus+" VUs are "+anyVus+" clients" : "VUs are clients"; } function renderValidity(){ @@ -406,7 +415,11 @@

Glossary

function txt(x,y,s,o={}){ return `${esc(s)}`; } -function widthOf(el){ return Math.max(260, Math.floor(el.clientWidth || (el.parentElement && el.parentElement.clientWidth) || 600)); } +function widthOf(el){ + const raw = el.clientWidth || (el.parentElement && el.parentElement.clientWidth) || 600; + const cs = getComputedStyle(el), pad = (parseFloat(cs.paddingLeft)||0)+(parseFloat(cs.paddingRight)||0); + return Math.max(260, Math.floor(raw - pad)); +} const tipAttr = t => ` data-tip="${esc(t)}" tabindex="0"`; function roundRight(x,y,w,h,r,fill,extra=""){ if(!(w>0)) return ""; diff --git a/.github/scripts/fhir-bench/test_history.py b/.github/scripts/fhir-bench/test_history.py index bcd8e2f070..2c3f86eb27 100644 --- a/.github/scripts/fhir-bench/test_history.py +++ b/.github/scripts/fhir-bench/test_history.py @@ -150,7 +150,8 @@ def test_alias_join_and_cell(self): "| ↳ 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.NEW_INDEX, [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, @@ -159,6 +160,17 @@ def test_alias_join_and_cell(self): 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)] @@ -210,5 +222,16 @@ 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 index d078abc93e..3321861884 100644 --- a/.github/scripts/fhir-bench/test_md_charts.py +++ b/.github/scripts/fhir-bench/test_md_charts.py @@ -292,6 +292,39 @@ def test_leg_inline_vs_rebuild(self): 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) diff --git a/.github/scripts/fhir-bench/test_report_html.py b/.github/scripts/fhir-bench/test_report_html.py index 96e371b5d7..948c1be5ec 100644 --- a/.github/scripts/fhir-bench/test_report_html.py +++ b/.github/scripts/fhir-bench/test_report_html.py @@ -126,6 +126,9 @@ def test_labels_and_dropped_text(self): self.assertNotRegex(self.html, r"(?i)indexing suite") self.assertNotIn("Bolivia", self.html) + def test_no_literal_run_id_from_a_past_run(self): + self.assertNotIn("39657850695", self.html) + def test_docker_cpus_omitted_when_unknown(self): self.assertIsNone(self.data["docker_cpus"]) self.assertNotIn("host CPUs\"", self.html.split("