Logging, Tracing, Metrics, and Observability

Good observability capabilities are key to the development and growth of Sui. This is made more challenging by the distributed and asynchronous nature of Sui, with multiple client and validator processes distributed over a potentially global network.

The observability stack in Sui is based on the Tokio tracing library. The rest of this document highlights specific aspects of achieving good observability through structured logging and metrics in Sui.

Note: The output here is largely for the consumption of Sui operators, administrators, and developers. The content of logs and traces do not represent the authoritative, certified output of validators and are subject to potentially byzantine behavior.

Contexts, scopes, and tracing transaction flow

In a distributed and asynchronous system like Sui, one cannot rely on looking at individual logs over time in a single thread. To solve this problem, use the approach of structured logging. Structured logging offers a way to tie together logs, events, and blocks of functionality across threads and process boundaries.

Spans and events

In the Tokio tracing library, structured logging is implemented using spans and events. Spans cover a whole block of functionality - like one function call, a future or asynchronous task, etc. They can be nested, and key-value pairs in spans give context to events or logs inside the function.

  • spans and their key-value pairs add essential context to enclosed logs, such as a transaction ID.
  • spans also track time spent in different sections of code, enabling distributed tracing functionality.
  • individual logs can also add key-value pairs to aid in parsing, filtering and aggregation.

Here is a list of context information of interest:

  • TX Digest
  • Object reference/ID, when applicable
  • Address
  • Certificate digest, if applicable
  • For Client HTTP endpoint: route, method, status
  • Epoch
  • Host information, for both clients and validators

In the digest, process_tx is a span that covers handling the initial transaction request, and "Checked locks" is a single log message within the transaction handling method in the validator.

Every log message that occurs within the span inherits the key-value properties defined in the span, including the tx_digest and any other fields that are added. Log messages can set their own keys and values. The fact that logs inherit the span properties allows you to trace, for example, the flow of a transaction across thread and process boundaries.

Key-value pairs schema

Spans capture not a single event but an entire block of time; so start, end, duration, etc. can be captured and analyzed for tracing, performance analysis, and so on.

Tags - keys

The idea is that every event and span would get tagged with key-value pairs. Events that log within any context or nested contexts would also inherit the context-level tags.

These tags represent fields that can be analyzed and filtered by. For example, one could filter out broadcasts and see the errors for all instances where the bad stake exceeded a certain amount, but not enough for an error.

Logging levels

This is always tricky, to balance the right amount of verbosity especially by default -- while keeping in mind this is a high performance system.

LevelType of Messages
ErrorProcess-level faults (not transaction-level errors, there could be a ton of those)
WarnUnusual or byzantine activity
InfoHigh level aggregate stats, major events related to data sync, epoch changes.
DebugHigh level tracing for individual transactions, eg Gateway/client side -> validator -> Move execution etc.
TraceExtremely detailed tracing for individual transactions

Going from info to debug results in a much larger spew of messages.

Use the RUST_LOG environment variable to set both the overall logging level as well as the level for individual components. Filtering down to specific spans or tags within spans is even possible.

For more details, see the EnvFilter topic.


Sui includes Prometheus-based metrics:

  • rpc_requests_by_route and related for RPC Server API metrics and latencies (see rpc-server.rs)
  • Validator transaction metrics (see AuthorityMetrics in authority.rs)

Viewing logs, traces, metrics

The tracing architecture is based on the idea of subscribers which can be plugged into the tracing library to process and forward output to different sinks for viewing. Multiple subscribers can be active at the same time.

You can feed JSON logs, for example, through a local sidecar log forwarder such as Vector, and then onwards to destinations such as ElasticSearch.

The use of a log and metrics aggregator such as Vector allows for easy reconfiguration without interrupting the validator server, as well as offloading observability traffic.

Metrics: served with a Prometheus scrape endpoint, by default at <host>:9184/metrics.

Stdout (default)

By default, logs (but not spans) are formatted for human readability and output to stdout, with key-value tags at the end of every line.

You can configure RUST_LOG for custom logging output, including filtering - see the Logging levels section earlier in this topic.

Tracing and span output

To generate detailed span start and end logs, define the SUI_JSON_SPAN_LOGS environment variable. This causes all output to be in JSON format, which is not as human-readable, so it is not enabled by default.

You can send this output to a tool or service for indexing, alerts, aggregation, and analysis.

The following example output shows certificate processing in the authority with span logging. Note the START and END annotations, and notice how DB_UPDATE_STATE which is nested is embedded within PROCESS_CERT. Also notice elapsed_milliseconds, which logs the duration of each span.

{"v":0,"name":"sui","msg":"[PROCESS_CERT - START]","level":20,"hostname":"Evan-MLbook.lan","pid":51425,"time":"2022-03-08T22:48:11.241421Z","target":"sui_core::authority_server","line":67,"file":"sui_core/src/authority_server.rs","tx_digest":"t#d1385064287c2ad67e4019dd118d487a39ca91a40e0fd8e678dbc32e112a1493"}
{"v":0,"name":"sui","msg":"[PROCESS_CERT - EVENT] Read inputs for transaction from DB","level":20,"hostname":"Evan-MLbook.lan","pid":51425,"time":"2022-03-08T22:48:11.246688Z","target":"sui_core::authority","line":393,"file":"sui_core/src/authority.rs","num_inputs":2,"tx_digest":"t#d1385064287c2ad67e4019dd118d487a39ca91a40e0fd8e678dbc32e112a1493"}
{"v":0,"name":"sui","msg":"[PROCESS_CERT - EVENT] Finished execution of transaction with status Success { gas_used: 18 }","level":20,"hostname":"Evan-MLbook.lan","pid":51425,"time":"2022-03-08T22:48:11.246759Z","target":"sui_core::authority","line":409,"file":"sui_core/src/authority.rs","gas_used":18,"tx_digest":"t#d1385064287c2ad67e4019dd118d487a39ca91a40e0fd8e678dbc32e112a1493"}
{"v":0,"name":"sui","msg":"[DB_UPDATE_STATE - START]","level":20,"hostname":"Evan-MLbook.lan","pid":51425,"time":"2022-03-08T22:48:11.247888Z","target":"sui_core::authority","line":430,"file":"sui_core/src/authority.rs","tx_digest":"t#d1385064287c2ad67e4019dd118d487a39ca91a40e0fd8e678dbc32e112a1493"}
{"v":0,"name":"sui","msg":"[DB_UPDATE_STATE - END]","level":20,"hostname":"Evan-MLbook.lan","pid":51425,"time":"2022-03-08T22:48:11.248114Z","target":"sui_core::authority","line":430,"file":"sui_core/src/authority.rs","tx_digest":"t#d1385064287c2ad67e4019dd118d487a39ca91a40e0fd8e678dbc32e112a1493","elapsed_milliseconds":0}
{"v":0,"name":"sui","msg":"[PROCESS_CERT - END]","level":20,"hostname":"Evan-MLbook.lan","pid":51425,"time":"2022-03-08T22:48:11.248688Z","target":"sui_core::authority_server","line":67,"file":"sui_core/src/authority_server.rs","tx_digest":"t#d1385064287c2ad67e4019dd118d487a39ca91a40e0fd8e678dbc32e112a1493","elapsed_milliseconds":2}

Jaeger (seeing distributed traces)

To see nested spans visualized with Jaeger, do the following:

  1. Run this to get a local Jaeger container:
docker run -d -p6831:6831/udp -p6832:6832/udp -p16686:16686 jaegertracing/all-in-one:latest
  1. Run Sui like this (trace enables the most detailed spans):
SUI_TRACING_ENABLE=1 RUST_LOG="info,sui_core=trace" ./sui start
  1. Run some transfers with Sui CLI client, or run the benchmarking tool.
  2. Browse to http://localhost:16686/ and select Sui as the service.

Note: - Separate spans (that are not nested) are not connected as a single trace for now.

Live async inspection / Tokio Console

Tokio-console is an awesome CLI tool designed to analyze and help debug Rust apps using Tokio, in real time! It relies on a special subscriber.

  1. Build Sui using a special flag: RUSTFLAGS="--cfg tokio_unstable" cargo build.
  2. Start Sui with SUI_TOKIO_CONSOLE set to 1.
  3. Clone the console repo and cargo run to launch the console.

Note: Adding Tokio-console support might significantly slow down Sui validators/gateways.

Memory profiling

Sui uses the jemalloc memory allocator by default on most platforms, and there is code that enables automatic memory profiling using jemalloc's sampling profiler, which is very lightweight and designed for production use. The profiling code spits out profiles at most every 5 minutes, and only when total memory has increased by a default 20%. Profiling files are named jeprof.<TIMESTAMP>.<memorysize>MB.prof so that it is easy to correlate to metrics and incidents, for ease of debugging.

For the memory profiling to work, you need to set the environment variable _RJEM_MALLOC_CONF=prof:true. If you use the Docker image they are set automatically.

Running some allocator-based heap profilers such as Bytehound will essentially disable automatic jemalloc profiling, because they interfere with or don't implement jemalloc_ctl stats APIs.

To view the profile files, one needs to do the following, on the same platform as where the profiles were gathered:

  1. Install libunwind, the dot utility from graphviz, and jeprof. On Debian: apt-get install libjemalloc-dev libunwind-dev graphviz.
  2. Build with debug symbols: cargo build --profile bench-profiling
  3. cd to $SUI_REPO/target/bench-profiling
  4. Run jeprof --svg sui-node jeprof.xxyyzz.heap - select the heap profile based on

timestamp and memory size in the filename.

Note: With automatic memory profiling, it is no longer necessary to configure environment variables beyond those previously listed. It is possible to configure custom profiling options:

For example, set _RJEM_MALLOC_CONF to: prof:true,lg_prof_interval:24,lg_prof_sample:19

The preceding setting means: turn on profiling, sample every 2^19 or 512KB bytes allocated, and dump out the profile every 2^24 or 16MB of memory allocated. However, the automatic profiling is designed to produce files that are better named and at less intervals, so overriding the default configuration is not usually recommended.

Last update 3/13/2023, 5:00:44 PM