Logging (2/2): Replace DelayDetector (#9543)

Continues #9540

Deletes the `DelayDetector` class and replaces the uses of it with
spans.

---------

Co-authored-by: Anton Puhach <anton@near.org>
Co-authored-by: Simonas Kazlauskas <git@kazlauskas.me>
Co-authored-by: Jakob Meier <mail@jakobmeier.ch>

Cargo.toml

@@ -67,7 +67,6 @@ members = [
     "test-utils/testlib",
     "tools/database",
     "tools/chainsync-loadtest",
-    "tools/delay-detector",
     "tools/fork-network",
     "tools/indexer/example",
     "tools/mirror",
@@ -130,7 +129,6 @@ crossbeam-channel = "0.5"
 crossbeam-queue = "0.3.8"
 csv = "1.2.1"
 curve25519-dalek = "3"
-delay-detector = { path = "tools/delay-detector" }
 derive-enum-from-into = "0.1.1"
 derive_more = "0.99.9"
 dirs = "4"

chain/chain/Cargo.toml

@@ -13,7 +13,6 @@ borsh.workspace = true
 bytesize.workspace = true
 chrono.workspace = true
 crossbeam-channel.workspace = true
-delay-detector.workspace = true
 enum-map.workspace = true
 itertools.workspace = true
 itoa.workspace = true
@@ -49,7 +48,6 @@ assert_matches.workspace = true
 byzantine_asserts = []
 expensive_tests = []
 test_features = []
-delay_detector = ["delay-detector/delay_detector"]
 no_cache = ["near-store/no_cache"]
 new_epoch_sync = ["near-store/new_epoch_sync", "near-primitives/new_epoch_sync"]
 

chain/chain/src/chain.rs

@@ -23,7 +23,6 @@ use crate::{metrics, DoomslugThresholdMode};
 use borsh::BorshSerialize;
 use chrono::Duration;
 use crossbeam_channel::{unbounded, Receiver, Sender};
-use delay_detector::DelayDetector;
 use itertools::Itertools;
 use lru::LruCache;
 use near_chain_primitives::error::{BlockKnownError, Error, LogTransientStorageError};
@@ -940,7 +939,7 @@ impl Chain {
         tries: ShardTries,
         gc_config: &near_chain_configs::GCConfig,
     ) -> Result<(), Error> {
-        let _d = DelayDetector::new(|| "GC".into());
+        let _span = tracing::debug_span!(target: "chain", "clear_data").entered();
 
         let head = self.store.head()?;
         let tail = self.store.tail()?;
@@ -1028,7 +1027,7 @@ impl Chain {
     ///
     /// `gc_height_limit` limits how many heights will the function process.
     pub fn clear_archive_data(&mut self, gc_height_limit: BlockHeightDelta) -> Result<(), Error> {
-        let _d = DelayDetector::new(|| "GC".into());
+        let _span = tracing::debug_span!(target: "chain", "clear_archive_data").entered();
 
         let head = self.store.head()?;
         let gc_stop_height = self.runtime_adapter.get_gc_stop_height(&head.last_block_hash);

chain/client/Cargo.toml

@@ -37,7 +37,6 @@ thiserror.workspace = true
 tokio.workspace = true
 tracing.workspace = true
 
-delay-detector.workspace = true
 near-async.workspace = true
 near-chain-configs.workspace = true
 near-chain-primitives.workspace = true
@@ -69,11 +68,6 @@ test_features = [
   "near-chain/test_features",
   "near-chunks/test_features",
 ]
-delay_detector = [
-  "near-chain/delay_detector",
-  "near-network/delay_detector",
-  "delay-detector/delay_detector",
-]
 nightly_protocol = [
   "near-async/nightly_protocol",
   "near-chain-configs/nightly_protocol",

chain/client/src/client_actor.rs

@@ -263,8 +263,7 @@ impl ClientActor {
     ) -> Res {
         let (_span, msg) = handler_debug_span!(target: "client", msg, msg_type);
         self.check_triggers(ctx);
-        let _d =
-            delay_detector::DelayDetector::new(|| format!("NetworkClientMessage {:?}", msg).into());
+        let _span_inner = tracing::debug_span!(target: "client", "NetworkClientMessage").entered();
         metrics::CLIENT_MESSAGES_COUNT.with_label_values(&[msg_type]).inc();
         let timer =
             metrics::CLIENT_MESSAGES_PROCESSING_TIME.with_label_values(&[msg_type]).start_timer();
@@ -619,7 +618,6 @@ impl Handler<WithSpanContext<Status>> for ClientActor {
     fn handle(&mut self, msg: WithSpanContext<Status>, ctx: &mut Context<Self>) -> Self::Result {
         let (_span, msg) = handler_debug_span!(target: "client", msg);
         tracing::debug!(target: "client", ?msg);
-        let _d = delay_detector::DelayDetector::new(|| "client status".into());
         self.check_triggers(ctx);
 
         let head = self.client.chain.head()?;
@@ -772,7 +770,6 @@ impl Handler<WithSpanContext<GetNetworkInfo>> for ClientActor {
         ctx: &mut Context<Self>,
     ) -> Self::Result {
         let (_span, _msg) = handler_debug_span!(target: "client", msg);
-        let _d = delay_detector::DelayDetector::new(|| "client get network info".into());
         self.check_triggers(ctx);
 
         Ok(NetworkInfoResponse {
@@ -1103,6 +1100,7 @@ impl ClientActor {
     /// Returns the delay before the next time `check_triggers` should be called, which is
     /// min(time until the closest trigger, 1 second).
     fn check_triggers(&mut self, ctx: &mut Context<ClientActor>) -> Duration {
+        let _span = tracing::debug_span!(target: "client", "check_triggers").entered();
         if let Some(config_updater) = &mut self.config_updater {
             config_updater.try_update(&|updateable_client_config| {
                 self.client.update_client_config(updateable_client_config)
@@ -1121,8 +1119,6 @@ impl ClientActor {
             }
         }
 
-        let _d = delay_detector::DelayDetector::new(|| "client triggers".into());
-
         self.try_process_unfinished_blocks();
 
         let mut delay = Duration::from_secs(1);
@@ -1496,16 +1492,19 @@ impl ClientActor {
     /// Runs catchup on repeat, if this client is a validator.
     /// Schedules itself again if it was not ran as response to state parts job result
     fn catchup(&mut self, ctx: &mut Context<ClientActor>) {
-        let _d = delay_detector::DelayDetector::new(|| "client catchup".into());
-        if let Err(err) = self.client.run_catchup(
-            &self.network_info.highest_height_peers,
-            &self.state_parts_task_scheduler,
-            &self.block_catch_up_scheduler,
-            &self.state_split_scheduler,
-            self.get_apply_chunks_done_callback(),
-            &self.state_parts_client_arbiter.handle(),
-        ) {
-            error!(target: "client", "{:?} Error occurred during catchup for the next epoch: {:?}", self.client.validator_signer.as_ref().map(|vs| vs.validator_id()), err);
+        {
+            // An extra scope to limit the lifetime of the span.
+            let _span = tracing::debug_span!(target: "client", "catchup").entered();
+            if let Err(err) = self.client.run_catchup(
+                &self.network_info.highest_height_peers,
+                &self.state_parts_task_scheduler,
+                &self.block_catch_up_scheduler,
+                &self.state_split_scheduler,
+                self.get_apply_chunks_done_callback(),
+                &self.state_parts_client_arbiter.handle(),
+            ) {
+                error!(target: "client", "{:?} Error occurred during catchup for the next epoch: {:?}", self.client.validator_signer.as_ref().map(|vs| vs.validator_id()), err);
+            }
         }
 
         near_performance_metrics::actix::run_later(
@@ -1561,8 +1560,7 @@ impl ClientActor {
     /// Runs itself iff it was not ran as reaction for message with results of
     /// finishing state part job
     fn run_sync_step(&mut self) {
-        let _span = tracing::debug_span!(target: "client", "sync").entered();
-        let _d = delay_detector::DelayDetector::new(|| "client sync".into());
+        let _span = tracing::debug_span!(target: "client", "run_sync_step").entered();
 
         macro_rules! unwrap_and_report (($obj: expr) => (match $obj {
             Ok(v) => v,
@@ -1729,7 +1727,6 @@ impl ClientActor {
     /// Print current summary.
     fn log_summary(&mut self) {
         let _span = tracing::debug_span!(target: "client", "log_summary").entered();
-        let _d = delay_detector::DelayDetector::new(|| "client log summary".into());
         self.info_helper.log_summary(
             &self.client,
             &self.node_id,
@@ -1850,7 +1847,6 @@ impl Handler<WithSpanContext<GetClientConfig>> for ClientActor {
     ) -> Self::Result {
         let (_span, msg) = handler_debug_span!(target: "client", msg);
         tracing::debug!(target: "client", ?msg);
-        let _d = delay_detector::DelayDetector::new(|| "client get client config".into());
 
         Ok(self.client.config.clone())
     }

chain/client/src/view_client.rs

@@ -1466,7 +1466,6 @@ impl Handler<WithSpanContext<GetSplitStorageInfo>> for ViewClientActor {
     ) -> Self::Result {
         let (_span, msg) = handler_debug_span!(target: "client", msg);
         tracing::debug!(target: "client", ?msg);
-        let _d = delay_detector::DelayDetector::new(|| "client get split storage info".into());
 
         let store = self.chain.store().store();
         let head = store.get_ser::<Tip>(DBCol::BlockMisc, HEAD_KEY)?;

chain/network/Cargo.toml

@@ -48,7 +48,6 @@ tokio-util.workspace = true
 tracing.workspace = true
 time.workspace = true
 
-delay-detector.workspace = true
 near-async.workspace = true
 near-fmt.workspace = true
 near-o11y.workspace = true
@@ -83,7 +82,6 @@ nightly = [
   "near-primitives/nightly",
   "near-store/nightly",
 ]
-delay_detector = ["delay-detector/delay_detector"]
 performance_stats = [
     "near-performance-metrics/performance_stats",
 ]

chain/network/src/peer/peer_actor.rs

@@ -1607,7 +1607,6 @@ impl actix::Handler<WithSpanContext<SendMessage>> for PeerActor {
     #[perf]
     fn handle(&mut self, msg: WithSpanContext<SendMessage>, _: &mut Self::Context) {
         let (_span, msg) = handler_debug_span!(target: "network", msg);
-        let _d = delay_detector::DelayDetector::new(|| "send message".into());
         self.send_message_or_log(&msg.message);
     }
 }

chain/network/src/peer_manager/peer_manager_actor.rs

@@ -731,9 +731,6 @@ impl PeerManagerActor {
         let _span =
             tracing::trace_span!(target: "network", "handle_msg_network_requests", msg_type)
                 .entered();
-        let _d = delay_detector::DelayDetector::new(|| {
-            format!("network request {}", msg.as_ref()).into()
-        });
         metrics::REQUEST_COUNT_BY_TYPE_TOTAL.with_label_values(&[msg.as_ref()]).inc();
         match msg {
             NetworkRequests::Block { block } => {

core/o11y/src/log_counter.rs

@@ -56,14 +56,16 @@ impl LogCounter {
         line: Option<u32>,
     ) {
         match level {
-            &tracing::Level::ERROR | &tracing::Level::WARN => LOG_WITH_LOCATION_COUNTER
-                .with_label_values(&[
-                    &level.as_str(),
-                    target,
-                    file.unwrap_or(""),
-                    &line.map_or("".to_string(), |x| x.to_string()),
-                ])
-                .inc(),
+            &tracing::Level::ERROR | &tracing::Level::WARN | &tracing::Level::INFO => {
+                LOG_WITH_LOCATION_COUNTER
+                    .with_label_values(&[
+                        &level.as_str(),
+                        target,
+                        file.unwrap_or(""),
+                        &line.map_or("".to_string(), |x| x.to_string()),
+                    ])
+                    .inc()
+            }
             // Retaining LoC for low-severity messages can lead to excessive memory usage.
             // Therefore, only record LoC for high severity log messages.
             _ => {}

nearcore/Cargo.toml

@@ -67,8 +67,6 @@ near-vm-runner.workspace = true
 node-runtime.workspace = true
 near-config-utils.workspace = true
 
-delay-detector.workspace = true
-
 [dev-dependencies]
 bencher.workspace = true
 primitive-types.workspace = true
@@ -105,7 +103,6 @@ no_cache = [
   "near-chain/no_cache",
   "near-epoch-manager/no_cache",
 ]
-delay_detector = ["near-client/delay_detector", "delay-detector/delay_detector"]
 rosetta_rpc = ["near-rosetta-rpc"]
 json_rpc = ["near-jsonrpc", "near-jsonrpc-primitives"]
 protocol_feature_fix_staking_threshold = [

neard/Cargo.toml

@@ -66,7 +66,6 @@ c_memory_stats = ["nearcore/c_memory_stats"]
 test_features = ["nearcore/test_features"]
 expensive_tests = ["nearcore/expensive_tests"]
 no_cache = ["nearcore/no_cache"]
-delay_detector = ["nearcore/delay_detector"]
 rosetta_rpc = ["nearcore/rosetta_rpc"]
 json_rpc = ["nearcore/json_rpc"]
 protocol_feature_fix_staking_threshold = ["nearcore/protocol_feature_fix_staking_threshold"]