moved PerfTimer to a separate crate - "trace-time" (#7985)

This commit is contained in:
Marek Kotewicz 2018-02-23 19:49:08 +01:00 committed by Robert Habermeier
parent 893979b5da
commit f9d5d618dc
7 changed files with 39 additions and 20 deletions

9
Cargo.lock generated
View File

@ -499,6 +499,7 @@ dependencies = [
"table 0.1.0", "table 0.1.0",
"tempdir 0.3.5 (registry+https://github.com/rust-lang/crates.io-index)", "tempdir 0.3.5 (registry+https://github.com/rust-lang/crates.io-index)",
"time 0.1.38 (registry+https://github.com/rust-lang/crates.io-index)", "time 0.1.38 (registry+https://github.com/rust-lang/crates.io-index)",
"trace-time 0.1.0",
"trie-standardmap 0.1.0", "trie-standardmap 0.1.0",
"triehash 0.1.0", "triehash 0.1.0",
"unexpected 0.1.0", "unexpected 0.1.0",
@ -3236,6 +3237,14 @@ dependencies = [
"serde 1.0.27 (registry+https://github.com/rust-lang/crates.io-index)", "serde 1.0.27 (registry+https://github.com/rust-lang/crates.io-index)",
] ]
[[package]]
name = "trace-time"
version = "0.1.0"
dependencies = [
"log 0.3.8 (registry+https://github.com/rust-lang/crates.io-index)",
"time 0.1.38 (registry+https://github.com/rust-lang/crates.io-index)",
]
[[package]] [[package]]
name = "traitobject" name = "traitobject"
version = "0.1.0" version = "0.1.0"

View File

@ -60,6 +60,7 @@ rust-crypto = "0.2.34"
rustc-hex = "1.0" rustc-hex = "1.0"
stats = { path = "../util/stats" } stats = { path = "../util/stats" }
time = "0.1" time = "0.1"
trace-time = { path = "../util/trace-time" }
using_queue = { path = "../util/using_queue" } using_queue = { path = "../util/using_queue" }
table = { path = "../util/table" } table = { path = "../util/table" }
vm = { path = "vm" } vm = { path = "vm" }

View File

@ -24,7 +24,6 @@ use itertools::Itertools;
// util // util
use hash::keccak; use hash::keccak;
use timer::PerfTimer;
use bytes::Bytes; use bytes::Bytes;
use journaldb; use journaldb;
use util_error::UtilError; use util_error::UtilError;
@ -517,7 +516,7 @@ impl Client {
if blocks.is_empty() { if blocks.is_empty() {
return 0; return 0;
} }
let _timer = PerfTimer::new("import_verified_blocks"); trace_time!("import_verified_blocks");
let start = precise_time_ns(); let start = precise_time_ns();
for block in blocks { for block in blocks {
@ -592,7 +591,7 @@ impl Client {
let _import_lock = self.import_lock.lock(); let _import_lock = self.import_lock.lock();
{ {
let _timer = PerfTimer::new("import_old_block"); trace_time!("import_old_block");
let chain = self.chain.read(); let chain = self.chain.read();
let mut ancient_verifier = self.ancient_verifier.lock(); let mut ancient_verifier = self.ancient_verifier.lock();
@ -888,7 +887,7 @@ impl Client {
/// Import transactions from the IO queue /// Import transactions from the IO queue
pub fn import_queued_transactions(&self, transactions: &[Bytes], peer_id: usize) -> usize { pub fn import_queued_transactions(&self, transactions: &[Bytes], peer_id: usize) -> usize {
trace!(target: "external_tx", "Importing queued"); trace!(target: "external_tx", "Importing queued");
let _timer = PerfTimer::new("import_queued_transactions"); trace_time!("import_queued_transactions");
self.queue_transactions.fetch_sub(transactions.len(), AtomicOrdering::SeqCst); self.queue_transactions.fetch_sub(transactions.len(), AtomicOrdering::SeqCst);
let txs: Vec<UnverifiedTransaction> = transactions.iter().filter_map(|bytes| UntrustedRlp::new(bytes).as_val().ok()).collect(); let txs: Vec<UnverifiedTransaction> = transactions.iter().filter_map(|bytes| UntrustedRlp::new(bytes).as_val().ok()).collect();
let hashes: Vec<_> = txs.iter().map(|tx| tx.hash()).collect(); let hashes: Vec<_> = txs.iter().map(|tx| tx.hash()).collect();
@ -1927,7 +1926,7 @@ impl MiningBlockChainClient for Client {
let route = { let route = {
// scope for self.import_lock // scope for self.import_lock
let _import_lock = self.import_lock.lock(); let _import_lock = self.import_lock.lock();
let _timer = PerfTimer::new("import_sealed_block"); trace_time!("import_sealed_block");
let number = block.header().number(); let number = block.header().number();
let block_data = block.rlp_bytes(); let block_data = block.rlp_bytes();

View File

@ -122,6 +122,8 @@ extern crate macros;
extern crate log; extern crate log;
#[macro_use] #[macro_use]
extern crate lazy_static; extern crate lazy_static;
#[macro_use]
extern crate trace_time;
#[cfg_attr(test, macro_use)] #[cfg_attr(test, macro_use)]
extern crate evm; extern crate evm;
@ -150,7 +152,6 @@ pub mod snapshot;
pub mod spec; pub mod spec;
pub mod state; pub mod state;
pub mod state_db; pub mod state_db;
pub mod timer;
pub mod trace; pub mod trace;
pub mod verification; pub mod verification;
pub mod views; pub mod views;

View File

@ -40,7 +40,6 @@ use ethcore_miner::service_transaction_checker::ServiceTransactionChecker;
use miner::{MinerService, MinerStatus}; use miner::{MinerService, MinerStatus};
use price_info::fetch::Client as FetchClient; use price_info::fetch::Client as FetchClient;
use price_info::{Client as PriceInfoClient, PriceInfo}; use price_info::{Client as PriceInfoClient, PriceInfo};
use timer::PerfTimer;
use transaction::{ use transaction::{
Action, Action,
UnverifiedTransaction, UnverifiedTransaction,
@ -388,7 +387,7 @@ impl Miner {
/// Prepares new block for sealing including top transactions from queue. /// Prepares new block for sealing including top transactions from queue.
fn prepare_block(&self, chain: &MiningBlockChainClient) -> (ClosedBlock, Option<H256>) { fn prepare_block(&self, chain: &MiningBlockChainClient) -> (ClosedBlock, Option<H256>) {
let _timer = PerfTimer::new("prepare_block"); trace_time!("prepare_block");
let chain_info = chain.chain_info(); let chain_info = chain.chain_info();
let (transactions, mut open_block, original_work_hash) = { let (transactions, mut open_block, original_work_hash) = {
let nonce_cap = if chain_info.best_block_number + 1 >= self.engine.params().dust_protection_transition { let nonce_cap = if chain_info.best_block_number + 1 >= self.engine.params().dust_protection_transition {

View File

@ -0,0 +1,8 @@
[package]
name = "trace-time"
version = "0.1.0"
authors = ["Parity Technologies <admin@parity.io>"]
[dependencies]
time = "0.1.34"
log = "0.3"

View File

@ -15,37 +15,39 @@
// along with Parity. If not, see <http://www.gnu.org/licenses/>. // along with Parity. If not, see <http://www.gnu.org/licenses/>.
//! Performance timer with logging //! Performance timer with logging
extern crate time;
#[macro_use]
extern crate log;
use time::precise_time_ns; use time::precise_time_ns;
#[macro_export]
macro_rules! trace_time {
($name: expr) => {
let _timer = $crate::PerfTimer::new($name);
}
}
/// Performance timer with logging. Starts measuring time in the constructor, prints /// Performance timer with logging. Starts measuring time in the constructor, prints
/// elapsed time in the destructor or when `stop` is called. /// elapsed time in the destructor or when `stop` is called.
pub struct PerfTimer { pub struct PerfTimer {
name: &'static str, name: &'static str,
start: u64, start: u64,
stopped: bool,
} }
impl PerfTimer { impl PerfTimer {
/// Create an instance with given name. /// Create an instance with given name.
pub fn new(name: &'static str) -> PerfTimer { pub fn new(name: &'static str) -> PerfTimer {
PerfTimer { PerfTimer {
name: name, name,
start: precise_time_ns(), start: precise_time_ns(),
stopped: false,
}
}
/// Stop the timer and print elapsed time on trace level with `perf` target.
pub fn stop(&mut self) {
if !self.stopped {
trace!(target: "perf", "{}: {:.2}ms", self.name, (precise_time_ns() - self.start) as f32 / 1000_000.0);
self.stopped = true;
} }
} }
} }
impl Drop for PerfTimer { impl Drop for PerfTimer {
fn drop(&mut self) { fn drop(&mut self) {
self.stop() trace!(target: "perf", "{}: {:.2}ms", self.name, (precise_time_ns() - self.start) as f32 / 1000_000.0);
} }
} }