From b2ce5dc9f571db38b89f60e0a5d0d0af7dda57a8 Mon Sep 17 00:00:00 2001 From: Pankaj Garg Date: Fri, 17 May 2019 07:00:06 -0700 Subject: [PATCH] Adjust log level for counter metrics (#4323) --- core/src/banking_stage.rs | 14 +++---- core/src/blocktree_processor.rs | 4 +- core/src/broadcast_stage.rs | 11 ++++-- core/src/cluster_info.rs | 54 +++++++++++++------------- core/src/cluster_info_vote_listener.rs | 4 +- core/src/fetch_stage.rs | 4 +- core/src/packet.rs | 4 +- core/src/replay_stage.rs | 4 +- core/src/retransmit_stage.rs | 4 +- core/src/sigverify.rs | 8 ++-- core/src/window_service.rs | 14 +++---- metrics/src/counter.rs | 39 +++++++++++++++++++ runtime/src/accounts.rs | 8 ++-- runtime/src/bank.rs | 22 ++++++----- 14 files changed, 120 insertions(+), 74 deletions(-) diff --git a/core/src/banking_stage.rs b/core/src/banking_stage.rs index c04d13d1a0..04f629c588 100644 --- a/core/src/banking_stage.rs +++ b/core/src/banking_stage.rs @@ -15,7 +15,7 @@ use crate::service::Service; use crate::sigverify_stage::VerifiedPackets; use bincode::deserialize; use itertools::Itertools; -use solana_metrics::inc_new_counter_info; +use solana_metrics::{inc_new_counter_debug, inc_new_counter_info, inc_new_counter_warn}; use solana_runtime::accounts_db::ErrorCounters; use solana_runtime::bank::Bank; use solana_runtime::locked_accounts_results::LockedAccountsResults; @@ -187,7 +187,7 @@ impl BankingStage { inc_new_counter_info!("banking_stage-rebuffered_packets", rebuffered_packets); inc_new_counter_info!("banking_stage-consumed_buffered_packets", new_tx_count); - inc_new_counter_info!("banking_stage-process_transactions", new_tx_count); + inc_new_counter_debug!("banking_stage-process_transactions", new_tx_count); Ok(unprocessed_packets) } @@ -359,7 +359,7 @@ impl BankingStage { debug!("processed: {} ", processed_transactions.len()); // unlock all the accounts with errors which are filtered by the above `filter_map` if !processed_transactions.is_empty() { - inc_new_counter_info!( + inc_new_counter_warn!( "banking_stage-record_transactions", processed_transactions.len() ); @@ -664,7 +664,7 @@ impl BankingStage { timing::duration_as_ms(&recv_start.elapsed()), count, ); - inc_new_counter_info!("banking_stage-transactions_received", count); + inc_new_counter_debug!("banking_stage-transactions_received", count); let proc_start = Instant::now(); let mut new_tx_count = 0; let mut mms_iter = mms.into_iter(); @@ -711,7 +711,7 @@ impl BankingStage { } } - inc_new_counter_info!( + inc_new_counter_debug!( "banking_stage-time_ms", timing::duration_as_ms(&proc_start.elapsed()) as usize ); @@ -725,8 +725,8 @@ impl BankingStage { new_tx_count, (new_tx_count as f32) / (total_time_s) ); - inc_new_counter_info!("banking_stage-process_packets", count); - inc_new_counter_info!("banking_stage-process_transactions", new_tx_count); + inc_new_counter_debug!("banking_stage-process_packets", count); + inc_new_counter_debug!("banking_stage-process_transactions", new_tx_count); *recv_start = Instant::now(); diff --git a/core/src/blocktree_processor.rs b/core/src/blocktree_processor.rs index 562831925e..a301c4a8e9 100644 --- a/core/src/blocktree_processor.rs +++ b/core/src/blocktree_processor.rs @@ -3,7 +3,7 @@ use crate::blocktree::Blocktree; use crate::entry::{Entry, EntrySlice}; use crate::leader_schedule_cache::LeaderScheduleCache; use rayon::prelude::*; -use solana_metrics::{datapoint, inc_new_counter_info}; +use solana_metrics::{datapoint, inc_new_counter_debug}; use solana_runtime::bank::Bank; use solana_runtime::locked_accounts_results::LockedAccountsResults; use solana_sdk::genesis_block::GenesisBlock; @@ -26,7 +26,7 @@ fn par_execute_entries( bank: &Bank, entries: &[(&Entry, LockedAccountsResults)], ) -> Result<()> { - inc_new_counter_info!("bank-par_execute_entries-count", entries.len()); + inc_new_counter_debug!("bank-par_execute_entries-count", entries.len()); let results: Vec> = entries .into_par_iter() .map(|(e, locked_accounts)| { diff --git a/core/src/broadcast_stage.rs b/core/src/broadcast_stage.rs index 3c232a441e..04f465e12d 100644 --- a/core/src/broadcast_stage.rs +++ b/core/src/broadcast_stage.rs @@ -10,7 +10,10 @@ use crate::result::{Error, Result}; use crate::service::Service; use crate::staking_utils; use rayon::prelude::*; -use solana_metrics::{datapoint, inc_new_counter_info}; +use solana_metrics::{ + datapoint, inc_new_counter_debug, inc_new_counter_error, inc_new_counter_info, + inc_new_counter_warn, +}; use solana_sdk::hash::Hash; use solana_sdk::pubkey::Pubkey; use solana_sdk::timing::duration_as_ms; @@ -77,7 +80,7 @@ impl Broadcast { .unwrap() .sorted_tvu_peers(staking_utils::staked_nodes_at_epoch(&bank, bank_epoch).as_ref()); - inc_new_counter_info!("broadcast_service-num_peers", broadcast_table.len() + 1); + inc_new_counter_warn!("broadcast_service-num_peers", broadcast_table.len() + 1); // Layer 1, leader nodes are limited to the fanout size. broadcast_table.truncate(DATA_PLANE_FANOUT); @@ -126,7 +129,7 @@ impl Broadcast { // Send out data ClusterInfo::broadcast(&self.id, contains_last_tick, &broadcast_table, sock, &blobs)?; - inc_new_counter_info!("streamer-broadcast-sent", blobs.len()); + inc_new_counter_debug!("streamer-broadcast-sent", blobs.len()); // send out erasures ClusterInfo::broadcast(&self.id, false, &broadcast_table, sock, &coding)?; @@ -198,7 +201,7 @@ impl BroadcastStage { Error::RecvTimeoutError(RecvTimeoutError::Timeout) => (), Error::ClusterInfoError(ClusterInfoError::NoPeers) => (), // TODO: Why are the unit-tests throwing hundreds of these? _ => { - inc_new_counter_info!("streamer-broadcaster-error", 1, 1); + inc_new_counter_error!("streamer-broadcaster-error", 1, 1); error!("broadcaster error: {:?}", e); } } diff --git a/core/src/cluster_info.rs b/core/src/cluster_info.rs index d6dd532007..091e153aba 100644 --- a/core/src/cluster_info.rs +++ b/core/src/cluster_info.rs @@ -29,7 +29,7 @@ use core::cmp; use hashbrown::HashMap; use rand::{thread_rng, Rng}; use rayon::prelude::*; -use solana_metrics::{datapoint, inc_new_counter_info}; +use solana_metrics::{datapoint, inc_new_counter_debug, inc_new_counter_error}; use solana_netutil::{ bind_in_range, bind_to, find_available_port_in_range, multi_bind_in_range, PortRange, }; @@ -661,7 +661,7 @@ impl ClusterInfo { ) -> Result<()> { if broadcast_table.is_empty() { debug!("{}:not enough peers in cluster_info table", id); - inc_new_counter_info!("cluster_info-broadcast-not_enough_peers_error", 1); + inc_new_counter_error!("cluster_info-broadcast-not_enough_peers_error", 1); Err(ClusterInfoError::NoPeers)?; } @@ -678,7 +678,7 @@ impl ClusterInfo { e?; } - inc_new_counter_info!("cluster_info-broadcast-max_idx", blobs.len()); + inc_new_counter_debug!("cluster_info-broadcast-max_idx", blobs.len()); Ok(()) } @@ -724,7 +724,7 @@ impl ClusterInfo { wblob.set_forwarded(was_forwarded); for e in errs { if let Err(e) = &e { - inc_new_counter_info!("cluster_info-retransmit-send_to_error", 1, 1); + inc_new_counter_error!("cluster_info-retransmit-send_to_error", 1, 1); error!("retransmit result {:?}", e); } e?; @@ -1017,14 +1017,14 @@ impl ClusterInfo { let blob = blocktree.get_data_blob(slot, blob_index); if let Ok(Some(mut blob)) = blob { - inc_new_counter_info!("cluster_info-window-request-ledger", 1); + inc_new_counter_debug!("cluster_info-window-request-ledger", 1); blob.meta.set_addr(from_addr); return vec![Arc::new(RwLock::new(blob))]; } } - inc_new_counter_info!("cluster_info-window-request-fail", 1); + inc_new_counter_debug!("cluster_info-window-request-fail", 1); trace!( "{}: failed RequestWindowIndex {} {} {}", me.id, @@ -1112,7 +1112,7 @@ impl ClusterInfo { from_addr: &SocketAddr, ) -> Vec { let self_id = me.read().unwrap().gossip.id; - inc_new_counter_info!("cluster_info-pull_request", 1); + inc_new_counter_debug!("cluster_info-pull_request", 1); if caller.contact_info().is_none() { return vec![]; } @@ -1122,7 +1122,7 @@ impl ClusterInfo { "PullRequest ignored, I'm talking to myself: me={} remoteme={}", self_id, from.id ); - inc_new_counter_info!("cluster_info-window-request-loopback", 1); + inc_new_counter_debug!("cluster_info-window-request-loopback", 1); return vec![]; } let now = timestamp(); @@ -1138,10 +1138,10 @@ impl ClusterInfo { // This may or may not be correct for everybody, but it's better than leaving the remote with // an unspecified address in our table if from.gossip.ip().is_unspecified() { - inc_new_counter_info!("cluster_info-window-request-updates-unspec-gossip", 1); + inc_new_counter_debug!("cluster_info-window-request-updates-unspec-gossip", 1); from.gossip = *from_addr; } - inc_new_counter_info!("cluster_info-pull_request-rsp", len); + inc_new_counter_debug!("cluster_info-pull_request-rsp", len); to_shared_blob(rsp, from.gossip).ok().into_iter().collect() } fn handle_pull_response(me: &Arc>, from: &Pubkey, data: Vec) { @@ -1153,8 +1153,8 @@ impl ClusterInfo { .unwrap() .gossip .process_pull_response(from, data, timestamp()); - inc_new_counter_info!("cluster_info-pull_request_response", 1); - inc_new_counter_info!("cluster_info-pull_request_response-size", len); + inc_new_counter_debug!("cluster_info-pull_request_response", 1); + inc_new_counter_debug!("cluster_info-pull_request_response-size", len); report_time_spent("ReceiveUpdates", &now.elapsed(), &format!(" len: {}", len)); } @@ -1164,17 +1164,17 @@ impl ClusterInfo { data: Vec, ) -> Vec { let self_id = me.read().unwrap().gossip.id; - inc_new_counter_info!("cluster_info-push_message", 1, 0, 1000); + inc_new_counter_debug!("cluster_info-push_message", 1, 0, 1000); let prunes: Vec<_> = me .write() .unwrap() .gossip .process_push_message(data, timestamp()); if !prunes.is_empty() { - inc_new_counter_info!("cluster_info-push_message-prunes", prunes.len()); + inc_new_counter_debug!("cluster_info-push_message-prunes", prunes.len()); let ci = me.read().unwrap().lookup(from).cloned(); let pushes: Vec<_> = me.write().unwrap().new_push_requests(); - inc_new_counter_info!("cluster_info-push_message-pushes", pushes.len()); + inc_new_counter_debug!("cluster_info-push_message-pushes", pushes.len()); let mut rsp: Vec<_> = ci .and_then(|ci| { let mut prune_msg = PruneData { @@ -1231,7 +1231,7 @@ impl ClusterInfo { "{}: Ignored received repair request from ME {}", self_id, from.id, ); - inc_new_counter_info!("cluster_info-handle-repair--eq", 1); + inc_new_counter_debug!("cluster_info-handle-repair--eq", 1); return vec![]; } @@ -1245,7 +1245,7 @@ impl ClusterInfo { let (res, label) = { match &request { Protocol::RequestWindowIndex(from, slot, blob_index) => { - inc_new_counter_info!("cluster_info-request-window-index", 1); + inc_new_counter_debug!("cluster_info-request-window-index", 1); ( Self::run_window_request( from, @@ -1260,7 +1260,7 @@ impl ClusterInfo { } Protocol::RequestHighestWindowIndex(_, slot, highest_index) => { - inc_new_counter_info!("cluster_info-request-highest-window-index", 1); + inc_new_counter_debug!("cluster_info-request-highest-window-index", 1); ( Self::run_highest_window_request( &from_addr, @@ -1272,7 +1272,7 @@ impl ClusterInfo { ) } Protocol::RequestOrphan(_, slot) => { - inc_new_counter_info!("cluster_info-request-orphan", 1); + inc_new_counter_debug!("cluster_info-request-orphan", 1); ( Self::run_orphan(&from_addr, blocktree, *slot, MAX_ORPHAN_REPAIR_RESPONSES), "RequestOrphan", @@ -1297,7 +1297,7 @@ impl ClusterInfo { // TODO verify messages faster Protocol::PullRequest(filter, caller) => { if !caller.verify() { - inc_new_counter_info!("cluster_info-gossip_pull_request_verify_fail", 1); + inc_new_counter_error!("cluster_info-gossip_pull_request_verify_fail", 1); vec![] } else { Self::handle_pull_request(me, filter, caller, from_addr) @@ -1307,7 +1307,7 @@ impl ClusterInfo { data.retain(|v| { let ret = v.verify(); if !ret { - inc_new_counter_info!("cluster_info-gossip_pull_response_verify_fail", 1); + inc_new_counter_error!("cluster_info-gossip_pull_response_verify_fail", 1); } ret }); @@ -1318,7 +1318,7 @@ impl ClusterInfo { data.retain(|v| { let ret = v.verify(); if !ret { - inc_new_counter_info!("cluster_info-gossip_push_msg_verify_fail", 1); + inc_new_counter_error!("cluster_info-gossip_push_msg_verify_fail", 1); } ret }); @@ -1326,8 +1326,8 @@ impl ClusterInfo { } Protocol::PruneMessage(from, data) => { if data.verify() { - inc_new_counter_info!("cluster_info-prune_message", 1); - inc_new_counter_info!("cluster_info-prune_message-size", data.prunes.len()); + inc_new_counter_debug!("cluster_info-prune_message", 1); + inc_new_counter_debug!("cluster_info-prune_message-size", data.prunes.len()); match me.write().unwrap().gossip.process_prune_msg( &from, &data.destination, @@ -1336,16 +1336,16 @@ impl ClusterInfo { timestamp(), ) { Err(CrdsGossipError::PruneMessageTimeout) => { - inc_new_counter_info!("cluster_info-prune_message_timeout", 1) + inc_new_counter_debug!("cluster_info-prune_message_timeout", 1) } Err(CrdsGossipError::BadPruneDestination) => { - inc_new_counter_info!("cluster_info-bad_prune_destination", 1) + inc_new_counter_debug!("cluster_info-bad_prune_destination", 1) } Err(_) => (), Ok(_) => (), } } else { - inc_new_counter_info!("cluster_info-gossip_prune_msg_verify_fail", 1); + inc_new_counter_debug!("cluster_info-gossip_prune_msg_verify_fail", 1); } vec![] } diff --git a/core/src/cluster_info_vote_listener.rs b/core/src/cluster_info_vote_listener.rs index e8759c149b..3752c17184 100644 --- a/core/src/cluster_info_vote_listener.rs +++ b/core/src/cluster_info_vote_listener.rs @@ -4,7 +4,7 @@ use crate::result::Result; use crate::service::Service; use crate::sigverify_stage::VerifiedPackets; use crate::{packet, sigverify}; -use solana_metrics::inc_new_counter_info; +use solana_metrics::inc_new_counter_debug; use std::sync::atomic::{AtomicBool, Ordering}; use std::sync::mpsc::Sender; use std::sync::{Arc, Mutex, RwLock}; @@ -56,7 +56,7 @@ impl ClusterInfoVoteListener { let (votes, new_ts) = cluster_info.read().unwrap().get_votes(last_ts); if poh_recorder.lock().unwrap().bank().is_some() { last_ts = new_ts; - inc_new_counter_info!("cluster_info_vote_listener-recv_count", votes.len()); + inc_new_counter_debug!("cluster_info_vote_listener-recv_count", votes.len()); let msgs = packet::to_packets(&votes); if !msgs.is_empty() { let r = if sigverify_disabled { diff --git a/core/src/fetch_stage.rs b/core/src/fetch_stage.rs index 9593755f5a..599e29b921 100644 --- a/core/src/fetch_stage.rs +++ b/core/src/fetch_stage.rs @@ -4,7 +4,7 @@ use crate::poh_recorder::PohRecorder; use crate::result::{Error, Result}; use crate::service::Service; use crate::streamer::{self, PacketReceiver, PacketSender}; -use solana_metrics::inc_new_counter_info; +use solana_metrics::{inc_new_counter_debug, inc_new_counter_info}; use solana_sdk::timing::DEFAULT_TICKS_PER_SLOT; use std::net::UdpSocket; use std::sync::atomic::AtomicBool; @@ -66,7 +66,7 @@ impl FetchStage { .unwrap() .would_be_leader(DEFAULT_TICKS_PER_SLOT * 2) { - inc_new_counter_info!("fetch_stage-honor_forwards", len); + inc_new_counter_debug!("fetch_stage-honor_forwards", len); for packets in batch { if sendr.send(packets).is_err() { return Err(Error::SendError); diff --git a/core/src/packet.rs b/core/src/packet.rs index d2a60e437a..cc97da77e4 100644 --- a/core/src/packet.rs +++ b/core/src/packet.rs @@ -4,7 +4,7 @@ use crate::result::{Error, Result}; use bincode; use byteorder::{ByteOrder, LittleEndian}; use serde::Serialize; -use solana_metrics::inc_new_counter_info; +use solana_metrics::inc_new_counter_debug; use solana_sdk::hash::Hash; pub use solana_sdk::packet::PACKET_DATA_SIZE; use solana_sdk::pubkey::Pubkey; @@ -245,7 +245,7 @@ impl Packets { } } self.packets.truncate(i); - inc_new_counter_info!("packets-recv_count", i); + inc_new_counter_debug!("packets-recv_count", i); Ok(i) } diff --git a/core/src/replay_stage.rs b/core/src/replay_stage.rs index 89fd897154..b9b7a9b3c7 100644 --- a/core/src/replay_stage.rs +++ b/core/src/replay_stage.rs @@ -14,7 +14,7 @@ use crate::result::{Error, Result}; use crate::rpc_subscriptions::RpcSubscriptions; use crate::service::Service; use hashbrown::HashMap; -use solana_metrics::{datapoint, inc_new_counter_info}; +use solana_metrics::{datapoint, inc_new_counter_error, inc_new_counter_info}; use solana_runtime::bank::Bank; use solana_sdk::hash::Hash; use solana_sdk::pubkey::Pubkey; @@ -286,7 +286,7 @@ impl ReplayStage { } else { info!("debug to verify entries {}", len); //TODO: mark this fork as failed - inc_new_counter_info!("replicate-stage_failed_process_entries", len); + inc_new_counter_error!("replicate-stage_failed_process_entries", len); } Ok(()) } diff --git a/core/src/retransmit_stage.rs b/core/src/retransmit_stage.rs index 26c29372dd..bc8c69c733 100644 --- a/core/src/retransmit_stage.rs +++ b/core/src/retransmit_stage.rs @@ -10,7 +10,7 @@ use crate::service::Service; use crate::staking_utils; use crate::streamer::BlobReceiver; use crate::window_service::{should_retransmit_and_persist, WindowService}; -use solana_metrics::{datapoint, inc_new_counter_info}; +use solana_metrics::{datapoint, inc_new_counter_error}; use solana_runtime::epoch_schedule::EpochSchedule; use solana_sdk::hash::Hash; use std::net::UdpSocket; @@ -89,7 +89,7 @@ fn retransmitter( Error::RecvTimeoutError(RecvTimeoutError::Disconnected) => break, Error::RecvTimeoutError(RecvTimeoutError::Timeout) => (), _ => { - inc_new_counter_info!("streamer-retransmit-error", 1, 1); + inc_new_counter_error!("streamer-retransmit-error", 1, 1); } } } diff --git a/core/src/sigverify.rs b/core/src/sigverify.rs index 636d7e3355..616dd4b725 100644 --- a/core/src/sigverify.rs +++ b/core/src/sigverify.rs @@ -6,7 +6,7 @@ use crate::packet::{Packet, Packets}; use crate::result::Result; -use solana_metrics::inc_new_counter_info; +use solana_metrics::inc_new_counter_debug; use solana_sdk::pubkey::Pubkey; use solana_sdk::short_vec::decode_len; use solana_sdk::signature::Signature; @@ -178,7 +178,7 @@ pub fn ed25519_verify_cpu(batches: &[Packets]) -> Vec> { .into_par_iter() .map(|p| p.packets.par_iter().map(verify_packet).collect()) .collect(); - inc_new_counter_info!("ed25519_verify_cpu", count); + inc_new_counter_debug!("ed25519_verify_cpu", count); rv } @@ -190,7 +190,7 @@ pub fn ed25519_verify_disabled(batches: &[Packets]) -> Vec> { .into_par_iter() .map(|p| vec![1u8; p.packets.len()]) .collect(); - inc_new_counter_info!("ed25519_verify_disabled", count); + inc_new_counter_debug!("ed25519_verify_disabled", count); rv } @@ -279,7 +279,7 @@ pub fn ed25519_verify(batches: &[Packets]) -> Vec> { } } } - inc_new_counter_info!("ed25519_verify_gpu", count); + inc_new_counter_debug!("ed25519_verify_gpu", count); rvs } diff --git a/core/src/window_service.rs b/core/src/window_service.rs index d2acd04607..0251dd27b5 100644 --- a/core/src/window_service.rs +++ b/core/src/window_service.rs @@ -9,7 +9,7 @@ use crate::repair_service::{RepairService, RepairStrategy}; use crate::result::{Error, Result}; use crate::service::Service; use crate::streamer::{BlobReceiver, BlobSender}; -use solana_metrics::inc_new_counter_info; +use solana_metrics::{inc_new_counter_debug, inc_new_counter_error}; use solana_runtime::bank::Bank; use solana_sdk::hash::Hash; use solana_sdk::pubkey::Pubkey; @@ -34,7 +34,7 @@ fn retransmit_blobs(blobs: &[SharedBlob], retransmit: &BlobSender, id: &Pubkey) } if !retransmit_queue.is_empty() { - inc_new_counter_info!( + inc_new_counter_debug!( "streamer-recv_window-retransmit", retransmit_queue.len(), 0, @@ -88,13 +88,13 @@ pub fn should_retransmit_and_persist( }; if blob.id() == *my_id { - inc_new_counter_info!("streamer-recv_window-circular_transmission", 1); + inc_new_counter_debug!("streamer-recv_window-circular_transmission", 1); false } else if slot_leader_id == None { - inc_new_counter_info!("streamer-recv_window-unknown_leader", 1); + inc_new_counter_debug!("streamer-recv_window-unknown_leader", 1); true } else if slot_leader_id != Some(blob.id()) { - inc_new_counter_info!("streamer-recv_window-wrong_leader", 1); + inc_new_counter_debug!("streamer-recv_window-wrong_leader", 1); false } else { true @@ -119,7 +119,7 @@ where blobs.append(&mut blob) } let now = Instant::now(); - inc_new_counter_info!("streamer-recv_window-recv", blobs.len(), 0, 1000); + inc_new_counter_debug!("streamer-recv_window-recv", blobs.len(), 0, 1000); blobs.retain(|blob| { blob_filter(&blob.read().unwrap()) @@ -223,7 +223,7 @@ impl WindowService { Error::RecvTimeoutError(RecvTimeoutError::Disconnected) => break, Error::RecvTimeoutError(RecvTimeoutError::Timeout) => (), _ => { - inc_new_counter_info!("streamer-window-error", 1, 1); + inc_new_counter_error!("streamer-window-error", 1, 1); error!("window error: {:?}", e); } } diff --git a/metrics/src/counter.rs b/metrics/src/counter.rs index 027571804a..81d6ac7057 100644 --- a/metrics/src/counter.rs +++ b/metrics/src/counter.rs @@ -63,6 +63,32 @@ macro_rules! inc_new_counter { }}; } +#[macro_export] +macro_rules! inc_new_counter_error { + ($name:expr, $count:expr) => {{ + inc_new_counter!($name, $count, log::Level::Error, 0, 0); + }}; + ($name:expr, $count:expr, $lograte:expr) => {{ + inc_new_counter!($name, $count, log::Level::Error, $lograte, 0); + }}; + ($name:expr, $count:expr, $lograte:expr, $metricsrate:expr) => {{ + inc_new_counter!($name, $count, log::Level::Error, $lograte, $metricsrate); + }}; +} + +#[macro_export] +macro_rules! inc_new_counter_warn { + ($name:expr, $count:expr) => {{ + inc_new_counter!($name, $count, log::Level::Warn, 0, 0); + }}; + ($name:expr, $count:expr, $lograte:expr) => {{ + inc_new_counter!($name, $count, log::Level::Warn, $lograte, 0); + }}; + ($name:expr, $count:expr, $lograte:expr, $metricsrate:expr) => {{ + inc_new_counter!($name, $count, log::Level::Warn, $lograte, $metricsrate); + }}; +} + #[macro_export] macro_rules! inc_new_counter_info { ($name:expr, $count:expr) => {{ @@ -76,6 +102,19 @@ macro_rules! inc_new_counter_info { }}; } +#[macro_export] +macro_rules! inc_new_counter_debug { + ($name:expr, $count:expr) => {{ + inc_new_counter!($name, $count, log::Level::Debug, 0, 0); + }}; + ($name:expr, $count:expr, $lograte:expr) => {{ + inc_new_counter!($name, $count, log::Level::Debug, $lograte, 0); + }}; + ($name:expr, $count:expr, $lograte:expr, $metricsrate:expr) => {{ + inc_new_counter!($name, $count, log::Level::Debug, $lograte, $metricsrate); + }}; +} + impl Counter { fn default_log_rate() -> usize { let v = env::var("SOLANA_DEFAULT_LOG_RATE") diff --git a/runtime/src/accounts.rs b/runtime/src/accounts.rs index 3283283470..c4c8b654b0 100644 --- a/runtime/src/accounts.rs +++ b/runtime/src/accounts.rs @@ -8,7 +8,7 @@ use crate::message_processor::has_duplicates; use bincode::serialize; use hashbrown::{HashMap, HashSet}; use log::*; -use solana_metrics::inc_new_counter_info; +use solana_metrics::inc_new_counter_error; use solana_sdk::account::Account; use solana_sdk::fee_calculator::FeeCalculator; use solana_sdk::hash::{Hash, Hasher}; @@ -477,9 +477,11 @@ impl Accounts { }) .collect(); if error_counters.account_in_use != 0 { - inc_new_counter_info!( + inc_new_counter_error!( "bank-process_transactions-account_in_use", - error_counters.account_in_use + error_counters.account_in_use, + 0, + 100 ); } rv diff --git a/runtime/src/bank.rs b/runtime/src/bank.rs index 978e585e98..d6a85fa496 100644 --- a/runtime/src/bank.rs +++ b/runtime/src/bank.rs @@ -14,7 +14,9 @@ use crate::status_cache::StatusCache; use bincode::serialize; use hashbrown::HashMap; use log::*; -use solana_metrics::{datapoint, inc_new_counter_info}; +use solana_metrics::{ + datapoint, inc_new_counter_debug, inc_new_counter_error, inc_new_counter_info, +}; use solana_sdk::account::Account; use solana_sdk::fee_calculator::FeeCalculator; use solana_sdk::genesis_block::GenesisBlock; @@ -385,7 +387,7 @@ impl Bank { self.tick_height.fetch_add(1, Ordering::SeqCst); self.tick_height.load(Ordering::SeqCst) as u64 }; - inc_new_counter_info!("bank-register_tick-registered", 1); + inc_new_counter_debug!("bank-register_tick-registered", 1); // Register a new block hash if at the last tick in the slot if current_tick_height % self.ticks_per_slot == self.ticks_per_slot - 1 { @@ -603,20 +605,20 @@ impl Bank { } if err_count > 0 { debug!("{} errors of {} txs", err_count, err_count + tx_count); - inc_new_counter_info!( + inc_new_counter_error!( "bank-process_transactions-account_not_found", error_counters.account_not_found, 0, 1000 ); - inc_new_counter_info!("bank-process_transactions-error_count", err_count, 0, 1000); + inc_new_counter_error!("bank-process_transactions-error_count", err_count, 0, 1000); } self.increment_transaction_count(tx_count); inc_new_counter_info!("bank-process_transactions-txs", tx_count, 0, 1000); if 0 != error_counters.blockhash_not_found { - inc_new_counter_info!( + inc_new_counter_error!( "bank-process_transactions-error-blockhash_not_found", error_counters.blockhash_not_found, 0, @@ -624,7 +626,7 @@ impl Bank { ); } if 0 != error_counters.invalid_account_index { - inc_new_counter_info!( + inc_new_counter_error!( "bank-process_transactions-error-invalid_account_index", error_counters.invalid_account_index, 0, @@ -632,7 +634,7 @@ impl Bank { ); } if 0 != error_counters.reserve_blockhash { - inc_new_counter_info!( + inc_new_counter_error!( "bank-process_transactions-error-reserve_blockhash", error_counters.reserve_blockhash, 0, @@ -640,7 +642,7 @@ impl Bank { ); } if 0 != error_counters.duplicate_signature { - inc_new_counter_info!( + inc_new_counter_error!( "bank-process_transactions-error-duplicate_signature", error_counters.duplicate_signature, 0, @@ -648,7 +650,7 @@ impl Bank { ); } if 0 != error_counters.insufficient_funds { - inc_new_counter_info!( + inc_new_counter_error!( "bank-process_transactions-error-insufficient_funds", error_counters.insufficient_funds, 0, @@ -656,7 +658,7 @@ impl Bank { ); } if 0 != error_counters.account_loaded_twice { - inc_new_counter_info!( + inc_new_counter_error!( "bank-process_transactions-account_loaded_twice", error_counters.account_loaded_twice, 0,