diff --git a/crates/node/src/scheduler/mod.rs b/crates/node/src/scheduler/mod.rs index 247083aa..7e424e4e 100644 --- a/crates/node/src/scheduler/mod.rs +++ b/crates/node/src/scheduler/mod.rs @@ -502,6 +502,11 @@ impl TaskManager for Scheduler { running_task.task_started.elapsed().as_secs() ); + // NOTE: The transaction execution time measurement is not logged + // here as it doesn't represent the real time the tx took to execute + // and timeout value would only mess the statistics of valid run + // times. + tracing::debug!("terminating VM running tx {}", tx_hash); if let Some(program_handle) = state.running_vms.remove(&tx_hash) { @@ -548,12 +553,19 @@ impl TaskManager for Scheduler { let mut state = self.state.lock().await; if let Some(running_task) = state.running_tasks.remove(&tx_hash) { + let task_runtime = running_task.task_started.elapsed(); tracing::info!( "task of Tx {} finished in {}sec", running_task.task.tx, - running_task.task_started.elapsed().as_secs() + task_runtime.as_secs() ); + let kind = match running_task.task.kind { + TaskKind::Proof => "proof", + TaskKind::Verification => "verification", + _ => "unknown", + }; + if let Err(err) = self.database.mark_tx_executed(&running_task.task.tx).await { tracing::error!( "failed to update transaction.executed => true - tx.hash: {}", @@ -616,6 +628,12 @@ impl TaskManager for Scheduler { ); } }; + + // Log the execution time. + metrics::TX_EXECUTION_TIME_COLLECTOR + .with_label_values(&[kind, "success"]) + .observe(task_runtime.as_millis() as f64); + tracing::info!("Submit result Tx created:{}", tx.hash.to_string()); // Move tx file from execution Tx path to new Tx path @@ -630,6 +648,11 @@ impl TaskManager for Scheduler { })?; } grpc::task_result_request::Result::Error(error) => { + // Log the execution time. + metrics::TX_EXECUTION_TIME_COLLECTOR + .with_label_values(&[kind, "failure"]) + .observe(task_runtime.as_millis() as f64); + tracing::warn!("Error during Tx:{tx_hash} execution:{error:?}"); } }