Skip to content

Commit

Permalink
docs(dev-guide/tracing): mention RUSTUP_LOG and console-based tracing
Browse files Browse the repository at this point in the history
  • Loading branch information
rami3l committed Jun 22, 2024
1 parent 97c64cc commit 6eb71e9
Showing 1 changed file with 67 additions and 26 deletions.
93 changes: 67 additions & 26 deletions doc/dev-guide/src/tracing.md
Original file line number Diff line number Diff line change
@@ -1,16 +1,72 @@
# Tracing

The feature "otel" can be used when building rustup to turn on Opentelemetry
tracing with an OLTP GRPC exporter.
Similar to other tools in the Rust ecosystem like rustc and cargo,
rustup also provides observability/logging features via the `tracing` crate.

This can be very useful for diagnosing performance or correctness issues in more
complicated scenarios.
The verbosity of logs is controlled via the `RUSTUP_LOG` environment
variable using `tracing_subscriber`'s [directive syntax].

[directive syntax]: https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/struct.EnvFilter.html#directives

## Prerequisites
## Console-based tracing

`protoc` must be installed, which can be downloaded from GitHub or installed via package manager.
A `tracing_subscriber` that prints log lines directly to `stderr` is directly
available in the prebuilt version of rustup since v1.28.0.

For historical reasons, if `RUSTUP_LOG` is not set, this subscriber will print
the log lines in a format that mimics the "legacy" `stderr` output in older
versions of rustup:

```console
> rustup default stable
info: using existing install for 'stable-aarch64-apple-darwin'
info: default toolchain set to 'stable-aarch64-apple-darwin'

stable-aarch64-apple-darwin unchanged - rustc 1.79.0 (129f3b996 2024-06-10)
```

## Usage
However, once `RUSTUP_LOG` is set to any value, rustup's "custom logging mode" will
be activated, and `tracing_subscriber`'s builtin output format will be used instead:

```console
> RUSTUP_LOG=trace rustup default stable
2024-06-16T12:08:48.732894Z INFO rustup::cli::common: using existing install for 'stable-aarch64-apple-darwin'
2024-06-16T12:08:48.739232Z INFO rustup::cli::common: default toolchain set to 'stable-aarch64-apple-darwin'

stable-aarch64-apple-darwin unchanged - rustc 1.79.0 (129f3b996 2024-06-10)
```

Please note that since `RUSTUP_LOG=trace` essentially accepts log lines from
all possible sources, you might sometimes see log lines coming from rustup's
dependencies, such as `hyper_util` in the following example:

```console
> RUSTUP_LOG=trace rustup update
[..]
2024-06-16T12:12:45.569428Z TRACE hyper_util::client::legacy::client: http1 handshake complete, spawning background dispatcher task
2024-06-16T12:12:45.648682Z TRACE hyper_util::client::legacy::pool: pool dropped, dropping pooled (("https", static.rust-lang.org))

stable-aarch64-apple-darwin unchanged - rustc 1.79.0 (129f3b996 2024-06-10)
nightly-aarch64-apple-darwin unchanged - rustc 1.81.0-nightly (3cf924b93 2024-06-15)

2024-06-16T12:12:45.693350Z INFO rustup::cli::rustup_mode: cleaning up downloads & tmp directories
```

It is also possible to limit the sources of the log lines and the desired
max level for each source. For example, set `RUSTUP_LOG=rustup=DEBUG` to
receive log lines only from `rustup` itself with a max verbosity of `DEBUG`.

## Opentelemetry tracing

> **Prerequisites:** Before following the instructions in this section,
> `protoc` must be installed, which can be downloaded from GitHub
> or installed via a package manager.
The feature `otel` can be used when building rustup to turn on Opentelemetry
tracing with an OLTP GRPC exporter.

This can be very useful for diagnosing performance or correctness issues in more
complicated scenarios.

The normal [OTLP environment
variables](https://github.com/open-telemetry/opentelemetry-specification/blob/main/specification/protocol/exporter.md)
Expand All @@ -21,31 +77,24 @@ run a Jaeger docker container on the same host:
docker run -d --name jaeger -e COLLECTOR_ZIPKIN_HOST_PORT=:9411 -e COLLECTOR_OTLP_ENABLED=true -p 6831:6831/udp -p 6832:6832/udp -p 5778:5778 -p 16686:16686 -p 4317:4317 -p 4318:4318 -p 14250:14250 -p 14268:14268 -p 14269:14269 -p 9411:9411 jaegertracing/all-in-one:latest
```

Then build rustup-init with tracing:
Then build `rustup-init` with tracing:

```sh
cargo build --features=otel
```

Run the operation you want to analyze:
Run the operation you want to analyze. For example, we can now run `rustup show` with tracing:

```sh
RUSTUP_FORCE_ARG0="rustup" ./target/debug/rustup-init show
```

And [look in Jaeger for a trace](http://localhost:16686/search?service=rustup).

## Tracing and tests

Tracing can also be used in tests to get a trace of the operations taken during the test.
To use this feature, build the project with `--features=otel,test`.

The custom macro `rustup_macros::test` adds a prelude and suffix to each test to
ensure that there is a tracing context setup, that the test function is a span,
and that the spans from the test are flushed.

Build with features=otel,test to use this feature.

## Adding instrumentation
### Adding instrumentation

The `otel` feature uses conditional compilation to only add function instrument
when enabled. Instrumenting a currently uninstrumented function is mostly simply
Expand All @@ -71,11 +120,3 @@ Some good general heuristics:
- Be way of debug build timing - release optimisations make a huge difference,
though debug is a lot faster to iterate on. If something isn't a problem in
release don't pay it too much heed in debug.

## Caveats

Cross-thread propagation isn't connected yet. This will cause instrumentation in
a thread to make a new root span until it is fixed. If any Tokio runtime-related
code gets added in those threads this will also cause a panic. We have a couple
of threadpools in use today; if you need to instrument within that context, use
a thunk to propagate the tokio runtime into those threads.

0 comments on commit 6eb71e9

Please sign in to comment.