diff --git a/docs/live.md b/docs/live.md index 8d64140..a4767cb 100644 --- a/docs/live.md +++ b/docs/live.md @@ -83,6 +83,25 @@ apply when a header is enabled; enabling a flag is not a measurement of accuracy latency or cost. See [images](https://docs.typesafe.ai/images), [Box](https://docs.typesafe.ai/primitives/box), and [models](https://docs.typesafe.ai/models). +### Context limits + +These are the limits the models page states, read on 2026-10-31 at +. Its table gives the context length of `jev-1.14.0` and +`jev-1.13.0` as "64k per-request / 32k per-question". The page defines the per-request context as +the state plus all questions combined and the per-question context as the state plus any one +question, and a request has to fit both. It sets no separate limit on the number of questions. +Sending the header `TypeSafe-Danger-Zone-Long-Context: true`, which `long_context=True` adds, +raises both limits to 262k tokens on either model. The page adds that long context costs the same +per token and is slower and less accurate than staying inside the default limits. + +The page states the 262k figure in tokens and does not say what a "k" in its table counts, so this +cookbook converts none of the three limits to characters, and it does not check a request against +them. [`context_size`](vision.md#context-size-and-the-comparison-table) counts characters and +UTF-8 bytes, which are not tokens. The one token count the cookbook can show is the +`usage.input_tokens` of a recorded response, which may be `null`. The documentation index at + (read on 2026-10-31) lists no page or endpoint for counting or +estimating tokens, and the cookbook has no estimator. + ## What a call does - Requests are built from the question objects: `state` as given, each question as the raw @@ -97,8 +116,9 @@ latency or cost. See [images](https://docs.typesafe.ai/images), - The `request_id` (the `x-typesafe-request-id` header, when present) is not part of the stored response format, and `DecisionResult` rejects unknown fields, so it is kept beside the result: `backend.last_request_id`, `backend.request_ids`, `backend.records` (one `CallRecord` per - successful call: replay key, model, request id, usage, date, and `images` and `distinct_images`, - both 0 unless the call carried image assets) and the recorder's optional sidecar. + successful call: replay key, model, request id, usage, date, `images` and `distinct_images` + (both 0 unless the call carried image assets) and `latency_seconds`, see [Latency](#latency)) + and the recorder's optional sidecar. ## Budget guard @@ -165,6 +185,53 @@ returning an SDK-style response. The backend requires no opt-in or key for it (i requests; a client without that parameter that retries inside itself is invisible to the budget, so build it with retries off. +## Latency + +Each HTTP attempt is timed with the backend's `clock` (default `time.perf_counter`, a monotonic +clock; pass `clock=` to inject one in a test). The clock is read once immediately before +`client.system_one(...)` is called and once immediately after that call returns or raises. The +difference, rounded to a nanosecond, is the attempt's `latency_seconds`. + +| What | In the timed window? | +| --- | --- | +| Whatever the client does inside the one `system_one` call | Yes | +| The budget check that counts the attempt | No: it comes first, so `requests_made` already includes the attempt at the first reading | +| The cookbook's validation of the response | No: it comes after the second reading | +| The backoff sleep before a retry | No: it falls between one attempt's second reading and the next attempt's first | +| The recorder's ledger write | No: it happens after `decide` has returned | + +The cookbook does not look inside the client, so `latency_seconds` is the wall-clock time of that +call as seen from the machine that made it. It is not a server-side or model-only time. + +Where it is kept: + +- `CallRecord.latency_seconds` and `backend.last_latency_seconds` hold the answering attempt's. +- Each entry of `backend.last_retried` holds the `latency_seconds` of the failed attempt it + describes. +- The recorder's sidecar holds it on a `recorded` line (the answering attempt), on every entry of + `retried`, and on a failed line (the attempt that ended the call; null when that call sent + nothing, such as a budget stop or a refusal). +- It is not in the responses file and not in the replay key: recording one request under two + different clocks writes byte-identical response files. +- `backend.ledger()`, the in-memory summary, has no latency field. + +A latency is null when the clock gave no usable reading: a difference that is negative or not +finite, a clock that raises, or readings that cannot be subtracted. A call that took several +attempts has one latency for its answering attempt; the failed attempts' latencies are in +`retried`, and the backoff between attempts is in none of them, so their sum is not the call's +elapsed time. + +### Reading a captured latency back + +`load_ledger_latency(ledger_path, replay_key)` returns a `LedgerLatency(latency_seconds, date, +model)` for the `recorded` line stored under the key. It returns `None`, meaning "not measured", +when the ledger has no `recorded` line under that key or the line has no latency (a ledger +written before latency was captured has none). It reads only the line under the key itself: not a +`!failed-N` line, not a `superseded` history entry, and nothing from a replay. It raises +`FileNotFoundError` for a ledger file that does not exist and `ValueError` for a latency that is +not a finite, non-negative number, or a line without a text date or model. +[vision.md](vision.md#honest-accounting) shows the result feeding `run_record`. + ## Recorder ```python @@ -233,27 +300,32 @@ report = record( there, and a path that is the same file as `responses_path` (including through a different spelling or a link). Never commit it as a fixture. It is rewritten atomically after every call. - A call that produced a response is `{replay_key: {status: "recorded", request_id, model, date, - input_tokens, output_tokens, attempts, retried}}`, written before that response is merged, so - a merge conflict still leaves its request id. `request_id` is the id of the answering - attempt. `attempts` is every HTTP attempt that call spent, the answering one included (1 when + input_tokens, output_tokens, latency_seconds, attempts, retried}}`, written before that + response is merged, so a merge conflict still leaves its request id. `request_id` is the id + of the answering attempt, and `latency_seconds` is that attempt's [latency](#latency). + `attempts` is every HTTP attempt that call spent, the answering one included (1 when nothing was retried). `retried` lists the failed attempts it retried past, oldest first, as - `{error_type, http_status, request_id}` (`http_status` and `request_id` are null when the - attempt got no response, for example a timeout); it is `[]` when nothing was retried. + `{error_type, http_status, request_id, latency_seconds}` (`http_status` and `request_id` are + null when the attempt got no response, for example a timeout; `latency_seconds` is that + attempt's own latency); it is `[]` when nothing was retried. `images` and `distinct_images` (the image copies and the distinct assets, counts only, never bytes or references) are added only when the call carried image assets; a text-only call's line has neither. - A call that produced nothing to record is written before the error is re-raised, as `{replay_key + "!failed-N": {status, error_type, http_status, request_id, model, date, - attempts, retried}}`. `status` is `invalid_response` (the API answered but the result failed - validation, or contained the key), `error` (an HTTP or connection error, or any other + latency_seconds, attempts, retried}}`. `status` is `invalid_response` (the API answered but + the result failed validation, or contained the key), `error` (an HTTP or connection error, or any other exception that ended the call, including a request refused before anything was sent), `timeout` or `budget_stopped`. `error_type`, `http_status` and `request_id` describe the last attempt (the one that ended the call; a timeout has no request id; for `budget_stopped` - `error_type` is `BudgetExceeded` and the other two are null). A `decide` call refused before - anything was sent (`ImageRequestTooLarge` for an image request over a 32 MiB cap, or + `error_type` is `BudgetExceeded` and the other two are null). `latency_seconds` is the + [latency](#latency) of that same attempt, and null when the call sent nothing (a budget stop + or a refusal, including a budget stop after earlier attempts were retried). A `decide` call + refused before anything was sent (`ImageRequestTooLarge` for an image request over a 32 MiB cap, or `LiveConfigError` for a request the backend is not set up for, such as image assets without `images=True`) is `status: "error"` with `error_type` the exception's class name, - `http_status` and `request_id` null, `attempts: 0` and `retried: []`; it is not a paid call. + `http_status`, `request_id` and `latency_seconds` null, `attempts: 0` and `retried: []`; it is + not a paid call. A request that fails validation is not one of these: it raises from `record` before `decide` is called and gets no line. `attempts` is the HTTP attempts this call spent: 0 when nothing was sent (a budget already spent, or a refusal as above), and otherwise includes any diff --git a/docs/offline-and-live.md b/docs/offline-and-live.md index c5706b9..c974f2e 100644 --- a/docs/offline-and-live.md +++ b/docs/offline-and-live.md @@ -315,3 +315,69 @@ A recorded fixture contains the answers and their provenance, never the state maintainer with a key. The notebook executor (`tools/execute_notebook.py`) never runs live and removes `JEV_COOKBOOK_*` and `TYPESAFE_*` from the kernel it starts, so a committed notebook cannot hold a live result by accident ([recipe-template.md](recipe-template.md#executing-a-notebook)). + +## Long-context workloads + +A long-context study needs inputs of a chosen size, and a text of thousands of characters does not +belong in `inputs.jsonl`, where a reviewer has to read every line. Keep the recipe for the text in +the example and generate the text: + +- `fields` holds the parameters, for example `{"seed": 7, "target_characters": 2000}`, and + whatever else decides the text (the position of an evidence passage, which distractors are + included). +- The recipe's `helpers.build_state(fields)` builds the state from them. The notebook and the + recipe's tests call that same function ([fixtures.md](fixtures.md) describes `fields` and + `build_state`). +- The replay key is a hash of the state `build_state` returns, so it follows from `fields` alone. + It is stable for a given seed when `build_state` depends on nothing but `fields`: the example + below hashes `":"` with SHA-256 for each sentence, so no clock, environment + variable or interpreter setting enters the text. + +The test below pins the replay key for one seed, shows that another seed and another length each +give a different key, and shows that the row a recipe would commit stays short. In a recipe, +`build_state` lives in `helpers.py`; replace the pinned key with the one your own `build_state` +gives for the committed seed, after checking that it is the text you meant. + +```python +import hashlib +import json + +from jev_cookbook import Noul, replay_key + +WORDS = ("ledger", "invoice", "shipment", "warranty", "renewal", "audit", "tariff", "carrier") +QUESTIONS = {"renewal": Noul(instructions="Does the document mention a renewal?")} + + +def build_state(fields): # in a recipe this lives in helpers.py + seed, target = fields["seed"], fields["target_characters"] + sentences, size, index = [], 0, 0 + while size <= target: + digest = hashlib.sha256(f"{seed}:{index}".encode()).digest() + sentence = " ".join(WORDS[b % len(WORDS)] for b in digest[:8]) + "." + sentences.append(sentence) + size += len(sentence) + 1 + index += 1 + return {"document": " ".join(sentences)[:target]} + + +def test_the_replay_key_is_stable_for_a_seed(): + fields = {"seed": 7, "target_characters": 2000} + state = build_state(fields) + key = replay_key(state, QUESTIONS) + assert len(state["document"]) == 2000 + assert build_state(dict(fields)) == state + assert key == "e02f7cf95ab3d7f540cfe056b94f9e437a739bc2494a64d86fc694eba4e642c9" + assert replay_key(build_state({**fields, "seed": 8}), QUESTIONS) != key + assert replay_key(build_state({**fields, "target_characters": 2001}), QUESTIONS) != key + row = json.dumps({"id": "e1", "split": "test", "fields": fields, "replay_keys": [key]}) + assert len(row) < 300 and state["document"][:20] not in row +``` + +To report how large a generated text is, use +[`context_size`](vision.md#context-size-and-the-comparison-table): it returns characters and +UTF-8 bytes, which are not tokens. The token count of a request is the `usage.input_tokens` of a +recorded response, and the limits that apply are in [live.md](live.md#context-limits). A character +count or an offline run does not demonstrate a measured 262k-token inference +([multimodal-track.md](multimodal-track.md#what-an-evaluation-must-show)). Report latency, input +tokens and cost only when they were measured and recorded, with the model, the capture date and N, +as section 2 of [CONTRIBUTING.md](../CONTRIBUTING.md) requires. diff --git a/docs/vision.md b/docs/vision.md index 48a61a2..950e436 100644 --- a/docs/vision.md +++ b/docs/vision.md @@ -726,14 +726,16 @@ fields = { ## Honest accounting `run_record(result, mode=...)` creates one row with mode, returned model, -input/output tokens, latency in seconds and cost in USD: +input/output tokens, latency in seconds and cost in USD, and the capture date and N when you +pass them: ```python from jev_cookbook.vision import run_record # result is a DecisionResult from the recipe's existing replay or live backend. -# row = run_record(result, mode="synthetic") -# row = run_record(result, mode="recorded", measured_latency_seconds=captured_seconds) +# row = run_record(result, mode="synthetic", n=len(examples)) +# row = run_record(result, mode="recorded", measured_latency_seconds=captured_seconds, +# capture_date="2026-10-31", n=len(examples)) ``` Synthetic and scripted rows contain `None` for model, tokens, latency and cost, @@ -745,10 +747,92 @@ Provide `measured_latency_seconds` only for actual inference timing, and `measured_cost_usd` only for an actual measured charge. Replay execution time is not inference latency. Token-derived price calculations are estimates and do not belong in the measured-cost field. The helper neither times a request nor infers a -price. For a replay of recorded responses, load any actual measurements from the -capture record; leave missing ones null. +price. For a replay of recorded responses, read the latency the recorder captured with +`jev_cookbook.live.load_ledger_latency` ([live](live.md#latency) says what the timing +covers) and leave a measurement that was not captured null. + +`capture_date` is a `YYYY-MM-DD` calendar date string and `n` a positive integer: the number of +examples the row's numbers cover. Each is a key of the row only when you pass it, so a row built +without them has the keys it had before. A synthetic or scripted row takes `n` and refuses +`capture_date`, because nothing was captured. `2026-02-30`, `20261031` and a `datetime.date` +object are refused as a capture date. + +```python +from jev_cookbook.live import load_ledger_latency +from jev_cookbook.vision import run_record + +# `ledger` is the sidecar that live.record(..., ledger_path=...) wrote, `key` the replay key of +# the request, and `result` the recorded DecisionResult replayed for that key. +measured = load_ledger_latency(ledger, key) # None when no latency was captured for this key +row = run_record( + result, + mode="recorded", + measured_latency_seconds=None if measured is None else measured.latency_seconds, + capture_date=None if measured is None else measured.date, + n=1, +) +``` + +For a ledger line that holds 0.8 seconds captured on 2026-10-31 and a result that reported 61 +input tokens, `row` is: + +```text +{'model': 'jev-1.13.0', 'input_tokens': 61, 'output_tokens': 0, 'latency_seconds': 0.8, 'cost_usd': None, 'mode': 'recorded', 'capture_date': '2026-10-31', 'n': 1} +``` Continue to use `run_header`, the recipe's measured-results disclosure and the [offline/live contract](offline-and-live.md). Accounting rows do not make a synthetic pipeline check a model benchmark, or turn validation selection into a held-out result. + +### Context size and the comparison table + +`context_size(state, questions)` counts the text of a request on your machine and returns +`{"characters": ..., "utf8_bytes": ...}`, the sum of `len(s)` and of `len(s.encode("utf-8"))` +over the strings it covers. They are counts of characters and bytes, not tokens: the result has +no token key, and the API's own count is the `usage.input_tokens` of a recorded response. + +The strings covered are the ones in the state (a string, the items of a list, or the keys and +string values of an object, at any depth) and, for each question, its name and every string in +its instructions and criteria, object keys included, so a `Choice`'s option names count. +Numbers, booleans, JSON punctuation and the question type are not counted. An image reference +counts as the text it is; the image behind it does not. A string shared by two questions is +counted once per question. Pass one question to get the state plus that question, the +per-question context that [live](live.md#context-limits) describes. A string that cannot be +encoded as UTF-8, such as a lone surrogate, raises `ValueError`. + +`comparison_table(rows)` formats rows as aligned text. A row is a mapping with keys from `label`, +`mode`, `model`, `characters`, `utf8_bytes`, `input_tokens`, `output_tokens`, `latency_seconds`, +`cost_usd`, `capture_date` and `n`: normally a `run_record` row plus a label and the output of +`context_size`. A column appears when at least one row has the key. A row without the key shows +`-`; a key whose value is `None` shows `not measured`, so a synthetic or scripted row, or a +recorded row whose response reported no `input_tokens`, shows no number it does not have. It +raises `ValueError` for no rows, for a key outside that list, and for a synthetic or scripted row +that holds a model, tokens, latency or cost. + +```python +from jev_cookbook.vision import comparison_table, context_size + +# Continuing from above: `state` and `questions` are the request, `row` is the recorded row, +# `synthetic_result` was replayed from a synthetic fixture, and `unreported` is a recorded result +# whose response reported no usage. +size = context_size(state, questions) # {'characters': 123, 'utf8_bytes': 123} +rows = [ + {"label": "synthetic check", **run_record(synthetic_result, mode="synthetic", n=1), **size}, + {"label": "recorded", **row, **size}, + {"label": "no usage reported", **run_record(unreported, mode="recorded", n=1), **size}, +] +print(comparison_table(rows)) +``` + +```text +label mode model characters utf8_bytes input_tokens output_tokens latency_seconds cost_usd capture_date n +----------------- --------- ------------ ---------- ---------- ------------ ------------- --------------- ------------ ------------ - +synthetic check synthetic not measured 123 123 not measured not measured not measured not measured - 1 +recorded recorded jev-1.13.0 123 123 61 0 0.8 not measured 2026-10-31 1 +no usage reported recorded jev-1.13.0 123 123 not measured not measured not measured not measured - 1 +``` + +A character count or a synthetic row does not demonstrate a measured long-context inference +([multimodal-track.md](multimodal-track.md#what-an-evaluation-must-show)). `run_record` takes +`input_tokens` from the recorded response and gives a synthetic or scripted row none. diff --git a/src/jev_cookbook/live.py b/src/jev_cookbook/live.py index 7cde43e..6961e75 100644 --- a/src/jev_cookbook/live.py +++ b/src/jev_cookbook/live.py @@ -17,6 +17,7 @@ import inspect import json import logging +import math import os import re import tempfile @@ -46,6 +47,7 @@ "API_KEY_ENV", "BudgetExceeded", "CallRecord", + "LedgerLatency", "LiveBackend", "LiveCallError", "LiveConfigError", @@ -54,6 +56,7 @@ "RecordReport", "dump_responses", "live_backend_from_env", + "load_ledger_latency", "merge_responses", "record", ] @@ -141,7 +144,13 @@ class RecordConflict(ValueError): @dataclass(frozen=True) class CallRecord: - """Ledger line for one successful call (no key, no state, no answers).""" + """Ledger line for one successful call (no key, no state, no answers). + + ``latency_seconds`` is the wall-clock time of the HTTP attempt that produced the response, + measured by the backend's clock around the ``client.system_one`` call (see ``LiveBackend``), + or ``None`` when the clock gave no usable reading. It is never part of a stored response or + a replay key. + """ replay_key: str model: str @@ -150,6 +159,7 @@ class CallRecord: date: str images: int = 0 distinct_images: int = 0 + latency_seconds: float | None = None def _secret_variants(*raw: str | None) -> tuple[str, ...]: @@ -258,6 +268,21 @@ def _today_utc() -> str: return datetime.datetime.now(datetime.timezone.utc).date().isoformat() +def _elapsed_seconds(start: Any, end: Any) -> float | None: + """Seconds from one clock reading to the next, or ``None`` when that is not a measurement. + + A difference that is not a finite number, or is negative, is reported as missing and never + clamped or guessed, so a broken or injected clock cannot put an invented latency on disk. + A valid difference is rounded to nine decimal places (a nanosecond), which removes + floating-point subtraction noise such as ``0.20000000000000018``. + """ + try: + seconds = float(end - start) + except (TypeError, ValueError, OverflowError): + return None + return round(seconds, 9) if math.isfinite(seconds) and seconds >= 0 else None + + def _import_sdk() -> Any: try: import typesafe_sdk @@ -501,6 +526,18 @@ class LiveBackend: spent). A request over the budget raises ``BudgetExceeded`` before anything is sent. ``max_retries`` retries (default 2) apply to HTTP 408/429/5xx, connection errors and timeouts, with exponential backoff (``sleep`` is injectable). + + Latency: every HTTP attempt is timed with ``clock`` (default ``time.perf_counter``, a + monotonic clock; injectable for tests). The clock is read once immediately before + ``client.system_one`` is called and once immediately after it returns or raises, so the + window holds what the client does inside that one call. It starts after the budget check + and the request has been built, and it ends before the cookbook validates the response, + before the backoff sleep and before any ledger write. The answering attempt's seconds are on + its ``CallRecord`` and in ``last_latency_seconds``; each failed attempt that was retried + carries its own in ``last_retried``. Seconds are rounded to a nanosecond. A reading that is + not a finite, non-negative number of seconds is stored as ``None``, and so is the latency of + an attempt when the clock raises. + Latency is never part of a stored response or a replay key. """ mode = "live" @@ -517,9 +554,12 @@ def __init__( long_context: bool = False, sleep: Callable[[float], None] = time.sleep, today: Callable[[], str] = _today_utc, + clock: Callable[[], float] = time.perf_counter, ) -> None: if type(model) is not str or not model.strip(): raise ValueError("model must be a non-empty string such as 'jev-latest'") + if not callable(clock): + raise TypeError("clock must be a callable returning seconds") for name, value in (("images", images), ("long_context", long_context)): if type(value) is not bool: raise TypeError(f"{name} must be a bool") @@ -545,6 +585,8 @@ def __init__( self._request_kwargs = dict(request_kwargs or {}) self._sleep = sleep self._today = today + self._clock = clock + self._last_latency: float | None = None self._lock = threading.Lock() self._made = 0 self._failed = 0 @@ -632,8 +674,9 @@ def request_ids(self) -> tuple[str | None, ...]: def last_retried(self) -> tuple[dict[str, Any], ...]: """The failed attempts the latest ``decide`` call retried past, oldest first. - Each is ``{error_type, http_status, request_id}`` (scrubbed). Reset at the start of every - call, so it describes that call whether it then succeeded or raised. + Each is ``{error_type, http_status, request_id, latency_seconds}`` (scrubbed; + ``latency_seconds`` is that attempt's wall-clock time, or ``None``). Reset at the start of + every call, so it describes that call whether it then succeeded or raised. """ return tuple(dict(r) for r in self._retried) @@ -641,6 +684,17 @@ def last_retried(self) -> tuple[dict[str, Any], ...]: def last_request_id(self) -> str | None: return self._records[-1].request_id if self._records else None + @property + def last_latency_seconds(self) -> float | None: + """Wall-clock seconds of the latest HTTP attempt of the latest ``decide`` call. + + That is the answering attempt when the call succeeded, and otherwise the attempt that + ended it. ``None`` when that call sent nothing (it was refused, or the budget was spent) + or when the clock gave no usable reading. Reset at the start of every ``decide`` call and + again before each attempt. + """ + return self._last_latency + def ledger(self) -> dict[str, Any]: """Plain-data summary for an orchestrator's ledger (no key, state or answers).""" out: dict[str, Any] = { @@ -664,6 +718,13 @@ def ledger(self) -> dict[str, Any]: out["distinct_images"] = sum(r.distinct_images for r in self._records) return out + def _read_clock(self) -> Any: + """One reading of the clock, or ``None`` if it raises: a paid response must not be lost.""" + try: + return self._clock() + except Exception: + return None + def _spend(self) -> None: with self._lock: if self._made >= self.max_requests: @@ -696,6 +757,7 @@ def decide( # attempts on a refused request's ledger line (see ``last_retried``). with self._lock: self._retried = [] + self._last_latency = None plain_state, checked = _check_request(state, questions) key = replay_key(plain_state, checked, assets=assets) checked_assets = _check_assets(plain_state, checked, assets) @@ -731,21 +793,30 @@ def decide( # Errors are raised after their `except` block has ended, so neither `__cause__` nor # `__context__` carries the SDK exception (its message may echo the key). while True: + with self._lock: + self._last_latency = None self._spend() failure: Exception | None = None delay = 0.0 + started: Any = None try: - response = self._client.system_one( - state=plain_json(plain_state, "state"), - questions=payload, - model=self.requested_model, + call_kwargs = { + "state": plain_json(plain_state, "state"), + "questions": payload, + "model": self.requested_model, **asset_kwargs, **self._request_kwargs, **self._call_extra, - ) + } + started = self._read_clock() + response = self._client.system_one(**call_kwargs) except Exception as exc: + latency = None + if started is not None: + latency = _elapsed_seconds(started, self._read_clock()) with self._lock: self._failed += 1 + self._last_latency = latency if _is_retryable(exc) and attempt < self.max_retries: attempt += 1 delay = self._delay(exc, attempt) @@ -756,6 +827,7 @@ def decide( "error_type": note.error_type, "http_status": note.status, "request_id": note.request_id, + "latency_seconds": latency, } ) elif _is_validation_error(exc): @@ -763,6 +835,9 @@ def decide( else: failure = _describe_failure(exc, self._secrets) else: + latency = _elapsed_seconds(started, self._read_clock()) + with self._lock: + self._last_latency = latency break if failure is not None: raise failure @@ -791,7 +866,7 @@ def decide( request_id=_redact(rid, self._secrets) if rid else None, ) self._note_success( - CallRecord(key, result.model, rid, result.usage, date, images, distinct_images) + CallRecord(key, result.model, rid, result.usage, date, images, distinct_images, latency) ) return result @@ -978,16 +1053,21 @@ def record( format, so it lives there). A request that fails validation never becomes a ``decide`` call: ``record`` raises before any call and writes no line for it. A success is ``{replay_key: {status: "recorded", request_id, model, date, input_tokens, output_tokens, - attempts, retried}}``, plus ``images`` and ``distinct_images`` (counts only) when the call - carried image assets. A call that produced nothing to record (``invalid_response``, ``error``, - ``timeout``, ``budget_stopped``) is ``{replay_key + "!failed-N": {status, error_type, - http_status, request_id, model, date, attempts, retried}}`` with no image counts, written + latency_seconds, attempts, retried}}``, plus ``images`` and ``distinct_images`` (counts only) + when the call carried image assets. A call that produced nothing to record + (``invalid_response``, ``error``, ``timeout``, ``budget_stopped``) is + ``{replay_key + "!failed-N": {status, error_type, http_status, request_id, model, date, + latency_seconds, attempts, retried}}`` with no image counts, written before the error is re-raised. A ``decide`` call refused before anything was sent (``ImageRequestTooLarge``, ``LiveConfigError``) is ``status: "error"`` with ``error_type`` the exception's class name and ``attempts`` 0. ``attempts`` is the HTTP attempts that call spent (0 when nothing was sent) and ``retried`` - lists ``{error_type, http_status, request_id}`` for each failed attempt it retried past, on - both kinds of line. Re-recording a key with ``overwrite=True`` keeps the earlier + lists ``{error_type, http_status, request_id, latency_seconds}`` for each failed attempt it + retried past, on both kinds of line. ``latency_seconds`` is the wall-clock time of one HTTP + attempt (see ``LiveBackend``): on a ``recorded`` line the attempt that produced the response, + on a failed line the attempt that ended the call (null when that call sent nothing), and + null wherever the clock gave no usable reading. It lives only in this ledger, never in the + responses file or a replay key. Re-recording a key with ``overwrite=True`` keeps the earlier ``recorded`` entry under ``superseded``. A ``ledger_path`` inside a ``fixtures/`` directory, or the same file as ``responses_path``, is refused with ``ValueError`` before any call. """ @@ -1047,6 +1127,7 @@ def record( "date": rec.date, "input_tokens": rec.usage.input_tokens, "output_tokens": rec.usage.output_tokens, + "latency_seconds": rec.latency_seconds, "attempts": backend.requests_made - attempts_before, "retried": list(backend.last_retried), } @@ -1130,12 +1211,62 @@ def _ledger_failure( "request_id": getattr(exc, "request_id", None), "model": backend.requested_model, "date": backend._today(), + "latency_seconds": backend.last_latency_seconds, "attempts": attempts, "retried": list(backend.last_retried), } _write_atomic(ledger, dump_responses(old)) +@dataclass(frozen=True) +class LedgerLatency: + """The measured latency a ``record`` ledger holds for one replay key. + + ``latency_seconds`` is the wall-clock time of the HTTP attempt that produced the recorded + response, ``date`` is the UTC date of that call (the capture date) and ``model`` is the + model string the API returned. + """ + + latency_seconds: float + date: str + model: str + + +def load_ledger_latency( + ledger_path: str | os.PathLike[str], replay_key: str +) -> LedgerLatency | None: + """Read the measured latency of one recorded call from a ``record`` sidecar ledger. + + Returns ``None``, meaning "not measured", when the ledger has no ``recorded`` line under + ``replay_key`` or that line has no ``latency_seconds`` (null, or missing as in a ledger + written before latency was captured). Only the line stored under the key itself is read: a + ``!failed-N`` line, a ``superseded`` entry and the elapsed time of a replay are never used. + Raises ``FileNotFoundError`` when ``ledger_path`` does not exist, and ``ValueError`` when a + ``recorded`` line holds a latency that is not a finite, non-negative number or lacks a text + ``date`` or ``model``. Pass the result to ``vision.run_record`` as ``measured_latency_seconds`` + with ``capture_date=result.date``. + """ + if type(replay_key) is not str: + raise TypeError("replay_key must be a str") + path = Path(ledger_path) + if not path.exists(): + raise FileNotFoundError(f"no ledger file at {path}") + line = _load_responses(path).get(replay_key) + if not isinstance(line, dict) or line.get("status") != "recorded": + return None + seconds = line.get("latency_seconds") + if seconds is None: + return None + if type(seconds) not in (int, float) or not math.isfinite(seconds) or seconds < 0: + raise ValueError( + f"{path}: latency_seconds for {replay_key} must be a finite, non-negative number" + ) + date, model = line.get("date"), line.get("model") + if not (isinstance(date, str) and date and isinstance(model, str) and model): + raise ValueError(f"{path}: the recorded line for {replay_key} needs a text date and model") + return LedgerLatency(float(seconds), date, model) + + def live_backend_from_env( *, model: str | None = None, images: bool = False, long_context: bool = False, **_ignored: Any ) -> LiveBackend: diff --git a/src/jev_cookbook/vision.py b/src/jev_cookbook/vision.py index 82b1b70..d1346fd 100644 --- a/src/jev_cookbook/vision.py +++ b/src/jev_cookbook/vision.py @@ -8,12 +8,13 @@ import base64 import binascii +import datetime import hashlib import io import math import re import struct -from collections.abc import Iterable, Mapping +from collections.abc import Iterable, Iterator, Mapping from dataclasses import dataclass from fractions import Fraction from numbers import Integral, Real @@ -41,6 +42,8 @@ "LocalizationReport", "box_confidence", "box_iou", + "comparison_table", + "context_size", "crop_bounds", "crop_box", "draw_boxes", @@ -1279,22 +1282,50 @@ def load_frames( return state, assets +_CAPTURE_DATE = re.compile(r"[0-9]{4}-[0-9]{2}-[0-9]{2}") + + +def _capture_date(value: Any) -> str: + if not isinstance(value, str) or not _CAPTURE_DATE.fullmatch(value): + raise ValueError("capture_date must be a YYYY-MM-DD string") + try: + datetime.date.fromisoformat(value) + except ValueError: + raise ValueError("capture_date must be a real calendar date, YYYY-MM-DD") from None + return value + + def run_record( result: Any, *, mode: str, measured_latency_seconds: float | None = None, measured_cost_usd: float | None = None, + capture_date: str | None = None, + n: int | None = None, ) -> dict[str, Any]: """Make one accounting row without estimating tokens, latency or cost. ``result`` has the ``source``, ``model`` and ``usage`` attributes of DecisionResult. Synthetic/scripted records always contain null usage, latency, cost and model. Recorded/live rows take reported tokens and only explicitly supplied measurements. - Recorded latency must come from capture, never the elapsed time of replay. + Recorded latency must come from capture, never the elapsed time of replay: read it from + the recorder's ledger with ``jev_cookbook.live.load_ledger_latency``. + + ``capture_date`` (a ``YYYY-MM-DD`` calendar date) and ``n`` (a positive integer: how many + examples the row's numbers cover) become keys of the row only when they are given, so a row + built without them has exactly the keys it had before they existed. A synthetic or scripted + row refuses ``capture_date``, because no capture happened, and accepts ``n``. """ if mode not in ("synthetic", "scripted", "recorded", "live"): raise ValueError("mode must be synthetic, scripted, recorded or live") + extra: dict[str, Any] = {} + if capture_date is not None: + if mode in ("synthetic", "scripted"): + raise ValueError("synthetic/scripted runs have no capture, so no capture_date") + extra["capture_date"] = _capture_date(capture_date) + if n is not None: + extra["n"] = _positive_int(n, "n") row: dict[str, Any] = dict.fromkeys( ("model", "input_tokens", "output_tokens", "latency_seconds", "cost_usd") ) @@ -1304,6 +1335,7 @@ def run_record( raise ValueError("synthetic/scripted mode requires a synthetic result") if measured_latency_seconds is not None or measured_cost_usd is not None: raise ValueError("synthetic/scripted runs cannot report measured API latency or cost") + row.update(extra) return row model = getattr(result, "model", None) if ( @@ -1327,4 +1359,118 @@ def run_record( None if measured_cost_usd is None else _number(measured_cost_usd, "measured_cost_usd") ), ) + row.update(extra) return row + + +def _strings(value: Any) -> Iterator[str]: + """Every ``str`` in ``value`` at any depth: a bare string, list items, object keys and values.""" + if isinstance(value, str): + yield value + elif isinstance(value, Mapping): + for key, part in value.items(): + yield from _strings(key) + yield from _strings(part) + elif isinstance(value, (list, tuple)): + for part in value: + yield from _strings(part) + + +def context_size(state: Any, questions: Mapping[str, Any]) -> dict[str, int]: + """Count the text of a request in characters and in UTF-8 bytes. These are not tokens. + + The count is local and exact for the strings it covers, and it is not an estimate of + anything the API reports: the API's own count is ``usage.input_tokens`` of a recorded + response, which this module never derives. + + The strings counted are those in ``state`` (a string, the items of a list, or the keys and + string values of an object, at any depth) and, for every question, its name and every string + in its ``instructions`` and ``criteria`` (object keys included, so a ``Choice``'s option + names count). Each string is counted once where it appears, so an instruction shared by + two questions is counted twice. JSON punctuation, numbers, booleans and the question type + are not counted, and an image reference is counted as the text it is while the image behind + it is not. Pass a single question to count the state plus that question alone. + + Returns ``{"characters": ..., "utf8_bytes": ...}``: the sum of ``len(s)`` and of + ``len(s.encode("utf-8"))``. A string that cannot be encoded as UTF-8 (a lone surrogate) + raises ``ValueError``. + """ + if not isinstance(questions, Mapping): + raise TypeError("questions must be a mapping of name -> question") + parts = list(_strings(state)) + for name, question in questions.items(): + parts.extend(_strings(name)) + parts.extend(_strings(getattr(question, "instructions", None))) + parts.extend(_strings(getattr(question, "criteria", None))) + try: + utf8_bytes = sum(len(part.encode("utf-8")) for part in parts) + except UnicodeEncodeError: + raise ValueError("a string in the request cannot be encoded as UTF-8") from None + return {"characters": sum(len(part) for part in parts), "utf8_bytes": utf8_bytes} + + +_TABLE_COLUMNS = ( + "label", + "mode", + "model", + "characters", + "utf8_bytes", + "input_tokens", + "output_tokens", + "latency_seconds", + "cost_usd", + "capture_date", + "n", +) +_MEASUREMENT_FIELDS = ("model", "input_tokens", "output_tokens", "latency_seconds", "cost_usd") +_NOT_MEASURED = "not measured" + + +def comparison_table(rows: Iterable[Mapping[str, Any]]) -> str: + """Format accounting rows as an aligned text table; a value that is ``None`` reads ``not measured``. + + Each row is a mapping with keys from ``label``, ``mode``, ``model``, ``characters``, + ``utf8_bytes``, ``input_tokens``, ``output_tokens``, ``latency_seconds``, ``cost_usd``, + ``capture_date`` and ``n``: the keys of a :func:`run_record` row, plus a ``label`` and the + two keys of :func:`context_size` that the caller adds. A column appears when at least one + row has that key. A row without the key shows ``-``; a key whose value is ``None`` shows + ``not measured``, so a synthetic or scripted row, or a recorded row whose response reported + no ``input_tokens``, never shows a number it does not have. Other values are shown as + ``str`` of the value, unrounded. + + Raises ``ValueError`` for no rows, for a key outside the list above, and for a row whose + ``mode`` is ``synthetic`` or ``scripted`` but whose model, tokens, latency or cost is not + ``None``: such a row did not come from :func:`run_record`. + """ + table = [dict(row) for row in rows] + if not table: + raise ValueError("comparison_table needs at least one row") + for row in table: + unknown = [key for key in row if key not in _TABLE_COLUMNS] + if unknown: + raise ValueError(f"unknown comparison column(s) {unknown!r}; allowed: {_TABLE_COLUMNS}") + if row.get("mode") in ("synthetic", "scripted") and any( + row.get(field) is not None for field in _MEASUREMENT_FIELDS + ): + raise ValueError( + "a synthetic or scripted row cannot hold a model, tokens, latency or cost; " + "build rows with run_record" + ) + columns = [column for column in _TABLE_COLUMNS if any(column in row for row in table)] + + def cell(row: Mapping[str, Any], column: str) -> str: + if column not in row: + return "-" + return _NOT_MEASURED if row[column] is None else str(row[column]) + + body = [[cell(row, column) for column in columns] for row in table] + widths = [ + max(len(column), *(len(line[i]) for line in body)) for i, column in enumerate(columns) + ] + + def line(cells: list[str]) -> str: + return " ".join( + text.ljust(width) for text, width in zip(cells, widths, strict=True) + ).rstrip() + + return "\n".join([line(columns), line(["-" * width for width in widths]), *map(line, body)]) diff --git a/tests/test_live.py b/tests/test_live.py index a8f1a7b..b58d904 100644 --- a/tests/test_live.py +++ b/tests/test_live.py @@ -34,6 +34,7 @@ record, replay_key, ) +from jev_cookbook import live as live_module from jev_cookbook.live import _dump, dump_responses # A stand-in secret assembled at run time so no literal in this file looks like a credential. @@ -116,6 +117,12 @@ def make(*outcomes, **kw): return LiveBackend(kw.pop("model", "jev-latest"), client=client, **kw), client +def clock_of(*readings): + """A clock that returns the given readings in turn: two per HTTP attempt, before and after.""" + it = iter(readings) + return lambda: next(it) + + # -- protocol, provenance, shapes ------------------------------------------------------------ @@ -616,7 +623,10 @@ def test_record_surfaces_an_invalid_answer_and_writes_nothing_for_it(tmp_path): def test_record_writes_an_optional_request_id_sidecar(tmp_path): path, ledger = tmp_path / "r.json", tmp_path / "ledger.json" - backend, _ = make(Resp(api_body(usage={"input_tokens": 7, "output_tokens": None}), "req-9")) + backend, _ = make( + Resp(api_body(usage={"input_tokens": 7, "output_tokens": None}), "req-9"), + clock=clock_of(1.0, 1.25), + ) report = record(backend, [(STATE, QUESTIONS)], path, ledger_path=ledger) key = replay_key(STATE, QUESTIONS) assert report.ledger_path == ledger @@ -628,6 +638,7 @@ def test_record_writes_an_optional_request_id_sidecar(tmp_path): "date": DAY, "input_tokens": 7, "output_tokens": None, + "latency_seconds": 0.25, "attempts": 1, "retried": [], } @@ -755,7 +766,9 @@ def test_a_200_with_a_text_body_has_no_parsed_response(): def test_failure_on_the_second_call_leaves_a_ledger_with_the_first_request_id(tmp_path): path, ledger = tmp_path / "r.json", tmp_path / "ledger.json" - backend, _ = make(Resp(api_body(), "req-paid"), ApiError(400, "bad")) + backend, _ = make( + Resp(api_body(), "req-paid"), ApiError(400, "bad"), clock=clock_of(0.0, 0.5, 1.0, 1.125) + ) with pytest.raises(LiveCallError): record(backend, two_requests(), path, ledger_path=ledger) first = replay_key(*two_requests()[0]) @@ -771,6 +784,7 @@ def test_failure_on_the_second_call_leaves_a_ledger_with_the_first_request_id(tm "request_id": "req-err-400", "model": "jev-latest", "date": DAY, + "latency_seconds": 0.125, "attempts": 1, "retried": [], } @@ -977,6 +991,11 @@ def test_sidecar_attempts_add_up_to_requests_made_and_keep_retried_request_ids(t ApiError(503), max_requests=7, max_retries=2, + # Seven attempts, two readings each: A 0.5 s; B 1.0 s (timeout), 2.0 s (500), 0.25 s (200); + # C 0.75 s; D 0.125 s and 0.375 s. + clock=clock_of( + 0.0, 0.5, 10.0, 11.0, 20.0, 22.0, 30.0, 30.25, 40.0, 40.75, 50.0, 50.125, 60.0, 60.375 + ), ) record(backend, doc(1), path, ledger_path=ledger) record(backend, doc(2), path, ledger_path=ledger) @@ -991,24 +1010,47 @@ def test_sidecar_attempts_add_up_to_requests_made_and_keep_retried_request_ids(t assert [side[k]["attempts"] for k in (keys[0], keys[1])] == [1, 3] assert side[keys[1]]["request_id"] == "req-b" assert side[keys[1]]["retried"] == [ - {"error_type": "TimeoutError", "http_status": None, "request_id": None}, - {"error_type": "ApiError", "http_status": 500, "request_id": "req-err-500"}, + { + "error_type": "TimeoutError", + "http_status": None, + "request_id": None, + "latency_seconds": 1.0, + }, + { + "error_type": "ApiError", + "http_status": 500, + "request_id": "req-err-500", + "latency_seconds": 2.0, + }, ] assert side[keys[0]]["retried"] == [] and side[keys[2] + "!failed-1"]["retried"] == [] stopped = side[keys[3] + "!failed-1"] assert stopped["status"] == "budget_stopped" and stopped["attempts"] == 2 assert [r["request_id"] for r in stopped["retried"]] == ["req-err-503", "req-err-503"] + assert side[keys[0]]["latency_seconds"] == 0.5 and side[keys[1]]["latency_seconds"] == 0.25 + assert side[keys[2] + "!failed-1"]["latency_seconds"] == 0.75 + # The budget stopped D before a third attempt was sent, so no attempt ended the call. + assert stopped["latency_seconds"] is None + assert [r["latency_seconds"] for r in stopped["retried"]] == [0.125, 0.375] assert "req-err-500" in ledger.read_text("utf-8") def test_a_failed_call_after_retries_lists_them_on_the_failed_line(tmp_path): - backend, _ = make(ApiError(502), ApiError(400), max_retries=2) + backend, _ = make( + ApiError(502), ApiError(400), max_retries=2, clock=clock_of(0.0, 0.5, 1.0, 1.25) + ) _, side, _ = sidecar_after(tmp_path, backend) line = list(side.values())[0] assert line["attempts"] == 2 and line["http_status"] == 400 assert line["retried"] == [ - {"error_type": "ApiError", "http_status": 502, "request_id": "req-err-502"} + { + "error_type": "ApiError", + "http_status": 502, + "request_id": "req-err-502", + "latency_seconds": 0.5, + } ] + assert line["latency_seconds"] == 0.25 def test_retried_entries_are_scrubbed(tmp_path, clean_env): @@ -1115,3 +1157,233 @@ def test_a_text_only_live_ledger_summary_has_exactly_its_original_fields(): "request_ids", ] assert backend.records[0].images == backend.records[0].distinct_images == 0 + + +# -- latency capture: per attempt, around the client call, in the ledger only ---------------- + + +def test_latency_window_is_the_client_call_and_nothing_around_it(monkeypatch): + events = [] + readings = iter([10.0, 10.25]) + + def clock(): + events.append(f"clock(requests_made={backend.requests_made})") + return next(readings) + + class TimedClient: + def system_one(self, **kwargs): + events.append(f"client(requests_made={backend.requests_made})") + return Resp(api_body()) + + real_parse = live_module._parse_response + + def parse(*args, **kwargs): + events.append("parse") + return real_parse(*args, **kwargs) + + monkeypatch.setattr(live_module, "_parse_response", parse) + backend = LiveBackend( + "jev-latest", + client=TimedClient(), + clock=clock, + today=lambda: DAY, + sleep=lambda seconds: events.append("sleep"), + ) + backend.decide(STATE, QUESTIONS) + # The attempt is already counted when the first reading is taken, and the second reading + # comes before the response is validated. + assert events == [ + "clock(requests_made=1)", + "client(requests_made=1)", + "clock(requests_made=1)", + "parse", + ] + assert backend.records[0].latency_seconds == 0.25 + assert backend.last_latency_seconds == 0.25 + + +def test_each_attempt_is_timed_and_the_backoff_sleep_is_outside_every_window(): + events = [] + readings = iter([0.0, 0.5, 1.0, 3.0]) + + def clock(): + events.append("clock") + return next(readings) + + client = FakeClient(ApiError(503), Resp(api_body())) + original = client.system_one + + def logged(**kwargs): + events.append("client") + return original(**kwargs) + + client.system_one = logged + backend = LiveBackend( + "jev-latest", + client=client, + clock=clock, + today=lambda: DAY, + sleep=lambda seconds: events.append(f"sleep({seconds})"), + ) + backend.decide(STATE, QUESTIONS) + assert events == ["clock", "client", "clock", "sleep(0.5)", "clock", "client", "clock"] + assert [r["latency_seconds"] for r in backend.last_retried] == [0.5] + assert backend.records[0].latency_seconds == 2.0 + assert backend.last_latency_seconds == 2.0 + + +def _raising_clock(): + raise RuntimeError("the clock is broken") + + +@pytest.mark.parametrize( + "make_clock, expected", + [ + (lambda: clock_of(1.0, 3.5), 2.5), + (lambda: clock_of(5, 7), 2.0), + (lambda: clock_of(2.0, 2.0), 0.0), + (lambda: clock_of(0.1, 0.3), 0.2), # 0.3 - 0.1 is 0.19999999999999998 before rounding + (lambda: clock_of(5.0, 4.0), None), + (lambda: clock_of(1.0, float("nan")), None), + (lambda: clock_of(1.0, float("inf")), None), + (lambda: clock_of(None, 1.0), None), + (lambda: clock_of(1.0, "x"), None), + (lambda: _raising_clock, None), + ], +) +def test_latency_is_none_unless_the_clock_gives_a_finite_non_negative_difference( + make_clock, expected +): + backend, _ = make(Resp(api_body()), clock=make_clock()) + backend.decide(STATE, QUESTIONS) + # A clock that cannot measure never loses the paid response; the latency is just missing. + assert len(backend.records) == 1 and backend.requests_made == 1 + assert backend.records[0].latency_seconds == expected + assert backend.last_latency_seconds == expected + + +def test_the_clock_must_be_callable(): + with pytest.raises(TypeError, match="callable"): + LiveBackend("jev-latest", client=FakeClient(), clock=5) + + +def test_a_call_record_built_without_a_latency_has_none(): + assert live_module.CallRecord("k", "m", None, Usage(), DAY).latency_seconds is None + + +def test_the_ledger_line_holds_the_latency_and_the_responses_file_and_keys_do_not(tmp_path): + for name, readings in (("fast", (0.0, 0.25)), ("slow", (100.0, 107.5))): + backend, _ = make(Resp(api_body(), "req-1"), clock=clock_of(*readings)) + record( + backend, + [(STATE, QUESTIONS)], + tmp_path / name / "r.json", + ledger_path=tmp_path / f"{name}-ledger.json", + ) + fast = (tmp_path / "fast" / "r.json").read_text("utf-8") + slow = (tmp_path / "slow" / "r.json").read_text("utf-8") + assert fast == slow and "latency" not in fast + key = replay_key(STATE, QUESTIONS) + assert set(json.loads(fast)) == {key} + ledger = { + n: json.loads((tmp_path / f"{n}-ledger.json").read_text("utf-8")) for n in ("fast", "slow") + } + assert ledger["fast"][key]["latency_seconds"] == 0.25 + assert ledger["slow"][key]["latency_seconds"] == 7.5 + + +def test_a_failed_line_has_the_latency_of_the_attempt_that_ended_the_call(tmp_path): + path, ledger = tmp_path / "r.json", tmp_path / "ledger.json" + backend, _ = make( + ApiError(400), + Resp({"model": MODEL, "answers": {}}), + clock=clock_of(0.0, 0.75, 10.0, 10.5), + ) + with pytest.raises(LiveCallError): + record(backend, doc(1), path, ledger_path=ledger) + with pytest.raises(LiveResponseError): + record(backend, doc(2), path, ledger_path=ledger) + side = json.loads(ledger.read_text("utf-8")) + keys = [replay_key(*doc(n)[0]) for n in (1, 2)] + assert side[keys[0] + "!failed-1"]["latency_seconds"] == 0.75 + assert side[keys[1] + "!failed-1"]["latency_seconds"] == 0.5 + assert backend.last_latency_seconds == 0.5 + + +def test_a_call_that_sends_nothing_has_no_latency_not_the_previous_calls(): + backend, _ = make(Resp(api_body()), clock=clock_of(0.0, 0.25), max_requests=1) + backend.decide(STATE, QUESTIONS) + assert backend.last_latency_seconds == 0.25 + with pytest.raises(ValueError): + backend.decide(STATE, {}) + assert backend.last_latency_seconds is None + with pytest.raises(BudgetExceeded): + backend.decide({"document": "other"}, QUESTIONS) + assert backend.last_latency_seconds is None + + +LEDGER_LINE = {"status": "recorded", "model": MODEL, "date": DAY} + + +def write_ledger(tmp_path, lines): + path = tmp_path / "ledger.json" + path.write_text(json.dumps(lines), encoding="utf-8") + return path + + +def test_load_ledger_latency_reads_what_record_wrote(tmp_path): + backend, _ = make(Resp(api_body()), clock=clock_of(1.0, 1.25)) + record(backend, [(STATE, QUESTIONS)], tmp_path / "r.json", ledger_path=tmp_path / "l.json") + found = live_module.load_ledger_latency(tmp_path / "l.json", replay_key(STATE, QUESTIONS)) + assert found == live_module.LedgerLatency(0.25, DAY, MODEL) + + +@pytest.mark.parametrize( + "lines", + [ + {}, + {"k": dict(LEDGER_LINE)}, + {"k": {**LEDGER_LINE, "latency_seconds": None}}, + {"k!failed-1": {**LEDGER_LINE, "latency_seconds": 9.0}}, + {"k": {**LEDGER_LINE, "status": "error", "latency_seconds": 9.0}}, + {"k": 5}, + ], +) +def test_load_ledger_latency_is_none_when_nothing_was_measured(tmp_path, lines): + assert live_module.load_ledger_latency(write_ledger(tmp_path, lines), "k") is None + + +def test_a_zero_latency_is_a_measurement_not_a_missing_one(tmp_path): + path = write_ledger(tmp_path, {"k": {**LEDGER_LINE, "latency_seconds": 0}}) + assert live_module.load_ledger_latency(path, "k") == live_module.LedgerLatency(0.0, DAY, MODEL) + + +def test_only_the_line_under_the_key_is_read_not_its_history(tmp_path): + old = {**LEDGER_LINE, "latency_seconds": 99.0} + path = write_ledger(tmp_path, {"k": {**LEDGER_LINE, "latency_seconds": 2, "superseded": [old]}}) + assert live_module.load_ledger_latency(path, "k") == live_module.LedgerLatency(2.0, DAY, MODEL) + + +@pytest.mark.parametrize( + "change", + [ + {"latency_seconds": -1.0}, + {"latency_seconds": True}, + {"latency_seconds": "1"}, + {"latency_seconds": float("nan")}, + {"latency_seconds": float("inf")}, + {"latency_seconds": 1.0, "date": None}, + {"latency_seconds": 1.0, "model": ""}, + ], +) +def test_load_ledger_latency_rejects_a_malformed_recorded_line(tmp_path, change): + path = write_ledger(tmp_path, {"k": {**LEDGER_LINE, **change}}) + with pytest.raises(ValueError): + live_module.load_ledger_latency(path, "k") + + +def test_load_ledger_latency_refuses_a_missing_file_and_a_non_text_key(tmp_path): + with pytest.raises(FileNotFoundError): + live_module.load_ledger_latency(tmp_path / "nope.json", "k") + with pytest.raises(TypeError): + live_module.load_ledger_latency(write_ledger(tmp_path, {}), 5) diff --git a/tests/test_multimodal_backends.py b/tests/test_multimodal_backends.py index 36e570e..cb0e6a1 100644 --- a/tests/test_multimodal_backends.py +++ b/tests/test_multimodal_backends.py @@ -822,6 +822,7 @@ def test_a_backend_config_refusal_before_sending_writes_the_documented_error_lin assert line["status"] == "error" and line["error_type"] == "LiveConfigError" assert line["http_status"] is None and line["request_id"] is None assert line["attempts"] == 0 and line["retried"] == [] + assert line["latency_seconds"] is None def test_a_request_that_fails_validation_raises_from_record_and_gets_no_sidecar_line( @@ -865,3 +866,63 @@ def test_the_live_ledger_carries_image_counts_beside_the_token_fields(fake_sdk, assert (summary["images"], summary["distinct_images"]) == (4, 1) # The counts say nothing about bytes, content or references. assert "data_base64" not in json.dumps([line, summary]) and REF not in json.dumps(line) + + +# -- a configurable long-context workload: fields in inputs.jsonl, the text generated ----------- + +WORKLOAD_WORDS = ( + "ledger", + "invoice", + "shipment", + "warranty", + "renewal", + "audit", + "tariff", + "carrier", +) +WORKLOAD_QUESTIONS = {"renewal": Noul(instructions="Does the document mention a renewal?")} + + +def workload_build_state(fields): + """What a recipe's ``helpers.build_state`` does: the long text is generated from ``fields``. + + Only ``fields`` ({seed, target_characters}) is committed in ``inputs.jsonl``. The text comes + from SHA-256 of ``":"`` rather than from ``random``, so the text depends on + nothing but the fields. + """ + seed, target = fields["seed"], fields["target_characters"] + sentences, size, index = [], 0, 0 + while size <= target: + digest = hashlib.sha256(f"{seed}:{index}".encode()).digest() + sentence = " ".join(WORKLOAD_WORDS[b % len(WORKLOAD_WORDS)] for b in digest[:8]) + "." + sentences.append(sentence) + size += len(sentence) + 1 + index += 1 + return {"document": " ".join(sentences)[:target]} + + +def test_a_seeded_workload_has_a_stable_replay_key_and_a_readable_inputs_row(): + from jev_cookbook.vision import context_size + + fields = {"seed": 7, "target_characters": 2000} + state = workload_build_state(fields) + key = replay_key(state, WORKLOAD_QUESTIONS) + assert len(state["document"]) == 2000 + # Equal fields give the same text and the same key, however the fields dictionary is ordered. + assert workload_build_state(dict(reversed(fields.items()))) == state + # Pinned: the key a recorded response is stored under cannot drift for seed 7. + assert key == "e02f7cf95ab3d7f540cfe056b94f9e437a739bc2494a64d86fc694eba4e642c9" + # A field that changes the text changes the key. + other_seed = workload_build_state({**fields, "seed": 8}) + assert replay_key(other_seed, WORKLOAD_QUESTIONS) == ( + "4cc46beae73ac8ba9e89d89b9086d891a00ad88e120ccc063803a1fc35b57a23" + ) + longer = workload_build_state({**fields, "target_characters": 2001}) + assert replay_key(longer, WORKLOAD_QUESTIONS) == ( + "6e93217eab9d7fe10da4f960b9b6bdad9cb939ba3d5fe1ffae02032d0058ed5d" + ) + # The row a recipe commits holds the fields and the key, not the 2,000-character text. + row = json.dumps({"id": "e1", "split": "test", "fields": fields, "replay_keys": [key]}) + assert len(row) < 300 and state["document"][:20] not in row + # Hand count: "document" 8 + text 2000 + question name "renewal" 7 + its 36-character text. + assert context_size(state, WORKLOAD_QUESTIONS) == {"characters": 2051, "utf8_bytes": 2051} diff --git a/tests/test_vision.py b/tests/test_vision.py index 7da9ae0..d20c834 100644 --- a/tests/test_vision.py +++ b/tests/test_vision.py @@ -4,6 +4,7 @@ import base64 import contextlib +import datetime import hashlib import importlib.util import io @@ -20,7 +21,7 @@ import pytest from PIL import Image -from jev_cookbook import vision +from jev_cookbook import Choice, Noul, Score, live, vision from jev_cookbook._canonical import canonical_image_format from jev_cookbook.fixtures._scan import scan_text @@ -812,6 +813,246 @@ def test_run_record_rejects_unknown_mode(): vision.run_record(SimpleNamespace(), mode="unknown") +# -- capture date and N on a run record; context size; the comparison table -------------------- + +RECORDED = SimpleNamespace( + source="recorded", + model="jev-1.13.0", + usage=SimpleNamespace(input_tokens=50, output_tokens=8), +) +SIX_KEYS = {"mode", "model", "input_tokens", "output_tokens", "latency_seconds", "cost_usd"} + + +@pytest.mark.parametrize("mode", ["recorded", "live"]) +def test_run_record_has_no_capture_date_or_n_keys_unless_they_are_given(mode): + assert set(vision.run_record(RECORDED, mode=mode)) == SIX_KEYS + assert set(vision.run_record(RECORDED, mode=mode, measured_latency_seconds=0.5)) == SIX_KEYS + + +@pytest.mark.parametrize("mode", ["recorded", "live"]) +def test_run_record_adds_capture_date_and_n_when_given(mode): + base = vision.run_record(RECORDED, mode=mode) + both = vision.run_record(RECORDED, mode=mode, capture_date="2026-10-31", n=12) + assert both == {**base, "capture_date": "2026-10-31", "n": 12} + only_date = vision.run_record(RECORDED, mode=mode, capture_date="2026-10-31") + assert only_date == {**base, "capture_date": "2026-10-31"} + assert vision.run_record(RECORDED, mode=mode, n=1) == {**base, "n": 1} + + +@pytest.mark.parametrize("mode", ["synthetic", "scripted"]) +def test_synthetic_and_scripted_rows_accept_n_but_refuse_a_capture_date(mode): + synthetic = SimpleNamespace(source="synthetic") + row = vision.run_record(synthetic, mode=mode, n=3) + assert row == { + "mode": mode, + "model": None, + "input_tokens": None, + "output_tokens": None, + "latency_seconds": None, + "cost_usd": None, + "n": 3, + } + with pytest.raises(ValueError, match="capture_date"): + vision.run_record(synthetic, mode=mode, capture_date="2026-10-31") + + +@pytest.mark.parametrize( + "bad", + [ + "2026-02-30", + "20261031", + "2026-1-5", + "2026-10-31\n", + " 2026-10-31", + "", + "٢٠٢٦-١٠-٣١", + 20261031, + datetime.date(2026, 10, 31), + ], +) +def test_run_record_rejects_a_capture_date_that_is_not_a_real_yyyy_mm_dd_string(bad): + with pytest.raises(ValueError, match="capture_date"): + vision.run_record(RECORDED, mode="recorded", capture_date=bad) + + +@pytest.mark.parametrize("bad", [True, 0, -1, 2.0, "3"]) +def test_run_record_rejects_an_n_that_is_not_a_positive_integer(bad): + with pytest.raises(ValueError, match="n must"): + vision.run_record(RECORDED, mode="recorded", n=bad) + with pytest.raises(ValueError, match="n must"): + vision.run_record(SimpleNamespace(source="synthetic"), mode="synthetic", n=bad) + + +def test_measured_latency_flows_from_the_ledger_into_a_recorded_row(tmp_path): + ledger = tmp_path / "ledger.json" + ledger.write_text( + json.dumps( + { + "key-with-latency": { + "status": "recorded", + "model": "jev-1.13.0", + "date": "2026-10-31", + "latency_seconds": 0.75, + }, + "key-without-latency": { + "status": "recorded", + "model": "jev-1.13.0", + "date": "2026-10-31", + }, + } + ), + encoding="utf-8", + ) + found = live.load_ledger_latency(ledger, "key-with-latency") + row = vision.run_record( + RECORDED, + mode="recorded", + measured_latency_seconds=found.latency_seconds, + capture_date=found.date, + n=1, + ) + assert row["latency_seconds"] == 0.75 and row["capture_date"] == "2026-10-31" + # A call with no captured latency stays unmeasured; nothing is taken from replay timing. + assert live.load_ledger_latency(ledger, "key-without-latency") is None + assert vision.run_record(RECORDED, mode="recorded")["latency_seconds"] is None + + +CONTEXT_CASES = [ + # (state, questions, characters, utf8_bytes), each counted by hand in the comment beside it + ("abc", {"q": Noul(instructions="Is it?")}, 10, 10), # 3 + name 1 + instructions 6 + (["ab", "cd"], {"q": Noul(instructions="Is it?")}, 11, 11), # 2 + 2 + 1 + 6 + ({"k": "vv"}, {"q": Noul(instructions="Is it?")}, 10, 10), # key 1 + value 2 + 1 + 6 + ({"a": {"bb": ["c", "dd"]}}, {"q": Noul(instructions="Is it?")}, 13, 13), # 1+2+1+2 + 7 + ({"n": 1, "b": True, "z": None}, {"q": Noul(instructions="Is it?")}, 10, 10), # keys 3 + 7 + ( + "", + {"c": Choice(criteria={"yes": "y d", "no": None}, instructions="i")}, + 10, + 10, + ), # name 1 + option names 3 + 2 + description 3 + instructions 1 + ("", {"s": Score(criteria=["lo", "high"])}, 7, 7), # name 1 + levels 2 + 4 + ("", {"q": Noul(instructions={"rule": "r1"})}, 7, 7), # name 1 + key 4 + value 2 + ("", {"a": Noul(instructions="xx"), "b": Noul(instructions="xx")}, 6, 6), # shared text twice + ("é€\U0001f600", {}, 3, 9), # 3 characters, 2 + 3 + 4 UTF-8 bytes +] + + +@pytest.mark.parametrize("state, questions, characters, utf8_bytes", CONTEXT_CASES) +def test_context_size_counts_characters_and_utf8_bytes_by_hand( + state, questions, characters, utf8_bytes +): + assert vision.context_size(state, questions) == { + "characters": characters, + "utf8_bytes": utf8_bytes, + } + + +def test_context_size_has_exactly_two_keys_and_none_names_tokens(): + size = vision.context_size({"d": "x" * 100}, {"q": Noul(instructions="Is it?")}) + assert set(size) == {"characters", "utf8_bytes"} + assert not any("token" in key.lower() for key in size) + assert all(type(value) is int for value in size.values()) + + +def test_context_size_of_one_question_plus_the_state_is_the_per_question_count(): + state = "abc" + both = {"a": Noul(instructions="xx"), "b": Noul(instructions="yyyy")} + whole = vision.context_size(state, both)["characters"] + only_a = vision.context_size(state, {"a": both["a"]})["characters"] + only_b = vision.context_size(state, {"b": both["b"]})["characters"] + assert (only_a, only_b, whole) == (3 + 1 + 2, 3 + 1 + 4, 3 + 1 + 2 + 1 + 4) + assert whole == only_a + only_b - vision.context_size(state, {})["characters"] + + +def test_context_size_rejects_a_lone_surrogate_and_a_non_mapping_of_questions(): + with pytest.raises(ValueError, match="UTF-8"): + vision.context_size("\ud800", {"q": Noul(instructions="Is it?")}) + with pytest.raises(TypeError): + vision.context_size("abc", [Noul(instructions="Is it?")]) + + +def _row(result, label, **kwargs): + return {**vision.run_record(result, **kwargs), "label": label} + + +def test_comparison_table_prints_not_measured_wherever_a_value_is_none(): + unreported = SimpleNamespace(source="recorded", model="jev-1.13.0", usage=None) + rows = [ + { + **_row(SimpleNamespace(source="synthetic"), "full", mode="synthetic", n=4), + "characters": 120, + "utf8_bytes": 130, + }, + _row( + RECORDED, + "retrieved", + mode="recorded", + capture_date="2026-10-31", + n=4, + measured_latency_seconds=0.25, + ), + _row(unreported, "no usage", mode="recorded"), + ] + assert vision.comparison_table(rows) == "\n".join( + [ + "label mode model characters utf8_bytes input_tokens " + "output_tokens latency_seconds cost_usd capture_date n", + "--------- --------- ------------ ---------- ---------- ------------ " + "------------- --------------- ------------ ------------ -", + "full synthetic not measured 120 130 not measured " + "not measured not measured not measured - 4", + "retrieved recorded jev-1.13.0 - - 50 " + "8 0.25 not measured 2026-10-31 4", + "no usage recorded jev-1.13.0 - - not measured " + "not measured not measured not measured - -", + ] + ) + + +@pytest.mark.parametrize( + "column", ["model", "input_tokens", "output_tokens", "latency_seconds", "cost_usd"] +) +def test_comparison_table_reads_not_measured_for_a_none_in_each_measured_column(column): + table = vision.comparison_table([{"mode": "recorded", column: None}]) + assert table.splitlines()[-1].split(" ")[-1].strip() == "not measured" + assert vision.comparison_table([{"mode": "recorded", column: 5}]).splitlines()[-1].endswith("5") + + +def test_comparison_table_shows_a_missing_key_as_a_dash_and_accepts_any_iterable(): + assert vision.comparison_table([{"mode": "synthetic"}]) == "mode\n---------\nsynthetic" + assert vision.comparison_table(iter([{"mode": "recorded", "n": 2}, {"mode": "live"}])) == ( + "mode n\n-------- -\nrecorded 2\nlive -" + ) + + +def test_comparison_table_does_not_change_its_rows(): + rows = [{"mode": "recorded", "input_tokens": None}] + vision.comparison_table(rows) + assert rows == [{"mode": "recorded", "input_tokens": None}] + + +@pytest.mark.parametrize( + "rows", + [ + [], + [{"input_token": 1}], + [{"mode": "synthetic", "model": "jev-1.13.0"}], + [{"mode": "synthetic", "input_tokens": 5}], + [{"mode": "scripted", "output_tokens": 0}], + [{"mode": "scripted", "latency_seconds": 0.0}], + [{"mode": "synthetic", "cost_usd": 0.0}], + ], +) +def test_comparison_table_refuses_unknown_columns_and_measurements_on_fixture_rows(rows): + with pytest.raises(ValueError): + vision.comparison_table(rows) + + +def test_comparison_table_needs_mapping_rows(): + with pytest.raises(TypeError): + vision.comparison_table([5]) + + TINY = {"top": 0.0, "bottom": 1e-200, "left": 0.0, "right": 1e-200}