Skip to main content

Logging, Tracing, Metrics, and Observability

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

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

info

Sui operators, administrators, and developers primarily consume this output. The content of logs and traces does not represent the authoritative, certified output of validators and is 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, and so on. 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 references/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, and similar values can be captured and analyzed for tracing, performance analysis, and so on.

Tags - keys​

Every event and span gets tagged with key-value pairs. Events that log within any context or nested contexts also inherit the context-level tags.

These tags represent fields that you can analyze and filter by. For example, you can 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​

Balancing the right amount of verbosity, especially by default, is always tricky 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, for example Gateway/client side -> validator -> Move execution.
TraceExtremely detailed tracing for individual transactions

Going from information 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.

Metrics​

Sui includes Prometheus-based metrics:

  • rpc_requests_by_route and related metrics for RPC server API metrics and latencies
  • Validator transaction metrics (see AuthorityMetrics in the Sui source code)

Viewing logs, traces, metrics​

The tracing architecture uses subscribers that you can plug 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 through a local sidecar log forwarder such as Vector, and then onwards to destinations such as ElasticSearch.

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

Sui serves metrics through a Prometheus scrape endpoint, by default at <host>:9184/metrics.

Stdout (default)​

By default, the system formats logs (but not spans) for human readability and outputs them 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. The START and END annotations show how DB_UPDATE_STATE, which is nested, is embedded within PROCESS_CERT. The elapsed_milliseconds field 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, complete the following steps:

  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.
info

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

Live async inspection / Tokio Console​

Tokio-console is a 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.
tip

Adding Tokio-console support might significantly slow down Sui validators and 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 on the same platform where the profiles were gathered, complete the following steps:

  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.
tip

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.