observability.md: how spans nest (a Trace per owner, the workbook's trace, Parent handles, entered long-lived spans), the ids in the JSON log and OTLP, the ClickHouse and DuckDB queries that show the tree, and the on-path costs. extending.md pattern 10: how to add a nested span.
- commit
- 1997ea4feb13a9a443d97d2c316c99e9fae2e8ce
- parent
- de03a0c642cf9a778613fb2715dce7d7690f3ae7
- author
- Dami <dami.etoile@gmail.com>
| M | docs/ | 6 | +- |
| M | docs/ | 8 | ++ |
| M | docs/ | 111 | ++++++++++++++++++++++++++++-- |
@@ -480,7 +480,11 @@ both (see [observability.md](observability.md)). The OTLP exporter uses
480480 only the standard library: bounded queues per signal, drained by one481481 goroutine in batches; when a queue is full new items are dropped and482482 counted, so the UI never waits on the network. Operation durations are483-histograms keyed by span name, which are fixed in the code.483+histograms keyed by span name, which are fixed in the code. Spans nest484+through a `telemetry.Trace` per owner (each Model, each import) and485+explicit `Parent` handles across goroutines; a workbook holds its486+owner's trace, opaque to the engine, so recalculations nest in the487+command that caused them.484488 485489 ## Testing486490 @@ -171,6 +171,14 @@ Every seam above has a telemetry span and a `-tags stress` benchmark
171171 (`make stress`, `make stress-report`), and [limits.md](limits.md) records172172 the bounds. A change to a seam reports before and after numbers.173173 174+Spans nest without a `context.Context` through the engine: start a UI175+span through the model's trace (`m.spans.Start`), so it holds what it176+causes; hand work on another goroutine `m.spans.Parent()` (in the177+`context.Context` if the API already takes one); and give a workbook a178+new owner's trace with `SetTrace`. Never keep a "current span" in a179+global: `012 serve` runs many programs in one process (see180+[observability.md](observability.md#nested-spans)).181+174182 ### 11. Shape limits175183 176184 `make lint`: no function over cognitive complexity 25, no Go file over 500@@ -37,8 +37,10 @@ load (15 ns, no allocation; `go test -bench . ./internal/telemetry`,
3737 and `TestOffAllocatesNothing` guards the zero), and a keystroke3838 through to its frame costs the same with telemetry on or off (1.06 ms on3939 a 200x60 screen of an 8192x26 sheet, `BenchmarkTelemetry` under40-`-tags stress`). With it on, each event costs about 0.5 us written to41-the file, and about 0.6 us queued for OTLP (`BenchmarkSpanOTLP`).40+`-tags stress`). With it on, each span costs about 0.66 us written to41+the file (`BenchmarkSpanOn`; 0.7 us nested under an open span,42+`BenchmarkTraceOn`), and about 0.67 us queued for OTLP43+(`BenchmarkSpanOTLP`).4244 4345 Events carry sizes, counts and durations, never cell contents, file4446 contents or secrets. The JEV API key is never logged; neither are file@@ -48,12 +50,15 @@ names, OTLP endpoints or OTLP headers.
4850 4951 Every event has `time`, `level`, `msg` (the event name), `event` (the5052 same, as an attribute for queries), `service` (`012`) and `dur_ms`.53+Spans (every event below but `start`, `otlp`, `frames` and `frame`) also54+have `trace_id`, `span_id` and, below a root, `parent_id`, the same ids55+OTLP sends (see [Nested spans](#nested-spans)).5156 5257 | Event | When | Attributes |5358 |---|---|---|5459 | `start` | the log opens | `version` (VCS revision), `go`, `os`, `arch`, `cpus`, `pid`, `file` and `otlp` (which outputs are on) |5560 | `otlp` | on exit, with OTLP on | per signal (`logs`, `traces`, `metrics`): `sent`, `dropped` (queue full), `failed` (request failed) so far |56-| `recalc` | every recalculation | `full` (after loading), `evaluated` (dirty cells recomputed), `cells` (stored), `volatile`, `circular` |61+| `recalc` | every recalculation, including the pivot refreshes it causes (nested in it) | `full` (after loading), `evaluated` (dirty cells recomputed), `cells` (stored), `volatile`, `circular` |5762 | `frames` | once a second while frames are drawn | `frames`, `render_p50_ms`, `render_p95_ms`, `render_max_ms` (View), `keys`, `key_p50_ms`, `key_p95_ms`, `key_max_ms` (key press to the end of its frame), `heap_bytes`, and gauges: `cells`, `jev_in_flight`, `jev_queued` |5863 | `frame` | every frame, at debug level | `key_ms` |5964 | `command` | every registered command | `id`, e.g. `data.sort` |@@ -65,15 +70,100 @@ same, as an attribute for queries), `service` (`012`) and `dur_ms`.
6570 | `save`, `open` | the native `.012` file | `cells`, `bytes` (save times serializing, on the UI goroutine) |6671 | `jev` | each question sent | `kind`, `queued` (waiting when sent), `outcome` (`ok` or `failed`) |6772 | `chart.image` | each kitty-graphics chart image | `type`, `w`, `h`, `bytes` |73+| `serve.session` | each `012 serve` SSH session, from start to end | `term`, `idle` |6874 6975 Failures are logged at `WARN` with an `error` message.7076 71-The engine doesn't log: `sheet.OnRecalc` hands each recalculation's72-counts to `cmd/012`, which logs them, and `sheet.OnPivot` each pivot73-table's. The call sites use77+The engine doesn't log: `sheet.OnBegin` says a recalculation or pivot78+refresh starts, and `sheet.OnRecalc` and `sheet.OnPivot` hand its counts79+to `cmd/012` as it ends, which logs them. The call sites use7480 `internal/telemetry` (`Start`/`End` spans, `Event`, `Frame`, `Set`), so7581 the backends (the JSON file, OTLP) sit behind it without touching them.7682 83+## Nested spans84+85+Spans nest, so a trace shows what an action caused:86+87+```88+command format.bold89+ recalc90+ pivot91+ recalc (what reads the pivot's results)92+import93+ recalc94+macro95+ command set / recalc ...96+serve.session97+ command ...98+```99+100+A child shares its parent's trace id and names it as its parent span.101+No `context.Context` goes through the engine for it; instead102+(`internal/telemetry/trace.go`):103+104+- **A `Trace` per owner.** Each UI `Model` keeps a `telemetry.Trace`,105+ the stack of spans it has open, used only on its program's goroutine.106+ `m.spans.Start("command", ...)` opens a span under the innermost one;107+ its `End` closes it (and anything left open inside it). There is no108+ goroutine-global current span: `012 serve` runs many programs in one109+ process, and background `tea.Cmd`s run on other goroutines.110+- **The workbook carries its owner's trace.** `Workbook.SetTrace` hands111+ it the trace, opaque to the engine (the UI sets its own; an import's112+ builder and `sheet.ReadTraced` set one under the import's or open's113+ span). The engine's hooks get it back: `OnBegin` begins a span in it,114+ `OnRecalc`/`OnPivot` end it, so recalculations and pivot refreshes115+ nest in whatever command, import or macro changed the sheet. A116+ workbook with no trace logs them as roots.117+- **Explicit `Parent` handles across goroutines.** `m.spans.Parent()`118+ (or `span.Parent()`) is a small value any goroutine can start under:119+ JEV questions, opening a file, and imports and exports, which take it120+ in the `context.Context` they already have (`telemetry.WithParent`,121+ `ParentFrom`).122+- **Long-lived spans are entered.** A macro run's span starts under the123+ command that ran it and is entered (`Trace.Enter`/`Leave`) while the124+ UI serves the script's calls, so its commands and recalculations nest125+ in it. `012 serve` enters each session's `serve.session` span at the126+ bottom of that session's Model's trace for good, so every command of a127+ session is in its trace, and sessions never share one.128+129+Off, every one of these calls is still one atomic load and no130+allocation (`TestOffAllocatesNothing`, `TestTraceOff`,131+`BenchmarkTraceOff` 16 ns).132+133+In ClickHouse, a join on `ParentSpanId` shows the tree:134+135+```sql136+SELECT p.SpanName AS parent, if(p.SpanName = 'command', p.SpanAttributes['id'], '') AS id,137+ c.SpanName AS child, count() AS n138+FROM otel.otel_traces AS c139+JOIN otel.otel_traces AS p ON c.ParentSpanId = p.SpanId AND c.TraceId = p.TraceId140+WHERE c.ServiceName = '012'141+GROUP BY parent, id, child ORDER BY parent, child;142+```143+144+From a scripted session (import a CSV, paste a table, make a pivot of145+it, clear a source cell, bold it):146+147+```148+┌─parent──┬─id──────────┬─child──┬─n─┐149+│ command │ data.pivot │ recalc │ 2 │150+│ command │ format.bold │ recalc │ 1 │151+│ command │ clear │ recalc │ 1 │152+│ import │ │ recalc │ 4 │153+│ recalc │ │ pivot │ 6 │154+│ recalc │ │ recalc │ 3 │155+└─────────┴─────────────┴────────┴───┘156+```157+158+and one trace, `command clear` > `recalc` > (`pivot`, `recalc`). With159+the JSON log, the same tree comes from `span_id` and `parent_id`:160+161+```sql162+SELECT p.msg AS parent, p.id, c.msg AS child, count(*) AS n163+FROM read_json_auto('events.jsonl') c JOIN read_json_auto('events.jsonl') p164+ ON c.parent_id = p.span_id GROUP BY ALL ORDER BY n DESC;165+```166+77167 ## OTLP78168 79169 012 speaks OTLP/HTTP with the JSON encoding itself, with the Go@@ -81,8 +171,8 @@ standard library only (no OpenTelemetry SDK, no new dependency):
81171 82172 | Signal | What | Shape |83173 |---|---|---|84-| Logs (`/v1/logs`) | every event above | body = event name, severity from the level (INFO 9, WARN 13, DEBUG 5), the event's attributes (`event`, `dur_ms`, counts) as typed values. The log record of a span carries its `traceId` and `spanId` |85-| Traces (`/v1/traces`) | every `Start`/`End` span and `Event` (recalc, import, sort, jev, command, ...) | one root span per operation, in a trace of its own: call sites pass no context, so spans don't nest. Kind INTERNAL; status ERROR with the message on `Fail`. Frames aren't spans |174+| Logs (`/v1/logs`) | every event above | body = event name, severity from the level (INFO 9, WARN 13, DEBUG 5), the event's attributes (`event`, `dur_ms`, counts, `parent_id`) as typed values. The log record of a span carries its `traceId` and `spanId` |175+| Traces (`/v1/traces`) | every `Start`/`End` span and `Event` (recalc, import, sort, jev, command, ...) | nested (see [Nested spans](#nested-spans)): a child carries `parentSpanId` and its parent's `traceId`; a root has no `parentSpanId`. Kind INTERNAL; status ERROR with the message on `Fail`. Frames aren't spans |86176 | Metrics (`/v1/metrics`) | the frame summary and running totals | `o12.frame.duration` and `o12.key.latency` (ms): summaries per second with count, sum and the 0.5, 0.95 and 1 quantiles. `o12.heap` (bytes) and the gauges `o12.cells`, `o12.jev_in_flight`, `o12.jev_queued`. Cumulative: `o12.frames` (sum), `o12.operation.duration` (ms histogram per `event`, buckets 0.5 ms to 30 s), `o12.telemetry.dropped` (per `signal`) |87177 88178 Every request carries the resource `service.name=012`,@@ -264,7 +354,10 @@ WHERE ServiceName = '012' AND MetricName = 'o12.key.latency' ORDER BY TimeUnix;
264354 265355 From `make stress-e2e` sent over OTLP, `otel_traces` held 221 `recalc`266356 spans (p95 51 ms), 1 `import` (94 ms, 8192 rows) and 3 `command`, and267-the metrics tables a summary, heap and cells gauge per second.357+the metrics tables a summary, heap and cells gauge per second. The358+import's trace holds two full recalculations under it (33 ms each of359+127 ms): the builder's, and the one renaming the sheet after the file360+causes.268361 269362 The `012 runtime` dashboard shows recalculation time (p50, p95, max),270363 frame and key-to-frame p95 per second, heap and cells, JEV answer time