tracing
tracing copied to clipboard
Proposal: optimize for binary size
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 ofMetadata
is useful to theEvent
, neither thefile
,line
, andmodule_path
are useful to theSpan
? We really need to share the sameMetadata
struct forEvent
andSpan
? - Seems like we have a lot of discusses on whether we deserve the
level
field forSpan
, I still in favor of level-lessSpan
. 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?
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 https://github.com/tokio-rs/tracing/pull/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,
Thanks, @hawkw. The new ValueSet
API and using function-call to prevent monomorphism are so great! 🥳
TIL, I'm too naive, haha.
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: https://github.com/tokio-rs/tracing/discussions/1925#discussioncomment-2174719
PS2: I found the culprit https://github.com/tokio-rs/tracing/blob/690a9a68098aa1eb86d1c5c4aad085ef12245bca/tracing/src/macros.rs#L857 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", "", ...)?
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.
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,