gh-rust-lang/log
Watch
1
0
Fork
You've already forked log
 0
Code Issues 16 Pull requests 2 Releases Activity

Executable size impact #275

New issue
Closed
opened 2018-06-03 12:05:12 -05:00 by RazrFalcon · 5 comments
RazrFalcon commented 2018-06-03 12:05:12 -05:00 (Migrated from github.com)

Here is a simple demo:

#[macro_use] extern crate log;
extern crate fern;

fn main() {
    fern::Dispatch::new()
        .level(log::LevelFilter::Warn)
        .chain(std::io::stderr())
        .apply().unwrap();

    warn!("Hello, world!");
//     println!("Hello, world!");
    test();
}

fn test() {
    warn!("Hello, world!");
//     println!("Hello, world!");
}

According to the cargo-bloat, the code size with warn in the release build is 1000B and with println - 717B. Why it impacts the size so much? Maybe this is a cargo-bloat bug (yes, I'm the author)?

In the real world applications, the results are even more drastic. For example, if I remove all the logging from this module the size in the release build will be reduced from 9.1KiB to 3.1KiB. It's ridiculous.

I this is a correct behavior or am I missing something?

log v0.4.1
fern v0.5.5
cargo-bloat v0.5.0
rustc 1.26.1

Here is a simple demo: ```rust #[macro_use] extern crate log; extern crate fern; fn main() { fern::Dispatch::new() .level(log::LevelFilter::Warn) .chain(std::io::stderr()) .apply().unwrap(); warn!("Hello, world!"); // println!("Hello, world!"); test(); } fn test() { warn!("Hello, world!"); // println!("Hello, world!"); } ``` According to the `cargo-bloat`, the code size with `warn` in the release build is 1000B and with `println` - 717B. Why it impacts the size so much? Maybe this is a `cargo-bloat` bug (yes, I'm the author)? In the real world applications, the results are even more drastic. For example, if I remove all the logging from [this](https://github.com/RazrFalcon/usvg/blob/master/src/convert/shapes.rs) module the size in the release build will be reduced from 9.1KiB to 3.1KiB. It's ridiculous. I this is a correct behavior or am I missing something? log v0.4.1 fern v0.5.5 cargo-bloat v0.5.0 rustc 1.26.1
sfackler commented 2018-06-03 12:24:02 -05:00 (Migrated from github.com)

Log is tracking significantly more information than a println.

It's grabbing the filename, the line number, the module name, the log target, and the actual log string, rather than just the string, and performing an extra check against the global max log level: https://github.com/rust-lang-nursery/log/blob/master/src/macros.rs#L33-L51

It looks like a main function that just contains warn!("hello world") is 204 bytes and a main function that just contains println!("hello world") is 77 bytes.

There is some impact from the way the log macro is currently structured avoiding the construction of the Record struct cuts the size of main down to 124 bytes:

#[macro_use]
extern crate log;

use std::fmt::Arguments;
use log::{Level, RecordBuilder};

fn main() {
    if Level::Warn <= log::max_level() {
        log_fast(Level::Warn, "foo", format_args!("hello world"), module_path!(), file!(), line!());
    }
}

#[inline(never)]
fn log_fast(level: Level, target: &str, args: Arguments, module: &str, file: &str, line: u32) {
    log::logger()
        .log(
            &RecordBuilder::new()
                .level(level)
                .target(target)
                .args(args)
                .module_path(Some(module))
                .file(Some(file))
                .line(Some(line))
                .build(),
        );
}

That came up as an option during the 0.4 API overhauls, and it may be worth adding back a "secret" function like log_fast for the use of the log macros.

Log is tracking significantly more information than a println. It's grabbing the filename, the line number, the module name, the log target, and the actual log string, rather than just the string, and performing an extra check against the global max log level: https://github.com/rust-lang-nursery/log/blob/master/src/macros.rs#L33-L51 It looks like a main function that just contains `warn!("hello world")` is 204 bytes and a main function that just contains `println!("hello world")` is 77 bytes. There is some impact from the way the log macro is currently structured avoiding the construction of the Record struct cuts the size of main down to 124 bytes: ```rust #[macro_use] extern crate log; use std::fmt::Arguments; use log::{Level, RecordBuilder}; fn main() { if Level::Warn <= log::max_level() { log_fast(Level::Warn, "foo", format_args!("hello world"), module_path!(), file!(), line!()); } } #[inline(never)] fn log_fast(level: Level, target: &str, args: Arguments, module: &str, file: &str, line: u32) { log::logger() .log( &RecordBuilder::new() .level(level) .target(target) .args(args) .module_path(Some(module)) .file(Some(file)) .line(Some(line)) .build(), ); } ``` That came up as an option during the 0.4 API overhauls, and it may be worth adding back a "secret" function like log_fast for the use of the log macros.
RazrFalcon commented 2018-06-03 13:16:31 -05:00 (Migrated from github.com)

Hmm... Interesting.

I was able to reduce the exe/crate size to the same size a bit.

  • default log! - 275.3KiB
  • custom log! - 270.2KiB
  • minimal custom log! - 267.6KiB
  • eprintln! - 266.7KiB

Custom:

#[inline(never)]
fn log_fast(level: log::Level, module: &str, file: &str, line: u32, args: ::std::fmt::Arguments) {
    if level <= ::log::STATIC_MAX_LEVEL && level <= ::log::max_level() {
        log::logger()
            .log(
                &log::RecordBuilder::new()
                    .level(level)
                    .target(module)
                    .args(args)
                    .module_path(Some(module))
                    .file(Some(file))
                    .line(Some(line))
                    .build(),
            );
    }
}

macro_rules! log {
    ($lvl:expr, $($arg:tt)+) => ({
        ::log_fast($lvl, module_path!(), file!(), line!(), format_args!($($arg)+))
    });
    ($lvl:expr, $($arg:tt)+) => (log!($lvl, $($arg)+))
}

Minimal:

#[inline(never)]
fn log_fast(level: log::Level, args: ::std::fmt::Arguments) {
    if level <= ::log::STATIC_MAX_LEVEL && level <= ::log::max_level() {
        log::logger()
            .log(
                &log::RecordBuilder::new()
                    .level(level)
                    .target("")
                    .args(args)
                    .module_path(None)
                    .file(None)
                    .line(None)
                    .build(),
            );
    }
}

macro_rules! log {
    ($lvl:expr, $($arg:tt)+) => ({
        ::log_fast($lvl, format_args!($($arg)+))
    });
    ($lvl:expr, $($arg:tt)+) => (log!($lvl, $($arg)+))
}

PS: surprisingly, removing the useless trace! from a hot method reduced the size by 8% by itself with a default log implementation.

Hmm... Interesting. I was able to reduce the exe/crate size to the same size a bit. - default log! - 275.3KiB - custom log! - 270.2KiB - minimal custom log! - 267.6KiB - eprintln! - 266.7KiB Custom: ```rust #[inline(never)] fn log_fast(level: log::Level, module: &str, file: &str, line: u32, args: ::std::fmt::Arguments) { if level <= ::log::STATIC_MAX_LEVEL && level <= ::log::max_level() { log::logger() .log( &log::RecordBuilder::new() .level(level) .target(module) .args(args) .module_path(Some(module)) .file(Some(file)) .line(Some(line)) .build(), ); } } macro_rules! log { ($lvl:expr, $($arg:tt)+) => ({ ::log_fast($lvl, module_path!(), file!(), line!(), format_args!($($arg)+)) }); ($lvl:expr, $($arg:tt)+) => (log!($lvl, $($arg)+)) } ``` Minimal: ```rust #[inline(never)] fn log_fast(level: log::Level, args: ::std::fmt::Arguments) { if level <= ::log::STATIC_MAX_LEVEL && level <= ::log::max_level() { log::logger() .log( &log::RecordBuilder::new() .level(level) .target("") .args(args) .module_path(None) .file(None) .line(None) .build(), ); } } macro_rules! log { ($lvl:expr, $($arg:tt)+) => ({ ::log_fast($lvl, format_args!($($arg)+)) }); ($lvl:expr, $($arg:tt)+) => (log!($lvl, $($arg)+)) } ``` PS: surprisingly, removing the useless `trace!` from a [hot method](https://github.com/RazrFalcon/usvg/blob/23d3c4addddd40e3621add31ed70eed2fd9ca2f4/src/traits.rs#L186) reduced the size by 8% by itself with a default log implementation.
sfackler commented 2018-06-03 13:36:32 -05:00 (Migrated from github.com)

That would make sense if the hot method was inlined in a bunch of places.
On Sun, Jun 3, 2018 at 11:16 AM Evgeniy Reizner notifications@github.com
wrote:

Hmm... Interesting.

I was able to reduce the exe/crate size to the same size a bit.

  • default log! - 275.3KiB
  • custom log! - 270.2KiB
  • minimal custom log! - 267.6KiB
  • eprintln! - 266.7KiB

Custom:

#[inline(never)]fn log_fast(level: log::Level, module: &str, file: &str, line: u32, args: ::std::fmt::Arguments) {
if level <= ::log::STATIC_MAX_LEVEL && level <= ::log::max_level() {
log::logger()
.log(
&log::RecordBuilder::new()
.level(level)
.target(module)
.args(args)
.module_path(Some(module))
.file(Some(file))
.line(Some(line))
.build(),
);
}
}
macro_rules! log {
($lvl:expr, $($arg:tt)+) => ({
::log_fast($lvl, module_path!(), file!(), line!(), format_args!($($arg)+))
});
($lvl:expr, $($arg:tt)+) => (log!($lvl, $($arg)+))
}

Minimal:

#[inline(never)]fn log_fast(level: log::Level, args: ::std::fmt::Arguments) {
if level <= ::log::STATIC_MAX_LEVEL && level <= ::log::max_level() {
log::logger()
.log(
&log::RecordBuilder::new()
.level(level)
.target("")
.args(args)
.module_path(None)
.file(None)
.line(None)
.build(),
);
}
}
macro_rules! log {
($lvl:expr, $($arg:tt)+) => ({
::log_fast($lvl, format_args!($($arg)+))
});
($lvl:expr, $($arg:tt)+) => (log!($lvl, $($arg)+))
}

PS: surprisingly, removing the useless trace! from a hot method
https://github.com/RazrFalcon/usvg/blob/23d3c4addddd40e3621add31ed70eed2fd9ca2f4/src/traits.rs#L186
reduced the size by 8% by itself with a default log implementation.

—
You are receiving this because you commented.

Reply to this email directly, view it on GitHub
https://github.com/rust-lang-nursery/log/issues/275#issuecomment-394180726,
or mute the thread
https://github.com/notifications/unsubscribe-auth/ABY2UfzRUiZ6zpRI-fv0_R9SjDd_isf0ks5t5CgAgaJpZM4UYKCY
.

That would make sense if the hot method was inlined in a bunch of places. On Sun, Jun 3, 2018 at 11:16 AM Evgeniy Reizner <notifications@github.com> wrote: > Hmm... Interesting. > > I was able to reduce the exe/crate size to the same size a bit. > > - default log! - 275.3KiB > - custom log! - 270.2KiB > - minimal custom log! - 267.6KiB > - eprintln! - 266.7KiB > > Custom: > > #[inline(never)]fn log_fast(level: log::Level, module: &str, file: &str, line: u32, args: ::std::fmt::Arguments) { > if level <= ::log::STATIC_MAX_LEVEL && level <= ::log::max_level() { > log::logger() > .log( > &log::RecordBuilder::new() > .level(level) > .target(module) > .args(args) > .module_path(Some(module)) > .file(Some(file)) > .line(Some(line)) > .build(), > ); > } > } > macro_rules! log { > ($lvl:expr, $($arg:tt)+) => ({ > ::log_fast($lvl, module_path!(), file!(), line!(), format_args!($($arg)+)) > }); > ($lvl:expr, $($arg:tt)+) => (log!($lvl, $($arg)+)) > } > > Minimal: > > #[inline(never)]fn log_fast(level: log::Level, args: ::std::fmt::Arguments) { > if level <= ::log::STATIC_MAX_LEVEL && level <= ::log::max_level() { > log::logger() > .log( > &log::RecordBuilder::new() > .level(level) > .target("") > .args(args) > .module_path(None) > .file(None) > .line(None) > .build(), > ); > } > } > macro_rules! log { > ($lvl:expr, $($arg:tt)+) => ({ > ::log_fast($lvl, format_args!($($arg)+)) > }); > ($lvl:expr, $($arg:tt)+) => (log!($lvl, $($arg)+)) > } > > PS: surprisingly, removing the useless trace! from a hot method > <https://github.com/RazrFalcon/usvg/blob/23d3c4addddd40e3621add31ed70eed2fd9ca2f4/src/traits.rs#L186> > reduced the size by 8% by itself with a default log implementation. > > — > You are receiving this because you commented. > > > Reply to this email directly, view it on GitHub > <https://github.com/rust-lang-nursery/log/issues/275#issuecomment-394180726>, > or mute the thread > <https://github.com/notifications/unsubscribe-auth/ABY2UfzRUiZ6zpRI-fv0_R9SjDd_isf0ks5t5CgAgaJpZM4UYKCY> > . >
RazrFalcon commented 2018-06-03 13:41:35 -05:00 (Migrated from github.com)

It was.

It was.
sfackler commented 2018-06-03 14:39:50 -05:00 (Migrated from github.com)

You can also disable specific logging levels entirely at compile time, which will remove all of the code from the resulting binary, btw: https://docs.rs/log/0.4.1/log/#compile-time-filters

You can also disable specific logging levels entirely at compile time, which will remove all of the code from the resulting binary, btw: https://docs.rs/log/0.4.1/log/#compile-time-filters
Sign in to join this conversation.
No Branch/Tag specified
Branches Tags
master
archive/20261005T153738Z-deleted/ci/msrv-build-vs-test
archive/20260925T210104Z-rescue/djugei/dyn_downcast
fix/lifetime-rules
0.3.x
0.4.34
0.4.33
0.4.32
0.4.31
0.4.30
0.4.29
0.4.28
0.4.27
0.4.26
0.4.25
0.4.24
0.4.23
0.4.22
0.4.21
0.4.20
0.4.19
0.4.18
0.4.17
0.4.15
0.4.14
0.4.13
0.4.12
0.4.11
0.4.10
0.4.9
0.4.8
0.4.7
0.4.6
0.4.5
0.4.4
0.4.3
0.4.2
0.4.1
0.3.9
0.4.0
0.4.0-rc.1
env_logger-0.4.3
0.3.8
0.3.7
env_logger-0.4.2
env_logger-0.4.1
env_logger-0.4.0
env_logger-0.3.5
env_logger-0.3.4
env_logger-0.3.3
0.3.6
Labels
Clear labels   
bug

   
duplicate

   
easy

   
enhancement

   
help wanted

   
invalid

   
question

   
rfc

   
structured-logging

   
wontfix
No labels
bug
duplicate
easy
enhancement
help wanted
invalid
question
rfc
structured-logging
wontfix
Milestone
Clear milestone
No items
No milestone
Assignees
Clear assignees
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set

Reference
gh-rust-lang/log#275
No description provided.