add timing logs

f3r10 · f3r10 · commit 04116046a734 · 2026-01-22T08:04:40.000-05:00
diff --git a/lightning-liquidity/src/lsps4/client.rs b/lightning-liquidity/src/lsps4/client.rs
@@ -28,6 +28,7 @@ use std::string::String;
 
 use core::default::Default;
 use core::ops::Deref;
+use std::time::Instant;
 
 use crate::lsps4::msgs::{
 	RegisterNodeRequest, RegisterNodeResponse, LSPS4Message, LSPS4Request,
@@ -89,14 +90,19 @@ where
 	pub fn register_node(
 		&self, counterparty_node_id: PublicKey
 	) -> Result<LSPSRequestId, APIError> {
+		let fn_start = Instant::now();
+		eprintln!("TIMING: [LSPS4 Client] register_node START for peer {}", counterparty_node_id);
+
 		let request_id = crate::utils::generate_request_id(&self.entropy_source);
 
 		{
+			let step_start = Instant::now();
 			let mut outer_state_lock = self.per_peer_state.write().unwrap();
 			let inner_state_lock = outer_state_lock
 				.entry(counterparty_node_id)
 				.or_insert(Mutex::new(PeerState::new()));
 			let mut peer_state_lock = inner_state_lock.lock().unwrap();
+			eprintln!("TIMING: [LSPS4 Client] register_node state lock acquisition took {}ms", step_start.elapsed().as_millis());
 
 			if !peer_state_lock
 				.pending_register_node_requests
@@ -114,13 +120,17 @@ where
 		let mut message_queue_notifier = self.pending_messages.notifier();
 		message_queue_notifier.enqueue(&counterparty_node_id, msg);
 
+		eprintln!("TIMING: [LSPS4 Client] register_node TOTAL took {}ms", fn_start.elapsed().as_millis());
 		Ok(request_id)
 	}
 
 
 	fn handle_register_node_response(
 		&self, request_id: LSPSRequestId, counterparty_node_id: &PublicKey, result: RegisterNodeResponse,
 	) -> Result<(), LightningError> {
+		let fn_start = Instant::now();
+		eprintln!("TIMING: [LSPS4 Client] handle_register_node_response START from peer {} with SCID {:?}", counterparty_node_id, result.jit_channel_scid);
+
 		let outer_state_lock = self.per_peer_state.read().unwrap();
 		match outer_state_lock.get(counterparty_node_id) {
 			Some(inner_state_lock) => {
@@ -146,6 +156,7 @@ where
 							cltv_expiry_delta: result.lsp_cltv_expiry_delta,
 						},
 					));
+					eprintln!("TIMING: [LSPS4 Client] handle_register_node_response TOTAL took {}ms - InvoiceParametersReady event enqueued with SCID {}", fn_start.elapsed().as_millis(), intercept_scid);
 				} else {
 					return Err(LightningError {
 						err: format!(
diff --git a/lightning-liquidity/src/lsps4/service.rs b/lightning-liquidity/src/lsps4/service.rs
@@ -53,6 +53,7 @@ const HTLC_EXPIRY_THRESHOLD_SECS: u64 = 10;
 use crate::utils::async_poll::dummy_waker;
 use core::task;
 use std::future::Future;
+use std::time::Instant;
 
 /// Action to forward a specific HTLC through a channel
 #[derive(Debug)]
@@ -147,18 +148,21 @@ where
 		&self, intercept_scid: u64, intercept_id: InterceptId, expected_outbound_amount_msat: u64,
 		payment_hash: PaymentHash,
 	) -> Result<(), APIError> {
+		let fn_start = Instant::now();
 		log_info!(
 			self.logger,
-			"[LSPS4] HTLC intercepted - SCID: {}, intercept_id: {:?}, amount: {} msat, payment_hash: {}",
+			"TIMING: [LSPS4] htlc_intercepted START - SCID: {}, intercept_id: {:?}, amount: {} msat, payment_hash: {}",
 			intercept_scid,
 			intercept_id,
 			expected_outbound_amount_msat,
 			payment_hash
 		);
+		let step_start = Instant::now();
 		if let Some(counterparty_node_id) = self.scid_store.get_peer(intercept_scid) {
 			log_info!(
 				self.logger,
-				"[LSPS4] SCID {} matched to peer {}, processing HTLC",
+				"TIMING: [LSPS4] htlc_intercepted scid_store.get_peer() took {}ms - SCID {} matched to peer {}",
+				step_start.elapsed().as_millis(),
 				intercept_scid,
 				counterparty_node_id
 			);
@@ -173,35 +177,43 @@ where
 			if !self.is_peer_connected(&counterparty_node_id) {
 				log_debug!(
 					self.logger,
-					"[htlc_intercepted] Peer {} not connected, storing HTLC and sending webhook",
+					"TIMING: [htlc_intercepted] Peer {} not connected, storing HTLC and sending webhook",
 					counterparty_node_id
 				);
+				let store_start = Instant::now();
 				self.htlc_store.insert(htlc).unwrap(); // TODO: handle persistence failures
+				log_info!(self.logger, "TIMING: [LSPS4] htlc_intercepted htlc_store.insert() took {}ms", store_start.elapsed().as_millis());
 				let mut event_queue_notifier = self.pending_events.notifier();
 				event_queue_notifier.enqueue(crate::events::LiquidityEvent::LSPS4Service(LSPS4ServiceEvent::SendWebhook {
 					counterparty_node_id: counterparty_node_id.clone(),
 				}));
 			} else {
 				log_debug!(
 					self.logger,
-					"[htlc_intercepted] Peer {} connected, processing HTLC immediately",
+					"TIMING: [htlc_intercepted] Peer {} connected, processing HTLC immediately",
 					counterparty_node_id
 				);
+				let calc_start = Instant::now();
 				let actions =
 					self.calculate_htlc_actions_for_peer(counterparty_node_id, vec![htlc.clone()]);
+				log_info!(self.logger, "TIMING: [LSPS4] htlc_intercepted calculate_htlc_actions_for_peer() took {}ms", calc_start.elapsed().as_millis());
 
 				if actions.new_channel_needed_msat.is_some() {
+					let store_start = Instant::now();
 					self.htlc_store.insert(htlc).unwrap(); // TODO: handle persistence failures
+					log_info!(self.logger, "TIMING: [LSPS4] htlc_intercepted htlc_store.insert() took {}ms", store_start.elapsed().as_millis());
 				}
 
 				log_debug!(
 					self.logger,
-					"[htlc_intercepted] Calculated actions for peer {}: {:?}",
+					"TIMING: [htlc_intercepted] Calculated actions for peer {}: {:?}",
 					counterparty_node_id,
 					actions
 				);
 
+				let exec_start = Instant::now();
 				self.execute_htlc_actions(actions, counterparty_node_id.clone());
+				log_info!(self.logger, "TIMING: [LSPS4] htlc_intercepted execute_htlc_actions() took {}ms", exec_start.elapsed().as_millis());
 			}
 		} else {
 			log_error!(
@@ -211,9 +223,10 @@ where
 					intercept_id
 				);
 		}
-		log_debug!(
+		log_info!(
 			self.logger,
-			"[htlc_intercepted] Finalizing htlc_intercepted for intercept_scid {}",
+			"TIMING: [LSPS4] htlc_intercepted TOTAL took {}ms for intercept_scid {}",
+			fn_start.elapsed().as_millis(),
 			intercept_scid
 		);
 
@@ -295,31 +308,42 @@ where
 	fn handle_register_node_request(
 		&self, request_id: LSPSRequestId, counterparty_node_id: &PublicKey, _params: RegisterNodeRequest,
 	) -> Result<(), LightningError> {
+		let fn_start = Instant::now();
 		log_info!(
 			self.logger,
-			"[LSPS4] Received RegisterNodeRequest from {} with request_id {:?}",
+			"TIMING: [LSPS4] handle_register_node_request START from {} with request_id {:?}",
 			counterparty_node_id,
 			request_id
 		);
 
+		let step_start = Instant::now();
 		let intercept_scid = match self.scid_store.get_scid(counterparty_node_id) {
 			Some(intercept_scid) => {
 				log_info!(
 					self.logger,
-					"[LSPS4] Found existing intercept SCID {} for peer {}",
+					"TIMING: [LSPS4] handle_register_node_request scid_store.get_scid() took {}ms - Found existing intercept SCID {} for peer {}",
+					step_start.elapsed().as_millis(),
 					intercept_scid,
 					counterparty_node_id
 				);
 				intercept_scid
 			},
 			None => {
+				log_info!(
+					self.logger,
+					"TIMING: [LSPS4] handle_register_node_request scid_store.get_scid() took {}ms - No existing SCID",
+					step_start.elapsed().as_millis()
+				);
+				let gen_start = Instant::now();
 				let intercept_scid = self.channel_manager.get_cm().get_intercept_scid();
 				log_info!(
 					self.logger,
-					"[LSPS4] Generated NEW intercept SCID {} for peer {}",
+					"TIMING: [LSPS4] handle_register_node_request get_intercept_scid() took {}ms - Generated NEW intercept SCID {} for peer {}",
+					gen_start.elapsed().as_millis(),
 					intercept_scid,
 					counterparty_node_id
 				);
+				let store_start = Instant::now();
 				self.scid_store.add_intercepted_scid(intercept_scid, counterparty_node_id.clone())
 					.map_err(|e| {
 						log_error!(
@@ -336,7 +360,8 @@ where
 					})?;
 				log_info!(
 					self.logger,
-					"[LSPS4] Successfully stored intercept SCID {} for peer {}",
+					"TIMING: [LSPS4] handle_register_node_request scid_store.add_intercepted_scid() took {}ms - Successfully stored intercept SCID {} for peer {}",
+					store_start.elapsed().as_millis(),
 					intercept_scid,
 					counterparty_node_id
 				);
@@ -360,7 +385,8 @@ where
 
 		log_info!(
 			self.logger,
-			"[LSPS4] RegisterNodeResponse enqueued successfully for peer {}",
+			"TIMING: [LSPS4] handle_register_node_request TOTAL took {}ms for peer {}",
+			fn_start.elapsed().as_millis(),
 			counterparty_node_id
 		);
 
@@ -474,6 +500,9 @@ where
 	pub(crate) fn execute_htlc_actions(
 		&self, actions: HtlcProcessingActions, their_node_id: PublicKey,
 	) {
+		let fn_start = Instant::now();
+		log_info!(self.logger, "TIMING: [LSPS4] execute_htlc_actions START for peer {} with {} forwards", their_node_id, actions.forwards.len());
+
 		// Execute forwards
 		for forward_action in actions.forwards {
 			log_debug!(
@@ -485,6 +514,7 @@ where
 				forward_action.skimmed_fee_msat
 			);
 
+			let fwd_start = Instant::now();
 			if let Err(e) = self.channel_manager.get_cm().forward_intercepted_htlc(
 				forward_action.htlc.id(),
 				&forward_action.channel_id,
@@ -493,18 +523,21 @@ where
 			) {
 				log_error!(self.logger, "Failed to forward intercepted HTLC: {:?}", e);
 			}
+			log_info!(self.logger, "TIMING: [LSPS4] execute_htlc_actions forward_intercepted_htlc() took {}ms", fwd_start.elapsed().as_millis());
 
 			// Remove the HTLC from store after forwarding
+			let rm_start = Instant::now();
 			if let Err(e) = self.htlc_store.remove(&forward_action.htlc.id()) {
 				log_error!(self.logger, "Failed to remove intercepted HTLC from store: {}", e);
 			}
+			log_info!(self.logger, "TIMING: [LSPS4] execute_htlc_actions htlc_store.remove() took {}ms", rm_start.elapsed().as_millis());
 		}
 
 		// Handle new channel opening
 		if let Some(channel_size_msat) = actions.new_channel_needed_msat {
 			log_info!(
 				self.logger,
-				"Need a new channel with peer {} for {}msat to forward HTLCs",
+				"TIMING: [LSPS4] execute_htlc_actions Need a new channel with peer {} for {}msat to forward HTLCs",
 				their_node_id,
 				channel_size_msat
 			);
@@ -516,18 +549,27 @@ where
 				channel_count: actions.channel_count,
 			}));
 		}
+
+		log_info!(self.logger, "TIMING: [LSPS4] execute_htlc_actions TOTAL took {}ms", fn_start.elapsed().as_millis());
 	}
 
 	/// Convenience function that calculates and executes HTLC actions in one call
 	pub(crate) fn process_htlcs_for_peer(
 		&self, their_node_id: PublicKey, htlcs: Vec<InterceptedHtlc>,
 	) {
+		let fn_start = Instant::now();
+		let htlc_count = htlcs.len();
+		log_info!(self.logger, "TIMING: [LSPS4] process_htlcs_for_peer START for peer {} with {} HTLCs", their_node_id, htlc_count);
+
+		let calc_start = Instant::now();
 		let actions = self.calculate_htlc_actions_for_peer(their_node_id, htlcs);
+		log_info!(self.logger, "TIMING: [LSPS4] process_htlcs_for_peer calculate_htlc_actions_for_peer() took {}ms", calc_start.elapsed().as_millis());
 
 		log_info!(self.logger, "Calculated actions for peer {}: {:?}", their_node_id, actions);
 
 		if actions.is_empty() {
 			log_debug!(self.logger, "No HTLCs to process for peer {}", their_node_id);
+			log_info!(self.logger, "TIMING: [LSPS4] process_htlcs_for_peer TOTAL took {}ms (no actions)", fn_start.elapsed().as_millis());
 			return;
 		}
 
@@ -542,6 +584,7 @@ where
 		}
 
 		self.execute_htlc_actions(actions, their_node_id);
+		log_info!(self.logger, "TIMING: [LSPS4] process_htlcs_for_peer TOTAL took {}ms", fn_start.elapsed().as_millis());
 	}
 
 	/// Persists the state of the service handler towards the given [`KVStore`] implementation.
diff --git a/lightning/src/ln/channelmanager.rs b/lightning/src/ln/channelmanager.rs
@@ -184,6 +184,8 @@ use core::ops::Deref;
 use core::sync::atomic::{AtomicBool, AtomicUsize, Ordering};
 use core::time::Duration;
 use core::{cmp, mem};
+#[cfg(feature = "std")]
+use crate::util::time::Instant;
 // Re-export this for use in the public API.
 #[cfg(any(test, feature = "_externalize_tests"))]
 pub(crate) use crate::ln::outbound_payment::PaymentSendFailure;
@@ -7093,6 +7095,9 @@ where
 	/// Users implementing their own background processing logic should call this in irregular,
 	/// randomly-distributed intervals.
 	pub fn process_pending_htlc_forwards(&self) {
+		#[cfg(feature = "std")]
+		let fn_start = Instant::now();
+
 		if self
 			.pending_htlc_forwards_processor
 			.compare_exchange(false, true, Ordering::Acquire, Ordering::Relaxed)
@@ -7106,6 +7111,9 @@ where
 		});
 
 		self.pending_htlc_forwards_processor.store(false, Ordering::Release);
+
+		#[cfg(feature = "std")]
+		log_trace!(self.logger, "TIMING: process_pending_htlc_forwards() took {}ms", fn_start.elapsed().as_millis());
 	}
 
 	// Returns whether or not we need to re-persist.
diff --git a/lightning/src/ln/outbound_payment.rs b/lightning/src/ln/outbound_payment.rs
@@ -1426,6 +1426,10 @@ where
 		L::Target: Logger,
 		IH: Fn() -> InFlightHtlcs,
 	{
+		#[cfg(feature = "std")]
+		let fn_start = Instant::now();
+		log_trace!(self.logger, "TIMING: find_initial_route() START payment_id={} final_value_msat={}", payment_id, route_params.final_value_msat);
+
 		#[cfg(feature = "std")] {
 			if has_expired(&route_params) {
 				log_error!(self.logger, "Payment with id {} and hash {} had expired before we started paying",
@@ -1443,6 +1447,8 @@ where
 				RetryableSendFailure::OnionPacketSizeExceeded
 			})?;
 
+		#[cfg(feature = "std")]
+		let route_start = Instant::now();
 		let mut route = router.find_route_with_id(
 			&node_signer.get_node_id(Recipient::Node).unwrap(), route_params,
 			Some(&first_hops.iter().collect::<Vec<_>>()), inflight_htlcs(),
@@ -1452,6 +1458,8 @@ where
 				payment_id, payment_hash);
 			RetryableSendFailure::RouteNotFound
 		})?;
+		#[cfg(feature = "std")]
+		log_trace!(self.logger, "TIMING: find_initial_route() router.find_route_with_id() took {}ms", route_start.elapsed().as_millis());
 
 		if route.route_params.as_ref() != Some(route_params) {
 			debug_assert!(false,
@@ -1460,6 +1468,8 @@ where
 			route.route_params = Some(route_params.clone());
 		}
 
+		#[cfg(feature = "std")]
+		log_trace!(self.logger, "TIMING: find_initial_route() TOTAL took {}ms paths={}", fn_start.elapsed().as_millis(), route.paths.len());
 		Ok(route)
 	}
 
diff --git a/lightning/src/routing/router.rs b/lightning/src/routing/router.rs
@@ -39,6 +39,7 @@ use crate::util::ser::{Readable, ReadableArgs, Writeable, Writer};
 
 use crate::io;
 use crate::prelude::*;
+use crate::util::time::Instant;
 use alloc::collections::BinaryHeap;
 use core::ops::Deref;
 use core::{cmp, fmt};
@@ -2423,10 +2424,24 @@ pub fn find_route<L: Deref, GL: Deref, S: ScoreLookUp>(
 	scorer: &S, score_params: &S::ScoreParams, random_seed_bytes: &[u8; 32]
 ) -> Result<Route, &'static str>
 where L::Target: Logger, GL::Target: Logger {
+	let fn_start = Instant::now();
+	log_trace!(logger, "TIMING: find_route() START final_value_msat={}", route_params.final_value_msat);
+
+	let step_start = Instant::now();
 	let graph_lock = network_graph.read_only();
+	let graph_lock_time = step_start.elapsed().as_millis();
+
+	let step_start = Instant::now();
 	let mut route = get_route(our_node_pubkey, &route_params, &graph_lock, first_hops, logger,
 		scorer, score_params, random_seed_bytes)?;
+	let get_route_time = step_start.elapsed().as_millis();
+
 	add_random_cltv_offset(&mut route, &route_params.payment_params, &graph_lock, random_seed_bytes);
+	let total_time = fn_start.elapsed().as_millis();
+	let path_count = route.paths.len();
+
+	#[cfg(feature = "std")]
+	eprintln!("TIMING: find_route() network_graph.read_only() took {}ms, get_route() took {}ms, TOTAL took {}ms paths={}", graph_lock_time, get_route_time, total_time, path_count);
 	Ok(route)
 }
 
@@ -3722,6 +3737,7 @@ where L::Target: Logger {
 	}
 
 	log_info!(logger, "Got route: {}", log_route!(route));
+	log_trace!(logger, "TIMING: get_route() completed with {} paths", route.paths.len());
 	Ok(route)
 }
 
