- commit
- 3d3b7b7076af1d7d906447c6a0c95de4c88bce70
- parent
- 5b5b276cd44ce87e03fd08a7904dc9d8be519b6e
- author
- Dami <dami.etoile@gmail.com>
| M | docs/ | 2 | +- |
| M | docs/ | 133 | ++++++++++++++++++++++++------ |
@@ -16,5 +16,5 @@
1616 - [UX and visual bar](UX.md): the rules every change follows1717 - [Testing](testing.md): unit, end-to-end through libghostty, golden screens, the excelize oracle1818 - [Limits](limits.md): measured bounds of support and known bottlenecks19-- [Observability](observability.md): event logs, DuckDB queries, the local telemetry stack19+- [Observability](observability.md): event logs, OTLP export, DuckDB queries, the local telemetry stack2020 - [Roadmap](../ROADMAP.md)@@ -6,32 +6,39 @@ runs. There are two paths that share one set of numbers:
66 - **Zero setup**: 012 writes JSON event logs, `make stress` writes JSONL77 run records, and DuckDB queries both files directly.88 - **Stack**: `make obs-up` starts an OpenTelemetry Collector, ClickHouse9- and Grafana in Docker; the collector tails 012's logs and the stress10- runs load into ClickHouse, with dashboards on top.9+ and Grafana in Docker; 012 sends its logs, traces and metrics over10+ OTLP (or the collector tails its log file), the stress runs load into11+ ClickHouse, and dashboards sit on top.1112 1213 The measured bounds these tools track are in [limits.md](limits.md).1314 1415 ## Turning it on1516 16-Telemetry is off unless a log file is given:17+Telemetry is off unless a log file or an OTLP endpoint is given:1718 1819 ```sh1920 012 --log events.jsonl budget.012 # or --log=events.jsonl2021 O12_LOG=events.jsonl 012 budget.012 # the same through the environment2122 O12_LOG_LEVEL=debug # also one event per frame23+24+012 --otlp http://localhost:4318 budget.012 # OTLP/HTTP25+OTEL_EXPORTER_OTLP_ENDPOINT=http://localhost:4318 012 budget.012 # the same2226 ```2327 24-Stdout belongs to the terminal UI, so events only ever go to the file,25-appended one JSON object per line. With no log file nothing is timed:26-each instrumented call site costs one atomic load (15 ns, no27-allocation; `go test -bench . ./internal/telemetry`), and a keystroke28+The two can be on together or separately. Stdout belongs to the29+terminal UI, so events go to the file, appended one JSON object per30+line, and/or to the OTLP endpoint (see [OTLP](#otlp) below). With31+neither, nothing is timed: each instrumented call site costs one atomic32+load (15 ns, no allocation; `go test -bench . ./internal/telemetry`,33+and `TestOffAllocatesNothing` guards the zero), and a keystroke2834 through to its frame costs the same with telemetry on or off (1.06 ms on2935 a 200x60 screen of an 8192x26 sheet, `BenchmarkTelemetry` under30-`-tags stress`). With it on, each event costs about 0.5 us.36+`-tags stress`). With it on, each event costs about 0.5 us written to37+the file, and about 0.6 us queued for OTLP (`BenchmarkSpanOTLP`).3138 3239 Events carry sizes, counts and durations, never cell contents, file3340 contents or secrets. The JEV API key is never logged; neither are file34-names.41+names, OTLP endpoints or OTLP headers.3542 3643 ## What is recorded3744 @@ -40,7 +47,8 @@ same, as an attribute for queries), `service` (`012`) and `dur_ms`.
4047 4148 | Event | When | Attributes |4249 |---|---|---|43-| `start` | the log opens | `version` (VCS revision), `go`, `os`, `arch`, `cpus`, `pid` |50+| `start` | the log opens | `version` (VCS revision), `go`, `os`, `arch`, `cpus`, `pid`, `file` and `otlp` (which outputs are on) |51+| `otlp` | on exit, with OTLP on | per signal (`logs`, `traces`, `metrics`): `sent`, `dropped` (queue full), `failed` (request failed) so far |4452 | `recalc` | every recalculation | `full` (after loading), `evaluated` (dirty cells recomputed), `cells` (stored), `volatile`, `circular` |4553 | `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` |4654 | `frame` | every frame, at debug level | `key_ms` |@@ -55,8 +63,56 @@ Failures are logged at `WARN` with an `error` message.
5563 5664 The engine doesn't log: `sheet.OnRecalc` hands each recalculation's5765 counts to `cmd/012`, which logs them. The call sites use58-`internal/telemetry` (`Start`/`End` spans, `Event`, `Frame`, `Set`), so a59-different backend can replace the JSON file without touching them.66+`internal/telemetry` (`Start`/`End` spans, `Event`, `Frame`, `Set`), so67+the backends (the JSON file, OTLP) sit behind it without touching them.68+69+## OTLP70+71+012 speaks OTLP/HTTP with the JSON encoding itself, with the Go72+standard library only (no OpenTelemetry SDK, no new dependency):73+74+| Signal | What | Shape |75+|---|---|---|76+| 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` |77+| 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 |78+| 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`) |79+80+Every request carries the resource `service.name=012`,81+`service.version` (VCS revision), `service.instance.id` (random per82+run), `os.type`, `host.arch`, `process.runtime.name` and83+`process.runtime.version`, plus any from `OTEL_RESOURCE_ATTRIBUTES`.84+85+Configuration is the standard environment; nothing is sent unless an86+endpoint is set:87+88+| Variable | Effect |89+|---|---|90+| `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://` |91+| `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 |92+| `OTEL_LOGS_EXPORTER`, `OTEL_TRACES_EXPORTER`, `OTEL_METRICS_EXPORTER` | `none` leaves that signal out |93+| `OTEL_EXPORTER_OTLP_HEADERS` | `key=value,...` (values percent-decoded) sent with every request, e.g. `Authorization=Bearer%20...` |94+| `OTEL_EXPORTER_OTLP_TIMEOUT` | per request, in milliseconds; 3000 by default (shorter than the spec's 10 s, so quitting never waits long) |95+| `OTEL_EXPORTER_OTLP_COMPRESSION` | `none` for plain JSON; gzip otherwise |96+| `OTEL_RESOURCE_ATTRIBUTES` | extra resource attributes (`service.name` stays `012`) |97+| `OTEL_SDK_DISABLED` | `true` turns OTLP off whatever else is set |98+99+`OTEL_EXPORTER_OTLP_PROTOCOL` is ignored: 012 only sends `http/json`,100+which the collector's HTTP receiver (4318) accepts; the gRPC port (4317)101+won't work.102+103+The UI never waits on the network. Events go into bounded in-memory104+queues (2048 items per signal); a background goroutine sends them every105+2 seconds, or sooner once 512 are waiting, gzipped, with no retries. A106+full queue drops new items and a failed request drops its batch; both107+are counted in `o12.telemetry.dropped` and the `otlp` event on exit.108+On exit, what is queued is sent within one request timeout (so at most109+about 3 s with a collector that doesn't answer).110+111+`internal/telemetry/otlp_test.go` checks the payloads against the112+spec's JSON mapping with a fake collector (hex ids, 64-bit integers as113+strings, enums as numbers, resource attributes, gzip), plus the drops114+on overflow, the flush on close, the bounded close with a stuck115+collector, and that nothing is sent while off.60116 61117 ## Querying logs with DuckDB62118 @@ -137,18 +193,34 @@ make obs-down # stop; data stays in the named volumes
137193 138194 | Service | Image | Role |139195 |---|---|---|140-| `otel-collector` | `otel/opentelemetry-collector-contrib:0.161.0` | OTLP gRPC (4317) and HTTP (4318) 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 |141-| `clickhouse` | `clickhouse/clickhouse-server:26.3.34.136` | OLAP store: `otel.otel_logs` (and the traces and metrics tables the exporter creates), `stress.results`, `stress.latest_vs_previous`. 3 GB container limit, 75% of it for queries. User `o12`, password `o12` |196+| `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 |197+| `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` |142198 | `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` |143199 144-To send a session to it, log into the directory the collector tails:200+To send a session to it, point 012 at the collector's OTLP/HTTP201+receiver (127.0.0.1:4318), which feeds logs, traces and metrics into202+ClickHouse:145203 146204 ```sh147205 make obs-up148-O12_LOG=$PWD/.deps/obs/logs/012.jsonl ./bin/012 big.csv206+./bin/012 --otlp http://localhost:4318 big.csv207+# or, for the e2e stress check:208+OTEL_EXPORTER_OTLP_ENDPOINT=http://localhost:4318 make stress-e2e149209 make obs-status150210 ```151211 212+Logs land in `otel.otel_logs` (`ServiceName` `012`, the event's213+attributes as strings in `LogAttributes`, `TraceId`/`SpanId` on span214+events), spans in `otel.otel_traces`, and metrics in215+`otel.otel_metrics_summary`, `_gauge`, `_sum` and `_histogram`.216+217+The alternative, logs only, is to log into the directory the collector218+tails (use one or the other, or the logs arrive twice):219+220+```sh221+O12_LOG=$PWD/.deps/obs/logs/012.jsonl ./bin/012 big.csv222+```223+152224 The collector parses each line: `time` becomes the timestamp, `level`153225 the severity, `msg` the body, `service` the `service.name` resource154226 attribute, and everything else a log attribute (as strings in@@ -169,12 +241,29 @@ FROM stress.results FINAL WHERE name = 'Edit/fanin-1000xSUM8192' ORDER BY ts;
169241 170242 -- What regressed since the previous run171243 SELECT * FROM stress.latest_vs_previous WHERE change > 0.1 ORDER BY change DESC;244+245+-- OTLP spans: time per operation246+SELECT SpanName, count() AS n, round(quantile(0.95)(Duration) / 1e6, 2) AS p95_ms,247+ countIf(StatusCode = 'Error') AS failed248+FROM otel.otel_traces WHERE ServiceName = '012' GROUP BY SpanName ORDER BY n DESC;249+250+-- OTLP metrics: key-to-frame p95 per second251+SELECT TimeUnix, Count AS keys,252+ ValueAtQuantiles.Value[indexOf(ValueAtQuantiles.Quantile, 0.95)] AS p95_ms253+FROM otel.otel_metrics_summary254+WHERE ServiceName = '012' AND MetricName = 'o12.key.latency' ORDER BY TimeUnix;172255 ```173256 257+From `make stress-e2e` sent over OTLP, `otel_traces` held 221 `recalc`258+spans (p95 51 ms), 1 `import` (94 ms, 8192 rows) and 3 `command`, and259+the metrics tables a summary, heap and cells gauge per second.260+174261 The `012 runtime` dashboard shows recalculation time (p50, p95, max),175262 frame and key-to-frame p95 per second, heap and cells, JEV answer time176263 and queue, imports and exports with throughput, the slowest operations,177-and events per minute. `012 stress runs` shows edit latency per264+and events per minute (all from the logs, so either way in works), and265+from OTLP the key-to-frame latency summary and the slowest spans with266+their trace ids. `012 stress runs` shows edit latency per178267 topology, frame and keystroke times, full recalc and file operations,179268 memory per cell (log scales where the spread is wide), the latest run180269 against the previous one, and the runs.@@ -184,13 +273,3 @@ The stack starts from scratch with `make obs-up` after
184273 `stress.results` is created on first start by185274 `clickhouse/init.sql`, and again (idempotently) by every186275 `make stress-load`.187-188-## Not yet: native OTLP from 012189-190-012 doesn't link the OpenTelemetry Go SDK: its events reach OTLP191-through the collector's `file_log` receiver, as logs. Emitting traces192-and metrics directly (OTLP/HTTP, configured by the standard193-`OTEL_EXPORTER_OTLP_*` variables) would add the SDK as a dependency;194-the backend would sit behind `internal/telemetry`, whose spans and195-frame summaries map onto OTLP spans and histograms, with no call site196-changes. The collector's OTLP receivers are already running for it.