Skip to content

Conversation

@jmacd
Copy link
Contributor

@jmacd jmacd commented Jan 7, 2026

Implements new internal logging configuration option.

Changes the default logging configuration to use internal logging at level INFO. Previously, default logging was disabled.

Implements a lightweight Tokio tracing layer to construct partially-encoded OTLP bytes from the Event, forming a struct that can be passed through a channel to a global subscriber.

As the first step, implements "raw logging" directly to the console using simple write! macros and the view object for LogRecord to interpret the partial encoding and print it. The raw logging limits console message size to 4KiB.

Adds a new configs/internal-telemetry.yaml to demonstrate this configuration.

Adds benchmarks showing good performance, in the 50-200ns range to encode or encode/format:

encode/0_attrs/100_events
                        time:   [5.5326 µs 5.5691 µs 5.6054 µs]
                        change: [−7.3098% −4.0342% −1.9226%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 1 outliers among 100 measurements (1.00%)
  1 (1.00%) high mild
encode/3_attrs/100_events
                        time:   [8.5902 µs 8.6810 µs 8.7775 µs]
                        change: [−5.7968% −3.2559% −1.1958%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 7 outliers among 100 measurements (7.00%)
  2 (2.00%) low mild
  2 (2.00%) high mild
  3 (3.00%) high severe
encode/10_attrs/100_events
                        time:   [19.583 µs 19.764 µs 19.944 µs]
                        change: [−1.5682% +0.0078% +1.3193%] (p = 0.99 > 0.05)
                        No change in performance detected.
Found 3 outliers among 100 measurements (3.00%)
  3 (3.00%) high mild
encode/0_attrs/1000_events
                        time:   [53.424 µs 53.874 µs 54.289 µs]
                        change: [−2.8602% −1.8582% −0.9413%] (p = 0.00 < 0.05)
                        Change within noise threshold.
Found 2 outliers among 100 measurements (2.00%)
  1 (1.00%) low mild
  1 (1.00%) high severe
encode/3_attrs/1000_events
                        time:   [84.768 µs 85.161 µs 85.562 µs]
                        change: [−3.3406% −2.4035% −1.5473%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 5 outliers among 100 measurements (5.00%)
  1 (1.00%) low mild
  4 (4.00%) high mild
encode/10_attrs/1000_events
                        time:   [193.04 µs 194.07 µs 195.13 µs]
                        change: [−1.8940% −0.1358% +1.7994%] (p = 0.89 > 0.05)
                        No change in performance detected.
Found 7 outliers among 100 measurements (7.00%)
  1 (1.00%) low severe
  1 (1.00%) low mild
  2 (2.00%) high mild
  3 (3.00%) high severe

format/0_attrs/100_events
                        time:   [26.281 µs 26.451 µs 26.633 µs]
                        change: [−16.944% −14.312% −10.992%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 6 outliers among 100 measurements (6.00%)
  1 (1.00%) low mild
  1 (1.00%) high mild
  4 (4.00%) high severe
format/3_attrs/100_events
                        time:   [38.813 µs 39.180 µs 39.603 µs]
                        change: [−8.0880% −6.7812% −5.5109%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 8 outliers among 100 measurements (8.00%)
  1 (1.00%) low severe
  1 (1.00%) low mild
  4 (4.00%) high mild
  2 (2.00%) high severe
format/10_attrs/100_events
                        time:   [70.655 µs 71.176 µs 71.752 µs]
                        change: [−4.8840% −3.9457% −3.0096%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 4 outliers among 100 measurements (4.00%)
  4 (4.00%) high mild
format/0_attrs/1000_events
                        time:   [295.80 µs 310.56 µs 325.75 µs]
                        change: [−3.2629% −0.5673% +2.4337%] (p = 0.71 > 0.05)
                        No change in performance detected.
Found 10 outliers among 100 measurements (10.00%)
  3 (3.00%) high mild
  7 (7.00%) high severe
format/3_attrs/1000_events
                        time:   [422.93 µs 430.42 µs 439.21 µs]
                        change: [−1.3953% +0.8886% +3.3330%] (p = 0.46 > 0.05)
                        No change in performance detected.
Found 5 outliers among 100 measurements (5.00%)
  5 (5.00%) high mild
format/10_attrs/1000_events
                        time:   [720.96 µs 725.68 µs 730.81 µs]
                        change: [−15.540% −13.383% −11.371%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 9 outliers among 100 measurements (9.00%)
  1 (1.00%) low mild
  5 (5.00%) high mild
  3 (3.00%) high severe

encode_and_format/0_attrs/100_events
                        time:   [32.698 µs 32.914 µs 33.147 µs]
                        change: [−9.4066% −7.8944% −6.3427%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 8 outliers among 100 measurements (8.00%)
  2 (2.00%) low mild
  3 (3.00%) high mild
  3 (3.00%) high severe
encode_and_format/3_attrs/100_events
                        time:   [48.927 µs 49.498 µs 50.133 µs]
                        change: [−7.2473% −5.1069% −2.7211%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 10 outliers among 100 measurements (10.00%)
  3 (3.00%) high mild
  7 (7.00%) high severe
encode_and_format/10_attrs/100_events
                        time:   [95.328 µs 96.088 µs 96.970 µs]
                        change: [−6.3169% −4.9414% −3.6501%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 5 outliers among 100 measurements (5.00%)
  4 (4.00%) high mild
  1 (1.00%) high severe
encode_and_format/0_attrs/1000_events
                        time:   [326.65 µs 328.86 µs 331.27 µs]
                        change: [−41.188% −39.915% −38.764%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 7 outliers among 100 measurements (7.00%)
  6 (6.00%) high mild
  1 (1.00%) high severe
encode_and_format/3_attrs/1000_events
                        time:   [500.59 µs 504.82 µs 509.33 µs]
                        change: [−50.787% −48.877% −47.483%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 4 outliers among 100 measurements (4.00%)
  3 (3.00%) high mild
  1 (1.00%) high severe
encode_and_format/10_attrs/1000_events
                        time:   [944.34 µs 951.79 µs 960.38 µs]
                        change: [−55.389% −54.741% −54.065%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 4 outliers among 100 measurements (4.00%)
  3 (3.00%) high mild
  1 (1.00%) high severe

@jmacd
Copy link
Contributor Author

jmacd commented Jan 8, 2026

From #1672 (comment)

Have discussed with @andborja and I realize that the internal::enabled setting is not well placed. Andres suggested having something at a higher level, not to conflict with the OTel declarative configuration model, and to have more of a mode selection like "noop", "raw", "global", "threaded", "opentelemetry", each with different behavior.

@jmacd
Copy link
Contributor Author

jmacd commented Jan 9, 2026

I removed the changes in crates/config and opentelemetry_client.rs, leaving only the encoding logic, formatting logic used and benchmarks for now.

Copy link
Contributor

@lquerel lquerel left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

Comment on lines +17 to +18
use tracing::callsite::Identifier;
use tracing::{Event, Level, Metadata};
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why not our own objects to break this dependency?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am not trying to avoid use of Tokio tracing, and I don't think we should. Even when our custom macros use the effect handler directly, they are likely to be Tokio tracing macros.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This layer of the architecture should not be coupled to external libraries, especially if they are just simple data structures. This is independent of the decision or not to couple another layer to tokio tracing.

@@ -0,0 +1,114 @@
// Copyright The OpenTelemetry Authors
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

self_tracing or internal_tracing? The concept used as of now is "internal", not "self"

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think of self-tracing as including this "raw" logging support for low-level logging about the process itself.
I think of "internal" logging as logging that passes through an internal pipeline starting at ITR.

I'm not against moving combining these two directories, if we decide it makes sense.


/// The operation to perform on each event within the layer.
#[derive(Clone, Copy)]
enum BenchOp {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

https://github.com/open-telemetry/opentelemetry-rust/pull/3307/changes

I was adding similar benches in OTel Rust to measure the cost of conversions!

fn on_event(&self, event: &Event<'_>, _ctx: tracing_subscriber::layer::Context<'_, S>) {
match self.op {
BenchOp::Encode => {
for _ in 0..self.iterations {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

any advantage doing the iteration ourselves, than doing just once, and let criterion do the repeated execution itself?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I did this I suppose to be certain that overhead from the subscriber isn't being picked up. I'm pleased when I see 100 executions at 8.6xxx and 1000 executions at 85.xxx.

prints colorized or uncolorized messages on the console. The
formatting code path in this module is safe for logging in critical
regions and to be used as a fallback inside other logging handlers.
It uses no synchronization and depends only on the console.
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

console writing internally uses locks.. not sure if that is worth mentioning here.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think the meaning is clear for the users of this low-level interface. If there's user-level configuration that allows configuring "raw" logging of this nature, then it will be important to emphasize this. Can't the OS buffer stdout any way it likes? I assume this is console and OS dependent.

@jmacd jmacd enabled auto-merge January 9, 2026 22:59
@jmacd jmacd added this pull request to the merge queue Jan 9, 2026
Merged via the queue into open-telemetry:main with commit 002f436 Jan 9, 2026
42 of 43 checks passed
@jmacd jmacd deleted the jmacd/tracing_to_otlp_bytes branch January 9, 2026 23:14
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

rust Pull requests that update Rust code

Projects

Status: Done

Development

Successfully merging this pull request may close these issues.

4 participants