Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

sim-lib: Log payment summary every minute for more consistent results #141

Merged
merged 2 commits into from
Nov 6, 2023
Merged

sim-lib: Log payment summary every minute for more consistent results #141

Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
0376a67
sim-lib/refactor: pass report logger into results method
carlaKC Oct 17, 2023
71d44cb
sim-lib: report results on time interval for more consistent logging
carlaKC Oct 17, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
71 changes: 52 additions & 19 deletions sim-lib/src/lib.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -549,7 +549,16 @@ impl Simulation {
listener.clone(),
));

let result_logger = Arc::new(Mutex::new(PaymentResultLogger::new()));

tasks.spawn(run_results_logger(
listener.clone(),
result_logger.clone(),
Duration::from_secs(60),
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We may want to make this configurable and default it to 1 min

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Clippy starts getting angry if we have too many args for Simulation::new - pushed example in e929a2d which adds a SimulationConfig struct to house all of our various flags.

If we like it, I'll break that up into a refactor commit + add some validation on the config so that we fail if we're given bad config values (eg, zero expected amount).

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Concept ACK on this. I think that's also a first step towards allowing reading conf options both from cmd and a config file. I don't think there's an idiomatic way of doing that, but here's an example of how I've dealt with that in the past: https://github.com/talaia-labs/rust-teos/blob/master/teos/src/config.rs

For context, StructOpt was just a wrapper around clap that made it nicer to use, but looks like the new version of the latter includes most (if not all) the functionality from the former

));

tasks.spawn(consume_simulation_results(
result_logger,
results_receiver,
listener,
self.print_batch_size,
Expand Down Expand Up @@ -874,21 +883,25 @@ async fn produce_random_events<N: NetworkGenerator, A: PaymentGenerator + Displa
}

async fn consume_simulation_results(
logger: Arc<Mutex<PaymentResultLogger>>,
receiver: Receiver<(Payment, PaymentResult)>,
listener: Listener,
print_batch_size: u32,
no_results: bool,
) {
log::debug!("Simulation results consumer started.");

if let Err(e) = write_payment_results(receiver, listener, print_batch_size, no_results).await {
if let Err(e) =
write_payment_results(logger, receiver, listener, print_batch_size, no_results).await
{
log::error!("Error while reporting payment results: {:?}.", e);
}

log::debug!("Simulation results consumer exiting.");
}

async fn write_payment_results(
logger: Arc<Mutex<PaymentResultLogger>>,
mut receiver: Receiver<(Payment, PaymentResult)>,
listener: Listener,
print_batch_size: u32,
Expand All @@ -906,8 +919,7 @@ async fn write_payment_results(
None
};

let mut result_logger = PaymentResultLogger::new();
let mut counter = 0;
let mut counter = 1;
loop {
tokio::select! {
biased;
Expand All @@ -918,7 +930,7 @@ async fn write_payment_results(
payment_report = receiver.recv() => {
match payment_report {
Some((details, result)) => {
result_logger.report_result(&details, &result);
logger.lock().await.report_result(&details, &result);
log::trace!("Resolved dispatched payment: {} with: {}.", details, result);

if let Some(ref mut w) = writer {
Expand All @@ -940,22 +952,17 @@ async fn write_payment_results(
}
}

/// PaymentResultLogger is an aggregate logger that will report on a summary of the payments that have been reported
/// to it at regular intervals (defined by the log_interval it is created with).
/// PaymentResultLogger is an aggregate logger that will report on a summary of the payments that have been reported.
#[derive(Default)]
struct PaymentResultLogger {
success_payment: u64,
failed_payment: u64,
total_sent: u64,
call_count: u8,
log_interval: u8,
}

impl PaymentResultLogger {
fn new() -> Self {
PaymentResultLogger {
// TODO: set the interval at which we log based on the number of payment we're expecting to log.
log_interval: 10,
..Default::default()
}
}
Expand All @@ -967,18 +974,44 @@ impl PaymentResultLogger {
}

self.total_sent += details.amount_msat;
self.call_count += 1;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I just realized that this was a u8, which would have made the logger task panic after 255 additions, so that's patches 😆

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

:')

}
}

if self.call_count % self.log_interval == 0 || self.call_count == 0 {
let total_payments = self.success_payment + self.failed_payment;
log::info!(
"Processed {} payments sending {} msat total with {}% success rate.",
total_payments,
self.total_sent,
(self.success_payment * 100 / total_payments)
);
impl Display for PaymentResultLogger {
fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result {
let total_payments = self.success_payment + self.failed_payment;
write!(
f,
"Processed {} payments sending {} msat total with {:.2}% success rate.",
total_payments,
self.total_sent,
(self.success_payment as f64 / total_payments as f64) * 100.0
)
}
}
Comment on lines +981 to +991
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It could now be the case that we sample before a single payment has been tracked yet, meaning that we'd get 0/0 when reporting the success rate, yielding NaN:

INFO  [sim_lib] Processed 0 payments sending 0 msat total with NaN% success rate.

We should treat that as a special case:

Suggested change
fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result {
let total_payments = self.success_payment + self.failed_payment;
write!(
f,
"Processed {} payments sending {} msat total with {:.2}% success rate.",
total_payments,
self.total_sent,
(self.success_payment as f64 / total_payments as f64) * 100.0
)
}
}
fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result {
let total_payments = self.success_payment + self.failed_payment;
let rate = self.success_payment as f64 / total_payments as f64;
if rate.is_nan() {
write!(
f,
"Processed {} payments sending {} msat total.",
total_payments, self.total_sent
)
} else {
write!(
f,
"Processed {} payments sending {} msat total with {:.2}% success rate.",
total_payments,
self.total_sent,
rate * 100.0
)
}
}

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Rate is only NaN if we haven't sent anything yet, so the special case will just print "Processed 0 payments sending 0 msat total." IMO it's not worth the effort to convey essentially the same information in double the LOC, I think it's reasonably understandable as is.


async fn run_results_logger(
listener: Listener,
logger: Arc<Mutex<PaymentResultLogger>>,
interval: Duration,
) {
log::debug!("Results logger started.");
log::info!("Summary of results will be reported every {:?}.", interval);

loop {
select! {
biased;
_ = listener.clone() => {
break
}

_ = time::sleep(interval) => {
log::info!("{}", logger.lock().await)
}
}
}

log::debug!("Results logger stopped.")
}

/// produce_results is responsible for receiving the outputs of events that the simulator has taken and
Expand Down