Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

refactor: Modify buffer and macros #6

Open
wants to merge 1 commit into
base: main
Choose a base branch
from
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
15 changes: 3 additions & 12 deletions README.md
Original file line number Diff line number Diff line change
Expand Up @@ -54,11 +54,11 @@ fn main() {
}
```

### Utilising `Serialize`
### Utilising `Serialize` through the `^` prefix

In order to avoid cloning a large struct, you can implement the `Serialize` trait.
As cloning a large object could be expensive, you can define how you want to copy and format your object into a human-readable String through the `Serialize` trait.

This allows you to copy specific parts of your struct onto a circular byte buffer and avoid copying the rest by encoding providing a function to decode your struct from a byte buffer.
Use a `^` prefix before your variable and `quicklog` will serialize your item onto a static byte buffer through the `encode` method you defined and decode it at the flush site through the `decode` function you have included in the `Store` struct.

For a complete example, refer to `~/quicklog/benches/logger_benchmark.rs`.

Expand Down Expand Up @@ -143,15 +143,6 @@ We are open to contributions and requests!

Please post your bug reports or feature requests on [Github Issues](https://github.com/ghpr-asia/quicklog/issues).

## Roadmap

- [] add single-threaded and multi-threaded variants
- [] Try to remove nested `lazy_format` in recursion
- [] Check number of copies of data made in each log line and possibly reduce it
- [] Review uses of unsafe code
- [] Benchmark multi-threaded performance
- [] Statically assert that strings inside Level and LevelFilter are the same size

## Authors and acknowledgment

[Zack Ng](https://github.com/nhzaci), Tien Dat Nguyen, Michiel van Slobbe, Dheeraj Oswal
Expand Down
28 changes: 17 additions & 11 deletions quicklog/build.rs
Original file line number Diff line number Diff line change
Expand Up @@ -18,34 +18,40 @@ fn parse_value_from_config_with_default<T: FromStr>(
Err(_) => match default {
Some(val) => Ok(val),
None => {
eprintln!("MAX_LOGGER_CAPACITY environment variable is not set");
Err(format!("env '{}' is not set and there are no defaults for it. Please set it in your env.", key))
}
},
}
}

const MAX_SERIALIZE_BUFFER_CAPACITY_BYTES: &'static str =
"QUICKLOG_MAX_SERIALIZE_BUFFER_CAPACITY_BYTES";
const MAX_LOGGER_CAPACITY_ITEMS: &'static str = "QUICKLOG_MAX_LOGGER_CAPACITY_ITEMS";

fn main() {
println!("cargo:rerun-if-env-changed=QUICKLOG_MAX_SERIALIZE_BUFFER_CAPACITY");
println!(
"cargo:rerun-if-env-changed={}",
MAX_SERIALIZE_BUFFER_CAPACITY_BYTES
);
let max_buffer_capacity = match parse_value_from_config_with_default(
"QUICKLOG_MAX_SERIALIZE_BUFFER_CAPACITY",
MAX_SERIALIZE_BUFFER_CAPACITY_BYTES,
Some(1_000_000_usize),
) {
Ok(val) => val,
Err(err) => {
println!("cargo:warning={}", err);
println!("cargo:warning={}, utilizing default value '1_000_000'", err);
1_000_000
}
};

println!("cargo:rerun-if-env-changed=QUICKLOG_MAX_LOGGER_CAPACITY");
println!("cargo:rerun-if-env-changed={}", MAX_LOGGER_CAPACITY_ITEMS);
let max_logger_capacity = match parse_value_from_config_with_default(
"QUICKLOG_MAX_LOGGER_CAPACITY",
MAX_LOGGER_CAPACITY_ITEMS,
Some(1_000_000_usize),
) {
Ok(val) => val,
Err(err) => {
println!("cargo:warning={}", err);
println!("cargo:warning={}, utilizing default value '1_000_000'", err);
1_000_000
}
};
Expand All @@ -54,11 +60,11 @@ fn main() {
let rust_code = format!(
"// This file was generated by `build.rs`, do not modify this file manually!

/// Sets max capacity of logging queue, can be set through env var `QUICKLOG_MAX_LOGGER_CAPACITY`.
pub const MAX_LOGGER_CAPACITY: usize = {};
/// Sets max capacity (in items) of logging queue, can be set through env var `QUICKLOG_MAX_LOGGER_CAPACITY_ITEMS`.
pub const MAX_LOGGER_CAPACITY_ITEMS: usize = {};

/// Sets max capacity of byte buffer used for serialization with `^` prefix in logging, can be set through `QUICKLOG_MAX_SERIALIZE_BUFFER_CAPACITY`.
pub const MAX_SERIALIZE_BUFFER_CAPACITY: usize = {};
/// Sets max capacity (in bytes) of byte buffer used for serialization with `^` prefix in logging, can be set through `QUICKLOG_MAX_SERIALIZE_BUFFER_CAPACITY_BYTES`.
pub const MAX_SERIALIZE_BUFFER_CAPACITY_BYTES: usize = {};
",
max_logger_capacity, max_buffer_capacity
);
Expand Down
6 changes: 4 additions & 2 deletions quicklog/examples/macros.rs
Original file line number Diff line number Diff line change
@@ -1,4 +1,4 @@
use quicklog::{debug, error, flush, info, trace, warn, with_flush};
use quicklog::{debug, error, info, init, trace, try_flush, warn, with_flush};
use quicklog_flush::stdout_flusher::StdoutFlusher;

#[derive(Clone)]
Expand All @@ -13,6 +13,8 @@ impl std::fmt::Display for S {
}

fn main() {
init!();

with_flush!(StdoutFlusher);

trace!("hello world! {} {} {}", 2, 3, 4);
Expand Down Expand Up @@ -46,5 +48,5 @@ fn main() {
s_0, s_1, s_2, s_3, s_4, s_5, s_6, s_7, s_8, s_9, s_10
);

flush!();
while let Ok(()) = try_flush!() {}
}
8 changes: 4 additions & 4 deletions quicklog/src/constants.rs
Original file line number Diff line number Diff line change
@@ -1,7 +1,7 @@
// This file was generated by `build.rs`, do not modify this file manually!

/// Sets max capacity of logging queue, can be set through env var `QUICKLOG_MAX_LOGGER_CAPACITY`.
pub const MAX_LOGGER_CAPACITY: usize = 1000000;
/// Sets max capacity (in items) of logging queue, can be set through env var `QUICKLOG_MAX_LOGGER_CAPACITY_ITEMS`.
pub const MAX_LOGGER_CAPACITY_ITEMS: usize = 1000000;

/// Sets max capacity of byte buffer used for serialization with `^` prefix in logging, can be set through `QUICKLOG_MAX_SERIALIZE_BUFFER_CAPACITY`.
pub const MAX_SERIALIZE_BUFFER_CAPACITY: usize = 1000000;
/// Sets max capacity (in bytes) of byte buffer used for serialization with `^` prefix in logging, can be set through `QUICKLOG_MAX_SERIALIZE_BUFFER_CAPACITY_BYTES`.
pub const MAX_SERIALIZE_BUFFER_CAPACITY_BYTES: usize = 1000000;
25 changes: 17 additions & 8 deletions quicklog/src/lib.rs
Original file line number Diff line number Diff line change
Expand Up @@ -80,6 +80,8 @@
//! you might not want to log. This functionality can be done through implementing the
//! [`Serialize`] trait, where you can implement how to copy which parts of the struct.
//!
//! The [`Serialize`] trait could be called upon with the `^` prefix.
//!
//! This could additionally be helpful if you already have the struct inside a buffer in byte
//! form, as you could simply pass the buffer directly into the decode fn, eliminiating any
//! need to copy.
Expand Down Expand Up @@ -129,6 +131,11 @@
//! be used in combination with `%` and `?` prefix on args to eagerly evaluate
//! expressions into format strings.
//!
//! **Note:** Do not use this if speed is a concern. This eagerly formats through the
//! `Display` trait by default if no prefix is used and does not utilise the
//! lazily evaluated capabilities of the normal logger. This is done because
//! there will be 2 clones made.
//!
//! ```
//! # use quicklog::{init, info};
//! # fn main() {
Expand All @@ -143,10 +150,12 @@
//!
//! There are two environment variables you can set:
//!
//! 1. `QUICKLOG_MAX_LOGGER_CAPACITY`
//! - sets the size of the spsc ring buffer used for logging
//! 2. `QUICKLOG_MAX_SERIALIZE_BUFFER_CAPACITY`
//! - sets the size of the byte buffer used for static serialization
//! 1. `QUICKLOG_MAX_LOGGER_CAPACITY_ITEMS`
//! - sets the maximum number of items in the spsc ring buffer used for logging
//! - each item is a tuple: (Instant, Box<dyn Display>), requiring 8 + 16 bytes each
//! - meaning 1m items would require 24m bytes to be available
//! 2. `QUICKLOG_MAX_SERIALIZE_BUFFER_CAPACITY_BYTES`
//! - sets the number of bytes in the static byte buffer used for serialization
//! - this can be increased when you run into issues out of memory in debug
//! when conducting load testing
//!
Expand All @@ -170,7 +179,7 @@
//! fn main() {
//! init!();
//!
//! with_clock!(SomeClock::new());
//! with_clock!(SomeClock);
//!
//! // logger now uses SomeClock for timestamping
//! info!("Hello, world!");
Expand Down Expand Up @@ -235,11 +244,11 @@ pub type Intermediate = (Instant, Box<dyn Display>);
static mut LOGGER: Lazy<Quicklog> = Lazy::new(Quicklog::default);

/// Producer side of queue
pub type Sender = heapless::spsc::Producer<'static, Intermediate, MAX_LOGGER_CAPACITY>;
pub type Sender = heapless::spsc::Producer<'static, Intermediate, MAX_LOGGER_CAPACITY_ITEMS>;
/// Result from pushing onto queue
pub type SendResult = Result<(), Intermediate>;
/// Consumer side of queue
pub type Receiver = heapless::spsc::Consumer<'static, Intermediate, MAX_LOGGER_CAPACITY>;
pub type Receiver = heapless::spsc::Consumer<'static, Intermediate, MAX_LOGGER_CAPACITY_ITEMS>;
/// Result from trying to pop from logging queue
pub type RecvResult = Result<(), FlushError>;

Expand Down Expand Up @@ -307,7 +316,7 @@ impl Quicklog {

/// Initializes channel for main logging queue
fn init_channel() {
static mut QUEUE: Queue<Intermediate, MAX_LOGGER_CAPACITY> = Queue::new();
static mut QUEUE: Queue<Intermediate, MAX_LOGGER_CAPACITY_ITEMS> = Queue::new();
let (sender, receiver): (Sender, Receiver) = unsafe { QUEUE.split() };
unsafe {
SENDER.set(sender).ok();
Expand Down
94 changes: 20 additions & 74 deletions quicklog/src/macros.rs
Original file line number Diff line number Diff line change
Expand Up @@ -124,7 +124,7 @@ macro_rules! try_log {

// allow unused_parens for case with 1 single field
#[allow(unused_parens)]
let ($([<$($field)*>]),*) = ($(($args).to_owned()),*);
let ($([<$($field)*>]),*) = ($(($args).clone()),*);

let log_line = lazy_format::make_lazy_format!(|f| {
write!(f, concat!("[{}]\t", $static_str), $lvl, $([<$($field)*>]),*)
Expand Down Expand Up @@ -153,82 +153,50 @@ macro_rules! try_log {
// 1. `literal = expr` arg
// 2. `$($ident).+ = expr` arg
// for 1 and 2, there are 4 sub cases:
// a. &expr - reference argument where we need to clone
// b. %expr - eager format into Display
// c. ?expr - eager format into Debug
// d. ^expr - serialize
// e. expr - no special handling required
// a. %expr - eager format into Display
// b. ?expr - eager format into Debug
// c. expr - eager format into Display
// 3. no prefix - $next: own and pass to lazy_format
// 4. `%` prefix - %$next: eagerly format object that implements Display
// 5. `?` prefix - ?$next: eagerly format object that implements Debug
// 6. `^` prefix - #$next: implemenets serialize trait, simply clone the Store

// case 1a: match `literal = &expr` argument, where argument is a reference
// example: info!("some string field {}", "string field here" = &some_variable)
// we need to own the argument before we can pass it into the lazy_format closure
($lvl:expr, $static_str:literal @@ {{ $(,)* $($args:expr),* }} @ ($($prefix:tt)*) ($($past:tt)*) $key:literal = &$next:expr, $($rest:tt)*) => {{
let arg = (&$next).to_owned();
$crate::try_log!($lvl, $static_str @@ {{ $($args),* , lazy_format::lazy_format!("{}={}", $key, arg) }} @ ($($prefix)* x) ($($past)* [$($prefix)*]) $($rest)*)
}};

// case 1b: match `literal = %expr` argument, eagerly format expr into Display
// case 1a: match `literal = %expr` argument, eagerly format expr into Display
// example: info!("some string field {}", "string field here" = %some_variable)
($lvl:expr, $static_str:literal @@ {{ $(,)* $($args:expr),* }} @ ($($prefix:tt)*) ($($past:tt)*) $key:literal = %$next:expr, $($rest:tt)*) => {
$crate::try_log!($lvl, $static_str @@ {{ $($args),* , format!("{}={}", $key, $next) }} @ ($($prefix)* x) ($($past)* [$($prefix)*]) $($rest)*)
};

// case 1c: match `literal = ?expr` argument, eagerly format expr into Debug
// case 1b: match `literal = ?expr` argument, eagerly format expr into Debug
// example: info!("some string field {}", "string field here" = ?some_variable)
($lvl:expr, $static_str:literal @@ {{ $(,)* $($args:expr),* }} @ ($($prefix:tt)*) ($($past:tt)*) $key:literal = ?$next:expr, $($rest:tt)*) => {
$crate::try_log!($lvl, $static_str @@ {{ $($args),* , format!("{}={:?}", $key, $next) }} @ ($($prefix)* x) ($($past)* [$($prefix)*]) $($rest)*)
};

// case 1d: match `literal = ^expr` argument, where argument impls `Serialize`
// example: info!("some string field {}", "string field here" = ^some_variable)
// we need to own the argument before we can pass it into the lazy_format closure
($lvl:expr, $static_str:literal @@ {{ $(,)* $($args:expr),* }} @ ($($prefix:tt)*) ($($past:tt)*) $key:literal = ^$next:expr, $($rest:tt)*) => {{
$crate::try_log!($lvl, $static_str @@ {{ $($args),* , lazy_format::lazy_format!("{}={}", $key, $crate::make_store!($next)) }} @ ($($prefix)* x) ($($past)* [$($prefix)*]) $($rest)*)
}};

// case 1e: match `literal = expr` argument, normal argument pass by move
// case 1c: match `literal = expr` argument, eagerly format into Display
// example: info!("some string field {}", "string field here" = some_variable)
($lvl:expr, $static_str:literal @@ {{ $(,)* $($args:expr),* }} @ ($($prefix:tt)*) ($($past:tt)*) $key:literal = $next:expr, $($rest:tt)*) => {
$crate::try_log!($lvl, $static_str @@ {{ $($args),* , lazy_format::lazy_format!("{}={}", $key, $next) }} @ ($($prefix)* x) ($($past)* [$($prefix)*]) $($rest)*)
$crate::try_log!($lvl, $static_str @@ {{ $($args),* , format!("{}={}", $key, $next) }} @ ($($prefix)* x) ($($past)* [$($prefix)*]) $($rest)*)
};

// case 2a: match `ident.ident1.ident2 = &expr` argument, where expr represents a reference
// example: info!("some nested ident {}", some.nested.field.of.idents = &some_expr)
// we need to own the argument first
($lvl:expr, $static_str:literal @@ {{ $(,)* $($args:expr),* }} @ ($($prefix:tt)*) ($($past:tt)*) $($key:ident).+ = &$next:expr, $($rest:tt)*) => {{
let arg = (&$next).to_owned();
$crate::try_log!($lvl, $static_str @@ {{ $($args),* , lazy_format::lazy_format!("{}={}", stringify!($($key).+), arg) }} @ ($($prefix)* x) ($($past)* [$($prefix)*]) $($rest)*)
}};

// case 2b: match `ident.ident1.ident2 = %expr` argument, eagerly format expr into Display
// case 2a: match `ident.ident1.ident2 = %expr` argument, eagerly format expr into Display
// example: info!("some nested ident {}", some.nested.field.of.idents = %some_expr)
// we need to own the argument first
($lvl:expr, $static_str:literal @@ {{ $(,)* $($args:expr),* }} @ ($($prefix:tt)*) ($($past:tt)*) $($key:ident).+ = %$next:expr, $($rest:tt)*) => {
$crate::try_log!($lvl, $static_str @@ {{ $($args),* , format!("{}={}", stringify!($($key).+), $next) }} @ ($($prefix)* x) ($($past)* [$($prefix)*]) $($rest)*)
};

// case 2c: match `ident.ident1.ident2 = ?expr` argument, eagerly format expr into Debug
// case 2b: match `ident.ident1.ident2 = ?expr` argument, eagerly format expr into Debug
// example: info!("some nested ident {}", some.nested.field.of.idents = ?some_expr)
// we need to own the argument first
($lvl:expr, $static_str:literal @@ {{ $(,)* $($args:expr),* }} @ ($($prefix:tt)*) ($($past:tt)*) $($key:ident).+ = ?$next:expr, $($rest:tt)*) => {
$crate::try_log!($lvl, $static_str @@ {{ $($args),* , format!("{}={}", stringify!($($key).+), $next) }} @ ($($prefix)* x) ($($past)* [$($prefix)*]) $($rest)*)
};

// case 2d: match `ident.ident1.ident2 = ^expr` argument, where argument implements Serialize
// example: info!("some nested ident {}", some.nested.field.of.idents = ^some_expr)
// we need to own the argument first
($lvl:expr, $static_str:literal @@ {{ $(,)* $($args:expr),* }} @ ($($prefix:tt)*) ($($past:tt)*) $($key:ident).+ = ^$next:expr, $($rest:tt)*) => {{
$crate::try_log!($lvl, $static_str @@ {{ $($args),* , lazy_format::lazy_format!("{}={}", stringify!($($key).+), $crate::make_store!($next)) }} @ ($($prefix)* x) ($($past)* [$($prefix)*]) $($rest)*)
}};

// case 2e: match `ident.ident1.ident2 = expr` argument
// case 2c: match `ident.ident1.ident2 = expr` argument
// example: info!("some nested ident {}", some.nested.field.of.idents = some_expr)
($lvl:expr, $static_str:literal @@ {{ $(,)* $($args:expr),* }} @ ($($prefix:tt)*) ($($past:tt)*) $($key:ident).+ = $next:expr, $($rest:tt)*) => {
$crate::try_log!($lvl, $static_str @@ {{ $($args),* , lazy_format::lazy_format!("{}={}", stringify!($($key).+), $next) }} @ ($($prefix)* x) ($($past)* [$($prefix)*]) $($rest)*)
$crate::try_log!($lvl, $static_str @@ {{ $($args),* , format!("{}={}", stringify!($($key).+), $next) }} @ ($($prefix)* x) ($($past)* [$($prefix)*]) $($rest)*)
};

// case 3: no prefix - own and pass to lazy_format
Expand Down Expand Up @@ -257,56 +225,34 @@ macro_rules! try_log {

// last recursive case - no more $($rest)* to recurse over

// case 1a - ref &$next
($lvl:expr, $static_str:literal @@ {{ $(,)* $($args:expr),* }} @ ($($prefix:tt)*) ($($past:tt)*) $key:literal = &$next:expr) => {{
let arg = (&$next).to_owned();
$crate::try_log!($lvl, $static_str @@ {{ $($args),* , lazy_format::lazy_format!("{}={}", $key, arg) }} @ ($($prefix)* x) ($($past)* [$($prefix)*]))
}};

// case 1b - %$next
// case 1a - %$next
($lvl:expr, $static_str:literal @@ {{ $(,)* $($args:expr),* }} @ ($($prefix:tt)*) ($($past:tt)*) $key:literal = %$next:expr) => {
$crate::try_log!($lvl, $static_str @@ {{ $($args),* , format!("{}={}", $key, $next) }} @ ($($prefix)* x) ($($past)* [$($prefix)*]))
};

// case 1c - ?$next
// case 1b - ?$next
($lvl:expr, $static_str:literal @@ {{ $(,)* $($args:expr),* }} @ ($($prefix:tt)*) ($($past:tt)*) $key:literal = ?$next:expr) => {
$crate::try_log!($lvl, $static_str @@ {{ $($args),* , format!("{}={:?}", $key, $next) }} @ ($($prefix)* x) ($($past)* [$($prefix)*]))
};

// case 1d - ^$next
($lvl:expr, $static_str:literal @@ {{ $(,)* $($args:expr),* }} @ ($($prefix:tt)*) ($($past:tt)*) $key:literal = ^$next:expr) => {
$crate::try_log!($lvl, $static_str @@ {{ $($args),* , lazy_format::lazy_format!("{}={}", $key, $crate::make_store!($next)) }} @ ($($prefix)* x) ($($past)* [$($prefix)*]))
};

// case 1e - move $next
// case 1c - $next
($lvl:expr, $static_str:literal @@ {{ $(,)* $($args:expr),* }} @ ($($prefix:tt)*) ($($past:tt)*) $key:literal = $next:expr) => {
$crate::try_log!($lvl, $static_str @@ {{ $($args),* , lazy_format::lazy_format!("{}={}", $key, $next) }} @ ($($prefix)* x) ($($past)* [$($prefix)*]))
$crate::try_log!($lvl, $static_str @@ {{ $($args),* , format!("{}={}", $key, $next) }} @ ($($prefix)* x) ($($past)* [$($prefix)*]))
};

// case 2a - ref &$next
($lvl:expr, $static_str:literal @@ {{ $(,)* $($args:expr),* }} @ ($($prefix:tt)*) ($($past:tt)*) $($key:ident).+ = &$next:expr) => {{
let arg = (&$next).to_owned();
$crate::try_log!($lvl, $static_str @@ {{ $($args),* , lazy_format::lazy_format!("{}={}", stringify!($($key).+), arg) }} @ ($($prefix)* x) ($($past)* [$($prefix)*]))
}};

// case 2b - %$next
// case 2a - %$next
($lvl:expr, $static_str:literal @@ {{ $(,)* $($args:expr),* }} @ ($($prefix:tt)*) ($($past:tt)*) $($key:ident).+ = %$next:expr) => {
$crate::try_log!($lvl, $static_str @@ {{ $($args),* , format!("{}={}", stringify!($($key).+), &$next) }} @ ($($prefix)* x) ($($past)* [$($prefix)*]))
};

// case 2c - ?$next
// case 2b - ?$next
($lvl:expr, $static_str:literal @@ {{ $(,)* $($args:expr),* }} @ ($($prefix:tt)*) ($($past:tt)*) $($key:ident).+ = ?$next:expr) => {
$crate::try_log!($lvl, $static_str @@ {{ $($args),* , format!("{}={:?}", stringify!($($key).+), $next) }} @ ($($prefix)* x) ($($past)* [$($prefix)*]))
};

// case 2d - ^$next
($lvl:expr, $static_str:literal @@ {{ $(,)* $($args:expr),* }} @ ($($prefix:tt)*) ($($past:tt)*) $($key:ident).+ = ^$next:expr) => {{
$crate::try_log!($lvl, $static_str @@ {{ $($args),* , lazy_format::lazy_format!("{}={}", stringify!($($key).+), $crate::make_store!($next)) }} @ ($($prefix)* x) ($($past)* [$($prefix)*]))
}};

// case 2e - move $next
// case 2c - $next
($lvl:expr, $static_str:literal @@ {{ $(,)* $($args:expr),* }} @ ($($prefix:tt)*) ($($past:tt)*) $($key:ident).+ = $next:expr) => {
$crate::try_log!($lvl, $static_str @@ {{ $($args),* , lazy_format::lazy_format!("{}={}", stringify!($($key).+), $next) }} @ ($($prefix)* x) ($($past)* [$($prefix)*]))
$crate::try_log!($lvl, $static_str @@ {{ $($args),* , format!("{}={}", stringify!($($key).+), $next) }} @ ($($prefix)* x) ($($past)* [$($prefix)*]))
};

// case 3
Expand Down
Loading