2b658cb29039048ff6ab3dac31f10519b3349bcc braney Tue Apr 28 09:06:06 2026 -0700 quickLiftBench: add --phases for per-phase timing breakdown, refs #37445 Add --phases flag that writes phases.tsv alongside results.tsv and summary.tsv. Long-form rows of every <span class='timing'> marker emitted by hgTracks (chromAliasSetup, trackDbLoad, parallel data fetch, image generation, cart write, etc.), one row per (case, variant, iteration, phase). A per-(case, variant, phase) median+p90 summary is appended. Useful for localizing where total_ms gaps come from. The first run on bench1_hgwdev surfaced the missing parallel-fetch span on the lifted variant (filed as #37470). Drop the now-unused parse_overall_total helper; total_ms is read directly from parse_phase_timings using the OVERALL_TIMING_LABEL key. Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com> diff --git src/utils/qa/quickLiftBench/quickLiftBench.py src/utils/qa/quickLiftBench/quickLiftBench.py index d3ebc098ff9..24542039b3e 100755 --- src/utils/qa/quickLiftBench/quickLiftBench.py +++ src/utils/qa/quickLiftBench/quickLiftBench.py @@ -1,491 +1,549 @@ #!/usr/bin/env python3 """ quickLiftBench.py - Benchmark hgTracks render time for two saved sessions on the same server. Each case names two (or more) variants, each variant is a saved-session reference of the form "user/sessionName". The runner loads the session, applies a position from the case, and times the hgTracks render with measureTiming=1. Output is one TSV row per (case, variant, position, iteration) plus a per-(case, position) summary with median/p90 and pairwise ratios. The headline metric is `total_ms`, taken from the "Overall total time" timing span emitted by hgTracks. `load_ms_sum` and `draw_ms_sum` are the sums across all visible tracks from the printTrackTiming() table. """ import argparse import csv import os import re import statistics import sys import time from datetime import datetime from urllib.parse import urlencode import requests import yaml # A row of the printTrackTiming() table: shortLabel, load, draw, total TRACK_TIMING_ROW_RE = re.compile( r"^\s*([^,<>]+?)\s*,\s*(\d+)\s*,\s*(\d+)\s*,\s*(\d+)\s*$" ) # <span class='trackTiming'> ... </span>. The opening span is never explicitly # closed by printTrackTiming(); the regex's non-greedy match terminates at the # first subsequent </span> from an unrelated span (e.g. the trailing # 'timing' span for "Time to write and close cart"). TRACK_TIMING_SPAN_RE = re.compile( r"<span class=['\"]trackTiming['\"]>(.*?)</span>", re.DOTALL | re.IGNORECASE, ) # <span class='timing'>label: NNN millis<BR></span> -- per-phase timings. # Also matches the "Overall total time" footer span which uses <br /> (XHTML). TIMING_SPAN_RE = re.compile( r"<span class=['\"]timing['\"]>(.+?):\s*(\d+)\s*millis(?:<br\s*/?>)?\s*</span>", re.DOTALL | re.IGNORECASE, ) OVERALL_TIMING_LABEL = "Overall total time" def parse_args(): p = argparse.ArgumentParser( description=( "Benchmark hgTracks render time for saved sessions. Each variant " "is a user/sessionName reference." ), formatter_class=argparse.RawDescriptionHelpFormatter, ) here = os.path.dirname(os.path.abspath(__file__)) p.add_argument( "--config", default=os.path.join(here, "cases.yaml"), help="YAML config file (default: cases.yaml next to script)", ) p.add_argument( "--cases", default=None, help="Comma-separated list of case ids to run (default: all)", ) p.add_argument( "--server-override", default=None, help="Override every case's server with this server name from defaults.servers", ) p.add_argument( "--iterations", type=int, default=None, help="Override defaults.iterations", ) p.add_argument( "--warmup", type=int, default=None, help="Override defaults.warmup", ) p.add_argument( "--out", default=None, help="Output directory (default: ./results/<timestamp>/)", ) p.add_argument( "--verbose", "-v", action="store_true", help="Print per-iteration timings to stderr", ) + p.add_argument( + "--phases", + action="store_true", + help="Also write phases.tsv with per-iteration phase timings parsed " + "from <span class='timing'> markers (chromAliasSetup, " + "trackDbLoad, parallel data fetch, etc.)", + ) return p.parse_args() def load_config(path): with open(path) as f: cfg = yaml.safe_load(f) if "cases" not in cfg or not cfg["cases"]: sys.exit(f"{path}: no `cases` defined") cfg.setdefault("defaults", {}) cfg["defaults"].setdefault("iterations", 5) cfg["defaults"].setdefault("warmup", 1) cfg["defaults"].setdefault("timeout", 60) cfg["defaults"].setdefault("servers", {}) return cfg def parse_session(s): """Split 'user/sessionName' (or '/s/user/name'). Returns (user, name).""" if not isinstance(s, str): raise ValueError(f"variant must be a 'user/sessionName' string, got: {s!r}") s = s.strip() if s.startswith("/s/"): s = s[3:] if "/" not in s: raise ValueError(f"variant must contain '/': {s!r}") user, name = s.split("/", 1) if not user or not name: raise ValueError(f"empty user or session name in: {s!r}") return user, name def resolve_server(case, defaults, server_override): server_key = server_override or case.get("server") if not server_key: raise ValueError(f"case '{case.get('id')}' has no server") servers = defaults.get("servers", {}) if server_key not in servers: raise ValueError( f"server '{server_key}' not in defaults.servers ({list(servers)})" ) return server_key, servers[server_key].rstrip("/") def build_url(server_url, user, session_name): """Build an hgTracks URL that loads a saved session at its saved position. The position is NOT overridden via URL: a native session and its quickLifted counterpart sit on different assemblies, so identical chr:start-end ranges would not be biologically equivalent. Whatever region the session was saved at is what gets rendered. """ params = [ ("hgS_doOtherUser", "submit"), ("hgS_otherUserName", user), ("hgS_otherUserSessionName", session_name), ("hgt.trackImgOnly", "1"), ("measureTiming", "1"), ] return f"{server_url}/cgi-bin/hgTracks?{urlencode(params)}" def parse_track_timing_rows(html): """Return a list of (shortLabel, load_ms, draw_ms, total_ms) rows.""" if not html: return [] rows = [] for span in TRACK_TIMING_SPAN_RE.findall(html): text = span.replace(" ", " ") for raw in text.split("<br />"): raw = raw.strip() # Drop the inner red <idiv> "average for all windows" rows. if "<idiv" in raw or "</idiv" in raw: continue if not raw or raw.startswith("track,"): continue m = TRACK_TIMING_ROW_RE.match(raw) if not m: continue label, load, draw, total = m.groups() rows.append((label.strip(), int(load), int(draw), int(total))) return rows def parse_phase_timings(html): """Pull all <span class='timing'>label: NNN millis</span> entries.""" if not html: return {} out = {} for m in TIMING_SPAN_RE.finditer(html): label = m.group(1).strip() # Strip HTML tags that sneak into labels (e.g. format strings) label = re.sub(r"<[^>]+>", "", label).strip() out[label] = int(m.group(2)) return out -def parse_overall_total(html): - """Return the 'Overall total time' value from the footer timing span, - or None if not found.""" - phases = parse_phase_timings(html) - return phases.get(OVERALL_TIMING_LABEL) - - def detect_block(html): """Return a short error reason if the response indicates bot-block / error.""" if html is None: return "no-response" lower = html.lower() if "you've been blocked" in lower or "you have been blocked" in lower: return "bot-blocked" if "<title>error" in lower or "errabort" in lower: return "errabort" return None def run_request(session, url, timeout): """Fetch a URL once. Return (http_ms, status_code, html, error).""" start = time.monotonic() try: resp = session.get(url, timeout=timeout, verify=True) except requests.exceptions.RequestException as e: elapsed_ms = int((time.monotonic() - start) * 1000) return elapsed_ms, None, None, f"transport: {e.__class__.__name__}" elapsed_ms = int((time.monotonic() - start) * 1000) err = None if resp.status_code != 200: err = f"http-{resp.status_code}" return elapsed_ms, resp.status_code, resp.text, err def median_or_none(xs): xs = [x for x in xs if x is not None] if not xs: return None return int(statistics.median(xs)) def p90(xs): xs = sorted(x for x in xs if x is not None) if not xs: return None if len(xs) == 1: return xs[0] k = max(0, int(round(0.9 * (len(xs) - 1)))) return xs[k] def fmt_ms(v): return "-" if v is None else str(v) def main(): args = parse_args() cfg = load_config(args.config) defaults = cfg["defaults"] iterations = args.iterations if args.iterations is not None else defaults["iterations"] warmup = args.warmup if args.warmup is not None else defaults["warmup"] timeout = defaults["timeout"] requested_ids = ( set(s.strip() for s in args.cases.split(",")) if args.cases else None ) cases = cfg["cases"] if requested_ids: cases = [c for c in cases if c["id"] in requested_ids] missing = requested_ids - {c["id"] for c in cases} if missing: sys.exit(f"unknown case id(s): {sorted(missing)}") if not cases: sys.exit("no cases selected") timestamp = datetime.now().strftime("%Y%m%d-%H%M%S") out_dir = args.out or os.path.join(os.path.dirname(os.path.abspath(__file__)), "results", timestamp) os.makedirs(out_dir, exist_ok=True) results_path = os.path.join(out_dir, "results.tsv") summary_path = os.path.join(out_dir, "summary.tsv") + phases_path = os.path.join(out_dir, "phases.tsv") if args.phases else None print(f"writing results to {out_dir}", file=sys.stderr) results_fields = [ "case", "variant", "server", "user", "session", "iteration", "http_ms", "load_ms_sum", "draw_ms_sum", "n_tracks", "total_ms", "status_code", "error", ] + phases_fields = [ + "case", "variant", "server", "user", "session", "iteration", + "phase", "ms", + ] all_rows = [] + all_phase_rows = [] with open(results_path, "w", newline="") as rf: writer = csv.DictWriter(rf, fieldnames=results_fields, delimiter="\t") writer.writeheader() for case in cases: cid = case["id"] description = case.get("description", "") print(f"\n=== {cid}: {description}", file=sys.stderr) try: server_key, server_url = resolve_server(case, defaults, args.server_override) except ValueError as e: print(f" {e}", file=sys.stderr) continue variants = case.get("variants") or {} if not variants: print(f" skipped: no variants", file=sys.stderr) continue # Fresh session per case to keep an independent hgsid lineage. session = requests.Session() session.headers.update({"User-Agent": "quickLiftBench/1.0"}) for vname, vraw in variants.items(): try: user, session_name = parse_session(vraw) except ValueError as e: print(f" variant {vname}: {e}", file=sys.stderr) continue url = build_url(server_url, user, session_name) if args.verbose: print(f" URL: {url}", file=sys.stderr) for _ in range(warmup): run_request(session, url, timeout) for it in range(1, iterations + 1): http_ms, code, html, err = run_request(session, url, timeout) block = detect_block(html) if not err else None if block and not err: err = block load_sum = draw_sum = total_ms = None n_tracks = None + phases = {} if html and not err: rows = parse_track_timing_rows(html) n_tracks = len(rows) if rows: load_sum = sum(r[1] for r in rows) draw_sum = sum(r[2] for r in rows) - total_ms = parse_overall_total(html) + phases = parse_phase_timings(html) + total_ms = phases.get(OVERALL_TIMING_LABEL) if total_ms is None and not rows: err = "no-timing" row = { "case": cid, "variant": vname, "server": server_key, "user": user, "session": session_name, "iteration": it, "http_ms": http_ms, "load_ms_sum": load_sum if load_sum is not None else "", "draw_ms_sum": draw_sum if draw_sum is not None else "", "n_tracks": n_tracks if n_tracks is not None else "", "total_ms": total_ms if total_ms is not None else "", "status_code": code if code is not None else "", "error": err or "", } writer.writerow(row) rf.flush() all_rows.append(row) + + if args.phases: + for label, ms in phases.items(): + all_phase_rows.append({ + "case": cid, + "variant": vname, + "server": server_key, + "user": user, + "session": session_name, + "iteration": it, + "phase": label, + "ms": ms, + }) if args.verbose: print( f" {vname:8s} it={it} " f"http={fmt_ms(http_ms)} " f"load_sum={fmt_ms(load_sum)} draw_sum={fmt_ms(draw_sum)} " f"tracks={fmt_ms(n_tracks)} " f"total={fmt_ms(total_ms)} {err or ''}", file=sys.stderr, ) write_summary(cases, all_rows, summary_path) print(f"\nresults: {results_path}", file=sys.stderr) print(f"summary: {summary_path}", file=sys.stderr) + if phases_path: + write_phases(all_phase_rows, phases_fields, phases_path) + print(f"phases: {phases_path}", file=sys.stderr) + def _to_int(v): if v == "" or v is None: return None return int(v) def write_summary(cases, rows, path): """ Per (case, variant): compute median + p90 of (http_ms, load_ms_sum, draw_ms_sum, total_ms). Then for each compare-pair, emit median ratios. """ by_case_var = {} for r in rows: by_case_var.setdefault(r["case"], {}).setdefault(r["variant"], []).append(r) fields = [ "case", "variant", "n", "n_ok", "http_median", "http_p90", "load_sum_median", "load_sum_p90", "draw_sum_median", "draw_sum_p90", "total_median", "total_p90", ] pair_fields = [ "case", "left_variant", "right_variant", "left_total_median", "right_total_median", "ratio_total", "ratio_load_sum", "ratio_draw_sum", "ratio_http", ] summary_lines = [] with open(path, "w", newline="") as f: w_v = csv.DictWriter(f, fieldnames=fields, delimiter="\t") w_v.writeheader() per_variant_stats = {} for cid, variants in sorted(by_case_var.items()): for vname, vrows in sorted(variants.items()): ok = [r for r in vrows if not r["error"]] http = [_to_int(r["http_ms"]) for r in ok] load = [_to_int(r["load_ms_sum"]) for r in ok] draw = [_to_int(r["draw_ms_sum"]) for r in ok] total = [_to_int(r["total_ms"]) for r in ok] stats = { "case": cid, "variant": vname, "n": len(vrows), "n_ok": len(ok), "http_median": median_or_none(http), "http_p90": p90(http), "load_sum_median": median_or_none(load), "load_sum_p90": p90(load), "draw_sum_median": median_or_none(draw), "draw_sum_p90": p90(draw), "total_median": median_or_none(total), "total_p90": p90(total), } w_v.writerow({k: ("" if v is None else v) for k, v in stats.items()}) per_variant_stats[(cid, vname)] = stats f.write("\n# Pairwise comparisons (right/left ratio of medians)\n") w_p = csv.DictWriter(f, fieldnames=pair_fields, delimiter="\t") w_p.writeheader() for case in cases: cid = case["id"] pairs = case.get("compare") variants = list((case.get("variants") or {}).keys()) if not pairs: if len(variants) < 2: continue pairs = [[variants[0], v] for v in variants[1:]] for left, right in pairs: ls = per_variant_stats.get((cid, left)) rs = per_variant_stats.get((cid, right)) if not ls or not rs: continue row = { "case": cid, "left_variant": left, "right_variant": right, "left_total_median": ls["total_median"] if ls["total_median"] is not None else "", "right_total_median": rs["total_median"] if rs["total_median"] is not None else "", "ratio_total": ratio(rs["total_median"], ls["total_median"]), "ratio_load_sum": ratio(rs["load_sum_median"], ls["load_sum_median"]), "ratio_draw_sum": ratio(rs["draw_sum_median"], ls["draw_sum_median"]), "ratio_http": ratio(rs["http_median"], ls["http_median"]), } w_p.writerow(row) summary_lines.append( f" {cid:30s} {left}->{right} " f"total {ls['total_median']}->{rs['total_median']} ms " f"ratio={row['ratio_total']}" ) if summary_lines: print("\nPairwise summary (right/left ratio of overall total render time):", file=sys.stderr) for line in summary_lines: print(line, file=sys.stderr) def ratio(num, denom): if num is None or denom is None or denom == 0: return "" return f"{num / denom:.2f}" +def write_phases(rows, fields, path): + """Write per-iteration phase timings, then a per-(case, variant, phase) + median + n summary appended below.""" + with open(path, "w", newline="") as f: + w = csv.DictWriter(f, fieldnames=fields, delimiter="\t") + w.writeheader() + for r in rows: + w.writerow(r) + + if not rows: + return + + # Per-(case, variant, phase) median for quick eyeballing. + groups = {} + for r in rows: + key = (r["case"], r["variant"], r["phase"]) + groups.setdefault(key, []).append(r["ms"]) + + f.write("\n# Per-(case, variant, phase) median ms across iterations\n") + summary_fields = ["case", "variant", "phase", "n", "median_ms", "p90_ms"] + sw = csv.DictWriter(f, fieldnames=summary_fields, delimiter="\t") + sw.writeheader() + for (cid, vname, phase), values in sorted(groups.items()): + sw.writerow({ + "case": cid, + "variant": vname, + "phase": phase, + "n": len(values), + "median_ms": median_or_none(values), + "p90_ms": p90(values), + }) + + if __name__ == "__main__": main()