diff --git a/Cargo.lock b/Cargo.lock index 5f1aab78b..89e4dbef1 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -499,6 +499,7 @@ dependencies = [ "table 0.1.0", "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)", + "trace-time 0.1.0", "trie-standardmap 0.1.0", "triehash 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)", ] +[[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]] name = "traitobject" version = "0.1.0" diff --git a/ethcore/Cargo.toml b/ethcore/Cargo.toml index 172239d84..8db9a2748 100644 --- a/ethcore/Cargo.toml +++ b/ethcore/Cargo.toml @@ -60,6 +60,7 @@ rust-crypto = "0.2.34" rustc-hex = "1.0" stats = { path = "../util/stats" } time = "0.1" +trace-time = { path = "../util/trace-time" } using_queue = { path = "../util/using_queue" } table = { path = "../util/table" } vm = { path = "vm" } diff --git a/ethcore/src/client/client.rs b/ethcore/src/client/client.rs index 26dc538fe..4d9a7614b 100644 --- a/ethcore/src/client/client.rs +++ b/ethcore/src/client/client.rs @@ -24,7 +24,6 @@ use itertools::Itertools; // util use hash::keccak; -use timer::PerfTimer; use bytes::Bytes; use journaldb; use util_error::UtilError; @@ -517,7 +516,7 @@ impl Client { if blocks.is_empty() { return 0; } - let _timer = PerfTimer::new("import_verified_blocks"); + trace_time!("import_verified_blocks"); let start = precise_time_ns(); for block in blocks { @@ -592,7 +591,7 @@ impl Client { 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 mut ancient_verifier = self.ancient_verifier.lock(); @@ -888,7 +887,7 @@ impl Client { /// Import transactions from the IO queue pub fn import_queued_transactions(&self, transactions: &[Bytes], peer_id: usize) -> usize { 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); let txs: Vec = transactions.iter().filter_map(|bytes| UntrustedRlp::new(bytes).as_val().ok()).collect(); let hashes: Vec<_> = txs.iter().map(|tx| tx.hash()).collect(); @@ -1927,7 +1926,7 @@ impl MiningBlockChainClient for Client { let route = { // scope for self.import_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 block_data = block.rlp_bytes(); diff --git a/ethcore/src/lib.rs b/ethcore/src/lib.rs index 3ae7e6e38..7a4e46adf 100644 --- a/ethcore/src/lib.rs +++ b/ethcore/src/lib.rs @@ -122,6 +122,8 @@ extern crate macros; extern crate log; #[macro_use] extern crate lazy_static; +#[macro_use] +extern crate trace_time; #[cfg_attr(test, macro_use)] extern crate evm; @@ -150,7 +152,6 @@ pub mod snapshot; pub mod spec; pub mod state; pub mod state_db; -pub mod timer; pub mod trace; pub mod verification; pub mod views; diff --git a/ethcore/src/miner/miner.rs b/ethcore/src/miner/miner.rs index 21fbac24b..4eb6ec787 100644 --- a/ethcore/src/miner/miner.rs +++ b/ethcore/src/miner/miner.rs @@ -40,7 +40,6 @@ use ethcore_miner::service_transaction_checker::ServiceTransactionChecker; use miner::{MinerService, MinerStatus}; use price_info::fetch::Client as FetchClient; use price_info::{Client as PriceInfoClient, PriceInfo}; -use timer::PerfTimer; use transaction::{ Action, UnverifiedTransaction, @@ -388,7 +387,7 @@ impl Miner { /// Prepares new block for sealing including top transactions from queue. fn prepare_block(&self, chain: &MiningBlockChainClient) -> (ClosedBlock, Option) { - let _timer = PerfTimer::new("prepare_block"); + trace_time!("prepare_block"); let chain_info = chain.chain_info(); let (transactions, mut open_block, original_work_hash) = { let nonce_cap = if chain_info.best_block_number + 1 >= self.engine.params().dust_protection_transition { diff --git a/util/trace-time/Cargo.toml b/util/trace-time/Cargo.toml new file mode 100644 index 000000000..e184f6663 --- /dev/null +++ b/util/trace-time/Cargo.toml @@ -0,0 +1,8 @@ +[package] +name = "trace-time" +version = "0.1.0" +authors = ["Parity Technologies "] + +[dependencies] +time = "0.1.34" +log = "0.3" diff --git a/ethcore/src/timer.rs b/util/trace-time/src/lib.rs similarity index 78% rename from ethcore/src/timer.rs rename to util/trace-time/src/lib.rs index 791c74f15..384813541 100644 --- a/ethcore/src/timer.rs +++ b/util/trace-time/src/lib.rs @@ -15,37 +15,39 @@ // along with Parity. If not, see . //! Performance timer with logging + +extern crate time; +#[macro_use] +extern crate log; + 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 /// elapsed time in the destructor or when `stop` is called. pub struct PerfTimer { name: &'static str, start: u64, - stopped: bool, } impl PerfTimer { /// Create an instance with given name. pub fn new(name: &'static str) -> PerfTimer { PerfTimer { - name: name, + name, 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 { fn drop(&mut self) { - self.stop() + trace!(target: "perf", "{}: {:.2}ms", self.name, (precise_time_ns() - self.start) as f32 / 1000_000.0); } }