From 40a0b9e1e0fc841383365ed5ce0491d4d6a586c8 Mon Sep 17 00:00:00 2001 From: antiyro Date: Wed, 22 May 2024 16:22:14 +0200 Subject: [PATCH 1/4] added elapsed sync times --- crates/client/sync/src/fetch/mod.rs | 2 +- crates/client/sync/src/l2.rs | 46 +++++++++++++++++-- crates/client/sync/src/lib.rs | 3 +- .../client/sync/src/metrics/block_metrics.rs | 19 +++++++- 4 files changed, 64 insertions(+), 6 deletions(-) diff --git a/crates/client/sync/src/fetch/mod.rs b/crates/client/sync/src/fetch/mod.rs index 9f3d16054..f166ef1a6 100644 --- a/crates/client/sync/src/fetch/mod.rs +++ b/crates/client/sync/src/fetch/mod.rs @@ -47,7 +47,7 @@ pub async fn l2_fetch_task( } }; - log::info!("🥳🥳🥳 The sync process caught up with the tip of the chain."); + log::info!("🥳 The sync process caught up with the tip of the chain."); if let Some(sync_polling_interval) = sync_polling_interval { // Polling diff --git a/crates/client/sync/src/l2.rs b/crates/client/sync/src/l2.rs index 6842888d0..e5e707bee 100644 --- a/crates/client/sync/src/l2.rs +++ b/crates/client/sync/src/l2.rs @@ -1,7 +1,9 @@ //! Contains the code required to sync data from the feeder efficiently. +use core::sync; use std::pin::pin; use std::str::FromStr; -use std::sync::{Arc, RwLock}; +use std::sync::{Arc, Mutex, RwLock}; +use std::time::Instant; use anyhow::{bail, Context}; use futures::{stream, StreamExt, TryStreamExt}; @@ -16,6 +18,7 @@ use mp_types::block::{DBlockT, DHashT}; use serde::Deserialize; use sp_blockchain::HeaderBackend; use sp_core::H256; +use starknet_api::block; use starknet_api::hash::{StarkFelt, StarkHash}; use starknet_core::types::{PendingStateUpdate, StateUpdate}; use starknet_ff::FieldElement; @@ -30,6 +33,7 @@ use crate::convert::convert_block; use crate::fetch::fetchers::L2BlockAndUpdates; use crate::fetch::l2_fetch_task; use crate::l1::ETHEREUM_STATE_UPDATE; +use crate::metrics::block_metrics::{self, BlockMetrics}; use crate::utils::PerfStopwatch; use crate::{stopwatch_end, CommandSink}; @@ -138,6 +142,8 @@ async fn l2_verify_and_apply_task( mut command_sink: CommandSink, verify: bool, backup_every_n_blocks: Option, + block_metrics: Option, + sync_timer: Arc>> ) -> anyhow::Result<()> { let block_sender = Arc::new(block_sender); @@ -209,7 +215,7 @@ async fn l2_verify_and_apply_task( }, async { let sw = PerfStopwatch::new(); - create_block(&mut command_sink, &mut last_block_hash).await.expect("creating block"); + create_block(&mut command_sink, &mut last_block_hash, block_n, block_metrics.clone(), sync_timer.clone()).await.expect("creating block"); stopwatch_end!(sw, "end create_block {}: {:?}", block_n); } ); @@ -284,6 +290,7 @@ pub async fn sync( provider: SequencerGatewayProvider, client: Arc, config: L2SyncConfig, + block_metrics: Option, ) -> anyhow::Result<()> where C: HeaderBackend + 'static, @@ -291,6 +298,7 @@ where let (fetch_stream_sender, fetch_stream_receiver) = mpsc::channel(10); let (block_conv_sender, block_conv_receiver) = mpsc::channel(10); let provider = Arc::new(provider); + let sync_timer = Arc::new(Mutex::new(None)); // [Fetch task] ==new blocks and updates=> [Block conversion task] ======> [Verification and apply // task] @@ -316,6 +324,8 @@ where command_sink, config.verify, config.backup_every_n_blocks, + block_metrics.clone(), + Arc::clone(&sync_timer), )); tokio::select!( @@ -346,7 +356,7 @@ where } /// Notifies the consensus engine that a new block should be created. -async fn create_block(cmds: &mut CommandSink, parent_hash: &mut Option) -> Result<(), String> { +async fn create_block(cmds: &mut CommandSink, parent_hash: &mut Option, block_number: u64, block_metrics: Option, sync_timer: Arc>>) -> Result<(), String> { let (sender, receiver) = futures::channel::oneshot::channel(); cmds.try_send(sc_consensus_manual_seal::rpc::EngineCommand::SealNewBlock { @@ -362,6 +372,36 @@ async fn create_block(cmds: &mut CommandSink, parent_hash: &mut Option) -> .map_err(|err| format!("failed to seal block: {err}"))? .map_err(|err| format!("failed to seal block: {err}"))?; + // Update Block sync time metrics + if let Some(block_metrics) = block_metrics { + let elapsed_time; + { + let mut timer_guard = sync_timer.lock().unwrap(); + if let Some(start_time) = *timer_guard { + elapsed_time = start_time.elapsed().as_secs_f64(); + log::info!("Block Elapsed Time: {:?}", elapsed_time); + *timer_guard = Some(Instant::now()); + } else { + // For the first block, there is no previous timer set + elapsed_time = 0.0; + *timer_guard = Some(Instant::now()); + } + } + + let sync_time = block_metrics.l2_sync_time.get() + elapsed_time; + block_metrics.l2_sync_time.set(sync_time); + block_metrics.l2_latest_sync_time.set(elapsed_time); + block_metrics.l2_avg_sync_time.set(block_metrics.l2_sync_time.get() / block_number as f64); + + log::info!( + "Block number: {}, Sync time: {}, Avg sync time: {}, Latest sync time: {}", + block_number, + block_metrics.l2_sync_time.get(), + block_metrics.l2_avg_sync_time.get(), + block_metrics.l2_latest_sync_time.get() + ); + } + *parent_hash = Some(create_block_info.hash); Ok(()) } diff --git a/crates/client/sync/src/lib.rs b/crates/client/sync/src/lib.rs index 223699d76..e5a199f43 100644 --- a/crates/client/sync/src/lib.rs +++ b/crates/client/sync/src/lib.rs @@ -76,7 +76,7 @@ pub mod starknet_sync_worker { } tokio::select!( - res = l1::sync(l1_url.clone(), block_metrics) => res.context("syncing L1 state")?, + res = l1::sync(l1_url.clone(), block_metrics.clone()) => res.context("syncing L1 state")?, res = l2::sync( block_sender, command_sink, @@ -89,6 +89,7 @@ pub mod starknet_sync_worker { sync_polling_interval: fetch_config.sync_polling_interval, backup_every_n_blocks, }, + block_metrics, ) => res.context("syncing L2 state")? ); diff --git a/crates/client/sync/src/metrics/block_metrics.rs b/crates/client/sync/src/metrics/block_metrics.rs index 7a1ed1057..07f0e2593 100644 --- a/crates/client/sync/src/metrics/block_metrics.rs +++ b/crates/client/sync/src/metrics/block_metrics.rs @@ -3,10 +3,15 @@ use prometheus_endpoint::{register, PrometheusError, Registry}; #[derive(Clone, Debug)] pub struct BlockMetrics { + // L2 network metrics pub l2_block_number: Gauge, - pub l1_block_number: Gauge, + pub l2_sync_time: Gauge, + pub l2_avg_sync_time: Gauge, + pub l2_latest_sync_time: Gauge, pub transaction_count: Gauge, pub event_count: Gauge, + // L1 network metrics + pub l1_block_number: Gauge, pub l1_gas_price_wei: Gauge, pub l1_gas_price_strk: Gauge, } @@ -18,6 +23,18 @@ impl BlockMetrics { Gauge::new("deoxys_l2_block_number", "Gauge for deoxys L2 block number")?, registry, )?, + l2_sync_time: register( + Gauge::new("deoxys_l2_sync_time", "Gauge for deoxys L2 sync time")?, + registry, + )?, + l2_avg_sync_time: register( + Gauge::new("deoxys_l2_avg_sync_time", "Gauge for deoxys L2 average sync time")?, + registry, + )?, + l2_latest_sync_time: register( + Gauge::new("deoxys_l2_latest_sync_time", "Gauge for deoxys L2 latest sync time")?, + registry, + )?, l1_block_number: register( Gauge::new("deoxys_l1_block_number", "Gauge for deoxys L1 block number")?, registry, From 7da48986745682ca7a8a653850570909319939fb Mon Sep 17 00:00:00 2001 From: antiyro Date: Wed, 22 May 2024 16:43:20 +0200 Subject: [PATCH 2/4] added change logs --- CHANGELOG.md | 1 + crates/client/sync/src/l2.rs | 25 +++++++++++++------ .../client/sync/src/metrics/block_metrics.rs | 5 +--- 3 files changed, 20 insertions(+), 11 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 8982ec788..4a8080db1 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -2,6 +2,7 @@ ## Next release +- feat(metrics): Added sync time metrics - feat(infra): corrected dockerfile + docker-compose - fix(rpc): error handling - fix(lib): updated core libs to match oss diff --git a/crates/client/sync/src/l2.rs b/crates/client/sync/src/l2.rs index e5e707bee..42c3856fe 100644 --- a/crates/client/sync/src/l2.rs +++ b/crates/client/sync/src/l2.rs @@ -1,5 +1,4 @@ //! Contains the code required to sync data from the feeder efficiently. -use core::sync; use std::pin::pin; use std::str::FromStr; use std::sync::{Arc, Mutex, RwLock}; @@ -18,7 +17,6 @@ use mp_types::block::{DBlockT, DHashT}; use serde::Deserialize; use sp_blockchain::HeaderBackend; use sp_core::H256; -use starknet_api::block; use starknet_api::hash::{StarkFelt, StarkHash}; use starknet_core::types::{PendingStateUpdate, StateUpdate}; use starknet_ff::FieldElement; @@ -33,7 +31,7 @@ use crate::convert::convert_block; use crate::fetch::fetchers::L2BlockAndUpdates; use crate::fetch::l2_fetch_task; use crate::l1::ETHEREUM_STATE_UPDATE; -use crate::metrics::block_metrics::{self, BlockMetrics}; +use crate::metrics::block_metrics::BlockMetrics; use crate::utils::PerfStopwatch; use crate::{stopwatch_end, CommandSink}; @@ -143,7 +141,7 @@ async fn l2_verify_and_apply_task( verify: bool, backup_every_n_blocks: Option, block_metrics: Option, - sync_timer: Arc>> + sync_timer: Arc>>, ) -> anyhow::Result<()> { let block_sender = Arc::new(block_sender); @@ -215,7 +213,15 @@ async fn l2_verify_and_apply_task( }, async { let sw = PerfStopwatch::new(); - create_block(&mut command_sink, &mut last_block_hash, block_n, block_metrics.clone(), sync_timer.clone()).await.expect("creating block"); + create_block( + &mut command_sink, + &mut last_block_hash, + block_n, + block_metrics.clone(), + sync_timer.clone(), + ) + .await + .expect("creating block"); stopwatch_end!(sw, "end create_block {}: {:?}", block_n); } ); @@ -356,7 +362,13 @@ where } /// Notifies the consensus engine that a new block should be created. -async fn create_block(cmds: &mut CommandSink, parent_hash: &mut Option, block_number: u64, block_metrics: Option, sync_timer: Arc>>) -> Result<(), String> { +async fn create_block( + cmds: &mut CommandSink, + parent_hash: &mut Option, + block_number: u64, + block_metrics: Option, + sync_timer: Arc>>, +) -> Result<(), String> { let (sender, receiver) = futures::channel::oneshot::channel(); cmds.try_send(sc_consensus_manual_seal::rpc::EngineCommand::SealNewBlock { @@ -379,7 +391,6 @@ async fn create_block(cmds: &mut CommandSink, parent_hash: &mut Option, bl let mut timer_guard = sync_timer.lock().unwrap(); if let Some(start_time) = *timer_guard { elapsed_time = start_time.elapsed().as_secs_f64(); - log::info!("Block Elapsed Time: {:?}", elapsed_time); *timer_guard = Some(Instant::now()); } else { // For the first block, there is no previous timer set diff --git a/crates/client/sync/src/metrics/block_metrics.rs b/crates/client/sync/src/metrics/block_metrics.rs index 07f0e2593..079637ed7 100644 --- a/crates/client/sync/src/metrics/block_metrics.rs +++ b/crates/client/sync/src/metrics/block_metrics.rs @@ -23,10 +23,7 @@ impl BlockMetrics { Gauge::new("deoxys_l2_block_number", "Gauge for deoxys L2 block number")?, registry, )?, - l2_sync_time: register( - Gauge::new("deoxys_l2_sync_time", "Gauge for deoxys L2 sync time")?, - registry, - )?, + l2_sync_time: register(Gauge::new("deoxys_l2_sync_time", "Gauge for deoxys L2 sync time")?, registry)?, l2_avg_sync_time: register( Gauge::new("deoxys_l2_avg_sync_time", "Gauge for deoxys L2 average sync time")?, registry, From 6fa8137060b211b3b2663e4bc571cfbd6ff6b635 Mon Sep 17 00:00:00 2001 From: antiyro Date: Wed, 22 May 2024 16:46:39 +0200 Subject: [PATCH 3/4] corrected docker --- Dockerfile | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/Dockerfile b/Dockerfile index c9d7d0845..4d67c0cf5 100644 --- a/Dockerfile +++ b/Dockerfile @@ -9,7 +9,7 @@ RUN apt-get -y update && \ build-essential # Set the working directory -WORKDIR /usr/local/bin +WORKDIR /usr/src/ # Copy the source code into the container COPY . . @@ -30,7 +30,7 @@ RUN apt-get -y update && \ WORKDIR /usr/local/bin # Copy the compiled binary from the builder stage -COPY --from=builder /usr/local/bin/target/release/deoxys . +COPY --from=builder /usr/src/target/release/deoxys . # Set the entrypoint -ENTRYPOINT ["./deoxys"] +ENTRYPOINT ["./deoxys"] \ No newline at end of file From 6eda94410dced5e88740db5dc5d9775514374c98 Mon Sep 17 00:00:00 2001 From: antiyro Date: Wed, 22 May 2024 17:18:13 +0200 Subject: [PATCH 4/4] removed unecessary log --- crates/client/sync/src/l2.rs | 8 -------- 1 file changed, 8 deletions(-) diff --git a/crates/client/sync/src/l2.rs b/crates/client/sync/src/l2.rs index 42c3856fe..b444923af 100644 --- a/crates/client/sync/src/l2.rs +++ b/crates/client/sync/src/l2.rs @@ -403,14 +403,6 @@ async fn create_block( block_metrics.l2_sync_time.set(sync_time); block_metrics.l2_latest_sync_time.set(elapsed_time); block_metrics.l2_avg_sync_time.set(block_metrics.l2_sync_time.get() / block_number as f64); - - log::info!( - "Block number: {}, Sync time: {}, Avg sync time: {}, Latest sync time: {}", - block_number, - block_metrics.l2_sync_time.get(), - block_metrics.l2_avg_sync_time.get(), - block_metrics.l2_latest_sync_time.get() - ); } *parent_hash = Some(create_block_info.hash);