Proposal: optimize for binary size

[Folyd]

Comparing to the log crate, tracing is so powerful and elegant. However, tracing also brings more binary size to the application due to the more complex expanded macro codes. I have a simple binary size test against tracing and log.
Here is the source code. For 1k lines of info!("Hello World!"); macro called, tracing is nearly 2x larger binary size than the log (in release mode, w/o strip).

$ ls -l target/release/tracing target/release/log 
-rwxr-xr-x  2 xx  staff   567848 Jun  7 21:35 target/release/log
-rwxr-xr-x  2 xx  staff  1137672 Jun  7 21:36 target/release/tracing

P.S. We recently replaced the log with tracing in our company project. What overwhelmed us is that we got 10 Mib large size than before! 😲

Proposal

Optimize the binary size without comprising the features, elegance, and performance.

I only have few thoughts right now:

• I don't think the name field of Metadata is useful to the Event, neither the file, line, and module_path are useful to the Span? We really need to share the same Metadata struct for Event and Span?
• Seems like we have a lot of discusses on whether we deserve the level field for Span, I still in favor of level-less Span. I believe this can reduce the complexity and is beneficial to binary size.

Alternative

Maybe we can have a tracing-lite crate, which is binary size friendly but missing some features?

[hawkw]

I don't think removing metadata fields will make a significant impact on binary size. Instead, I think a majority --- or perhaps all --- of the increased binary size you're seeing is due to the amount of code that is generated by macro invocations.

There was a previous attempt at fixing this, by moving the path where a span/event is actually recorded behind a function call so that the recording code isn't monomorphized at every macro invocation (see #943).

Unfortunately, this inadvertently caused a breaking change, and had to be reverted (see #987). In tracing 0.1, there isn't really a good way to avoid most of the code generated for the recording path, because of the borrowing issues discussed in #987 --- we can't invoke the recording code with a closure, because, when a field value is a subfield of a struct or tuple, the closure will borrow the entire struct/tuple, rather than the subfield. This breaks code that mutably borrows another subfield of that struct/tuple.

Fortunately, in tracing 0.2, the ValueSet construction will be much simpler --- value names will be determined based on their position in the valueset array, rather than by iterating over the field names and constructing tuples, as in the current approach. This will mean that we can generate the ValueSet with significantly less code (it's just an array literal, which will compile down to significantly fewer instructions than the current code which involves an iterator), and just pass those arrays into the recording code.

This means we can significantly reduce how much tracing-related code is monomorphized at each macro callsite --- instead, it will mostly be hidden behind a function call, so it's only generated once. This should result in significantly less binary size (probably several orders of magnitude less than dropping any individual metadata fields).

Incidentally, the file name, line number, and module paths on Span metadata definitely are all used currently --- for example,

[Folyd]

Thanks, @hawkw. The new ValueSet API and using function-call to prevent monomorphism are so great! 🥳

TIL, I'm too naive, haha.

[Altair-Bueno]

In my experience, the data section of binaries is packed with strings that refer to the source code.
These are not being used by any of my subscribers (at least to my knowledge) yet they are not being tree shaken by Rust.

For example, running the following command

readelf -x .rodata target/armv7-unknown-linux-gnueabihf/release/binary-name

yields the following output:

 0x002adcd0 6f206465 7374696e 6174696f 6e2e4661 o destination.Fa
  0x002adce0 696c6564 20746f20 72656365 69766520 iled to receive 
  0x002adcf0 53494749 4e542073 69676e61 6c2e6576 SIGINT signal.ev
  0x002add00 656e7420 7372632f 6163746f 722f636f ent src/actor/co
  0x002add10 6e647563 746f722e 72733a31 37336576 nductor.rs:173ev
  0x002add20 656e7420 7372632f 6163746f 722f636f ent src/actor/co
  0x002add30 6e647563 746f722e 72733a32 30376576 nductor.rs:207ev
  0x002add40 656e7420 7372632f 6163746f 722f636f ent src/actor/co
  0x002add50 6e647563 746f722e 72733a32 31326576 nductor.rs:212ev
  0x002add60 656e7420 7372632f 6163746f 722f636f ent src/actor/co
  0x002add70 6e647563 746f722e 72733a32 31366576 nductor.rs:216ev
  0x002add80 656e7420 7372632f 6163746f 722f636f ent src/actor/co
  0x002add90 6e647563 746f722e 72733a32 32316576 nductor.rs:221ev
  0x002adda0 656e7420 7372632f 6163746f 722f636f ent src/actor/co
  0x002addb0 6e647563 746f722e 72733a32 33336576 nductor.rs:233ev
  0x002addc0 656e7420 7372632f 6163746f 722f636f ent src/actor/co
  0x002addd0 6e647563 746f722e 72733a32 33366576 nductor.rs:236ev
  0x002adde0 656e7420 7372632f 6163746f 722f636f ent src/actor/co
  // ...

Each one of those line numbers refer to a tracing::{info,trace,debug,error} macro invocation! Removing these strings would significantly reduce the binary size for my application.

Is there any feature flags, either from tracing or tracing-subscribers, that I could toggle to remove these strings?

tracing = { workspace = "0.1.40", features = ["std", "attributes"] }
tracing-subscriber = { workspace = "0.3.18", default-features = false, features = ["std", "fmt", "registry", "json"] }

PS: I already followed these suggestions: #1925 (comment)

PS2: I found the culprit

tracing/tracing/src/macros.rs

Line 857 in 690a9a6

name: concat!(

Would it be possible to construct the name string at runtime instead? Is that string required to be unique? Could we just add a feature that replaces every one of those with the same string across all crates ("REDACTED", "", ...)?

[mladedav]

These are the default names of events. You could manually set name: "anything" in the macro invocations and that should get rid of it. The name does not have to be unique, but it has to be a &' static str.

Using features to control this is questionable because features are additive and so any crate anywhere in your dependency tree could enable a feature and you have no way to disable it.

But I think it's reasonable to consider changing the default event name for 0.2 since this would be most likely breaking. There is another mechanism to obtain the filename and line number so it is probably wasteful if every single event! invocation in all dependencies has this footprint even though the events may be and in most cases probably are filtered out.

[Altair-Bueno]

You could manually set name: "anything" in the macro invocations and that should get rid of it.

But that would only affect my crate, which is the tip of the iceberg.

so it is probably wasteful if every single event! invocation in all dependencies has this footprint even though the events may be and in most cases probably are filtered out.

Indeed, these names are being generated for every single consumer of tracing and appended to my binary. For example, the crate async-io consumes tracing (https://crates.io/crates/async-io/2.3.2/dependencies).

Running the following command on a binary that depends on async-io

readelf -p .rodata  target/armv7-unknown-linux-gnueabihf/release/az-mqtt | rg --regexp="event.*async_io.*.rs:\d+"

yields this:

  [  3070]  sleeping for  uscannot initialize I/O event notification ready wakersasync_io::main_loopevent /cargo/registry/src/index.crates.io-6f17d22bba15001f/async-io-2.3.2/src/driver.rs:68event /cargo/registry/src/index.crates.io-6f17d22bba15001f/async-io-2.3.2/src/driver.rs:83event /cargo/registry/src/index.crates.io-6f17d22bba15001f/async-io-2.3.2/src/driver.rs:85async_io::block_onevent /cargo/registry/src/index.crates.io-6f17d22bba15001f/async-io-2.3.2/src/driver.rs:203event /cargo/registry/src/index.crates.io-6f17d22bba15001f/async-io-2.3.2/src/driver.rs:209event /cargo/registry/src/index.crates.io-6f17d22bba15001f/async-io-2.3.2/src/driver.rs:242event /cargo/registry/src/index.crates.io-6f17d22bba15001f/async-io-2.3.2/src/driver.rs:247event /cargo/registry/src/index.crates.io-6f17d22bba15001f/async-io-2.3.2/src/driver.rs:252event /cargo/registry/src/index.crates.io-6f17d22bba15001f/async-io-2.3.2/src/driver.rs:258event /cargo/registry/src/index.crates.io-6f17d22bba15001f/async-io-2.3.2/src/driver.rs:277process_timersasync_io::reactorevent /cargo/registry/src/index.crates.io-6f17d22bba15001f/async-io-2.3.2/src/reactor.rs:241reactevent /cargo/registry/src/index.crates.io-6f17d22bba15001f/async-io-2.3.2/src/reactor.rs:359event /cargo/registry/src/index.crates.io-6f17d22bba15001f/async-io-2.3.2/src/reactor.rs:544event /cargo/registry/src/index.crates.io-6f17d22bba15001f/async-io-2.3.2/src/reactor.rs:564event /cargo/registry/src/index.crates.io-6f17d22bba15001f/async-io-2.3.2/src/reactor.rs:584Shouldn't be able to borrow parker reentrantlymust listen() on event listener before waitinglistener was never inserted into the list/cargo/registry/src/index.crates.io-6f17d22bba15001f/event-listener-4.0.3/src/std.rsinternal error: entered unreachable code: Invalid stateinvalid key/cargo/registry/src/index.crates.io-6f17d22bba15001f/async-io-2.3.2/src/reactor.rsreadable_ownedwritable_ownedfuture polled after completion/cargo/registry/src/index.crates.io-6f17d22bba15001f/event-listener-5.3.0/src/lib.rs/cargo/registry/src/index.crates.io-6f17d22bba15001f/event-listener-4.0.3/src/lib.rsEventListener was not inserted into the linked list, make sure you're not polling EventListener/listener! after it has finished/cargo/registry/src/index.crates.io-6f17d22bba15001f/event-listener-5.3.0/src/std.rstag already taken/cargo/registry/src/index.crates.io-6f17d22bba15001f/concurrent-queue-2.5.0/src/bounded.rs/cargo/registry/src/index.crates.io-6f17d22bba15001f/concurrent-queue-2.5.0/src/unbounded.rs

Notice the prefix for all of these. They could be removed, at least,