From 1a467215f8f81e26b5fd08b64e560302208f3860 Mon Sep 17 00:00:00 2001 From: Michael Vines Date: Wed, 1 Jan 2020 10:51:51 -0700 Subject: [PATCH 1/3] Move thread_mem_usage module into measure/ --- Cargo.lock | 6 ++++-- core/Cargo.toml | 4 ---- core/src/banking_stage.rs | 4 ++-- core/src/cluster_info.rs | 2 +- core/src/fetch_stage.rs | 2 +- core/src/lib.rs | 8 -------- core/src/replay_stage.rs | 2 +- core/src/streamer.rs | 3 ++- measure/Cargo.toml | 6 ++++++ measure/src/lib.rs | 8 ++++++++ {core => measure}/src/thread_mem_usage.rs | 0 11 files changed, 25 insertions(+), 20 deletions(-) rename {core => measure}/src/thread_mem_usage.rs (100%) diff --git a/Cargo.lock b/Cargo.lock index 87a44e025999c8..658ae59e82410a 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3364,8 +3364,6 @@ dependencies = [ "hex-literal 0.2.1 (registry+https://github.com/rust-lang/crates.io-index)", "indexmap 1.1.0 (registry+https://github.com/rust-lang/crates.io-index)", "itertools 0.8.2 (registry+https://github.com/rust-lang/crates.io-index)", - "jemalloc-ctl 0.3.3 (registry+https://github.com/rust-lang/crates.io-index)", - "jemallocator 0.3.2 (registry+https://github.com/rust-lang/crates.io-index)", "jsonrpc-core 14.0.5 (registry+https://github.com/rust-lang/crates.io-index)", "jsonrpc-derive 14.0.5 (registry+https://github.com/rust-lang/crates.io-index)", "jsonrpc-http-server 14.0.5 (registry+https://github.com/rust-lang/crates.io-index)", @@ -3722,6 +3720,10 @@ dependencies = [ name = "solana-measure" version = "0.23.0" dependencies = [ + "jemalloc-ctl 0.3.3 (registry+https://github.com/rust-lang/crates.io-index)", + "jemallocator 0.3.2 (registry+https://github.com/rust-lang/crates.io-index)", + "log 0.4.8 (registry+https://github.com/rust-lang/crates.io-index)", + "solana-metrics 0.23.0", "solana-sdk 0.23.0", ] diff --git a/core/Cargo.toml b/core/Cargo.toml index 4d76adda9224ea..6845b61d43d88f 100644 --- a/core/Cargo.toml +++ b/core/Cargo.toml @@ -73,10 +73,6 @@ untrusted = "0.7.0" solana-rayon-threadlimit = { path = "../rayon-threadlimit", version = "0.23.0" } reed-solomon-erasure = { package = "solana-reed-solomon-erasure", version = "4.0.1-3", features = ["simd-accel"] } -[target."cfg(unix)".dependencies] -jemallocator = "0.3.2" -jemalloc-ctl = "0.3.2" - [dev-dependencies] hex-literal = "0.2.1" matches = "0.1.6" diff --git a/core/src/banking_stage.rs b/core/src/banking_stage.rs index 2eaa952728d738..1cf3c9bc8383ef 100644 --- a/core/src/banking_stage.rs +++ b/core/src/banking_stage.rs @@ -6,7 +6,7 @@ use crate::{ packet::{limited_deserialize, Packet, Packets, PACKETS_PER_BATCH}, poh_recorder::{PohRecorder, PohRecorderError, WorkingBankEntry}, poh_service::PohService, - thread_mem_usage, + result::{Error, Result}, }; use crossbeam_channel::{Receiver as CrossbeamReceiver, RecvTimeoutError}; use itertools::Itertools; @@ -16,7 +16,7 @@ use solana_ledger::{ entry::hash_transactions, leader_schedule_cache::LeaderScheduleCache, }; -use solana_measure::measure::Measure; +use solana_measure::{measure::Measure, thread_mem_usage}; use solana_metrics::{inc_new_counter_debug, inc_new_counter_info, inc_new_counter_warn}; use solana_perf::{cuda_runtime::PinnedVec, perf_libs}; use solana_runtime::{ diff --git a/core/src/cluster_info.rs b/core/src/cluster_info.rs index 0145e00670769f..8074fe7d383752 100644 --- a/core/src/cluster_info.rs +++ b/core/src/cluster_info.rs @@ -24,7 +24,6 @@ use crate::{ repair_service::RepairType, result::{Error, Result}, sendmmsg::{multicast, send_mmsg}, - thread_mem_usage, weighted_shuffle::{weighted_best, weighted_shuffle}, }; use bincode::{serialize, serialized_size}; @@ -32,6 +31,7 @@ use core::cmp; use itertools::Itertools; use rand::{thread_rng, Rng}; use solana_ledger::{bank_forks::BankForks, blocktree::Blocktree, staking_utils}; +use solana_measure::thread_mem_usage; use solana_metrics::{datapoint_debug, inc_new_counter_debug, inc_new_counter_error}; use solana_net_utils::{ bind_common, bind_common_in_range, bind_in_range, find_available_port_in_range, diff --git a/core/src/fetch_stage.rs b/core/src/fetch_stage.rs index 8dd495c1d49ad7..aeff431aa6fcfa 100644 --- a/core/src/fetch_stage.rs +++ b/core/src/fetch_stage.rs @@ -5,7 +5,7 @@ use crate::packet::PacketsRecycler; use crate::poh_recorder::PohRecorder; use crate::result::{Error, Result}; use crate::streamer::{self, PacketReceiver, PacketSender}; -use crate::thread_mem_usage; +use solana_measure::thread_mem_usage; use solana_metrics::{inc_new_counter_debug, inc_new_counter_info}; use solana_perf::recycler::Recycler; use solana_sdk::clock::DEFAULT_TICKS_PER_SLOT; diff --git a/core/src/lib.rs b/core/src/lib.rs index faedb4ea1bea85..9639978f8b74e9 100644 --- a/core/src/lib.rs +++ b/core/src/lib.rs @@ -12,7 +12,6 @@ pub mod chacha_cuda; pub mod cluster_info_vote_listener; pub mod commitment; pub mod shred_fetch_stage; -pub mod thread_mem_usage; #[macro_use] pub mod contact_info; pub mod archiver; @@ -84,10 +83,3 @@ extern crate solana_metrics; #[cfg(test)] #[macro_use] extern crate matches; - -#[cfg(unix)] -extern crate jemallocator; - -#[cfg(unix)] -#[global_allocator] -static ALLOC: jemallocator::Jemalloc = jemallocator::Jemalloc; diff --git a/core/src/replay_stage.rs b/core/src/replay_stage.rs index 094cfd5d5a5f1a..5a55d5f4334063 100644 --- a/core/src/replay_stage.rs +++ b/core/src/replay_stage.rs @@ -7,7 +7,6 @@ use crate::{ poh_recorder::PohRecorder, result::{Error, Result}, rpc_subscriptions::RpcSubscriptions, - thread_mem_usage, }; use solana_ledger::entry::EntryVerificationStatus; use solana_ledger::{ @@ -20,6 +19,7 @@ use solana_ledger::{ snapshot_package::SnapshotPackageSender, }; use solana_measure::measure::Measure; +use solana_measure::thread_mem_usage; use solana_metrics::inc_new_counter_info; use solana_runtime::bank::Bank; use solana_sdk::{ diff --git a/core/src/streamer.rs b/core/src/streamer.rs index be67fcdfc8fd68..650ae746c82c1b 100644 --- a/core/src/streamer.rs +++ b/core/src/streamer.rs @@ -3,7 +3,8 @@ use crate::packet::{self, send_to, Packets, PacketsRecycler, PACKETS_PER_BATCH}; use crate::recvmmsg::NUM_RCVMMSGS; -use crate::thread_mem_usage; +use crate::result::{Error, Result}; +use solana_measure::thread_mem_usage; use solana_sdk::timing::duration_as_ms; use std::net::UdpSocket; use std::sync::atomic::{AtomicBool, Ordering}; diff --git a/measure/Cargo.toml b/measure/Cargo.toml index 8ce6aaa0931ca3..51730d5d43e601 100644 --- a/measure/Cargo.toml +++ b/measure/Cargo.toml @@ -11,4 +11,10 @@ license = "Apache-2.0" edition = "2018" [dependencies] +log = "0.4.8" solana-sdk = { path = "../sdk", version = "0.23.0" } +solana-metrics = { path = "../metrics", version = "0.23.0" } + +[target."cfg(unix)".dependencies] +jemallocator = "0.3.2" +jemalloc-ctl = "0.3.2" diff --git a/measure/src/lib.rs b/measure/src/lib.rs index a669b00899d8f7..d2848c956e0261 100644 --- a/measure/src/lib.rs +++ b/measure/src/lib.rs @@ -1 +1,9 @@ pub mod measure; +pub mod thread_mem_usage; + +#[cfg(unix)] +extern crate jemallocator; + +#[cfg(unix)] +#[global_allocator] +static ALLOC: jemallocator::Jemalloc = jemallocator::Jemalloc; diff --git a/core/src/thread_mem_usage.rs b/measure/src/thread_mem_usage.rs similarity index 100% rename from core/src/thread_mem_usage.rs rename to measure/src/thread_mem_usage.rs From 18a50eb08388571c09aee07e49f8df1838ea8d15 Mon Sep 17 00:00:00 2001 From: Michael Vines Date: Wed, 1 Jan 2020 12:19:20 -0700 Subject: [PATCH 2/3] Measure heap usage while processing the ledger --- core/src/banking_stage.rs | 1 - core/src/replay_stage.rs | 3 +-- core/src/streamer.rs | 1 - ledger/src/blocktree_processor.rs | 26 ++++++++++++++++++++++++-- measure/src/thread_mem_usage.rs | 6 ++++++ 5 files changed, 31 insertions(+), 6 deletions(-) diff --git a/core/src/banking_stage.rs b/core/src/banking_stage.rs index 1cf3c9bc8383ef..975b8ab86af77f 100644 --- a/core/src/banking_stage.rs +++ b/core/src/banking_stage.rs @@ -6,7 +6,6 @@ use crate::{ packet::{limited_deserialize, Packet, Packets, PACKETS_PER_BATCH}, poh_recorder::{PohRecorder, PohRecorderError, WorkingBankEntry}, poh_service::PohService, - result::{Error, Result}, }; use crossbeam_channel::{Receiver as CrossbeamReceiver, RecvTimeoutError}; use itertools::Itertools; diff --git a/core/src/replay_stage.rs b/core/src/replay_stage.rs index 5a55d5f4334063..dd24c0b046132d 100644 --- a/core/src/replay_stage.rs +++ b/core/src/replay_stage.rs @@ -18,8 +18,7 @@ use solana_ledger::{ leader_schedule_cache::LeaderScheduleCache, snapshot_package::SnapshotPackageSender, }; -use solana_measure::measure::Measure; -use solana_measure::thread_mem_usage; +use solana_measure::{measure::Measure, thread_mem_usage}; use solana_metrics::inc_new_counter_info; use solana_runtime::bank::Bank; use solana_sdk::{ diff --git a/core/src/streamer.rs b/core/src/streamer.rs index 650ae746c82c1b..83d183f45fa31f 100644 --- a/core/src/streamer.rs +++ b/core/src/streamer.rs @@ -3,7 +3,6 @@ use crate::packet::{self, send_to, Packets, PacketsRecycler, PACKETS_PER_BATCH}; use crate::recvmmsg::NUM_RCVMMSGS; -use crate::result::{Error, Result}; use solana_measure::thread_mem_usage; use solana_sdk::timing::duration_as_ms; use std::net::UdpSocket; diff --git a/ledger/src/blocktree_processor.rs b/ledger/src/blocktree_processor.rs index 3525284e1a5c78..953f152230de4d 100644 --- a/ledger/src/blocktree_processor.rs +++ b/ledger/src/blocktree_processor.rs @@ -11,6 +11,7 @@ use itertools::Itertools; use log::*; use rand::{seq::SliceRandom, thread_rng}; use rayon::{prelude::*, ThreadPool}; +use solana_measure::thread_mem_usage; use solana_metrics::{datapoint, datapoint_error, inc_new_counter_debug}; use solana_rayon_threadlimit::get_thread_count; use solana_runtime::{ @@ -292,6 +293,9 @@ pub fn process_blocktree_from_root( opts: &ProcessOptions, ) -> result::Result<(BankForks, Vec, LeaderScheduleCache), BlocktreeProcessorError> { info!("processing ledger from root slot {}...", bank.slot()); + let allocated = thread_mem_usage::Allocatedp::default(); + let initial_allocation = allocated.get(); + // Starting slot must be a root, and thus has no parents assert!(bank.parent().is_none()); let start_slot = bank.slot(); @@ -344,8 +348,9 @@ pub fn process_blocktree_from_root( }; info!( - "ledger processed in {}ms. {} fork{} at {}", + "ledger processed in {}ms. {} MB allocated. {} fork{} at {}", duration_as_ms(&now.elapsed()), + allocated.since(initial_allocation) / 1_000_000, bank_forks_info.len(), if bank_forks_info.len() > 1 { "s" } else { "" }, bank_forks_info @@ -461,6 +466,9 @@ fn process_next_slots( // Only process full slots in blocktree_processor, replay_stage // handles any partials if next_meta.is_full() { + let allocated = thread_mem_usage::Allocatedp::default(); + let initial_allocation = allocated.get(); + let next_bank = Arc::new(Bank::new_from_parent( &bank, &leader_schedule_cache @@ -468,7 +476,12 @@ fn process_next_slots( .unwrap(), *next_slot, )); - trace!("Add child bank {} of slot={}", next_slot, bank.slot()); + trace!( + "New bank for slot {}, parent slot is {}. {} bytes allocated", + next_slot, + bank.slot(), + allocated.since(initial_allocation) + ); pending_slots.push((*next_slot, next_meta, next_bank, bank.last_blockhash())); } else { let bfi = BankForksInfo { @@ -519,6 +532,9 @@ fn process_pending_slots( continue; } + let allocated = thread_mem_usage::Allocatedp::default(); + let initial_allocation = allocated.get(); + // Fetch all entries for this slot let entries = blocktree.get_slot_entries(slot, 0, None).map_err(|err| { warn!("Failed to load entries for slot {}: {:?}", slot, err); @@ -543,6 +559,12 @@ fn process_pending_slots( fork_info.clear(); } + trace!( + "Bank for slot {} is complete. {} bytes allocated", + slot, + allocated.since(initial_allocation) + ); + if slot >= dev_halt_at_slot { let bfi = BankForksInfo { bank_slot: slot }; fork_info.push((bank, bfi)); diff --git a/measure/src/thread_mem_usage.rs b/measure/src/thread_mem_usage.rs index 07ac1a5ec93791..cf8056259bce1f 100644 --- a/measure/src/thread_mem_usage.rs +++ b/measure/src/thread_mem_usage.rs @@ -28,6 +28,7 @@ impl Allocatedp { Self {} } + /// Return current thread heap usage pub fn get(&self) -> u64 { #[cfg(unix)] { @@ -36,4 +37,9 @@ impl Allocatedp { #[cfg(not(unix))] 0 } + + /// Return the difference in thread heap usage since a previous `get()` + pub fn since(&self, previous: u64) -> i64 { + self.get() as i64 - previous as i64 + } } From 4aa54d3a9ee41b59ab20f03c3869363d965441af Mon Sep 17 00:00:00 2001 From: Michael Vines Date: Wed, 1 Jan 2020 12:31:18 -0700 Subject: [PATCH 3/3] Log root slots while processing ledger --- ledger/src/blocktree_processor.rs | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/ledger/src/blocktree_processor.rs b/ledger/src/blocktree_processor.rs index 953f152230de4d..dd77005b27752d 100644 --- a/ledger/src/blocktree_processor.rs +++ b/ledger/src/blocktree_processor.rs @@ -509,6 +509,7 @@ fn process_pending_slots( let mut fork_info = vec![]; let mut last_status_report = Instant::now(); let mut pending_slots = vec![]; + let mut last_root_slot = root_bank.slot(); process_next_slots( root_bank, root_meta, @@ -523,7 +524,10 @@ fn process_pending_slots( let (slot, meta, bank, last_entry_hash) = pending_slots.pop().unwrap(); if last_status_report.elapsed() > Duration::from_secs(2) { - info!("processing ledger...slot {}", slot); + info!( + "processing ledger: slot={}, last root slot={}", + slot, last_root_slot + ); last_status_report = Instant::now(); } @@ -557,10 +561,12 @@ fn process_pending_slots( bank.squash(); pending_slots.clear(); fork_info.clear(); + last_root_slot = slot; } trace!( - "Bank for slot {} is complete. {} bytes allocated", + "Bank for {}slot {} is complete. {} bytes allocated", + if last_root_slot == slot { "root " } else { "" }, slot, allocated.since(initial_allocation) );