diff --git a/radiator/charts.py b/radiator/charts.py index 99f3fb6..a8dd1cb 100644 --- a/radiator/charts.py +++ b/radiator/charts.py @@ -227,3 +227,135 @@ def sy(y: float) -> float: return Markup( f'
{"".join(parts)}
{legend}' ) + + +def stage_chart( + stages: list[dict], + *, + slo_ms: Optional[float] = None, + knee_stage: Optional[int] = None, + width: int = WIDTH_HALF, + height: int = 220, + label: str = "", +) -> Markup: + """A load test's p99 latency at each stage of its ramp, against its SLO. + + The x-axis is the ramp (each stage's concurrent users), not time: stages + are discrete load levels, so they are drawn as points joined by a line. + A stage that kept inside the SLO is filled; one over it is hollow. The + knee, the highest stage that met the SLO, carries a label. + """ + points = [ + (i, s.get("p99_ms")) + for i, s in enumerate(stages) + if s.get("p99_ms") is not None + ] + if not points: + return Markup('

No stage measurements.

') + + def seconds(ms: float) -> str: + return f"{ms / 1000:,.0f}s" if ms >= 10000 or ms == 0 else f"{ms / 1000:,.1f}s" + + values = [v for _, v in points] + ([slo_ms] if slo_ms else []) + ticks = nice_ticks(0, max(values)) + lo, hi = 0, ticks[-1] + left, right, top, bottom = 52, 16, 14, 30 + plot_w, plot_h = width - left - right, height - top - bottom + n = len(stages) + + def sx(i: int) -> float: + return left + plot_w * ((i + 0.5) / n) + + def sy(y: float) -> float: + return top + plot_h - (y - lo) / (hi - lo) * plot_h if hi != lo else top + + parts = [ + f'' + ] + for tick in ticks: + y = sy(tick) + parts.append( + f'' + f'{escape(seconds(tick))}' + ) + base_y = top + plot_h + parts.append( + f'' + ) + for i, s in enumerate(stages): + users = s.get("users") + parts.append( + f'' + f'{escape(str(users) if users is not None else "?")}' + ) + if slo_ms: + y = sy(slo_ms) + parts.append( + f'' + f'p99 SLO {escape(seconds(slo_ms))}' + ) + d = " ".join(f"{sx(i):.1f},{sy(v):.1f}" for i, v in points) + if len(points) > 1: + parts.append( + f'' + ) + for i, v in points: + over = slo_ms is not None and v > slo_ms + parts.append( + f'' + ) + if knee_stage is not None and stages[i].get("stage") == knee_stage: + parts.append( + f'knee' + ) + parts.append( + f'' + f'' + "" + ) + + def fmt(value, f): + return None if value is None else f(value) + + hover = { + "width": width, + "xs": [round(sx(i), 1) for i in range(n)], + "titles": [f"{s.get('users', '?')} users" for s in stages], + "series": [ + { + "name": "p99", + "color": "var(--agent-1)", + "values": [fmt(s.get("p99_ms"), seconds) for s in stages], + }, + { + "name": "p50", + "color": None, + "values": [fmt(s.get("p50_ms"), seconds) for s in stages], + }, + { + "name": "errors", + "color": None, + "values": [ + fmt(s.get("error_rate"), lambda v: f"{v * 100:.1f}%") + for s in stages + ], + }, + { + "name": "requests/s", + "color": None, + "values": [fmt(s.get("rps"), lambda v: f"{v:.2f}") for s in stages], + }, + ], + } + data = escape(json.dumps(hover)) + return Markup( + f'
{"".join(parts)}
' + '
p99 latency' + 'over the SLO' + 'p99 SLO' + 'x-axis: concurrent users at each stage
' + ) diff --git a/radiator/queries.py b/radiator/queries.py index 17fcb36..83bcfce 100644 --- a/radiator/queries.py +++ b/radiator/queries.py @@ -604,6 +604,19 @@ def performance_series( return out +def is_performance_run(run: Run) -> bool: + """Whether a run is a load test rather than an acceptance run. + + A run with performance results is one. Before the first arrives (HelmsDeep + reports only when a load test ends, tens of minutes in), a run with no + asset results either is taken to be one when its suite is a performance + suite. + """ + if run.performance: + return True + return not run.assets and "performance" in run.suite.lower() + + # --- live updates --------------------------------------------------------------- RUNNING, STALLED, FINISHED = "running", "stalled", "finished" diff --git a/radiator/static/style.css b/radiator/static/style.css index 041f212..69f7974 100644 --- a/radiator/static/style.css +++ b/radiator/static/style.css @@ -433,3 +433,29 @@ ul.flags li { margin: 4px 0; } .progress-card .sub { margin: 8px 0 0; } .callout { border: 1px solid var(--v-mixed); border-left-width: 4px; background: var(--surface); border-radius: 8px; padding: 10px 14px; margin: 0 0 16px; color: var(--ink); } + +/* --- a load-test run --------------------------------------------------- */ + +.perf-card h3 { font-size: 13px; font-weight: 650; margin: 18px 0 2px; } +.perf-card h3 + .sub { margin-bottom: 8px; } +.perf-card .scroll { margin-top: 10px; } +.figures { display: grid; grid-template-columns: repeat(auto-fit, minmax(170px, 1fr)); gap: 12px; margin: 4px 0 6px; } +.figure { border: 1px solid var(--border); border-radius: 8px; padding: 10px 12px; background: var(--surface-2); } +.figure .label { color: var(--ink-2); font-size: 12px; } +.figure .value { font-size: 22px; font-weight: 600; margin-top: 2px; font-variant-numeric: tabular-nums; } +.figure .value .unit { font-size: 13px; font-weight: 500; } +.figure .spark-value { margin: 4px 0 2px; } +.figure .delta { font-size: 12px; color: var(--ink-muted); } +.callout.bad { border-color: var(--status-failed); } +.badge.warn { border-color: var(--v-mixed); color: var(--ink); margin-left: 4px; cursor: help; } +table.stages tr.knee td { background: color-mix(in srgb, var(--accent) 8%, var(--surface)); } +table.data td.over { color: var(--down); font-weight: 600; } +.chart .slo { stroke: var(--status-failed); stroke-width: 1.5; stroke-dasharray: 5 4; } +.chart text.slo-label { fill: var(--down); } +.chart text.knee-label { fill: var(--ink); font-weight: 600; } +.chart[data-chart="stages"] .dot { fill: var(--agent-1); } +.chart[data-chart="stages"] .dot.over { fill: var(--surface); stroke: var(--status-failed); stroke-width: 2; } +.legend .line.dashed { background: repeating-linear-gradient(90deg, var(--status-failed) 0 5px, transparent 5px 9px); } +.legend .ring { width: 9px; height: 9px; border-radius: 50%; border: 2px solid var(--status-failed); box-sizing: border-box; } +ul.notes { margin: 4px 0 0; padding-left: 18px; color: var(--ink-2); font-size: 13px; } +ul.notes li { margin: 3px 0; } diff --git a/radiator/templates/performance_run.html b/radiator/templates/performance_run.html new file mode 100644 index 0000000..2bd7603 --- /dev/null +++ b/radiator/templates/performance_run.html @@ -0,0 +1,244 @@ +{% extends "base.html" %} +{% block title %}{{ run.suite }} · {{ when(run.started_at) }}{% endblock %} +{% block live %}{% if progress.running %} data-live="/api/runs/{{ run.id }}/progress" data-live-interval="15" data-live-version="{{ progress.version }}" data-live-until-done{% endif %}{% endblock %} +{% macro conc(value) -%}{{ '%.1f'|format(value) if value is not none else '–' }}{%- endmacro %} +{% block content %} +
+
Runs / Performance / {{ run.suite }}
+

#{{ run.number }} {{ run.suite }} · {{ run.env or 'no env' }}

+
+ {{ when(run.started_at) }} + {% if run.ended_at %}Duration {{ duration(run) }}{% else %}{{ run_badge(run) }} for {{ elapsed(run) }}{% endif %} + load test + {% if run.target %}target: {{ run.target }}{% endif %} + {% if run.trapi_version %}TRAPI {{ trapi_minor(run.trapi_version) }}{% endif %} + {% if run.harness_version %}harness {{ run.harness_version }}{% endif %} +
+
+ + +{% if trapi_change %} +
TRAPI {{ trapi_change[0] }} → {{ trapi_change[1] }} since the previous run: some of the changes may come from the version change rather than from the services.
+{% endif %} + +
+{% if progress.running %} + {% set done, total = progress.done_assets, progress.expected_assets %} +
+
+ {{ done }}{% if total %} of {{ total }}{% endif %} load test{{ '' if (total or done) == 1 else 's' }} finished + running for {{ elapsed(run) }} +
+ {% if total %} +
+ {% endif %} +

HelmsDeep steps the load up and holds each level for several minutes, so one load test takes tens of minutes. Its numbers arrive all at once when it ends; this page updates by itself.

+
+{% endif %} +
+ +
+ {% if views|length == 1 %}{% set v = views[0] %} +
+
Max sustainable concurrency
+
{{ conc(v.perf.max_sustainable_concurrency) }}
+ {% if v.msc_delta is not none %} +
{{ '%+.1f'|format(v.msc_delta) }} vs previous run
+ {% elif v.perf.max_sustainable_concurrency is none and not v.perf.error %} +
no stage met the SLO
+ {% else %} +
queries in flight at once, within the SLO
+ {% endif %} +
+ {% elif views %} +
+
Load tests passed
+
{{ passed }} of {{ views|length }}
+
ran, and met every checkpoint
+
+ {% else %} +
+
Max sustainable concurrency
+
–
+
{% if progress.running %}measured when the load test ends{% else %}no load test reported{% endif %}
+
+ {% endif %} +
+
Load tests
+
{{ views|length }}{% if progress.expected_assets %} of {{ progress.expected_assets }}{% endif %}
+
{{ passed }} passed · {{ views|length - passed }} failed
+
+
+
Checkpoints
+ {% if checkpoints_total %} +
{{ checkpoints_met }} of {{ checkpoints_total }} met
+
{{ 'every load level held' if checkpoints_met == checkpoints_total else 'a load level missed its bar' }}
+ {% else %} +
–
+
{% if views %}none configured: this run finds the knee{% else %}none yet{% endif %}
+ {% endif %} +
+
+
Previous run
+ {% if previous %} + +
{{ when(previous.started_at) }} · {{ ago(previous.started_at) }}
+ {% else %} +
–
+
no earlier run to compare
+ {% endif %} +
+
+ +
+{% if last_time %} +
+

Last time

+

What the previous run measured, for comparison while this one is going.

+
+ + + + {% for perf in last_time %} + + + + + + + {% endfor %} + +
ServiceResultMax sustainable concurrencyCheckpoints
{{ perf_series_name(perf) }}{{ status_badge(perf.status) }}{{ conc(perf.max_sustainable_concurrency) }}{% if perf.checkpoints_passed is none %}none configured{% else %}{{ status_badge('PASSED' if perf.checkpoints_passed else 'FAILED') }}{% endif %}
+
+
+{% elif not views %} +

{% if progress.running %}No load test has finished yet.{% else %}This run recorded no load test results.{% endif %}

+{% endif %} + +{% for v in views %}{% set perf = v.perf %} +
+
+
+

{{ perf.host }}

+

+ {{ v.config.get('component') or perf.helmsdeep_target or 'HelmsDeep' }} + · run type {{ perf.helmsdeep_target or '–' }} + · {{ perf.profile or 'default' }} profile + {% if v.config.get('protocol') %}· {{ v.config.get('protocol') }}{% endif %} +

+
+
{{ status_badge(perf.status) }}
+
+ + {% if perf.error %} + + {% endif %} + {% if v.compressed %} +
Compressed run (time scale {{ v.config.get('time_scale') }}): far fewer samples per stage, so these numbers aren't a quotable measurement.
+ {% endif %} + {% if perf.knee_unsupported %} +
Read the headline with care: HelmsDeep flagged the knee stage's measurement as not trustworthy (see the stage notes below).
+ {% endif %} + + {% if not perf.error %} +
+
+
Max sustainable concurrency
+
{{ conc(perf.max_sustainable_concurrency) }}
+
+ {% if v.msc_delta is not none %}{{ '%+.1f'|format(v.msc_delta) }} vs previous ({{ conc(v.previous.max_sustainable_concurrency) }}) + {% elif v.previous %}previous: {{ conc(v.previous.max_sustainable_concurrency) }} + {% else %}first run of this series{% endif %} +
+
+
+
Knee
+ {% if v.knee %} +
{{ v.knee.get('users', '?') }} users
+
p99 {{ ms(v.knee.get('p99_ms')) }} · {{ '%.2f'|format(v.knee.get('rps') or 0) }} req/s · {{ pct(v.knee.get('error_rate'), 1) }} errors
+ {% else %} +
–
+
no stage kept within the SLO
+ {% endif %} +
+
+
p99 SLO
+
{{ ms(v.slo_ms) }}
+
errors under {{ pct(v.max_error_rate, 1) }}
+
+
+
Trend
+
{{ sparkline(v.trend, pct=False) }}
+
last {{ v.history|length }} run{{ '' if v.history|length == 1 else 's' }} · all history
+
+
+ {% endif %} + + {% if v.stages %} +

The ramp

+

p99 latency at each load level. The knee is the highest level that kept within the SLO and the error cap.

+
{{ v.chart }}
+
{{ v.chart_narrow }}
+
+ + + + {% for s in v.stages %}{% set ok = v.within(s) %}{% set issues = v.warnings_for(s) %} + + + + + + + + + + + + + {% endfor %} + +
StageUsersRequestsReq/sErrorsp50p95p99ConcurrencyWithin SLO
{{ s.get('stage', loop.index0) }}{% if v.knee and s.get('stage') == v.knee.get('stage') %} knee{% endif %}{{ s.get('users') if s.get('users') is not none else '–' }}{{ '{:,}'.format(s.get('requests')) if s.get('requests') is not none else '–' }}{{ '%.2f'|format(s.get('rps')) if s.get('rps') is not none else '–' }}{{ pct(s.get('error_rate'), 1) }}{% if s.get('errors') %} ({{ s.get('errors') }}){% endif %}{{ ms(s.get('p50_ms')) }}{{ ms(s.get('p95_ms')) }}{{ ms(s.get('p99_ms')) }}{{ '%.1f'|format(s.get('concurrency')) if s.get('concurrency') is not none else '–' }}{% if ok is none %}–{% else %}{{ status_badge('PASSED' if ok else 'FAILED') }}{% endif %} + {% for issue in issues %}{{ (issue.get('kind') or 'warning')|replace('_', ' ') }}{% endfor %}
+
+ {% elif not perf.error %} +

HelmsDeep didn't report per-stage numbers for this run.

+ {% endif %} + + {% if v.checkpoints %} +

Checkpoints · {{ v.checkpoints_met }} of {{ v.checkpoints|length }} met

+

Pass/fail questions about set load levels: does the service hold this many users?

+
+ + + + {% for c in v.checkpoints %} + + + + + + + + + + + {% endfor %} + +
VerdictUsersGoalp99p99 barErrorsError capDetail
{% if c.get('verdict') == 'PASS' %}{{ status_badge('PASSED') }}{% elif c.get('verdict') == 'FAIL' %}{{ status_badge('FAILED') }}{% else %}{{ status_badge('NO_RESULTS') }}{% endif %}{{ c.get('users', '–') }}{{ c.get('goal') or '–' }}{{ ms(c.get('p99_ms')) }}{{ ms(c.get('p99_slo_ms')) if c.get('p99_slo_ms') is not none else 'not judged' }}{{ pct(c.get('error_rate'), 1) }}{{ pct(c.get('max_error_rate'), 1) }}{{ c.get('detail') or '' }}
+
+ {% endif %} + + {% if v.stage_warnings or v.red_flags %} +

Notes from HelmsDeep

+ + {% endif %} +
+{% endfor %} +
+{% endblock %} diff --git a/radiator/tests/test_pages.py b/radiator/tests/test_pages.py index ce89f9b..2eeecc0 100644 --- a/radiator/tests/test_pages.py +++ b/radiator/tests/test_pages.py @@ -533,3 +533,139 @@ def test_breakdown_by_agent_and_expected_output(app, browser): params={"agent": "arax", "status": "FAILED", "expected": "TopAnswer"}, ).text assert "A1 name" in filtered and "A2 name" not in filtered + + +def _helmsdeep_summary(msc=29.4): + """A HelmsDeep summary.json for a mixed run, shaped like the real thing.""" + + def stage(i, users, p99, errors=0.0): + return { + "stage": i, + "qtype": "__all__", + "users": users, + "requests": 100 * (i + 1), + "errors": int(errors * 100 * (i + 1)), + "error_rate": errors, + "duration_s": 300.0, + "rps": 0.5 * (i + 1), + "mean_ms": p99 / 2, + "p50_ms": p99 / 3, + "p95_ms": p99 * 0.9, + "p99_ms": p99, + "concurrency": users * 0.98, + } + + stages = [ + stage(0, 10, 90000.0), + stage(1, 30, 120000.0), + stage(2, 60, 410000.0, 0.08), + ] + return { + "config": { + "target": "aras_mixed", + "time_scale": 1.0, + "component": "Shepherd (Mixed)", + "protocol": "sync", + "p99_slo_ms": 300000, + "max_error_rate": 0.01, + }, + "stages": stages, + "knee": {**stages[1], "concurrency": msc}, + "max_sustainable_concurrency": msc, + "stage_warnings": [ + { + "stage": 2, + "users": 60, + "requests": 300, + "issues": [{"kind": "in_flight_bleed", "detail": "most queries bled"}], + } + ], + "knee_unsupported": False, + "checkpoints": [ + { + "users": 30, + "goal": "sustain peak load", + "p99_slo_ms": 300000, + "max_error_rate": 0.01, + "p99_ms": 120000.0, + "error_rate": 0.0, + "verdict": "PASS", + "detail": "within limits", + }, + { + "users": 60, + "goal": "survive overload", + "p99_slo_ms": None, + "max_error_rate": 0.05, + "p99_ms": 410000.0, + "error_rate": 0.08, + "verdict": "FAIL", + "detail": "errors 8.00% > 5.00%", + }, + ], + "checkpoints_passed": False, + } + + +def test_performance_run_page(app, browser): + """A load-test run's page shows the ramp, the knee and the checkpoints, + not the acceptance grid.""" + earlier = _perf_run(T0, msc=25.0) + this = _perf_run(T0 + timedelta(days=1), passed=False) + this.performance[0].max_sustainable_concurrency = 29.4 + this.performance[0].summary = _helmsdeep_summary() + _load(app, earlier, this) + + page = browser.get(f"/runs/{this.run.run_id}") + assert page.status_code == 200 + text = page.text + assert "Max sustainable concurrency" in text and "29.4" in text + assert "+4.4 vs previous run" in text + assert "1 0 of 1 load test finished" in text + assert "measured when the load test ends" in text + assert "Last time" in text and "25.0" in text + assert "No results yet" not in text and "By agent" not in text + + +def test_performance_run_that_failed_to_run(app, browser): + payload = _perf_run(T0, passed=False) + perf = payload.performance[0] + perf.max_sustainable_concurrency = None + perf.checkpoints_passed = None + perf.error = "HelmsDeep exited 2 without writing summary.json" + perf.exit_code = 2 + _load(app, payload) + + page = browser.get(f"/runs/{payload.run.run_id}") + assert page.status_code == 200 + assert "didn't produce a result" in page.text + assert "HelmsDeep exited 2 without writing summary.json" in page.text + assert "exit code 2" in page.text diff --git a/radiator/web.py b/radiator/web.py index 367ce93..2d09965 100644 --- a/radiator/web.py +++ b/radiator/web.py @@ -4,6 +4,7 @@ import uuid from dataclasses import dataclass from datetime import date, datetime, time, timedelta, timezone +from functools import partial from typing import Optional from urllib.parse import urlencode @@ -343,6 +344,8 @@ def run_page( previous = queries.previous_run(session, run) if previous is not None: previous = queries.get_run(session, previous.id) + if queries.is_performance_run(run): + return performance_run_page(request, session, run, previous) diff = queries.diff_runs(previous, run) agents = queries.run_agents(run) @@ -407,6 +410,153 @@ def run_page( ) +# How many of a service's earlier runs its trend on a run's page covers. +PERF_TREND_RUNS = 20 + + +@dataclass +class PerfView: + """One HelmsDeep load test in a run, laid out for its card.""" + + perf: object # models.PerformanceResult + # its series' earlier runs and this one, oldest first + history: list + previous: Optional[object] + previous_run: Optional[object] + config: dict + stages: list + knee: Optional[dict] + checkpoints: list + stage_warnings: list + red_flags: list + chart: Markup + # the same chart drawn for a phone; CSS shows one or the other + chart_narrow: Markup + + @property + def name(self) -> str: + return queries.perf_series_name(self.perf) + + @property + def slo_ms(self) -> Optional[float]: + return self.config.get("p99_slo_ms") + + @property + def max_error_rate(self) -> Optional[float]: + return self.config.get("max_error_rate") + + @property + def compressed(self) -> bool: + scale = self.config.get("time_scale") + return scale is not None and scale < 1.0 + + @property + def msc_delta(self) -> Optional[float]: + now = self.perf.max_sustainable_concurrency + before = self.previous.max_sustainable_concurrency if self.previous else None + if now is None or before is None: + return None + return now - before + + @property + def trend(self) -> list: + return [p.max_sustainable_concurrency for _, p in self.history] + + @property + def checkpoints_met(self) -> int: + return sum(1 for c in self.checkpoints if c.get("verdict") == "PASS") + + def within(self, stage: dict) -> Optional[bool]: + """Whether a stage kept inside both the p99 SLO and the error cap.""" + p99, errors = stage.get("p99_ms"), stage.get("error_rate") + if p99 is None or errors is None or self.slo_ms is None: + return None + cap = self.max_error_rate if self.max_error_rate is not None else 1.0 + return p99 <= self.slo_ms and errors <= cap + + def warnings_for(self, stage: dict) -> list: + return [ + issue + for w in self.stage_warnings + if w.get("stage") == stage.get("stage") + for issue in w.get("issues") or [] + ] + + +def perf_views(session: Session, run) -> list[PerfView]: + views = [] + for perf, history in queries.performance_series( + session, run, limit=PERF_TREND_RUNS + ): + summary = perf.summary or {} + stages = [s for s in summary.get("stages") or [] if isinstance(s, dict)] + knee = summary.get("knee") or None + config = summary.get("config") or {} + earlier = history[-2] if len(history) > 1 else (None, None) + stage_chart = partial( + charts.stage_chart, + stages, + slo_ms=config.get("p99_slo_ms"), + knee_stage=knee.get("stage") if knee else None, + label=f"p99 latency at each load stage for {perf.host}", + ) + views.append( + PerfView( + perf=perf, + history=history, + previous=earlier[1], + previous_run=earlier[0], + config=config, + stages=stages, + knee=knee, + checkpoints=list(summary.get("checkpoints") or []), + stage_warnings=list(summary.get("stage_warnings") or []), + red_flags=list(summary.get("red_flags") or []), + chart=stage_chart(width=charts.WIDTH_FULL, height=260), + chart_narrow=stage_chart(width=charts.WIDTH_THIRD, height=220), + ) + ) + return views + + +def ms(value: Optional[float]) -> str: + """A latency in milliseconds, in the unit people read it in.""" + if value is None: + return "–" + if value >= 10000: + return f"{value / 1000:,.0f}s" + if value >= 1000: + return f"{value / 1000:,.1f}s" + return f"{value:,.0f}ms" + + +def performance_run_page(request: Request, session: Session, run, previous): + """A load-test run's page: what each service sustained, and how the ramp + went, rather than the acceptance pass-rate grid.""" + views = perf_views(session, run) + progress = queries.run_progress(session, run) + checkpoints = [c for v in views for c in v.checkpoints] + return render( + request, + "performance_run.html", + nav="runs", + run=run, + previous=previous, + views=views, + progress=progress, + passed=sum(1 for v in views if v.perf.status == "PASSED"), + checkpoints_total=len(checkpoints), + checkpoints_met=sum(1 for c in checkpoints if c.get("verdict") == "PASS"), + # while the first load test is going there's nothing of this run's to + # show yet: what the previous run measured is what to expect + last_time=previous.performance if previous is not None and not views else [], + perf_series_name=queries.perf_series_name, + sparkline=sparkline, + ms=ms, + trapi_change=queries.trapi_change(previous, run), + ) + + @router.get("/runs/{run_id}/diff", response_class=HTMLResponse) def diff_page( request: Request, diff --git a/test_harness/main.py b/test_harness/main.py index 90e76fc..ae7ab2e 100644 --- a/test_harness/main.py +++ b/test_harness/main.py @@ -548,6 +548,14 @@ def resolve_trapi_version(args, test_env, logger) -> str: f"TRAPI {versions[0]}: what {infores} is registered with for " f"{test_env} in SmartAPI{others}" ) + if args.get("target_url"): + # the registry describes the deployed service, not the one at + # --target_url, which may well be on a different version + logger.warning( + f"--trapi_version auto read {infores}'s {test_env} SmartAPI " + f"entry, not the service at {args['target_url']}. If that " + "service is on another TRAPI version, pass --trapi_version." + ) return versions[0] logger.warning( f"--trapi_version auto: {why}; using {DEFAULT_TRAPI_VERSION}. Pass " diff --git a/test_harness/performance_test_runner.py b/test_harness/performance_test_runner.py index 9770dc4..a65ad60 100644 --- a/test_harness/performance_test_runner.py +++ b/test_harness/performance_test_runner.py @@ -27,7 +27,10 @@ import re import subprocess import sys +import time +from collections import deque from typing import Dict, List, Optional +from urllib.parse import urlparse from translator_testing_model.datamodel.pydanticmodel import PerformanceTestCase @@ -65,8 +68,15 @@ ) # How much of HelmsDeep's output to keep when it fails, so the failure reaches -# the log with its reason attached instead of just an exit code. +# the report with its reason attached instead of just an exit code. OUTPUT_TAIL_CHARS = 4000 +OUTPUT_TAIL_LINES = 200 + +# HelmsDeep's output goes to the harness log line by line, under this tag. +LOG_TAG = "[helmsdeep]" + +# How the run's TRAPI version reaches HelmsDeep (0.3.0 and later). +TRAPI_VERSION_ENV = "HELMSDEEP_TRAPI_VERSION" def _slugify(text: str) -> str: @@ -140,14 +150,121 @@ def _tail(text: Optional[str]) -> str: return text[-OUTPUT_TAIL_CHARS:] +def request_url(run_type: str, host: str) -> Optional[str]: + """The URL HelmsDeep will send its requests to, or None if unknown. + + HelmsDeep appends its run type's endpoint (eg ``/ars/api/submit``) to + ``--host``, so the host must be the service's base URL. + """ + try: + from helmsdeep import config as helmsdeep_config + + endpoint = helmsdeep_config.TARGETS[run_type]["endpoint"] + except Exception: # HelmsDeep missing or its registry changed shape. + return None + return f"{host.rstrip('/')}{endpoint}" + + +def check_host( + run_type: str, + host: str, + logger: logging.Logger = logging.getLogger(__name__), +) -> None: + """Say where the load will go, and warn when the host looks like it + already carries the endpoint's path (eg ``https://example.org/ars`` for an + ARS run, which would be sent to ``.../ars/ars/api/submit``).""" + url = request_url(run_type, host) + if url is None: + return + logger.info(f"HelmsDeep will send its requests to {url}") + path = urlparse(host).path.rstrip("/") + endpoint = url[len(host.rstrip("/")) :] + if path and endpoint.startswith(path + "/"): + parsed = urlparse(host) + logger.warning( + f"The host {host} ends in {path}, which HelmsDeep's endpoint " + f"{endpoint} starts with again, so requests go to {url}. The host " + f"should be the service's base URL, eg {parsed.scheme}://{parsed.netloc}." + ) + + +def _stream(cmd: List[str], logger: logging.Logger, extra_env: Optional[Dict] = None): + """Run ``cmd``, logging its output as it comes. Returns the exit code and + the last lines of output.""" + env = {**os.environ, **(extra_env or {})} + # Python block-buffers a pipe, which would hold HelmsDeep's (and the locust + # it starts') lines back for minutes at a time. + env["PYTHONUNBUFFERED"] = "1" + env["NO_COLOR"] = "1" + tail: deque = deque(maxlen=OUTPUT_TAIL_LINES) + with subprocess.Popen( + cmd, + stdout=subprocess.PIPE, + stderr=subprocess.STDOUT, + text=True, + errors="replace", + bufsize=1, + env=env, + ) as proc: + for line in proc.stdout: + line = line.rstrip() + if not line.strip(): + continue + logger.info(f"{LOG_TAG} {line}") + tail.append(line) + exit_code = proc.wait() + return exit_code, "\n".join(tail) + + +def _log_outcome( + summary: Optional[Dict], + exit_code: Optional[int], + elapsed_s: float, + prefix: str, + logger: logging.Logger, +) -> None: + """One line on how the run went, and a warning if nothing got through.""" + if not summary: + return + minutes = elapsed_s / 60 + stages = [s for s in summary.get("stages") or [] if isinstance(s, dict)] + requests = sum(s.get("requests") or 0 for s in stages) + errors = sum(s.get("errors") or 0 for s in stages) + msc = summary.get("max_sustainable_concurrency") + checkpoints = summary.get("checkpoints") or [] + verdict = "no checkpoints configured" + if checkpoints: + met = sum(1 for c in checkpoints if c.get("verdict") == "PASS") + verdict = f"checkpoints {met}/{len(checkpoints)} met" + logger.info( + f"HelmsDeep finished in {minutes:.0f}m (exit {exit_code}): " + f"{requests} requests, {errors} errors, max sustainable concurrency " + f"{msc if msc is not None else 'none (no stage met the SLO)'}, " + f"{verdict}. Outputs: {prefix}_*" + ) + if requests and errors == requests: + logger.warning( + "Every request HelmsDeep sent failed: check the host it was " + "pointed at, and the errors in its output above." + ) + elif not requests: + logger.warning("HelmsDeep completed no requests at all.") + + def run_helmsdeep( helmsdeep_run_type: str, host: str, prefix: str, logger: logging.Logger = logging.getLogger(__name__), + trapi_version: Optional[str] = None, ) -> Dict: """Run one HelmsDeep load test and collect what it wrote. + ``trapi_version`` is the version HelmsDeep writes its queries in: TRAPI 2.0 + carries ``bypass_cache`` under the query's ``parameters``, 1.x at the top + level. It goes over as ``HELMSDEEP_TRAPI_VERSION``, which releases before + HelmsDeep 0.3.0 ignore (they always write the 1.x shape). + Returns the parsed ``summary.json``, the HTML report, and the process exit code. @@ -175,18 +292,17 @@ def run_helmsdeep( "--no-live", ] logger.info(f"Running HelmsDeep: {' '.join(cmd)}") + check_host(helmsdeep_run_type, host, logger) + extra_env = {} + if trapi_version: + extra_env[TRAPI_VERSION_ENV] = trapi_version + logger.info(f"HelmsDeep will write its queries in TRAPI {trapi_version}") error = None - stdout = stderr = "" + output = "" + started = time.monotonic() try: - completed = subprocess.run( - cmd, - capture_output=True, - text=True, - check=False, - ) - exit_code = completed.returncode - stdout, stderr = completed.stdout, completed.stderr + exit_code, output = _stream(cmd, logger, extra_env) except OSError as e: exit_code = None error = f"Failed to launch HelmsDeep: {e}" @@ -205,7 +321,8 @@ def run_helmsdeep( error = ( f"HelmsDeep exited {exit_code} without writing " f"{prefix}{SUMMARY_SUFFIX}" ) - logger.error(f"{error}\n{_tail(stderr) or _tail(stdout)}") + logger.error(f"{error}; its output is above, tagged {LOG_TAG}") + _log_outcome(summary, exit_code, time.monotonic() - started, prefix, logger) return { "runner": "helmsdeep", @@ -219,7 +336,7 @@ def run_helmsdeep( "error": error, # Only kept when something went wrong; a successful run's stdout is a # long progress narration nobody needs in the report JSON. - "output": _tail(stderr) or _tail(stdout) if error else "", + "output": _tail(output) if error else "", } @@ -230,6 +347,7 @@ def run_performance_test( output_dir: str = "test_results", profile: Optional[str] = None, logger: logging.Logger = logging.getLogger(__name__), + trapi_version: Optional[str] = None, ) -> Dict: """Run a performance test case through HelmsDeep. @@ -238,6 +356,9 @@ def run_performance_test( says. Any target that isn't the ARS is queried as an ARA. ``profile`` overrides the HelmsDeep query profile the test case asks for. + + ``trapi_version`` is the run's TRAPI version, for HelmsDeep to write its + queries in. """ component = str(target or (test.components or [ARS_COMPONENT])[0]) component = component.split("infores:")[-1].lower() @@ -247,7 +368,7 @@ def run_performance_test( prefix = os.path.join( output_dir, f"helmsdeep_{_slugify(run_type)}_case_{_slugify(test.id)}" ) - results = run_helmsdeep(run_type, host, prefix, logger) + results = run_helmsdeep(run_type, host, prefix, logger, trapi_version) results["component"] = component results["profile"] = resolved_profile return results diff --git a/test_harness/run.py b/test_harness/run.py index 1634f2b..b7f99b8 100644 --- a/test_harness/run.py +++ b/test_harness/run.py @@ -401,6 +401,7 @@ def run_tests( output_dir=args.get("output_dir") or "test_results", profile=args.get("performance_profile"), logger=logger, + trapi_version=trapi_version, ) collector.collect_performance_result( test, diff --git a/tests/test_performance_logging.py b/tests/test_performance_logging.py new file mode 100644 index 0000000..5697b5d --- /dev/null +++ b/tests/test_performance_logging.py @@ -0,0 +1,97 @@ +"""What a performance run tells the log while HelmsDeep works.""" + +import json +import logging +import sys +import textwrap + +from test_harness import performance_test_runner as ptr + + +def _fake_helmsdeep(tmp_path, monkeypatch, body): + """Stand a script in for ``python -m helmsdeep.cli``.""" + (tmp_path / "fake_helmsdeep.py").write_text(textwrap.dedent(body)) + monkeypatch.syspath_prepend(str(tmp_path)) + monkeypatch.setenv("PYTHONPATH", str(tmp_path)) + monkeypatch.setattr(ptr, "HELMSDEEP_MODULE", "fake_helmsdeep") + + +def test_helmsdeep_output_reaches_the_log_as_it_runs(tmp_path, monkeypatch, caplog): + _fake_helmsdeep( + tmp_path, + monkeypatch, + """ + import json, sys + prefix = sys.argv[sys.argv.index("--csv-prefix") + 1] + print("stage 1/3 started: 10 users") + print("locust: request failed", file=sys.stderr) + stages = [{"stage": 0, "users": 10, "requests": 4, "errors": 4}] + with open(prefix + "_summary.json", "w") as f: + json.dump({"stages": stages, "max_sustainable_concurrency": None}, f) + sys.exit(1) + """, + ) + caplog.set_level(logging.INFO) + results = ptr.run_helmsdeep( + "aras", "https://example.org", str(tmp_path / "out" / "run") + ) + assert results["error"] is None and results["exit_code"] == 1 + messages = [r.getMessage() for r in caplog.records] + assert "[helmsdeep] stage 1/3 started: 10 users" in messages + assert "[helmsdeep] locust: request failed" in messages + assert any( + "HelmsDeep finished" in m and "4 requests, 4 errors" in m for m in messages + ) + assert any("Every request HelmsDeep sent failed" in m for m in messages) + + +def test_output_is_kept_for_a_run_that_wrote_no_summary(tmp_path, monkeypatch): + _fake_helmsdeep( + tmp_path, + monkeypatch, + """ + import sys + print("Traceback: config error", file=sys.stderr) + sys.exit(2) + """, + ) + results = ptr.run_helmsdeep("aras", "https://example.org", str(tmp_path / "run")) + assert "without writing" in results["error"] + assert "Traceback: config error" in results["output"] + + +def test_a_host_carrying_the_endpoint_path_is_flagged(caplog): + caplog.set_level(logging.INFO) + ptr.check_host("ars_mixed", "https://shepherd.example.org/ars") + messages = [r.getMessage() for r in caplog.records] + assert ( + "HelmsDeep will send its requests to " + "https://shepherd.example.org/ars/ars/api/submit" in messages + ) + [warning] = [r for r in caplog.records if r.levelno == logging.WARNING] + assert "https://shepherd.example.org." in warning.getMessage() + + +def test_a_base_url_host_is_not_flagged(caplog): + caplog.set_level(logging.INFO) + ptr.check_host("ars_mixed", "https://ars.ci.transltr.io") + assert not [r for r in caplog.records if r.levelno >= logging.WARNING] + + +def test_the_runs_trapi_version_reaches_helmsdeep(tmp_path, monkeypatch, caplog): + _fake_helmsdeep( + tmp_path, + monkeypatch, + """ + import os + print("trapi=" + os.environ.get("HELMSDEEP_TRAPI_VERSION", "unset")) + """, + ) + monkeypatch.delenv("HELMSDEEP_TRAPI_VERSION", raising=False) + caplog.set_level(logging.INFO) + ptr.run_helmsdeep( + "aras", "https://example.org", str(tmp_path / "run"), trapi_version="2.0.0" + ) + messages = [r.getMessage() for r in caplog.records] + assert "[helmsdeep] trapi=2.0.0" in messages + assert "HelmsDeep will write its queries in TRAPI 2.0.0" in messages diff --git a/tests/test_trapi_auto.py b/tests/test_trapi_auto.py index 2b5cc5a..2bd7a66 100644 --- a/tests/test_trapi_auto.py +++ b/tests/test_trapi_auto.py @@ -118,3 +118,21 @@ def html(*args, **kwargs): args = {"trapi_version": "auto"} assert resolve_trapi_version(args, "ci", logging.getLogger("t")) == "2.0.0" assert "couldn't read the SmartAPI registry" in caplog.text + + +def test_auto_with_a_target_url_says_where_the_version_came_from(registry, caplog): + """The registry describes the deployed service, not the one at + --target_url, so auto says so rather than quietly using it.""" + args = { + "trapi_version": "auto", + "target": "ars", + "target_url": "https://shepherd.example.org", + } + assert resolve_trapi_version(args, "prod", logging.getLogger("t")) == "1.6.0" + assert "not the service at https://shepherd.example.org" in caplog.text + + +def test_auto_without_a_target_url_has_no_such_warning(registry, caplog): + args = {"trapi_version": "auto", "target": None} + resolve_trapi_version(args, "prod", logging.getLogger("t")) + assert "not the service at" not in caplog.text