From cc37f604f1e3447d51a19baa7b2851f9cbcde50a Mon Sep 17 00:00:00 2001 From: Avril Date: Wed, 13 Apr 2022 04:09:06 +0100 Subject: [PATCH] Fixed tracing causing huge unneeded bottleneck in non `bytes` builds. MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Fortune for collect's current commit: Future small blessing − 末小吉 --- .gitignore | 1 + Cargo.toml | 7 ++++-- src/buffers.rs | 58 +++++++++++++++++++++++++++++++++++++++----------- src/main.rs | 27 ++++++++++++++++------- 4 files changed, 71 insertions(+), 22 deletions(-) diff --git a/.gitignore b/.gitignore index 667042e..d9a10ac 100644 --- a/.gitignore +++ b/.gitignore @@ -7,3 +7,4 @@ perf.* vgcore.* +collect-* diff --git a/Cargo.toml b/Cargo.toml index 5cb7b24..65a2653 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -6,7 +6,7 @@ edition = "2021" # See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html [features] -default = ["jemalloc"] +default = ["jemalloc", "tracing/release_max_level_warn"] # TODO: mmap, memfd_create() ver @@ -17,6 +17,9 @@ default = ["jemalloc"] # Seems to reduce overall memory usage at the cost of a very small speed drop. jemalloc = ["jemallocator"] +# Remove all tracing points +no-logging = ["tracing/max_level_off"] + [profile.release] opt-level = 3 lto = "fat" @@ -29,7 +32,7 @@ inherits="release" strip=false [dependencies] -bytes = {version = "1.1.0", optional = true } +bytes = { version = "1.1.0", optional = true } color-eyre = { version = "0.6.1", features = ["capture-spantrace"] } jemallocator = { version = "0.3.2", optional = true } libc = "0.2.122" diff --git a/src/buffers.rs b/src/buffers.rs index aecb246..0c8328e 100644 --- a/src/buffers.rs +++ b/src/buffers.rs @@ -85,6 +85,7 @@ const _: () = { impl<'a, B: ?Sized + Buffer> io::Read for BufferReader<'a, B> { #[inline] + #[instrument(level="trace", skip_all, fields(buf = ?buf.len()))] fn read(&mut self, buf: &mut [u8]) -> io::Result { let adv = self.0.copy_to_slice(self.1, buf); self.1 += adv; @@ -95,7 +96,7 @@ impl<'a, B: ?Sized + Buffer> io::Read for BufferReader<'a, B> impl<'a, B: ?Sized + MutBuffer> io::Write for BufferWriter<'a, B> { #[inline] - #[instrument(skip(self))] + #[instrument(level="trace", skip_all, fields(buf = ?buf.len()))] fn write(&mut self, buf: &[u8]) -> io::Result { let adv = self.0.copy_from_slice(self.1, buf); @@ -112,7 +113,8 @@ impl<'a, B: ?Sized + MutBuffer> io::Write for BufferWriter<'a, B> /// An immutable contiguous buffer pub trait Buffer: AsRef<[u8]> { - #[inline] + #[inline] + #[instrument(level="trace", skip_all, fields(buf = ?slice.len()))] fn copy_to_slice(&self, st: usize, slice: &mut [u8]) -> usize { let by = self.as_ref(); @@ -160,7 +162,7 @@ pub trait MutBuffer: AsMut<[u8]> fn freeze(self) -> Self::Frozen; #[inline] - #[instrument(skip(self))] + #[instrument(level="debug", skip_all, fields(st, buflen = ?slice.len()))] fn copy_from_slice(&mut self, st: usize, slice: &[u8]) -> usize { let by = self.as_mut(); @@ -187,13 +189,14 @@ pub trait MutBuffer: AsMut<[u8]> pub trait MutBufferExt: MutBuffer { #[inline(always)] - #[instrument(skip(self))] + #[instrument(level="info", skip(self))] fn writer_from(&mut self, st: usize) -> BufferWriter<'_, Self> { + debug!("creating writer at start {st}"); BufferWriter(self, st) } #[inline] - #[instrument(skip(self))] + //#[instrument(level="info", skip(self))] fn writer(&mut self) -> BufferWriter<'_, Self> { self.writer_from(0) @@ -205,23 +208,44 @@ impl MutBufferExt for B{} impl MutBuffer for bytes::BytesMut { type Frozen = bytes::Bytes; - #[inline(always)] + + #[inline(always)] + #[instrument(level="trace")] fn freeze(self) -> Self::Frozen { bytes::BytesMut::freeze(self) } //TODO: XXX: Impl copy_from_slice() as is done in impl for Vec + /*#[instrument] + fn copy_from_slice(&mut self, st: usize, buf: &[u8]) -> usize + { + //TODO: Special case for `st == 0` maybe? No slicing of the BytesMut might increase perf? Idk. + if (st + buf.len()) <= self.len() { + // We can put `buf` in st..buf.len() + self[st..].copy_from_slice(buf); +} else if st <= self.len() { + // The start is lower but the end is not + let rem = self.len() - st; + self[st..].copy_from_slice(&buf[..rem]); + self.extend_from_slice(&buf[rem..]); +} else { + // it is past the end, extend. + self.extend_from_slice(buf); +} + buf.len() +}*/ } impl MutBuffer for Vec { type Frozen = Box<[u8]>; + #[inline] - #[instrument] + #[instrument(level="trace")] fn freeze(self) -> Self::Frozen { self.into_boxed_slice() } - #[instrument] + #[instrument(level="trace", skip_all, fields(st, buflen = ?buf.len()))] fn copy_from_slice(&mut self, st: usize, buf: &[u8]) -> usize { if (st + buf.len()) <= self.len() { @@ -249,12 +273,16 @@ pub trait WithCapacity: Sized impl WithCapacity for Box<[u8]> { - #[inline(always)] + #[inline(always)] + #[instrument(level="info", fields(cap = "(unbound)"))] fn wc_new() -> Self { + info!("creating new boxed slice with size 0"); Vec::wc_new().into_boxed_slice() } - #[inline(always)] + #[inline(always)] + #[instrument(level="info")] fn wc_with_capacity(cap: usize) -> Self { + info!("creating new boxed slice with size {cap}"); Vec::wc_with_capacity(cap).into_boxed_slice() } } @@ -308,14 +336,18 @@ macro_rules! cap_buffer { ($name:ty) => { impl $crate::buffers::WithCapacity for $name { - #[inline(always)] + #[inline(always)] + #[instrument(level="info", fields(cap = "(unbound)"))] fn wc_new() -> Self { + info!("creating {} with no cap", std::any::type_name::()); Self::new() } - #[inline(always)] + #[inline(always)] + #[instrument(level="info")] fn wc_with_capacity(cap: usize) -> Self { + info!("creating {} with {cap}", std::any::type_name::()); Self::with_capacity(cap) } } @@ -360,5 +392,7 @@ pub mod prelude pub(crate) use cap_buffer; +// cap_buffer impls + #[cfg(feature="bytes")] buffers::cap_buffer!(bytes::BytesMut); cap_buffer!(Vec); diff --git a/src/main.rs b/src/main.rs index 33f5f61..94b6954 100644 --- a/src/main.rs +++ b/src/main.rs @@ -37,6 +37,7 @@ use bytes::{ BufMut, }; +#[instrument(level="debug", skip(reader), fields(reader = ?std::any::type_name::()))] fn try_get_size(reader: &R) -> Option where R: AsRawFd { @@ -70,33 +71,43 @@ fn init() -> eyre::Result<()> use tracing_subscriber::prelude::*; use tracing_subscriber::{fmt, EnvFilter}; - let fmt_layer = fmt::layer().with_target(false); + let fmt_layer = fmt::layer() + .with_target(false) + .with_writer(io::stderr); + let filter_layer = EnvFilter::try_from_default_env() - .or_else(|_| EnvFilter::try_new("info")) + .or_else(|_| EnvFilter::try_new(if cfg!(debug_assertions) { + "info" + } else if cfg!(feature="no-logging") { + "off" + } else { + "warn" + })) .unwrap(); tracing_subscriber::registry() - .with(filter_layer) .with(fmt_layer) + .with(filter_layer) .with(ErrorLayer::default()) .init(); } - - install_tracing(); + + //if !cfg!(feature="no-logging") { + install_tracing(); + //} color_eyre::install() } -#[instrument] +#[instrument(err)] fn main() -> eyre::Result<()> { init()?; - //info!("Initialised"); let (bytes, read) = { let stdin = io::stdin(); let mut bytes: buffers::DefaultMut = try_get_size(&stdin).create_buffer(); - let read = io::copy(&mut stdin.lock(), &mut bytes.writer()) + let read = io::copy(&mut stdin.lock(), &mut (&mut bytes).writer()) .with_section(|| bytes.len().header("Buffer size is")) .with_section(|| bytes.capacity().header("Buffer cap is")) .with_section(|| format!("{:?}", bytes).header("Buffer is"))