1---2title: "Observability"3sidebar_position: 74---56# Observability78How to see what 012 spends its time on, in a session or across stress9runs. There are two paths that share one set of numbers:1011- **Zero setup**: 012 writes JSON event logs, `make stress` writes JSONL12 run records, and DuckDB queries both files directly.13- **Stack**: `make obs-up` starts an OpenTelemetry Collector, ClickHouse14 and Grafana in Docker; 012 sends its logs, traces and metrics over15 OTLP (or the collector tails its log file), the stress runs load into16 ClickHouse, and dashboards sit on top.1718The measured bounds these tools track are in [Bounds of support](limits.md).1920## Turning it on2122Telemetry is off unless a log file or an OTLP endpoint is given:2324```sh25012 --log events.jsonl budget.012 # or --log=events.jsonl26O12_LOG=events.jsonl 012 budget.012 # the same through the environment27O12_LOG_LEVEL=debug # also one event per frame2829012 --otlp http://localhost:4318 budget.012 # OTLP/HTTP30OTEL_EXPORTER_OTLP_ENDPOINT=http://localhost:4318 012 budget.012 # the same31```3233Or keep them in the [config file](../reference/config.md) as `log-file`, `log-level`34and `otlp-endpoint`; flags win over the environment, which wins over the35file.3637The two can be on together or separately. Stdout belongs to the38terminal UI, so events go to the file, appended one JSON object per39line, and/or to the OTLP endpoint (see [OTLP](#otlp) below). With40neither, nothing is timed: each instrumented call site costs one atomic41load (15 ns, no allocation; `go test -bench . ./internal/telemetry`,42and `TestOffAllocatesNothing` guards the zero), and a keystroke43through to its frame costs the same with telemetry on or off (1.06 ms on44a 200x60 screen of an 8192x26 sheet, `BenchmarkTelemetry` under45`-tags stress`). With it on, each span costs about 0.66 us written to46the file (`BenchmarkSpanOn`; 0.7 us nested under an open span,47`BenchmarkTraceOn`), and about 0.67 us queued for OTLP48(`BenchmarkSpanOTLP`).4950Events carry sizes, counts and durations, never cell contents, file51contents or secrets. The JEV API key is never logged; neither are file52names, OTLP endpoints or OTLP headers.5354## What is recorded5556Every event has `time`, `level`, `msg` (the event name), `event` (the57same, as an attribute for queries), `service` (`012`) and `dur_ms`.58Spans (every event below but `start`, `otlp`, `frames` and `frame`) also59have `trace_id`, `span_id` and, below a root, `parent_id`, the same ids60OTLP sends (see [Nested spans](#nested-spans)).6162| Event | When | Attributes |63|---|---|---|64| `start` | the log opens | `version` (VCS revision), `go`, `os`, `arch`, `cpus`, `pid`, `file` and `otlp` (which outputs are on) |65| `otlp` | on exit, with OTLP on | per signal (`logs`, `traces`, `metrics`): `sent`, `dropped` (queue full), `failed` (request failed) so far |66| `recalc` | every recalculation, including the pivot refreshes it causes (nested in it) | `full` (after loading), `evaluated` (dirty cells recomputed), `cells` (stored), `volatile`, `circular` |67| `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` |68| `frame` | every frame, at debug level | `key_ms` |69| `command` | every registered command | `id`, e.g. `data.sort` |70| `macro` | each macro run, from start to end | `steps` (Starlark steps), `calls` (calls to the spreadsheet), `outcome` (`ok`, `error`, `cancelled` or `limit`) |71| `sort`, `filter`, `find`, `replace`, `fill` | the operation itself | `rows`, `cols`, `keys`; `hidden`; `matches`; `replaced`; `cells` |72| `pivot` | every pivot table recomputation (a change to its data or definition) | `records` (source rows summarized), `groups` (row groups at every depth), `cells` (results), `failed` (shows `#REF!`) |73| `frequency` | making a frequency table | `rows` (data rows counted) |74| `live` | each update of a [linked file](../files/following.md)'s rows applied, including the recalculation it causes (nested in it) | `rows` (rows it brought), `cells` (cells that changed), `reset` (the file read again whole) |75| `import`, `export` | file transfers (`internal/fileio`) | `format`, `bytes`, `rows`, `cells`, `notes` |76| `save`, `open` | the native `.012` file | `cells`, `bytes` (save times serializing, on the UI goroutine) |77| `jev` | each question sent | `kind`, `queued` (waiting when sent), `outcome` (`ok` or `failed`) |78| `chart.image` | each kitty-graphics chart image | `type`, `w`, `h`, `bytes` |79| `serve.session` | each `012 serve` SSH session, from start to end | `term`, `idle` |8081Failures are logged at `WARN` with an `error` message.8283The engine doesn't log: `sheet.OnBegin` says a recalculation or pivot84refresh starts, and `sheet.OnRecalc` and `sheet.OnPivot` hand its counts85to `cmd/012` as it ends, which logs them. The call sites use86`internal/telemetry` (`Start`/`End` spans, `Event`, `Frame`, `Set`), so87the backends (the JSON file, OTLP) sit behind it without touching them.8889## Nested spans9091Spans nest, so a trace shows what an action caused:9293```94command format.bold95 recalc96 pivot97 recalc (what reads the pivot's results)98import99 recalc100macro101 command set / recalc ...102serve.session103 command ...104```105106A child shares its parent's trace id and names it as its parent span.107No `context.Context` goes through the engine for it; instead108(`internal/telemetry/trace.go`):109110- **A `Trace` per owner.** Each UI `Model` keeps a `telemetry.Trace`,111 the stack of spans it has open, used only on its program's goroutine.112 `m.spans.Start("command", ...)` opens a span under the innermost one;113 its `End` closes it (and anything left open inside it). There is no114 goroutine-global current span: `012 serve` runs many programs in one115 process, and background `tea.Cmd`s run on other goroutines.116- **The workbook carries its owner's trace.** `Workbook.SetTrace` hands117 it the trace, opaque to the engine (the UI sets its own; an import's118 builder and `sheet.ReadTraced` set one under the import's or open's119 span). The engine's hooks get it back: `OnBegin` begins a span in it,120 `OnRecalc`/`OnPivot` end it, so recalculations and pivot refreshes121 nest in whatever command, import or macro changed the sheet. A122 workbook with no trace logs them as roots.123- **Explicit `Parent` handles across goroutines.** `m.spans.Parent()`124 (or `span.Parent()`) is a small value any goroutine can start under:125 JEV questions, opening a file, and imports and exports, which take it126 in the `context.Context` they already have (`telemetry.WithParent`,127 `ParentFrom`).128- **Long-lived spans are entered.** A macro run's span starts under the129 command that ran it and is entered (`Trace.Enter`/`Leave`) while the130 UI serves the script's calls, so its commands and recalculations nest131 in it. `012 serve` enters each session's `serve.session` span at the132 bottom of that session's Model's trace for good, so every command of a133 session is in its trace, and sessions never share one.134135Off, every one of these calls is still one atomic load and no136allocation (`TestOffAllocatesNothing`, `TestTraceOff`,137`BenchmarkTraceOff` 16 ns).138139In ClickHouse, a join on `ParentSpanId` shows the tree:140141```sql142SELECT p.SpanName AS parent, if(p.SpanName = 'command', p.SpanAttributes['id'], '') AS id,143 c.SpanName AS child, count() AS n144FROM otel.otel_traces AS c145JOIN otel.otel_traces AS p ON c.ParentSpanId = p.SpanId AND c.TraceId = p.TraceId146WHERE c.ServiceName = '012'147GROUP BY parent, id, child ORDER BY parent, child;148```149150From a scripted session (import a CSV, paste a table, make a pivot of151it, clear a source cell, bold it):152153```154┌─parent──┬─id──────────┬─child──┬─n─┐155│ command │ data.pivot │ recalc │ 2 │156│ command │ format.bold │ recalc │ 1 │157│ command │ clear │ recalc │ 1 │158│ import │ │ recalc │ 4 │159│ recalc │ │ pivot │ 6 │160│ recalc │ │ recalc │ 3 │161└─────────┴─────────────┴────────┴───┘162```163164and one trace, `command clear` > `recalc` > (`pivot`, `recalc`). With165the JSON log, the same tree comes from `span_id` and `parent_id`:166167```sql168SELECT p.msg AS parent, p.id, c.msg AS child, count(*) AS n169FROM read_json_auto('events.jsonl') c JOIN read_json_auto('events.jsonl') p170 ON c.parent_id = p.span_id GROUP BY ALL ORDER BY n DESC;171```172173## OTLP174175012 speaks OTLP/HTTP with the JSON encoding itself, with the Go176standard library only (no OpenTelemetry SDK, no new dependency):177178| Signal | What | Shape |179|---|---|---|180| 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` |181| 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 |182| 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`) |183184Every request carries the resource `service.name=012`,185`service.version` (VCS revision), `service.instance.id` (random per186run), `os.type`, `host.arch`, `process.runtime.name` and187`process.runtime.version`, plus any from `OTEL_RESOURCE_ATTRIBUTES`.188189Configuration is the standard environment; nothing is sent unless an190endpoint is set:191192| Variable | Effect |193|---|---|194| `OTEL_EXPORTER_OTLP_ENDPOINT` | base URL; `/v1/logs`, `/v1/traces`, `/v1/metrics` are appended. `012 --otlp URL` sets it too (and wins). A URL without a scheme gets `http://` |195| `OTEL_EXPORTER_OTLP_LOGS_ENDPOINT`, `_TRACES_ENDPOINT`, `_METRICS_ENDPOINT` | full URL for one signal, used as is; a signal with no endpoint (its own or the base) is not sent |196| `OTEL_LOGS_EXPORTER`, `OTEL_TRACES_EXPORTER`, `OTEL_METRICS_EXPORTER` | `none` leaves that signal out |197| `OTEL_EXPORTER_OTLP_HEADERS` | `key=value,...` (values percent-decoded) sent with every request, e.g. `Authorization=Bearer%20...` |198| `OTEL_EXPORTER_OTLP_TIMEOUT` | per request, in milliseconds; 3000 by default (shorter than the spec's 10 s, so quitting never waits long) |199| `OTEL_EXPORTER_OTLP_COMPRESSION` | `none` for plain JSON; gzip otherwise |200| `OTEL_RESOURCE_ATTRIBUTES` | extra resource attributes (`service.name` stays `012`) |201| `OTEL_SDK_DISABLED` | `true` turns OTLP off whatever else is set |202203`OTEL_EXPORTER_OTLP_PROTOCOL` is ignored: 012 only sends `http/json`,204which the collector's HTTP receiver (4318) accepts; the gRPC port (4317)205won't work.206207The UI never waits on the network. Events go into bounded in-memory208queues (2048 items per signal); a background goroutine sends them every2092 seconds, or sooner once 512 are waiting, gzipped, with no retries. A210full queue drops new items and a failed request drops its batch; both211are counted in `o12.telemetry.dropped` and the `otlp` event on exit.212On exit, what is queued is sent within a second at most, and not at all213once a request has failed this session.214215012 honors the standard `OTEL_*` variables it inherits, like any216OpenTelemetry program, unless its own config or flags override them. So217if your desktop session sets `OTEL_EXPORTER_OTLP_ENDPOINT` for every app,218012 exports there too; when that collector is gone (a laptop whose tailnet219collector isn't up), sends fail in the background, are counted, and cost220nothing at exit. Set `otlp-endpoint` in the config, or `OTEL_SDK_DISABLED=true`,221to change that for 012 alone.222223`internal/telemetry/otlp_test.go` checks the payloads against the224spec's JSON mapping with a fake collector (hex ids, 64-bit integers as225strings, enums as numbers, resource attributes, gzip), plus the drops226on overflow, the flush on close, the bounded close with a stuck227collector, and that nothing is sent while off.228229## Querying logs with DuckDB230231Nothing to install beyond the `duckdb` CLI:232233```sql234-- Time per event type235SELECT msg AS event, count(*) AS n,236 round(quantile_cont(dur_ms, 0.5), 2) AS p50_ms,237 round(quantile_cont(dur_ms, 0.95), 2) AS p95_ms,238 round(max(dur_ms), 2) AS max_ms239FROM read_json_auto('events.jsonl') WHERE msg <> 'frames'240GROUP BY ALL ORDER BY n DESC;241```242243From `make stress-e2e` (an 8192x26 import, 200 SUMs over a column, then244arrows and entries):245246```247┌─────────┬───────┬────────┬────────┬────────┐248│ event │ n │ p50_ms │ p95_ms │ max_ms │249├─────────┼───────┼────────┼────────┼────────┤250│ recalc │ 442 │ 1.0 │ 49.77 │ 56.94 │251│ command │ 6 │ 0.0 │ 0.0 │ 0.0 │252│ import │ 2 │ 96.4 │ 97.55 │ 97.68 │253│ start │ 2 │ │ │ │254└─────────┴───────┴────────┴────────┴────────┘255```256257```sql258-- The seconds with the slowest key presses, with memory and size259SELECT time, frames, render_p95_ms, key_p95_ms, key_max_ms,260 round(heap_bytes / 1048576) AS heap_mb, cells261FROM read_json_auto('events.jsonl') WHERE msg = 'frames'262ORDER BY key_max_ms DESC LIMIT 5;263264-- Slowest recalculations and how much they touched265SELECT time, dur_ms, evaluated, cells, full266FROM read_json_auto('events.jsonl') WHERE msg = 'recalc'267ORDER BY dur_ms DESC LIMIT 10;268269-- JEV latency percentiles and failures270SELECT count(*) AS asked, count(*) FILTER (WHERE outcome = 'failed') AS failed,271 quantile_cont(dur_ms, [0.5, 0.95, 0.99]) AS p50_p95_p99_ms272FROM read_json_auto('events.jsonl') WHERE msg = 'jev';273```274275## Stress runs276277`make stress` appends one JSON line per benchmark to278`.deps/stress/results/runs.jsonl` (gitignored): `run_id`, `ts`,279`git_sha`, `git_dirty`, `go_version`, `goos`, `goarch`, `cpu`, `host`,280`pkg`, `name`, `procs`, `n`, `ns_op`, `b_op`, `allocs_op`, `mb_s`, and281`metrics`, a map of custom units such as `B/cell`, `cells/s`,282`MB-file` or `us/answer`. `COUNT=n` runs each benchmark n times, one283record per sample. `make stress-report` loads them with284`scripts/stress/load.sql` (a benchmark's time in a run is the median of285its samples) and runs `scripts/stress/report.sql`: the latest run286against the previous one on the same CPU and against a baseline287(`BASELINE=run_id`, default the oldest run that covered most of the288same benchmarks), flagging changes past `THRESHOLD` (0.10) and289`MIN_DELTA_NS` (2000), and the headline benchmarks over the last eight290runs. With the default 500 ms per benchmark, runs on a busy machine (say291with the Docker stack ingesting) differ by 10 to 30% on benchmarks of a292few tens of milliseconds; use `BENCHTIME=2s` on a quiet machine before293trusting a single regression. `FAIL_ON_REGRESSION=1` also makes it exit2941 on a regression against the previous run. The same records load into295ClickHouse (`stress.results`) with the same columns; there, samples of296one benchmark in one run collapse into one row.297298### Regressions against the last release299300`make stress-report` then compares the latest run with the last301release's (`scripts/stress/release.sql`) and exits 1 when anything302regressed, so a release checklist ([Releasing](releasing.md)) can stop303on it:304305- **The release** is the newest `v*` tag reachable from HEAD whose306 commit has a clean recorded run on the latest run's CPU and OS (other307 than the latest run, and not on the latest run's commit). All such308 runs of that commit are pooled. `RELEASE=v1.2.3` picks the tag,309 `RELEASE_RUN=run_id` one run instead. With none recorded, the report310 says so and exits 0: record one with `make stress` on the tagged311 commit.312- **Noise** is each benchmark's spread, `(max - min) / median` of its313 samples, the larger of the release's and the latest run's. It is 0314 for a benchmark with one sample on each side, so `COUNT=3` or more on315 both runs gives the threshold room where a benchmark is noisy.316- **A regression** is a median slower than the release's by more than317 `THRESHOLD` plus the noise (10% plus, by default) and by more than318 `MIN_DELTA_NS`. Faster past the same bar is listed as `faster`.319320```sh321COUNT=3 BENCHTIME=2s make stress # on the tagged commit, then on the change322make stress-report # exit 1 on a regression against the tag323THRESHOLD=0.2 RELEASE=v0.2.0 make stress-report324```325326## The stack327328```sh329make obs-up # start, and print the environment for 012330make obs-status # containers, ClickHouse row counts, events of the last hour331make stress-load # load recorded stress runs into ClickHouse332make obs-down # stop; data stays in the named volumes333```334335`deploy/observability/docker-compose.yml`, all ports on 127.0.0.1:336337| Service | Image | Role |338|---|---|---|339| `otel-collector` | `otel/opentelemetry-collector-contrib:0.161.0` | OTLP gRPC (4317) and HTTP (4318, what 012 --otlp sends to) receivers; `file_log` receiver tailing `.deps/obs/logs/*.jsonl` (checkpointed, so restarts don't re-read); `memory_limiter` and `batch`; `clickhouse` exporter for logs, traces and metrics |340| `clickhouse` | `clickhouse/clickhouse-server:26.3.34.136` | OLAP store: `otel.otel_logs`, `otel.otel_traces` and `otel.otel_metrics_*` (created by the exporter), `stress.results`, `stress.latest_vs_previous`. 3 GB container limit, 75% of it for queries. User `o12`, password `o12` |341| `grafana` | `grafana/grafana:13.2.2` with `grafana-clickhouse-datasource` 4.21.3 | http://localhost:3000, anonymous viewing; dashboards `012 runtime` and `012 stress runs` |342343To send a session to it, point 012 at the collector's OTLP/HTTP344receiver (127.0.0.1:4318), which feeds logs, traces and metrics into345ClickHouse:346347```sh348make obs-up349./bin/012 --otlp http://localhost:4318 big.csv350# or, for the e2e stress check:351OTEL_EXPORTER_OTLP_ENDPOINT=http://localhost:4318 make stress-e2e352make obs-status353```354355Logs land in `otel.otel_logs` (`ServiceName` `012`, the event's356attributes as strings in `LogAttributes`, `TraceId`/`SpanId` on span357events), spans in `otel.otel_traces`, and metrics in358`otel.otel_metrics_summary`, `_gauge`, `_sum` and `_histogram`.359360The alternative, logs only, is to log into the directory the collector361tails (use one or the other, or the logs arrive twice):362363```sh364O12_LOG=$PWD/.deps/obs/logs/012.jsonl ./bin/012 big.csv365```366367The collector parses each line: `time` becomes the timestamp, `level`368the severity, `msg` the body, `service` the `service.name` resource369attribute, and everything else a log attribute (as strings in370ClickHouse's `LogAttributes` map). For example:371372```sql373-- ClickHouse: recalc and import percentiles for 012374SELECT LogAttributes['event'] AS event, count() AS n,375 round(quantile(0.5)(toFloat64OrZero(LogAttributes['dur_ms'])), 2) AS p50_ms,376 round(quantile(0.95)(toFloat64OrZero(LogAttributes['dur_ms'])), 2) AS p95_ms377FROM otel.otel_logs378WHERE ServiceName = '012' AND event NOT IN ('frames', 'start')379GROUP BY event ORDER BY n DESC;380381-- Stress trend of one benchmark382SELECT ts, git_sha, round(ns_op / 1e6, 2) AS ms383FROM stress.results FINAL WHERE name = 'Edit/fanin-1000xSUM8192' ORDER BY ts;384385-- What regressed since the previous run386SELECT * FROM stress.latest_vs_previous WHERE change > 0.1 ORDER BY change DESC;387388-- OTLP spans: time per operation389SELECT SpanName, count() AS n, round(quantile(0.95)(Duration) / 1e6, 2) AS p95_ms,390 countIf(StatusCode = 'Error') AS failed391FROM otel.otel_traces WHERE ServiceName = '012' GROUP BY SpanName ORDER BY n DESC;392393-- OTLP metrics: key-to-frame p95 per second394SELECT TimeUnix, Count AS keys,395 ValueAtQuantiles.Value[indexOf(ValueAtQuantiles.Quantile, 0.95)] AS p95_ms396FROM otel.otel_metrics_summary397WHERE ServiceName = '012' AND MetricName = 'o12.key.latency' ORDER BY TimeUnix;398```399400From `make stress-e2e` sent over OTLP, `otel_traces` held 221 `recalc`401spans (p95 51 ms), 1 `import` (94 ms, 8192 rows) and 3 `command`, and402the metrics tables a summary, heap and cells gauge per second. The403import's trace holds two full recalculations under it (33 ms each of404127 ms): the builder's, and the one renaming the sheet after the file405causes.406407The `012 runtime` dashboard shows recalculation time (p50, p95, max),408frame and key-to-frame p95 per second, heap and cells, JEV answer time409and queue, imports and exports with throughput, the slowest operations,410and events per minute (all from the logs, so either way in works), and411from OTLP the key-to-frame latency summary, the slowest spans, the412recent traces with nested spans (root span, command id, span count and413which spans nest in it), and a trace view: the spans of one trace as a414tree on a timeline, in Grafana's trace panel (the ClickHouse plugin's415trace format). A trace id in either table links to it, through the416dashboard's Trace id box; with the box empty the view shows the latest417trace with nested spans. `012 stress runs` shows edit latency per418topology, frame and keystroke times, full recalc and file operations,419memory per cell (log scales where the spread is wide), the latest run420against the previous one, and the runs.421422The stack starts from scratch with `make obs-up` after423`docker compose -f deploy/observability/docker-compose.yml down -v`.424`stress.results` is created on first start by425`clickhouse/init.sql`, and again (idempotently) by every426`make stress-load`.