Skip to content

all: Add opt-in OpenTelemetry tracing - #6744

Open
datanexus-vincent wants to merge 10 commits into
graphprotocol:masterfrom
datanexus-vincent:otel-tracing
Open

datanexus-vincent wants to merge 10 commits into
graphprotocol:masterfrom
datanexus-vincent:otel-tracing

Conversation

@datanexus-vincent

Copy link
Copy Markdown

Adds opt-in OpenTelemetry tracing to graph-node. With GRAPH_OTEL_TRACING=true, graph-node exports spans over OTLP (http/protobuf) to any collector or vendor agent. Off by default; when off, nothing is installed and the only new cost is one atomic load at the start and end of each instrumented section.

Documentation: docs/tracing.md, plus a section in docs/environment-variables.md and a NEWS entry.

Why

Prometheus metrics say how long block processing, writes and queries take on average. They cannot say where the time went in one slow block or one slow request, or which blocks a slow batch write came from. Traces can, and many enterprise-level operators already run OpenTelemetry collectors and vendor agents that accept OTLP.

Design

  • Spans are derived from StopwatchMetrics sections. The runner, the writer and the WASM host already wrap their work in stopwatch sections. Each section now optionally opens a span, so span names are the existing deployment_sync_secs section names and the tree nests exactly as the sections do. No tracing crate, no changes to logging; slog stays as it is.
  • Roots are explicit, not thread-local. process_block starts a trace per block, write_batch one per batch written by the write queue, graphql_query one per request. Nothing relies on the OpenTelemetry thread-local context except the one place where a GraphQL query runs on a dedicated blocking thread, which is where the store's db_query spans find their parent.
  • Write batches link to blocks instead of nesting in them. A batch holds several blocks and is written after they were processed, so it is its own trace with a span link to each block's process_block span (capped at 32, overflow counted in dropped_links).
  • Raw opentelemetry SDK behind a thin graph::telemetry module. Span, Context, extract/inject and the enabled flags are the only surface the rest of the code sees. The SDK reads the standard OTEL_* variables itself; graph-node adds only GRAPH_OTEL_TRACING and GRAPH_OTEL_SPANS.
  • Span groups. GRAPH_OTEL_SPANS selects block, handler, host_fn, store, graphql. host_fn is off by default because a handler can make thousands of store and chain calls.
  • Shutdown flushes. On SIGINT or SIGTERM the buffered spans are exported before the process exits.

What is traced

process_block {subgraph_id, block_number, block_hash, network, shard}
├── process_triggers
│   ├── match_and_decode
│   └── run_handler {handler, trigger, tx_hash?, log_index?}
│       └── host_export_* {host_function, ...}            (host_fn, off by default)
├── as_modifications
├── transact_block {entity_count}
└── update_proof_of_indexing

write_batch {subgraph_id, first_block, last_block, entity_count}   links -> process_block
└── transact_blocks_get_conn, apply_entity_modifications, transact_blocks_prune, ...

graphql_query {subgraph, api_version, query_id, deployment?}   parent <- traceparent header
└── db_query {subgraph_id, entity_count, sql?}

A request with a W3C traceparent header joins the caller's trace. query_id on the request span is the id the query timing logs and the SQL route comment carry, so spans, log lines and pg_stat_activity can be matched up. sql is only attached when GRAPH_LOG_QUERY_TIMING includes sql, the same gate as the logs.

Testing

  • An in-memory exporter in graph::telemetry::testing lets tests assert on exported span trees. Tests cover the module itself, the stopwatch span derivation, the per-block trace and handler attributes (block_spans runner test), write batch links and db_query parenting (test-store), and the HTTP server's header extraction and error status.
  • Tests that need the process-global exporter in a specific state run in a subprocess; the helper is in the same module.
  • Verified manually against the OpenTelemetry Collector's debug exporter: a traced request produced graphql_query under the header's span with db_query under it, a failing query carried an error status, and spans sent just before SIGTERM arrived during shutdown.
  • With tracing off, the unit, test-store and runner suites are unchanged.

Notes for reviewers

  • Cargo.lock only gains the new packages; unrelated entries were left as they were.
  • Along the way, two unrelated small things were fixed because the new code ran into them: the SQL text in query timing logs was truncated at a byte offset, which panics inside a multibyte character, and a stopwatch section that was never bound to anything was removed.
  • Not in this PR: injecting the trace context into outbound RPC and IPFS requests. It is a small follow-up if requested.

Add `graph::telemetry`, a thin wrapper around the opentelemetry crates
and the only place that uses them. It provides a `Span` type that is a
no-op unless a tracer provider has been installed, a `Context` for
parenting across threads, W3C header extraction and injection, and an
in-memory exporter for tests.

Tracing is switched on with `GRAPH_OTEL_TRACING` and the span groups to
emit are chosen with `GRAPH_OTEL_SPANS`.
`telemetry::init` installs an OTLP exporter over http/protobuf as the
global tracer provider when tracing is enabled, configured through the
standard `OTEL_*` environment variables. The node calls it at startup
and, since it has no shutdown sequence of its own, flushes buffered
spans on SIGINT and SIGTERM before exiting.
A section started with `start_root_section` begins a trace; sections
nested in it become child spans of the nearest enclosing section that
has one. Parenting comes from the section stack alone, so it works
unchanged across the threads that share a `StopwatchMetrics`.

Host function sections are gated by the `host_fn` span group, handler
sections by `handler`. With tracing off the only addition is one atomic
load per section start.
Each processed block becomes a trace rooted at the `process_block`
section, carrying the deployment, block number and hash, network and
shard. A block that fails processing marks its span with the error.

The `process_triggers` section was scoped to trigger processing when it
was added (graphprotocol#4558), but the runner refactor left its guard alive until
the end of block processing. It now ends after the triggers ran again.
…racing attributes

Handler spans name the handler and, for chain triggers, the transaction
and log index. `store.set` spans name the entity type and `eth_call`
spans the contract, function and address.

Section attributes are now built by closures that the stopwatch only
calls when the span is recorded, so an unsampled trace or a disabled
group formats nothing.

The `store_set` host function started a section whose guard was dropped
on the same line, so it only ever recorded an empty counter. It is
removed.
Each batch the writer commits is its own trace, linked to the
traces of the blocks whose changes it contains; a batch may hold several
blocks and is written after they were processed, so nesting it under
one of them would be wrong. Entity queries become child spans of the
trace attached to the thread that runs them.

The SQL text in query timing logs was truncated at a fixed byte offset,
which panics inside a multibyte character. It is now cut on a char
boundary.
The HTTP server starts a span for each GraphQL request, joining the
trace named by a W3C traceparent header when there is one. The span's
context travels with the query and is attached to the thread that runs
it, so the store's query spans nest under the request.
… synced

The runner and the writer disabled their stopwatch once the deployment was
synced so that `deployment_sync_secs` only measures the time to sync. With
spans anchored in the stopwatch that left a synced deployment with no block
and no write spans. `stop_recording` now stops the counter and, only with
tracing off, turns the sections into no-ops as before.
Most host functions share the `host_export_other` stopwatch section, so
their spans could not be told apart. Every host function span now carries
the WASM import name in `host_function`. The section names, and with them
the `deployment_sync_secs` label set, are unchanged.

This branch has not been deployed

No deployments
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants