add timing logs

Author: f3r10

Cargo.toml

@@ -41,18 +41,18 @@ default = []
 # lightning-liquidity = { version = "0.2.0", features = ["std"] }
 # lightning-macros = { version = "0.2.0" }
 
-# Branch: https://github.com/moneydevkit/rust-lightning/commits/lsp-0.2.0_accept-underpaying-htlcs
-lightning = { git = "https://github.com/moneydevkit/rust-lightning", rev = "edd82ba8dd7ed1c140a209eb1bafc30a2c38d80a", features = ["std"] }
-lightning-types = { git = "https://github.com/moneydevkit/rust-lightning", rev = "edd82ba8dd7ed1c140a209eb1bafc30a2c38d80a" }
-lightning-invoice = { git = "https://github.com/moneydevkit/rust-lightning", rev = "edd82ba8dd7ed1c140a209eb1bafc30a2c38d80a", features = ["std"] }
-lightning-net-tokio = { git = "https://github.com/moneydevkit/rust-lightning", rev = "edd82ba8dd7ed1c140a209eb1bafc30a2c38d80a" }
-lightning-persister = { git = "https://github.com/moneydevkit/rust-lightning", rev = "edd82ba8dd7ed1c140a209eb1bafc30a2c38d80a", features = ["tokio"] }
-lightning-background-processor = { git = "https://github.com/moneydevkit/rust-lightning", rev = "edd82ba8dd7ed1c140a209eb1bafc30a2c38d80a" }
-lightning-rapid-gossip-sync = { git = "https://github.com/moneydevkit/rust-lightning", rev = "edd82ba8dd7ed1c140a209eb1bafc30a2c38d80a" }
-lightning-block-sync = { git = "https://github.com/moneydevkit/rust-lightning", rev = "edd82ba8dd7ed1c140a209eb1bafc30a2c38d80a", features = ["rest-client", "rpc-client", "tokio"] }
-lightning-transaction-sync = { git = "https://github.com/moneydevkit/rust-lightning", rev = "edd82ba8dd7ed1c140a209eb1bafc30a2c38d80a", features = ["esplora-async-https", "time", "electrum-rustls-ring"] }
-lightning-liquidity = { git = "https://github.com/moneydevkit/rust-lightning", rev = "edd82ba8dd7ed1c140a209eb1bafc30a2c38d80a", features = ["std"] }
-lightning-macros = { git = "https://github.com/moneydevkit/rust-lightning", rev = "edd82ba8dd7ed1c140a209eb1bafc30a2c38d80a" }
+# Branch: https://github.com/moneydevkit/rust-lightning/tree/lsp-0.2.0_accept-underpaying-htlcs_with_timing_logs
+lightning = { git = "https://github.com/moneydevkit/rust-lightning", rev = "04116046a734275cceadae263c363ee0b4d2ea78", features = ["std"] }
+lightning-types = { git = "https://github.com/moneydevkit/rust-lightning", rev = "04116046a734275cceadae263c363ee0b4d2ea78" }
+lightning-invoice = { git = "https://github.com/moneydevkit/rust-lightning", rev = "04116046a734275cceadae263c363ee0b4d2ea78", features = ["std"] }
+lightning-net-tokio = { git = "https://github.com/moneydevkit/rust-lightning", rev = "04116046a734275cceadae263c363ee0b4d2ea78" }
+lightning-persister = { git = "https://github.com/moneydevkit/rust-lightning", rev = "04116046a734275cceadae263c363ee0b4d2ea78", features = ["tokio"] }
+lightning-background-processor = { git = "https://github.com/moneydevkit/rust-lightning", rev = "04116046a734275cceadae263c363ee0b4d2ea78" }
+lightning-rapid-gossip-sync = { git = "https://github.com/moneydevkit/rust-lightning", rev = "04116046a734275cceadae263c363ee0b4d2ea78" }
+lightning-block-sync = { git = "https://github.com/moneydevkit/rust-lightning", rev = "04116046a734275cceadae263c363ee0b4d2ea78", features = ["rest-client", "rpc-client", "tokio"] }
+lightning-transaction-sync = { git = "https://github.com/moneydevkit/rust-lightning", rev = "04116046a734275cceadae263c363ee0b4d2ea78", features = ["esplora-async-https", "time", "electrum-rustls-ring"] }
+lightning-liquidity = { git = "https://github.com/moneydevkit/rust-lightning", rev = "04116046a734275cceadae263c363ee0b4d2ea78", features = ["std"] }
+lightning-macros = { git = "https://github.com/moneydevkit/rust-lightning", rev = "04116046a734275cceadae263c363ee0b4d2ea78" }
 
 #lightning = { path = "../rust-lightning/lightning", features = ["std"] }
 #lightning-types = { path = "../rust-lightning/lightning-types" }
@@ -99,7 +99,7 @@ winapi = { version = "0.3", features = ["winbase"] }
 [dev-dependencies]
 # lightning = { version = "0.2.0", features = ["std", "_test_utils"] }
 # Branch: https://github.com/moneydevkit/rust-lightning/commits/lsp-0.2.0_accept-underpaying-htlcs
-lightning = { git = "https://github.com/moneydevkit/rust-lightning", rev = "edd82ba8dd7ed1c140a209eb1bafc30a2c38d80a", features = ["std", "_test_utils"] }
+lightning = { git = "https://github.com/moneydevkit/rust-lightning", rev = "04116046a734275cceadae263c363ee0b4d2ea78", features = ["std", "_test_utils"] }
 #lightning = { path = "../rust-lightning/lightning", features = ["std", "_test_utils"] }
 proptest = "1.0.0"
 regex = "1.5.6"

src/lib.rs

@@ -220,6 +220,8 @@ impl Node {
 	/// After this returns, the [`Node`] instance can be controlled via the provided API methods in
 	/// a thread-safe manner.
 	pub fn start(&self) -> Result<(), Error> {
+		let fn_start = Instant::now();
+
 		// Acquire a run lock and hold it until we're setup.
 		let mut is_running_lock = self.is_running.write().unwrap();
 		if *is_running_lock {
@@ -234,14 +236,18 @@ impl Node {
 		);
 
 		// Start up any runtime-dependant chain sources (e.g. Electrum)
+		let step_start = Instant::now();
 		self.chain_source.start(Arc::clone(&self.runtime)).map_err(|e| {
 			log_error!(self.logger, "Failed to start chain syncing: {}", e);
 			e
 		})?;
+		log_info!(self.logger, "TIMING: chain_source.start() took {}ms", step_start.elapsed().as_millis());
 
 		// Block to ensure we update our fee rate cache once on startup
+		let step_start = Instant::now();
 		let chain_source = Arc::clone(&self.chain_source);
 		self.runtime.block_on(async move { chain_source.update_fee_rate_estimates().await })?;
+		log_info!(self.logger, "TIMING: update_fee_rate_estimates() took {}ms", step_start.elapsed().as_millis());
 
 		// Spawn background task continuously syncing onchain, lightning, and fee rate cache.
 		let stop_sync_receiver = self.stop_sender.subscribe();
@@ -643,6 +649,7 @@ impl Node {
 			});
 		}
 
+		log_info!(self.logger, "TIMING: start() TOTAL took {}ms", fn_start.elapsed().as_millis());
 		log_info!(self.logger, "Startup complete.");
 		*is_running_lock = true;
 		Ok(())
@@ -1437,6 +1444,9 @@ impl Node {
 	///
 	/// [`EsploraSyncConfig::background_sync_config`]: crate::config::EsploraSyncConfig::background_sync_config
 	pub fn sync_wallets(&self) -> Result<(), Error> {
+		let fn_start = Instant::now();
+		log_info!(self.logger, "TIMING: sync_wallets() START");
+
 		if !*self.is_running.read().unwrap() {
 			return Err(Error::NotRunning);
 		}
@@ -1446,15 +1456,28 @@ impl Node {
 		let sync_cman = Arc::clone(&self.channel_manager);
 		let sync_cmon = Arc::clone(&self.chain_monitor);
 		let sync_sweeper = Arc::clone(&self.output_sweeper);
+		let logger = Arc::clone(&self.logger);
 		self.runtime.block_on(async move {
 			if chain_source.is_transaction_based() {
+				let step_start = Instant::now();
 				chain_source.update_fee_rate_estimates().await?;
+				log_info!(logger, "TIMING: sync_wallets update_fee_rate_estimates() took {}ms", step_start.elapsed().as_millis());
+
+				let step_start = Instant::now();
 				chain_source
 					.sync_lightning_wallet(sync_cman, sync_cmon, Arc::clone(&sync_sweeper))
 					.await?;
+				log_info!(logger, "TIMING: sync_wallets sync_lightning_wallet() took {}ms", step_start.elapsed().as_millis());
+
+				let step_start = Instant::now();
 				chain_source.sync_onchain_wallet(sync_wallet).await?;
+				log_info!(logger, "TIMING: sync_wallets sync_onchain_wallet() took {}ms", step_start.elapsed().as_millis());
 			} else {
+				let step_start = Instant::now();
 				chain_source.update_fee_rate_estimates().await?;
+				log_info!(logger, "TIMING: sync_wallets update_fee_rate_estimates() took {}ms", step_start.elapsed().as_millis());
+
+				let step_start = Instant::now();
 				chain_source
 					.poll_and_update_listeners(
 						sync_wallet,
@@ -1463,8 +1486,12 @@ impl Node {
 						Arc::clone(&sync_sweeper),
 					)
 					.await?;
+				log_info!(logger, "TIMING: sync_wallets poll_and_update_listeners() took {}ms", step_start.elapsed().as_millis());
 			}
+			let step_start = Instant::now();
 			let _ = sync_sweeper.regenerate_and_broadcast_spend_if_necessary().await;
+			log_info!(logger, "TIMING: sync_wallets regenerate_and_broadcast_spend_if_necessary() took {}ms", step_start.elapsed().as_millis());
+			log_info!(logger, "TIMING: sync_wallets() TOTAL took {}ms", fn_start.elapsed().as_millis());
 			Ok(())
 		})
 	}

src/liquidity.rs

@@ -10,7 +10,7 @@
 use std::collections::HashMap;
 use std::ops::Deref;
 use std::sync::{Arc, Mutex, RwLock};
-use std::time::{Duration, SystemTime, UNIX_EPOCH};
+use std::time::{Duration, Instant, SystemTime, UNIX_EPOCH};
 
 use bitcoin::hashes::{sha256, Hash};
 use bitcoin::secp256k1::{PublicKey, Secp256k1};
@@ -1637,6 +1637,9 @@ where
 	}
 
 	async fn lsps4_register_node(&self) -> Result<LSPS4RegisterNodeResponse, Error> {
+		let fn_start = Instant::now();
+		log_info!(self.logger, "TIMING: lsps4_register_node() START");
+
 		let lsps4_client = self.lsps4_client.as_ref().ok_or(Error::LiquiditySourceUnavailable)?;
 
 		let client_handler = self.liquidity_manager.lsps4_client_handler().ok_or_else(|| {
@@ -1651,8 +1654,9 @@ where
 			let request_id = client_handler.register_node(lsps4_client.lsp_node_id).unwrap();
 			pending_register_node_requests_lock.insert(request_id, register_node_sender);
 		}
+		log_info!(self.logger, "TIMING: lsps4_register_node() sent request, waiting for response...");
 
-		tokio::time::timeout(
+		let result = tokio::time::timeout(
 			Duration::from_secs(LIQUIDITY_REQUEST_TIMEOUT_SECS),
 			register_node_receiver,
 		)
@@ -1664,22 +1668,33 @@ where
 		.map_err(|e| {
 			log_error!(self.logger, "Failed to handle response from liquidity service: {}", e);
 			Error::LiquidityRequestFailed
-		})
+		});
+
+		log_info!(self.logger, "TIMING: lsps4_register_node() TOTAL took {}ms", fn_start.elapsed().as_millis());
+		result
 	}
 
 	pub(crate) async fn lsps4_receive_to_jit_channel(
 		&self, amount_msat: Option<u64>, description: &Bolt11InvoiceDescription, expiry_secs: u32,
 	) -> Result<Bolt11Invoice, Error> {
+		let fn_start = Instant::now();
+		log_info!(self.logger, "TIMING: lsps4_receive_to_jit_channel() START amount_msat={:?}", amount_msat);
+
+		let step_start = Instant::now();
 		let register_node_response = self.lsps4_register_node().await?;
+		log_info!(self.logger, "TIMING: lsps4_receive_to_jit_channel() lsps4_register_node() took {}ms", step_start.elapsed().as_millis());
 
+		let step_start = Instant::now();
 		let invoice = self.lsps4_create_jit_invoice(
 			register_node_response.intercept_scid,
 			register_node_response.cltv_expiry_delta,
 			amount_msat,
 			description,
 			expiry_secs,
 		)?;
+		log_info!(self.logger, "TIMING: lsps4_receive_to_jit_channel() lsps4_create_jit_invoice() took {}ms", step_start.elapsed().as_millis());
 
+		log_info!(self.logger, "TIMING: lsps4_receive_to_jit_channel() TOTAL took {}ms", fn_start.elapsed().as_millis());
 		log_info!(self.logger, "LSPS4 JIT-channel invoice created: {}", invoice);
 		Ok(invoice)
 	}

src/payment/bolt11.rs

@@ -10,6 +10,7 @@
 //! [BOLT 11]: https://github.com/lightning/bolts/blob/master/11-payment-encoding.md
 
 use std::sync::{Arc, RwLock};
+use std::time::Instant;
 
 use bitcoin::hashes::sha256::Hash as Sha256;
 use bitcoin::hashes::Hash;
@@ -93,6 +94,9 @@ impl Bolt11Payment {
 	pub fn send(
 		&self, invoice: &Bolt11Invoice, route_parameters: Option<RouteParametersConfig>,
 	) -> Result<PaymentId, Error> {
+		let fn_start = Instant::now();
+		log_info!(self.logger, "TIMING: bolt11_payment.send() START");
+
 		if !*self.is_running.read().unwrap() {
 			return Err(Error::NotRunning);
 		}
@@ -114,6 +118,7 @@ impl Bolt11Payment {
 		let retry_strategy = Retry::Timeout(LDK_PAYMENT_RETRY_TIMEOUT);
 		let payment_secret = Some(*invoice.payment_secret());
 
+		let step_start = Instant::now();
 		match self.channel_manager.pay_for_bolt11_invoice(
 			invoice,
 			payment_id,
@@ -122,6 +127,7 @@ impl Bolt11Payment {
 			retry_strategy,
 		) {
 			Ok(()) => {
+				log_info!(self.logger, "TIMING: bolt11_payment.send() channel_manager.pay_for_bolt11_invoice() took {}ms", step_start.elapsed().as_millis());
 				let payee_pubkey = invoice.recover_payee_pub_key();
 				let amt_msat = invoice.amount_milli_satoshis().unwrap();
 				log_info!(self.logger, "Initiated sending {}msat to {}", amt_msat, payee_pubkey);
@@ -142,6 +148,7 @@ impl Bolt11Payment {
 
 				self.payment_store.insert(payment)?;
 
+				log_info!(self.logger, "TIMING: bolt11_payment.send() TOTAL took {}ms", fn_start.elapsed().as_millis());
 				Ok(payment_id)
 			},
 			Err(Bolt11PaymentError::InvalidAmount) => {
@@ -752,6 +759,9 @@ impl Bolt11Payment {
 	pub fn receive_via_lsps4_jit_channel(
 		&self, amount_msat: Option<u64>, description: &Bolt11InvoiceDescription, expiry_secs: u32,
 	) -> Result<Bolt11Invoice, Error> {
+		let fn_start = Instant::now();
+		log_info!(self.logger, "TIMING: receive_via_lsps4_jit_channel() START amount_msat={:?}", amount_msat);
+
 		let description = maybe_try_convert_enum(description)?;
 
 		let liquidity_source =
@@ -768,24 +778,29 @@ impl Bolt11Payment {
 
 		// We need to use our main runtime here as a local runtime might not be around to poll
 		// connection futures going forward.
+		let step_start = Instant::now();
 		self.runtime.block_on(async move {
 			con_cm.connect_peer_if_necessary(con_node_id, con_addr).await
 		})?;
+		log_info!(self.logger, "TIMING: receive_via_lsps4_jit_channel() connect_peer_if_necessary() took {}ms", step_start.elapsed().as_millis());
 
 		log_info!(self.logger, "Connected to LSP {}@{}. ", peer_info.node_id, peer_info.address);
 
+		let step_start = Instant::now();
 		let liquidity_source = Arc::clone(&liquidity_source);
 		let invoice = self.runtime.block_on(async move {
 			liquidity_source
 				.lsps4_receive_to_jit_channel(amount_msat, &description, expiry_secs)
 				.await
 		})?;
+		log_info!(self.logger, "TIMING: receive_via_lsps4_jit_channel() lsps4_receive_to_jit_channel() took {}ms", step_start.elapsed().as_millis());
 
 		self.register_lsps4_payment(&invoice, amount_msat)?;
 
 		// Persist LSP peer to make sure we reconnect on restart.
 		self.peer_store.add_peer(peer_info)?;
 
+		log_info!(self.logger, "TIMING: receive_via_lsps4_jit_channel() TOTAL took {}ms", fn_start.elapsed().as_millis());
 		Ok(maybe_wrap(invoice))
 	}