Skip to content

Commit 083e2e5

Browse files
committed
Compare latency runs one kind of reply at a time
Two runs' median reply times do not show whether a change helped. On the same code the median tool reply moved by a few hundred milliseconds between runs an hour apart, and a run whose replies take fewer tool rounds is faster without any reply getting faster, so a prompt change that cut tool rounds looked like no change at all. The analyzer now reports per origin the share of replies a tool round came before, and with --compare sets a log against an earlier one: each kind's median with a 95% bootstrap interval for its shift, stalls as rates, and the change in the mean split exactly into mix, a different share of tool replies, and speed, each kind getting faster or slower. An origin with replies on one side only has no mix or speed. Under --strict both logs have to pass what strict mode asks of one.
1 parent d7ddd0e commit 083e2e5

3 files changed

Lines changed: 359 additions & 1 deletion

File tree

‎docs/latency-observability.md‎

Lines changed: 17 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -142,6 +142,23 @@ fewer than 20 replies is marked `small_n`: its p95 then lies between its two
142142
largest values. Compare matched yield settings and input recordings; this
143143
budget comparison cannot substitute for browser-perceived E2E measurement.
144144

145+
## Comparing two runs
146+
147+
`python3 scripts/analyze-latency.py --compare before.log after.log` compares
148+
two logs kind of reply by kind; several sessions are pooled by concatenating
149+
their logs. Two runs' overall medians mislead on their own: provider speed
150+
moves a run's median by a few hundred milliseconds with nothing else changed,
151+
and a reply preceded by a tool round waits for a second model pass, so a run
152+
whose replies take fewer tool rounds is faster without any reply getting
153+
faster. The comparison therefore reports, per origin, the share of replies a
154+
tool round came first (`tool_share` in the single-log summary), the median of
155+
each kind with a 95% bootstrap interval for its shift, and the change in the
156+
mean split exactly into mix, from a different share of tool replies, and
157+
speed, from each kind getting faster or slower. Stalls are compared as rates.
158+
The intervals resample replies one by one and so ignore what replies in one
159+
session share; interleave the two arms' sessions so that provider drift falls
160+
on both alike.
161+
145162
## What is not measured
146163

147164
Gemini Live is one combined audio and model pipeline. These records cannot

‎scripts/analyze-latency.py‎

Lines changed: 198 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,7 @@
99
import argparse
1010
import json
1111
import math
12+
import random
1213
import sys
1314
from collections import Counter
1415

@@ -254,6 +255,17 @@ def reply_kind(row):
254255
return f"{row['origin']}_{tool_label(row)}"
255256

256257

258+
def tool_share(rows):
259+
"""Per origin, how many replies a tool round came before, of how many."""
260+
return {
261+
origin: {
262+
"tool": sum(bool(r["tool_batches"]) for r in rows if r["origin"] == origin),
263+
"of": sum(r["origin"] == origin for r in rows),
264+
}
265+
for origin in sorted({r["origin"] for r in rows})
266+
}
267+
268+
257269
def waterfall(first):
258270
"""Consecutive segments from origin to the first native capture."""
259271
if not first or first.get("stage") != "native_audio_capture":
@@ -405,6 +417,9 @@ def ordering(event):
405417
# a rate, and kept out of the distributions, where a few of them would set
406418
# every mean and tail.
407419
typical = [r for r in comparable if not r["stalled"]]
420+
chosen = {id(r) for r in typical}
421+
for row in rows:
422+
row["typical"] = id(row) in chosen
408423

409424
# Whether replies slow as the conversation grows: the part of each wait
410425
# the model is responsible for, against the context it started from.
@@ -482,6 +497,10 @@ def ordering(event):
482497
if r["first_audio"].get("tool_ack_ms") is not None
483498
]
484499
),
500+
# A tool round costs the reply a second model pass, so how many
501+
# replies take one moves the typical wait as much as how fast each
502+
# kind is.
503+
"tool_share": tool_share(typical),
485504
"beyond_window_by_kind": {
486505
kind: statistics(
487506
[r["beyond_window_ms"] for r in typical if reply_kind(r) == kind]
@@ -530,6 +549,160 @@ def ordering(event):
530549
}
531550

532551

552+
# Resamples behind each interval. Seeded, so the same logs give the same report.
553+
BOOTSTRAP_RESAMPLES = 2000
554+
555+
556+
def median(values):
557+
return percentile(sorted(values), 0.50)
558+
559+
560+
def median_shift(before, after, rng):
561+
"""After's median less before's, with a 95% percentile-bootstrap interval.
562+
563+
Replies are resampled one by one, which ignores what replies in one session
564+
share, so the interval is if anything too narrow.
565+
"""
566+
shifts = sorted(
567+
median(rng.choices(after, k=len(after)))
568+
- median(rng.choices(before, k=len(before)))
569+
for _ in range(BOOTSTRAP_RESAMPLES)
570+
)
571+
return {
572+
"ms": round(median(after) - median(before), 1),
573+
"ci95_ms": [percentile(shifts, 0.025), percentile(shifts, 0.975)],
574+
}
575+
576+
577+
def compare(before, after):
578+
"""How replies of each origin changed between two reports.
579+
580+
Two runs' medians alone mislead: provider speed moves a run's median by a
581+
few hundred milliseconds, and a run with more tool replies is slower with
582+
nothing else changed. So each kind of reply is compared on its own, and the
583+
change in the mean is split exactly into mix, the part from a different
584+
share of tool replies, and speed, the part from each kind getting faster or
585+
slower. A kind one side never saw is priced at the other side's mean, so it
586+
counts as mix.
587+
"""
588+
rng = random.Random(0)
589+
sides = {
590+
name: [r for r in report["turns"] if r["typical"]]
591+
for name, report in (("before", before), ("after", after))
592+
}
593+
origins = sorted({r["origin"] for rows in sides.values() for r in rows})
594+
out = {}
595+
for origin in origins:
596+
kinds = {}
597+
mix = speed = 0.0
598+
totals = {
599+
name: sum(r["origin"] == origin for r in rows)
600+
for name, rows in sides.items()
601+
}
602+
for kind in ("no_tool", "tool"):
603+
values = {
604+
name: [
605+
r["beyond_window_ms"]
606+
for r in rows
607+
if r["origin"] == origin and tool_label(r) == kind
608+
]
609+
for name, rows in sides.items()
610+
}
611+
if not any(values.values()):
612+
continue
613+
share = {
614+
name: len(values[name]) / totals[name] if totals[name] else 0.0
615+
for name in sides
616+
}
617+
mean = {name: sum(v) / len(v) for name, v in values.items() if v}
618+
mean.setdefault("before", mean.get("after"))
619+
mean.setdefault("after", mean.get("before"))
620+
mix += (
621+
(share["after"] - share["before"])
622+
* (mean["after"] + mean["before"])
623+
/ 2
624+
)
625+
speed += (
626+
(share["after"] + share["before"])
627+
/ 2
628+
* (mean["after"] - mean["before"])
629+
)
630+
kinds[kind] = {
631+
"before": statistics(values["before"]),
632+
"after": statistics(values["after"]),
633+
"shift": median_shift(values["before"], values["after"], rng)
634+
if all(len(v) > 1 for v in values.values())
635+
else None,
636+
}
637+
means = {
638+
name: [r["beyond_window_ms"] for r in rows if r["origin"] == origin]
639+
for name, rows in sides.items()
640+
}
641+
out[origin] = {
642+
"tool_share": {
643+
name: tool_share(rows).get(origin, {"tool": 0, "of": 0})
644+
for name, rows in sides.items()
645+
},
646+
"kinds": kinds,
647+
"mean_ms": {
648+
name: round(sum(v) / len(v), 1) if v else None
649+
for name, v in means.items()
650+
},
651+
# With no replies on one side there is no mix to have shifted.
652+
"mix_ms": round(mix, 1) if all(totals.values()) else None,
653+
"speed_ms": round(speed, 1) if all(totals.values()) else None,
654+
}
655+
return {
656+
"origins": out,
657+
"stalls": {"before": before["stalls"], "after": after["stalls"]},
658+
}
659+
660+
661+
def render_comparison(comparison):
662+
lines = [
663+
"Time beyond the silence window, after less before. Medians per kind of",
664+
"reply, with a 95% bootstrap interval; the mean's change split into mix",
665+
"(share of tool replies) and speed (each kind faster or slower).",
666+
]
667+
for origin, entry in comparison["origins"].items():
668+
share = entry["tool_share"]
669+
lines.append(
670+
f"\n{origin}: tool round first in "
671+
+ " -> ".join(
672+
f"{share[side]['tool']}/{share[side]['of']}"
673+
for side in ("before", "after")
674+
)
675+
)
676+
for kind, stats in entry["kinds"].items():
677+
cells = [
678+
f"n{stats[side]['count']} p50={stats[side]['p50_ms']}"
679+
if stats[side]["count"]
680+
else "none"
681+
for side in ("before", "after")
682+
]
683+
line = f" {kind:<8} {cells[0]} -> {cells[1]}"
684+
if stats["shift"]:
685+
low, high = stats["shift"]["ci95_ms"]
686+
line += f" shift {stats['shift']['ms']:+} [{low:+}, {high:+}]"
687+
lines.append(line)
688+
mean = entry["mean_ms"]
689+
if None not in mean.values():
690+
lines.append(
691+
f" mean {mean['before']} -> {mean['after']} "
692+
f"({mean['after'] - mean['before']:+.1f}): "
693+
f"mix {entry['mix_ms']:+}, speed {entry['speed_ms']:+}"
694+
)
695+
stalls = comparison["stalls"]
696+
lines.append(
697+
"\nstalls "
698+
+ " -> ".join(
699+
f"{stalls[side]['count']}/{stalls[side]['of']}"
700+
for side in ("before", "after")
701+
)
702+
)
703+
return "\n".join(lines)
704+
705+
533706
def turn_id(row):
534707
return f"{row['room']}/s{row['session']}/t{row['turn']}"
535708

@@ -646,6 +819,8 @@ def summary_lines(report):
646819
):
647820
if report[label]["count"]:
648821
out.append(stat_line(label, report[label]))
822+
for origin, share in report["tool_share"].items():
823+
out.append(f"tool_share_{origin}={share['tool']}/{share['of']}")
649824
for kind, stats in report["beyond_window_by_kind"].items():
650825
out.append(stat_line(f"kind_{kind}", stats))
651826
for band, stats in report["beyond_window_by_context"].items():
@@ -668,6 +843,11 @@ def summary_lines(report):
668843
return out
669844

670845

846+
def strict_pass(report):
847+
"""What --strict asks of a report beyond having records at all."""
848+
return not report["rejected_records"] and verdict(report) != "NO_DATA"
849+
850+
671851
def main():
672852
parser = argparse.ArgumentParser(description=__doc__)
673853
parser.add_argument("log", nargs="?", help="server log; omit to read stdin")
@@ -688,6 +868,11 @@ def main():
688868
default=5000,
689869
help="count a reply this far beyond the window as a stall, not a slow reply",
690870
)
871+
parser.add_argument(
872+
"--compare",
873+
metavar="BEFORE_LOG",
874+
help="compare the log against this earlier one, kind of reply by kind",
875+
)
691876
parser.add_argument(
692877
"--strict",
693878
action="store_true",
@@ -699,6 +884,18 @@ def main():
699884
report = analyze(stream, args.slow_ms, args.stall_ms)
700885
else:
701886
report = analyze(sys.stdin, args.slow_ms, args.stall_ms)
887+
if args.compare:
888+
with open(args.compare, encoding="utf-8", errors="replace") as stream:
889+
before = analyze(stream, args.slow_ms, args.stall_ms)
890+
if not report["turns"] or not before["turns"]:
891+
return 1
892+
comparison = compare(before, report)
893+
print(
894+
json.dumps(comparison, indent=2)
895+
if args.json
896+
else render_comparison(comparison)
897+
)
898+
return int(args.strict and not all(map(strict_pass, (before, report))))
702899
if args.json:
703900
print(json.dumps(report, indent=2))
704901
elif args.summary:
@@ -707,7 +904,7 @@ def main():
707904
print(render(report))
708905
if not report["turns"]:
709906
return 1
710-
if args.strict and (report["rejected_records"] or verdict(report) == "NO_DATA"):
907+
if args.strict and not strict_pass(report):
711908
return 1
712909
return 0
713910

0 commit comments

Comments
 (0)