From 5a28570e633585729af3df446d917cb0751321e8 Mon Sep 17 00:00:00 2001 From: Remco Bloemen Date: Thu, 3 Apr 2025 13:40:42 +0200 Subject: [PATCH 1/4] Measuring allocator and span statistics --- noir-r1cs/src/main.rs | 102 +++++++++++++++++++++++++++++++++++++++--- 1 file changed, 96 insertions(+), 6 deletions(-) diff --git a/noir-r1cs/src/main.rs b/noir-r1cs/src/main.rs index 8c5f108c0..653a659d2 100644 --- a/noir-r1cs/src/main.rs +++ b/noir-r1cs/src/main.rs @@ -5,8 +5,12 @@ use { self::cmd::Command, anyhow::Result, std::{ + alloc::{GlobalAlloc, Layout, System as SystemAlloc}, fmt::{Display, Formatter}, - sync::{Arc, Mutex}, + sync::{ + atomic::{AtomicUsize, Ordering}, + Arc, Mutex, + }, time::Instant, }, tracing::{span, Subscriber}, @@ -18,6 +22,29 @@ use { }, }; +#[global_allocator] +static ALLOC: MeasuringAllocator = MeasuringAllocator::new(); + +/// Custom allocator that keeps track of statistics to see program memory +/// consumption. +struct MeasuringAllocator { + current: AtomicUsize, + max: AtomicUsize, + count: AtomicUsize, +} + +/// Logging layer that keeps track of time and memory consumption. +struct DurationLayer { + start: Arc>>, +} + +struct SpanStart { + time: Instant, + memory: usize, + max: usize, + allocations: usize, +} + fn main() -> Result<()> { let fmt_layer = fmt::Layer::default(); let subscriber = Registry::default() @@ -30,8 +57,46 @@ fn main() -> Result<()> { args.run() } -struct DurationLayer { - start: Arc>>, +impl MeasuringAllocator { + const fn new() -> Self { + Self { + current: AtomicUsize::new(0), + max: AtomicUsize::new(0), + count: AtomicUsize::new(0), + } + } + + fn current(&self) -> usize { + self.current.load(Ordering::SeqCst) + } + + fn max(&self) -> usize { + self.max.load(Ordering::SeqCst) + } + + fn reset_max(&self) { + self.max.store(self.current(), Ordering::SeqCst); + } + + fn count(&self) -> usize { + self.count.load(Ordering::SeqCst) + } +} + +#[allow(unsafe_code)] +unsafe impl GlobalAlloc for MeasuringAllocator { + unsafe fn alloc(&self, layout: Layout) -> *mut u8 { + // We just ignore the race conditions here... + let prev = self.current.fetch_add(layout.size(), Ordering::SeqCst); + self.max.fetch_max(prev + layout.size(), Ordering::SeqCst); + self.count.fetch_add(1, Ordering::SeqCst); + SystemAlloc.alloc(layout) + } + + unsafe fn dealloc(&self, ptr: *mut u8, layout: Layout) { + self.current.fetch_sub(layout.size(), Ordering::SeqCst); + SystemAlloc.dealloc(ptr, layout) + } } impl DurationLayer { @@ -49,7 +114,21 @@ where fn on_enter(&self, id: &span::Id, ctx: Context<'_, S>) { let mut lock = self.start.lock().unwrap(); let depth = lock.len(); - lock.push(Instant::now()); + + // Propagate current max down the stack. + let max = ALLOC.max(); + for entry in lock.iter_mut() { + entry.max = std::cmp::max(entry.max, max); + } + ALLOC.reset_max(); + + lock.push(SpanStart { + time: Instant::now(), + memory: ALLOC.current(), + max: ALLOC.current(), + allocations: ALLOC.count(), + }); + let span = ctx.span(id).expect("expected: span id exists in registry"); for _ in 0..depth { @@ -62,7 +141,12 @@ where fn on_exit(&self, id: &span::Id, ctx: Context<'_, S>) { let mut lock = self.start.lock().unwrap(); let depth = lock.len(); - let duration = lock.pop().expect("expected: start time exists").elapsed(); + let start = lock.pop().expect("expected: start time exists"); + + let duration = start.time.elapsed(); + let max = std::cmp::max(ALLOC.max(), start.max); + let allocations = ALLOC.count() - start.allocations; + let own = max - start.memory; let _span: tracing_subscriber::registry::SpanRef<'_, S> = ctx.span(id).expect("expected: span id exists in registry"); @@ -71,7 +155,13 @@ where eprint!("│ "); } - eprintln!("├─╯ {}s", human(duration.as_secs_f64())); + eprintln!( + "├─╯ took {}s, {} allocations, {}B peak memory, {}B own memory", + human(duration.as_secs_f64()), + human(allocations as f64), + human(max as f64), + human(own as f64) + ); } } From 32a7df1fe4a231f0e42561bb954e6cfb8bf21659 Mon Sep 17 00:00:00 2001 From: Remco Bloemen Date: Thu, 3 Apr 2025 15:08:57 +0200 Subject: [PATCH 2/4] Print memory stats --- Cargo.toml | 13 +- noir-r1cs/Cargo.toml | 23 ++- noir-r1cs/src/{ => bin}/cmd/circuit_stats.rs | 0 noir-r1cs/src/{ => bin}/cmd/mod.rs | 0 noir-r1cs/src/{ => bin}/cmd/prepare.rs | 0 noir-r1cs/src/{ => bin}/cmd/prove.rs | 0 noir-r1cs/src/bin/main.rs | 23 +++ noir-r1cs/src/bin/measuring_alloc.rs | 56 ++++++ noir-r1cs/src/bin/span_stats.rs | 157 +++++++++++++++ noir-r1cs/src/main.rs | 194 ------------------- 10 files changed, 255 insertions(+), 211 deletions(-) rename noir-r1cs/src/{ => bin}/cmd/circuit_stats.rs (100%) rename noir-r1cs/src/{ => bin}/cmd/mod.rs (100%) rename noir-r1cs/src/{ => bin}/cmd/prepare.rs (100%) rename noir-r1cs/src/{ => bin}/cmd/prove.rs (100%) create mode 100644 noir-r1cs/src/bin/main.rs create mode 100644 noir-r1cs/src/bin/measuring_alloc.rs create mode 100644 noir-r1cs/src/bin/span_stats.rs delete mode 100644 noir-r1cs/src/main.rs diff --git a/Cargo.toml b/Cargo.toml index 0e76f372d..b0a6bbf58 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -41,13 +41,8 @@ opt-level = 2 opt-level = 3 [workspace.dependencies] -anyhow = "1.0.93" -argh = "0.1.12" -clap = { version = "4.4", features = ["derive"] } serde = { version = "1.0", features = ["derive"] } serde_json = "1.0" -tracing = "0.1.41" -tracing-subscriber = { version = "0.3.18", features = ["env-filter", "ansi"] } base64 = "0.22.1" ruint = { version = "1.12.3", features = ["num-traits", "rand"] } rand = "0.8.5" @@ -82,5 +77,13 @@ ark-poly = "0.5" ark-std = { version = "0.5", features = ["std"] } ark-serialize = "0.5" +# Bin +anyhow = "1.0.93" +argh = "0.1.12" +tracing = "0.1.41" +tracing-subscriber = { version = "0.3.18", features = ["env-filter", "ansi"] } +nu-ansi-term = "0.46.0" + + [patch.crates-io] ruint = { git = "https://github.com/recmo/uint", branch = "main" } diff --git a/noir-r1cs/Cargo.toml b/noir-r1cs/Cargo.toml index 84a58f766..93ca89e1f 100644 --- a/noir-r1cs/Cargo.toml +++ b/noir-r1cs/Cargo.toml @@ -6,15 +6,14 @@ edition = "2021" [lints] workspace = true +[[bin]] +name = "noir-r1cs" +path = "src/bin/main.rs" + [dependencies] -argh.workspace = true serde.workspace = true serde_json.workspace = true -anyhow.workspace = true -tracing.workspace = true -tracing-subscriber.workspace = true base64.workspace = true -clap.workspace = true zeroize.workspace = true itertools.workspace = true ruint.workspace = true @@ -42,10 +41,10 @@ ark-poly.workspace = true ark-std.workspace = true ark-serialize.workspace = true -[[bin]] -name = "circuit_stats" -path = "src/bin/circuit_stats.rs" - -[[bin]] -name = "prover" -path = "src/bin/prover.rs" +# Binary +# See +argh.workspace = true +anyhow.workspace = true +tracing.workspace = true +tracing-subscriber.workspace = true +nu-ansi-term.workspace = true diff --git a/noir-r1cs/src/cmd/circuit_stats.rs b/noir-r1cs/src/bin/cmd/circuit_stats.rs similarity index 100% rename from noir-r1cs/src/cmd/circuit_stats.rs rename to noir-r1cs/src/bin/cmd/circuit_stats.rs diff --git a/noir-r1cs/src/cmd/mod.rs b/noir-r1cs/src/bin/cmd/mod.rs similarity index 100% rename from noir-r1cs/src/cmd/mod.rs rename to noir-r1cs/src/bin/cmd/mod.rs diff --git a/noir-r1cs/src/cmd/prepare.rs b/noir-r1cs/src/bin/cmd/prepare.rs similarity index 100% rename from noir-r1cs/src/cmd/prepare.rs rename to noir-r1cs/src/bin/cmd/prepare.rs diff --git a/noir-r1cs/src/cmd/prove.rs b/noir-r1cs/src/bin/cmd/prove.rs similarity index 100% rename from noir-r1cs/src/cmd/prove.rs rename to noir-r1cs/src/bin/cmd/prove.rs diff --git a/noir-r1cs/src/bin/main.rs b/noir-r1cs/src/bin/main.rs new file mode 100644 index 000000000..4ee420e32 --- /dev/null +++ b/noir-r1cs/src/bin/main.rs @@ -0,0 +1,23 @@ +#![allow(missing_docs)] +mod cmd; +mod measuring_alloc; +mod span_stats; + +use { + self::{cmd::Command, measuring_alloc::MeasuringAllocator, span_stats::SpanStats}, + anyhow::Result, + tracing_subscriber::{self, fmt, layer::SubscriberExt as _, Registry}, +}; + +#[global_allocator] +static ALLOC: MeasuringAllocator = MeasuringAllocator::new(); + +fn main() -> Result<()> { + let fmt_layer = fmt::Layer::default(); + let subscriber = Registry::default().with(fmt_layer).with(SpanStats::new()); + tracing::subscriber::set_global_default(subscriber)?; + + // Run CLI command + let args = argh::from_env::(); + args.run() +} diff --git a/noir-r1cs/src/bin/measuring_alloc.rs b/noir-r1cs/src/bin/measuring_alloc.rs new file mode 100644 index 000000000..a28830e28 --- /dev/null +++ b/noir-r1cs/src/bin/measuring_alloc.rs @@ -0,0 +1,56 @@ +use std::{ + alloc::{GlobalAlloc, Layout, System as SystemAlloc}, + sync::atomic::{AtomicUsize, Ordering}, +}; + +/// Custom allocator that keeps track of statistics to see program memory +/// consumption. +pub struct MeasuringAllocator { + current: AtomicUsize, + max: AtomicUsize, + count: AtomicUsize, +} + +impl MeasuringAllocator { + pub const fn new() -> Self { + Self { + current: AtomicUsize::new(0), + max: AtomicUsize::new(0), + count: AtomicUsize::new(0), + } + } + + pub fn current(&self) -> usize { + self.current.load(Ordering::SeqCst) + } + + pub fn max(&self) -> usize { + self.max.load(Ordering::SeqCst) + } + + pub fn reset_max(&self) -> usize { + let current = self.current(); + self.max.store(current, Ordering::SeqCst); + current + } + + pub fn count(&self) -> usize { + self.count.load(Ordering::SeqCst) + } +} + +#[allow(unsafe_code)] +unsafe impl GlobalAlloc for MeasuringAllocator { + unsafe fn alloc(&self, layout: Layout) -> *mut u8 { + // We just ignore the race conditions here... + let prev = self.current.fetch_add(layout.size(), Ordering::SeqCst); + self.max.fetch_max(prev + layout.size(), Ordering::SeqCst); + self.count.fetch_add(1, Ordering::SeqCst); + SystemAlloc.alloc(layout) + } + + unsafe fn dealloc(&self, ptr: *mut u8, layout: Layout) { + self.current.fetch_sub(layout.size(), Ordering::SeqCst); + SystemAlloc.dealloc(ptr, layout) + } +} diff --git a/noir-r1cs/src/bin/span_stats.rs b/noir-r1cs/src/bin/span_stats.rs new file mode 100644 index 000000000..0f2650cbc --- /dev/null +++ b/noir-r1cs/src/bin/span_stats.rs @@ -0,0 +1,157 @@ +//! Using `tracing` spans to print performance statistics for the program. +//! +//! NOTE: This module is only included in the bin, not in the lib. +use { + crate::ALLOC, + nu_ansi_term::{Color, Style}, + std::{ + fmt::{Display, Formatter, Write as _}, + sync::{Arc, Mutex}, + time::Instant, + }, + tracing::{span, Subscriber}, + tracing_subscriber::{self, layer::Context, registry::LookupSpan, Layer}, +}; + +const BOLD: &'static str = "\x1b[1m"; +const UNBOLD: &'static str = "\x1b[22m"; + +/// Logging layer that keeps track of time and memory consumption of spans. +pub struct SpanStats { + start: Arc>>, +} + +/// Statistics at start of the span. +struct SpanStart { + time: Instant, + memory: usize, + allocations: usize, + + /// `peak_memory` will be updated as it is not monotonic + peak_memory: usize, +} + +impl SpanStats { + pub fn new() -> Self { + Self { + start: Arc::new(Mutex::new(Vec::new())), + } + } +} + +impl Layer for SpanStats +where + S: Subscriber + for<'span> LookupSpan<'span>, +{ + fn on_enter(&self, id: &span::Id, ctx: Context<'_, S>) { + let mut lock = self.start.lock().unwrap(); + let depth = lock.len(); + + // Propagate current max down the stack. + let peak_memory = ALLOC.max(); + for entry in lock.iter_mut() { + entry.peak_memory = std::cmp::max(entry.peak_memory, peak_memory); + } + let current = ALLOC.reset_max(); // Reset so we can measure the new span. + + // Add the new span stats entry + lock.push(SpanStart { + time: Instant::now(), + memory: current, + allocations: ALLOC.count(), + peak_memory: current, + }); + + let span = ctx.span(id).expect("expected: span id exists in registry"); + + let mut buffer = String::with_capacity(100); + + // Box draw tree indentation + if depth >= 1 { + for _ in 0..(depth - 1) { + let _ = write!(&mut buffer, "│ "); + } + let _ = write!(&mut buffer, "├─"); + } + let _ = write!(&mut buffer, "╮ "); + + // Span name + let _ = write!( + &mut buffer, + "{}::{BOLD}{}{UNBOLD}", + span.metadata().target(), + span.metadata().name() + ); + + eprintln!("{}", buffer); + } + + fn on_exit(&self, id: &span::Id, ctx: Context<'_, S>) { + let mut lock = self.start.lock().unwrap(); + let depth = lock.len() - 1; + let start = lock.pop().expect("expected: start time exists"); + + let duration = start.time.elapsed(); + let peak_memory: usize = std::cmp::max(ALLOC.max(), start.peak_memory); + let allocations = ALLOC.count() - start.allocations; + let own = peak_memory - start.memory; + + let span: tracing_subscriber::registry::SpanRef<'_, S> = + ctx.span(id).expect("expected: span id exists in registry"); + + let mut buffer = String::with_capacity(100); + + // Box draw tree indentation + if depth >= 1 { + for _ in 0..(depth - 1) { + let _ = write!(&mut buffer, "│ "); + } + let _ = write!(&mut buffer, "├─"); + } + let _ = write!(&mut buffer, "╯ "); + + // Short span name + let _ = write!(&mut buffer, "{}: ", span.metadata().name()); + + // Print stats + let _ = write!( + &mut buffer, + "duration {BOLD}{}s{UNBOLD}, {BOLD}{}B{UNBOLD} peak memory, {BOLD}{}B{UNBOLD} local, \ + {BOLD}{:#}{UNBOLD} allocations", + human(duration.as_secs_f64()), + human(peak_memory as f64), + human(own as f64), + human(allocations as f64) + ); + + eprintln!("{}", buffer); + } +} + +/// Pretty print a float using SI-prefixes. +pub fn human(value: f64) -> impl Display { + pub struct Human(f64); + impl Display for Human { + fn fmt(&self, f: &mut Formatter) -> std::fmt::Result { + let log10 = if self.0.is_normal() { + self.0.abs().log10() + } else { + 0.0 + }; + let si_power = ((log10 / 3.0).floor() as isize).clamp(-10, 10); + let value = self.0 * 10_f64.powi((-si_power * 3) as i32); + let digits = f.precision().unwrap_or(3) - 1 - (log10 - 3.0 * si_power as f64) as usize; + let separator = if f.alternate() { "" } else { "\u{202F}" }; + write!(f, "{value:.digits$}{separator}")?; + let suffix = "qryzafpnμm kMGTPEZYRQ" + .chars() + .nth((si_power + 10) as usize) + .unwrap(); + if suffix != ' ' { + write!(f, "{suffix}")?; + } + Ok(()) + } + } + Human(value) +} diff --git a/noir-r1cs/src/main.rs b/noir-r1cs/src/main.rs deleted file mode 100644 index 653a659d2..000000000 --- a/noir-r1cs/src/main.rs +++ /dev/null @@ -1,194 +0,0 @@ -#![doc = include_str!("../README.md")] -mod cmd; - -use { - self::cmd::Command, - anyhow::Result, - std::{ - alloc::{GlobalAlloc, Layout, System as SystemAlloc}, - fmt::{Display, Formatter}, - sync::{ - atomic::{AtomicUsize, Ordering}, - Arc, Mutex, - }, - time::Instant, - }, - tracing::{span, Subscriber}, - tracing_subscriber::{ - self, fmt, - layer::{Context, SubscriberExt as _}, - registry::LookupSpan, - Layer, Registry, - }, -}; - -#[global_allocator] -static ALLOC: MeasuringAllocator = MeasuringAllocator::new(); - -/// Custom allocator that keeps track of statistics to see program memory -/// consumption. -struct MeasuringAllocator { - current: AtomicUsize, - max: AtomicUsize, - count: AtomicUsize, -} - -/// Logging layer that keeps track of time and memory consumption. -struct DurationLayer { - start: Arc>>, -} - -struct SpanStart { - time: Instant, - memory: usize, - max: usize, - allocations: usize, -} - -fn main() -> Result<()> { - let fmt_layer = fmt::Layer::default(); - let subscriber = Registry::default() - .with(fmt_layer) - .with(DurationLayer::new()); - tracing::subscriber::set_global_default(subscriber)?; - - // Run CLI command - let args = argh::from_env::(); - args.run() -} - -impl MeasuringAllocator { - const fn new() -> Self { - Self { - current: AtomicUsize::new(0), - max: AtomicUsize::new(0), - count: AtomicUsize::new(0), - } - } - - fn current(&self) -> usize { - self.current.load(Ordering::SeqCst) - } - - fn max(&self) -> usize { - self.max.load(Ordering::SeqCst) - } - - fn reset_max(&self) { - self.max.store(self.current(), Ordering::SeqCst); - } - - fn count(&self) -> usize { - self.count.load(Ordering::SeqCst) - } -} - -#[allow(unsafe_code)] -unsafe impl GlobalAlloc for MeasuringAllocator { - unsafe fn alloc(&self, layout: Layout) -> *mut u8 { - // We just ignore the race conditions here... - let prev = self.current.fetch_add(layout.size(), Ordering::SeqCst); - self.max.fetch_max(prev + layout.size(), Ordering::SeqCst); - self.count.fetch_add(1, Ordering::SeqCst); - SystemAlloc.alloc(layout) - } - - unsafe fn dealloc(&self, ptr: *mut u8, layout: Layout) { - self.current.fetch_sub(layout.size(), Ordering::SeqCst); - SystemAlloc.dealloc(ptr, layout) - } -} - -impl DurationLayer { - fn new() -> Self { - Self { - start: Arc::new(Mutex::new(Vec::new())), - } - } -} - -impl Layer for DurationLayer -where - S: Subscriber + for<'span> LookupSpan<'span>, -{ - fn on_enter(&self, id: &span::Id, ctx: Context<'_, S>) { - let mut lock = self.start.lock().unwrap(); - let depth = lock.len(); - - // Propagate current max down the stack. - let max = ALLOC.max(); - for entry in lock.iter_mut() { - entry.max = std::cmp::max(entry.max, max); - } - ALLOC.reset_max(); - - lock.push(SpanStart { - time: Instant::now(), - memory: ALLOC.current(), - max: ALLOC.current(), - allocations: ALLOC.count(), - }); - - let span = ctx.span(id).expect("expected: span id exists in registry"); - - for _ in 0..depth { - eprint!("│ "); - } - - eprintln!("├─╮ {}", span.name()); - } - - fn on_exit(&self, id: &span::Id, ctx: Context<'_, S>) { - let mut lock = self.start.lock().unwrap(); - let depth = lock.len(); - let start = lock.pop().expect("expected: start time exists"); - - let duration = start.time.elapsed(); - let max = std::cmp::max(ALLOC.max(), start.max); - let allocations = ALLOC.count() - start.allocations; - let own = max - start.memory; - - let _span: tracing_subscriber::registry::SpanRef<'_, S> = - ctx.span(id).expect("expected: span id exists in registry"); - - for _ in 0..(depth - 1) { - eprint!("│ "); - } - - eprintln!( - "├─╯ took {}s, {} allocations, {}B peak memory, {}B own memory", - human(duration.as_secs_f64()), - human(allocations as f64), - human(max as f64), - human(own as f64) - ); - } -} - -/// Pretty print a float using SI-prefixes. -pub fn human(value: f64) -> impl Display { - pub struct Human(f64); - impl Display for Human { - fn fmt(&self, f: &mut Formatter) -> std::fmt::Result { - let log10 = if self.0.is_normal() { - self.0.abs().log10() - } else { - 0.0 - }; - let si_power = ((log10 / 3.0).floor() as isize).clamp(-10, 10); - let value = self.0 * 10_f64.powi((-si_power * 3) as i32); - let digits = f.precision().unwrap_or(3) - 1 - (log10 - 3.0 * si_power as f64) as usize; - let separator = if f.alternate() { "" } else { "\u{202F}" }; - write!(f, "{value:.digits$}{separator}")?; - let suffix = "qryzafpnμm kMGTPEZYRQ" - .chars() - .nth((si_power + 10) as usize) - .unwrap(); - if suffix != ' ' { - write!(f, "{suffix}")?; - } - Ok(()) - } - } - Human(value) -} From 611bb72a90b6f9ca7e1dd67cddc3565aa2fcb38c Mon Sep 17 00:00:00 2001 From: Remco Bloemen Date: Thu, 3 Apr 2025 17:29:16 +0200 Subject: [PATCH 3/4] Polish span subscriber --- noir-r1cs/src/bin/main.rs | 3 +- noir-r1cs/src/bin/span_stats.rs | 198 +++++++++++++++++++++-------- noir-r1cs/src/noir_proof_scheme.rs | 16 ++- 3 files changed, 158 insertions(+), 59 deletions(-) diff --git a/noir-r1cs/src/bin/main.rs b/noir-r1cs/src/bin/main.rs index 4ee420e32..092603a3f 100644 --- a/noir-r1cs/src/bin/main.rs +++ b/noir-r1cs/src/bin/main.rs @@ -13,8 +13,7 @@ use { static ALLOC: MeasuringAllocator = MeasuringAllocator::new(); fn main() -> Result<()> { - let fmt_layer = fmt::Layer::default(); - let subscriber = Registry::default().with(fmt_layer).with(SpanStats::new()); + let subscriber = Registry::default().with(SpanStats); tracing::subscriber::set_global_default(subscriber)?; // Run CLI command diff --git a/noir-r1cs/src/bin/span_stats.rs b/noir-r1cs/src/bin/span_stats.rs index 0f2650cbc..f3fbe54c2 100644 --- a/noir-r1cs/src/bin/span_stats.rs +++ b/noir-r1cs/src/bin/span_stats.rs @@ -5,70 +5,113 @@ use { crate::ALLOC, nu_ansi_term::{Color, Style}, std::{ - fmt::{Display, Formatter, Write as _}, + fmt::{self, Display, Formatter, Write as _}, sync::{Arc, Mutex}, time::Instant, }, - tracing::{span, Subscriber}, + tracing::{ + field::{Field, Visit}, + span::{self, Attributes, Id}, + Level, Subscriber, + }, tracing_subscriber::{self, layer::Context, registry::LookupSpan, Layer}, }; -const BOLD: &'static str = "\x1b[1m"; -const UNBOLD: &'static str = "\x1b[22m"; +const DIM: &'static str = "\x1b[2m"; +const UNDIM: &'static str = "\x1b[22m"; -/// Logging layer that keeps track of time and memory consumption of spans. -pub struct SpanStats { - start: Arc>>, -} - -/// Statistics at start of the span. -struct SpanStart { +// Span extension data +pub(crate) struct Data { + depth: usize, time: Instant, memory: usize, allocations: usize, /// `peak_memory` will be updated as it is not monotonic peak_memory: usize, + children: bool, + kvs: Vec<(&'static str, String)>, +} + +impl Data { + pub fn new(attrs: &Attributes<'_>, depth: usize) -> Self { + let mut span = Self { + depth, + time: Instant::now(), + memory: ALLOC.current(), + allocations: ALLOC.count(), + peak_memory: ALLOC.current(), + children: false, + kvs: Vec::new(), + }; + attrs.record(&mut span); + span + } +} + +impl Visit for Data { + fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { + self.kvs.push((field.name(), format!("{:?}", value))) + } } -impl SpanStats { - pub fn new() -> Self { - Self { - start: Arc::new(Mutex::new(Vec::new())), +pub struct FmtEvent<'a>(&'a mut String); + +impl<'a> Visit for FmtEvent<'a> { + fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { + match field.name() { + "message" => { + write!(self.0, " {:?}", value).unwrap(); + } + name => { + write!(self.0, " {}={:?}", name, value).unwrap(); + } } } } +/// Logging layer that keeps track of time and memory consumption of spans. +pub struct SpanStats; + impl Layer for SpanStats where S: Subscriber + for<'span> LookupSpan<'span>, { - fn on_enter(&self, id: &span::Id, ctx: Context<'_, S>) { - let mut lock = self.start.lock().unwrap(); - let depth = lock.len(); - - // Propagate current max down the stack. - let peak_memory = ALLOC.max(); - for entry in lock.iter_mut() { - entry.peak_memory = std::cmp::max(entry.peak_memory, peak_memory); + fn on_new_span(&self, attrs: &Attributes, id: &Id, ctx: Context) { + let span = ctx.span(id).expect("invalid span in on_new_span"); + + // Add Data if it hasn't already + if span.extensions().get::().is_none() { + let depth = span + .parent() + .map(|s| { + s.extensions() + .get::() + .expect("parent span has no data") + .depth + + 1 + }) + .unwrap_or(0); + let data = Data::new(attrs, depth); + span.extensions_mut().insert(data); } - let current = ALLOC.reset_max(); // Reset so we can measure the new span. - // Add the new span stats entry - lock.push(SpanStart { - time: Instant::now(), - memory: current, - allocations: ALLOC.count(), - peak_memory: current, - }); + // Flag child on parent + if let Some(parent) = span.parent() { + if let Some(data) = parent.extensions_mut().get_mut::() { + data.children = true; + } + } - let span = ctx.span(id).expect("expected: span id exists in registry"); + // Fetch data + let ext = span.extensions(); + let data = ext.get::().expect("span does not have data"); let mut buffer = String::with_capacity(100); // Box draw tree indentation - if depth >= 1 { - for _ in 0..(depth - 1) { + if data.depth >= 1 { + for _ in 0..(data.depth - 1) { let _ = write!(&mut buffer, "│ "); } let _ = write!(&mut buffer, "├─"); @@ -78,46 +121,96 @@ where // Span name let _ = write!( &mut buffer, - "{}::{BOLD}{}{UNBOLD}", + "{DIM}{}::{UNDIM}{}", span.metadata().target(), span.metadata().name() ); + // KV args + for (key, val) in &data.kvs { + let _ = write!(&mut buffer, " {}={}", key, val); + } + eprintln!("{}", buffer); } - fn on_exit(&self, id: &span::Id, ctx: Context<'_, S>) { - let mut lock = self.start.lock().unwrap(); - let depth = lock.len() - 1; - let start = lock.pop().expect("expected: start time exists"); + fn on_event(&self, event: &tracing::Event<'_>, ctx: Context<'_, S>) { + let span = ctx.current_span().id().and_then(|id| ctx.span(id)); + + let mut buffer = String::with_capacity(100); + + // Span indentation + time in span + if let Some(span) = &span { + // Flag child on parent + if let Some(parent) = span.parent() { + if let Some(data) = parent.extensions_mut().get_mut::() { + data.children = true; + } + } + + if let Some(data) = span.extensions().get::() { + // Box draw tree indentation + for _ in 0..(data.depth + 1) { + let _ = write!(&mut buffer, "│ "); + } + + // Time + let elapsed = data.time.elapsed(); + let _ = write!( + &mut buffer, + "{DIM}{:6}s {UNDIM}", + human(elapsed.as_secs_f64()) + ); + } + } + + // Log level + match *event.metadata().level() { + Level::TRACE => write!(&mut buffer, "TRACE"), + Level::DEBUG => write!(&mut buffer, "DEBUG"), + Level::INFO => write!(&mut buffer, "\x1b[1;32mINFO\x1b[0m"), + Level::WARN => write!(&mut buffer, "\x1b[1;38;5;208mWARN\x1b[0m"), + Level::ERROR => write!(&mut buffer, "\x1b[1;31mERROR\x1b[0m"), + } + .unwrap(); - let duration = start.time.elapsed(); - let peak_memory: usize = std::cmp::max(ALLOC.max(), start.peak_memory); - let allocations = ALLOC.count() - start.allocations; - let own = peak_memory - start.memory; + let mut visitor = FmtEvent(&mut buffer); + event.record(&mut visitor); - let span: tracing_subscriber::registry::SpanRef<'_, S> = - ctx.span(id).expect("expected: span id exists in registry"); + eprintln!("{}", buffer); + } + + fn on_close(&self, id: Id, ctx: Context) { + let span = ctx.span(&id).expect("invalid span in on_close"); + let ext = span.extensions(); + let data = ext.get::().expect("span does not have data"); + + let duration = data.time.elapsed(); + let peak_memory: usize = std::cmp::max(ALLOC.max(), data.peak_memory); + let allocations = ALLOC.count() - data.allocations; + let own = peak_memory - data.memory; let mut buffer = String::with_capacity(100); // Box draw tree indentation - if depth >= 1 { - for _ in 0..(depth - 1) { + if data.depth >= 1 { + for _ in 0..(data.depth - 1) { let _ = write!(&mut buffer, "│ "); } let _ = write!(&mut buffer, "├─"); } let _ = write!(&mut buffer, "╯ "); - // Short span name - let _ = write!(&mut buffer, "{}: ", span.metadata().name()); + // Short span name if not childless + if data.children { + let _ = write!(&mut buffer, "{DIM}{}: {UNDIM}", span.metadata().name()); + } // Print stats let _ = write!( &mut buffer, - "duration {BOLD}{}s{UNBOLD}, {BOLD}{}B{UNBOLD} peak memory, {BOLD}{}B{UNBOLD} local, \ - {BOLD}{:#}{UNBOLD} allocations", + "{}s{DIM} duration, {UNDIM}{}B{DIM} peak memory, {UNDIM}{}B{DIM} local, \ + {UNDIM}{:#}{DIM} allocations{UNDIM}", human(duration.as_secs_f64()), human(peak_memory as f64), human(own as f64), @@ -142,6 +235,9 @@ pub fn human(value: f64) -> impl Display { let value = self.0 * 10_f64.powi((-si_power * 3) as i32); let digits = f.precision().unwrap_or(3) - 1 - (log10 - 3.0 * si_power as f64) as usize; let separator = if f.alternate() { "" } else { "\u{202F}" }; + if f.width() == Some(6) && digits == 0 { + write!(f, " ")?; + } write!(f, "{value:.digits$}{separator}")?; let suffix = "qryzafpnμm kMGTPEZYRQ" .chars() diff --git a/noir-r1cs/src/noir_proof_scheme.rs b/noir-r1cs/src/noir_proof_scheme.rs index 052890c73..9995787b2 100644 --- a/noir-r1cs/src/noir_proof_scheme.rs +++ b/noir-r1cs/src/noir_proof_scheme.rs @@ -26,11 +26,16 @@ pub struct NoirProof { } impl NoirProofScheme { - #[instrument(skip_all)] + #[instrument()] pub fn from_file(path: &Path) -> Result { let program = { - let _span = span!(Level::INFO, "serde_json").entered(); let file = File::open(path).context("while opening Noir program")?; + let _span = span!( + Level::INFO, + "serde_json", + size = file.metadata().map(|m| m.len()).ok(), + ) + .entered(); serde_json::from_reader(file).context("while reading Noir program")? }; Self::from_program(&program) @@ -77,10 +82,9 @@ impl NoirProofScheme { }) } - #[instrument(skip_all)] + #[instrument(skip_all, fields(size=input_toml.len()))] pub fn prove(&self, input_toml: &str) -> Result { - let span = span!(Level::INFO, "generate_witness"); - let enter = span.enter(); + let span = span!(Level::INFO, "generate_witness").entered(); // Create witness for provided input let input = self @@ -102,7 +106,7 @@ impl NoirProofScheme { self.r1cs .verify_witness(&witness) .context("While verifying R1CS instance")?; - drop(enter); + drop(span); // Prove R1CS instance let whir_r1cs_proof = self From a009158e05f9ffed5b7a38b73928655073dc6976 Mon Sep 17 00:00:00 2001 From: Remco Bloemen Date: Thu, 3 Apr 2025 17:31:18 +0200 Subject: [PATCH 4/4] use log --- noir-r1cs/src/noir_witness.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/noir-r1cs/src/noir_witness.rs b/noir-r1cs/src/noir_witness.rs index 7c4a848b3..95bfebedd 100644 --- a/noir-r1cs/src/noir_witness.rs +++ b/noir-r1cs/src/noir_witness.rs @@ -12,7 +12,7 @@ use { noirc_abi::{input_parser::Format, Abi}, noirc_artifacts::program::ProgramArtifact, std::collections::BTreeMap, - tracing::instrument, + tracing::{info, instrument}, }; #[derive(Clone, Debug)] @@ -88,7 +88,7 @@ fn generate_noir_witness( ACVMStatus::RequiresForeignCall(info) => { let result = match info.function.as_str() { "print" => { - eprintln!("NOIR PRINT: {:?}", info.inputs); + info!("NOIR PRINT: {:?}", info.inputs); Ok(ForeignCallResult::default()) } name => Err(anyhow!(