Merge pull request #3282 from TheBlueMatt/2024-08-fix-bench-logging

Dont output logs when benchmarking

Author: TheBlueMatt

lightning-rapid-gossip-sync/src/processing.rs

@@ -476,7 +476,6 @@ mod tests {
 	use lightning::ln::msgs::DecodeError;
 
 	use lightning::routing::gossip::{NetworkGraph, NodeId};
-	use lightning::util::logger::Level;
 	use lightning::util::test_utils::TestLogger;
 
 	use crate::processing::STALE_RGS_UPDATE_AGE_LIMIT_SECS;
@@ -534,8 +533,7 @@ mod tests {
 
 	#[test]
 	fn node_data_update_succeeds_with_v2() {
-		let mut logger = TestLogger::new();
-		logger.enable(Level::Gossip);
+		let logger = TestLogger::new();
 		let network_graph = NetworkGraph::new(Network::Bitcoin, &logger);
 
 		let example_input = vec![
@@ -597,8 +595,7 @@ mod tests {
 
 	#[test]
 	fn node_date_update_succeeds_without_channels() {
-		let mut logger = TestLogger::new();
-		logger.enable(Level::Gossip);
+		let logger = TestLogger::new();
 		let network_graph = NetworkGraph::new(Network::Bitcoin, &logger);
 		let rapid_sync = RapidGossipSync::new(&network_graph, &logger);
 
@@ -626,8 +623,7 @@ mod tests {
 
 	#[test]
 	fn update_ignores_v2_additional_data() {
-		let mut logger = TestLogger::new();
-		logger.enable(Level::Gossip);
+		let logger = TestLogger::new();
 		let network_graph = NetworkGraph::new(Network::Bitcoin, &logger);
 		let rapid_sync = RapidGossipSync::new(&network_graph, &logger);
 

lightning/src/util/logger.rs

@@ -294,8 +294,7 @@ mod tests {
 
 	#[test]
 	fn test_logging_macros() {
-		let mut logger = TestLogger::new();
-		logger.enable(Level::Gossip);
+		let logger = TestLogger::new();
 		let logger : Arc<dyn Logger> = Arc::new(logger);
 		let wrapper = WrapperLog::new(Arc::clone(&logger));
 		wrapper.call_macros();

lightning/src/util/test_utils.rs

@@ -43,7 +43,7 @@ use crate::routing::scoring::{ChannelUsage, ScoreUpdate, ScoreLookUp};
 use crate::sync::RwLock;
 use crate::util::config::UserConfig;
 use crate::util::test_channel_signer::{TestChannelSigner, EnforcementState};
-use crate::util::logger::{Logger, Level, Record};
+use crate::util::logger::{Logger, Record};
 use crate::util::ser::{Readable, ReadableArgs, Writer, Writeable};
 use crate::util::persist::KVStore;
 
@@ -1117,7 +1117,6 @@ impl events::MessageSendEventsProvider for TestRoutingMessageHandler {
 }
 
 pub struct TestLogger {
-	level: Level,
 	pub(crate) id: String,
 	pub lines: Mutex<HashMap<(&'static str, String), usize>>,
 	pub context: Mutex<HashMap<(&'static str, Option<PublicKey>, Option<ChannelId>), usize>>,
@@ -1129,15 +1128,11 @@ impl TestLogger {
 	}
 	pub fn with_id(id: String) -> TestLogger {
 		TestLogger {
-			level: Level::Trace,
 			id,
 			lines: Mutex::new(new_hash_map()),
 			context: Mutex::new(new_hash_map()),
 		}
 	}
-	pub fn enable(&mut self, level: Level) {
-		self.level = level;
-	}
 	pub fn assert_log(&self, module: &str, line: String, count: usize) {
 		let log_entries = self.lines.lock().unwrap();
 		assert_eq!(log_entries.get(&(module, line)), Some(&count));
@@ -1179,11 +1174,24 @@ impl TestLogger {
 
 impl Logger for TestLogger {
 	fn log(&self, record: Record) {
-		*self.lines.lock().unwrap().entry((record.module_path, format!("{}", record.args))).or_insert(0) += 1;
-		*self.context.lock().unwrap().entry((record.module_path, record.peer_id, record.channel_id)).or_insert(0) += 1;
-		if record.level >= self.level {
-			let pfx = format!("{} {} [{}:{}]", self.id, record.level.to_string(), record.module_path, record.line);
-			println!("{:<55}{}", pfx, record.args);
+		let s = format!("{:<55} {}",
+			format_args!("{} {} [{}:{}]", self.id, record.level.to_string(), record.module_path, record.line),
+			record.args
+		);
+		#[cfg(ldk_bench)] {
+			// When benchmarking, we don't actually want to print logs, but we do want to format
+			// them. To make sure LLVM doesn't skip the above entirely we push it through a
+			// volitile read. This may not be super fast, but it shouldn't be worse than anything a
+			// user actually does with a log
+			let s_bytes = s.as_bytes();
+			for i in 0..s.len() {
+				let _ = unsafe { core::ptr::read_volatile(&s_bytes[i]) };
+			}
+		}
+		#[cfg(not(ldk_bench))] {
+			*self.lines.lock().unwrap().entry((record.module_path, format!("{}", record.args))).or_insert(0) += 1;
+			*self.context.lock().unwrap().entry((record.module_path, record.peer_id, record.channel_id)).or_insert(0) += 1;
+			println!("{}", s);
 		}
 	}
 }