diff --git a/Cargo.toml b/Cargo.toml index edcb145af..034b1383b 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -70,6 +70,8 @@ stratum = ["ipc"] ethkey-cli = ["ethcore/ethkey-cli"] ethstore-cli = ["ethcore/ethstore-cli"] evm-debug = ["ethcore/evm-debug"] +evm-debug-tests = ["ethcore/evm-debug-tests"] +slow-blocks = ["ethcore/slow-blocks"] [[bin]] path = "parity/main.rs" diff --git a/ethcore/Cargo.toml b/ethcore/Cargo.toml index 96dcba3f8..7bda7e567 100644 --- a/ethcore/Cargo.toml +++ b/ethcore/Cargo.toml @@ -47,7 +47,9 @@ default-features = false [features] jit = ["evmjit"] -evm-debug = [] +evm-debug = ["slow-blocks"] +evm-debug-tests = ["evm-debug"] +slow-blocks = [] # Use SLOW_TX_DURATION="50" (compile time!) to track transactions over 50ms json-tests = [] test-heavy = [] dev = ["clippy"] diff --git a/ethcore/src/block.rs b/ethcore/src/block.rs index dc60f9bbe..80c35d1d0 100644 --- a/ethcore/src/block.rs +++ b/ethcore/src/block.rs @@ -16,14 +16,26 @@ //! Blockchain block. -use common::*; +use std::sync::Arc; +use std::collections::HashSet; + +use rlp::{UntrustedRlp, RlpStream, Encodable, Decodable, Decoder, DecoderError, View, Stream}; +use util::{Bytes, Address, Uint, FixedHash, Hashable, U256, H256, ordered_trie_root, SHA3_NULL_RLP}; +use util::error::{Mismatch, OutOfBounds}; + +use basic_types::{LogBloom, Seal}; +use env_info::{EnvInfo, LastHashes}; use engines::Engine; -use state::*; -use state_db::StateDB; -use verification::PreverifiedBlock; -use trace::FlatTrace; +use error::{Error, BlockError, TransactionError}; use factory::Factories; -use rlp::*; +use header::Header; +use receipt::Receipt; +use state::State; +use state_db::StateDB; +use trace::FlatTrace; +use transaction::SignedTransaction; +use verification::PreverifiedBlock; +use views::BlockView; /// A block, encoded as it is on the block chain. #[derive(Default, Debug, Clone, PartialEq)] @@ -518,25 +530,38 @@ pub fn enact( b.set_uncles_hash(header.uncles_hash().clone()); b.set_transactions_root(header.transactions_root().clone()); b.set_receipts_root(header.receipts_root().clone()); - for t in transactions { try!(b.push_transaction(t.clone(), None)); } - for u in uncles { try!(b.push_uncle(u.clone())); } + + try!(push_transactions(&mut b, transactions)); + for u in uncles { + try!(b.push_uncle(u.clone())); + } Ok(b.close_and_lock()) } -/// Enact the block given by `block_bytes` using `engine` on the database `db` with given `parent` block header -#[cfg_attr(feature="dev", allow(too_many_arguments))] -pub fn enact_bytes( - block_bytes: &[u8], - engine: &Engine, - tracing: bool, - db: StateDB, - parent: &Header, - last_hashes: Arc, - factories: Factories, -) -> Result { - let block = BlockView::new(block_bytes); - let header = block.header(); - enact(&header, &block.transactions(), &block.uncles(), engine, tracing, db, parent, last_hashes, factories) +#[inline(always)] +#[cfg(not(feature = "slow-blocks"))] +fn push_transactions(block: &mut OpenBlock, transactions: &[SignedTransaction]) -> Result<(), Error> { + for t in transactions { + try!(block.push_transaction(t.clone(), None)); + } + Ok(()) +} + +#[cfg(feature = "slow-blocks")] +fn push_transactions(block: &mut OpenBlock, transactions: &[SignedTransaction]) -> Result<(), Error> { + use std::time; + + let slow_tx = option_env!("SLOW_TX_DURATION").and_then(|v| v.parse().ok()).unwrap_or(100); + for t in transactions { + let hash = t.hash(); + let start = time::Instant::now(); + try!(block.push_transaction(t.clone(), None)); + let took = start.elapsed(); + if took > time::Duration::from_millis(slow_tx) { + warn!("Heavy transaction in block {:?}: {:?}", block.header().number(), hash); + } + } + Ok(()) } /// Enact the block given by `block_bytes` using `engine` on the database `db` with given `parent` block header @@ -554,26 +579,45 @@ pub fn enact_verified( enact(&block.header, &block.transactions, &view.uncles(), engine, tracing, db, parent, last_hashes, factories) } -/// Enact the block given by `block_bytes` using `engine` on the database `db` with given `parent` block header. Seal the block aferwards -#[cfg_attr(feature="dev", allow(too_many_arguments))] -pub fn enact_and_seal( - block_bytes: &[u8], - engine: &Engine, - tracing: bool, - db: StateDB, - parent: &Header, - last_hashes: Arc, - factories: Factories, -) -> Result { - let header = BlockView::new(block_bytes).header_view(); - Ok(try!(try!(enact_bytes(block_bytes, engine, tracing, db, parent, last_hashes, factories)).seal(engine, header.seal()))) -} - #[cfg(test)] mod tests { use tests::helpers::*; use super::*; use common::*; + use engines::Engine; + use factory::Factories; + use state_db::StateDB; + + /// Enact the block given by `block_bytes` using `engine` on the database `db` with given `parent` block header + #[cfg_attr(feature="dev", allow(too_many_arguments))] + fn enact_bytes( + block_bytes: &[u8], + engine: &Engine, + tracing: bool, + db: StateDB, + parent: &Header, + last_hashes: Arc, + factories: Factories, + ) -> Result { + let block = BlockView::new(block_bytes); + let header = block.header(); + enact(&header, &block.transactions(), &block.uncles(), engine, tracing, db, parent, last_hashes, factories) + } + + /// Enact the block given by `block_bytes` using `engine` on the database `db` with given `parent` block header. Seal the block aferwards + #[cfg_attr(feature="dev", allow(too_many_arguments))] + fn enact_and_seal( + block_bytes: &[u8], + engine: &Engine, + tracing: bool, + db: StateDB, + parent: &Header, + last_hashes: Arc, + factories: Factories, + ) -> Result { + let header = BlockView::new(block_bytes).header_view(); + Ok(try!(try!(enact_bytes(block_bytes, engine, tracing, db, parent, last_hashes, factories)).seal(engine, header.seal()))) + } #[test] fn open_block() { diff --git a/ethcore/src/evm/interpreter/informant.rs b/ethcore/src/evm/interpreter/informant.rs new file mode 100644 index 000000000..200b01526 --- /dev/null +++ b/ethcore/src/evm/interpreter/informant.rs @@ -0,0 +1,164 @@ +// Copyright 2015, 2016 Ethcore (UK) Ltd. +// This file is part of Parity. + +// Parity is free software: you can redistribute it and/or modify +// it under the terms of the GNU General Public License as published by +// the Free Software Foundation, either version 3 of the License, or +// (at your option) any later version. + +// Parity is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU General Public License for more details. + +// You should have received a copy of the GNU General Public License +// along with Parity. If not, see . + +pub use self::inner::*; + +#[macro_use] +#[cfg(not(feature = "evm-debug"))] +mod inner { + macro_rules! evm_debug { + ($x: expr) => {} + } + + pub struct EvmInformant; + impl EvmInformant { + pub fn new(_depth: usize) -> Self { + EvmInformant {} + } + pub fn done(&mut self) {} + } +} + +#[macro_use] +#[cfg(feature = "evm-debug")] +mod inner { + use std::iter; + use std::collections::HashMap; + use std::time::{Instant, Duration}; + + use evm::interpreter::stack::Stack; + use evm::instructions::{Instruction, InstructionInfo, INSTRUCTIONS}; + use evm::{CostType}; + + use util::U256; + + macro_rules! evm_debug { + ($x: expr) => { + $x + } + } + + fn print(data: String) { + if cfg!(feature = "evm-debug-tests") { + println!("{}", data); + } else { + debug!(target: "evm", "{}", data); + } + } + + pub struct EvmInformant { + spacing: String, + last_instruction: Instant, + stats: HashMap, + } + + impl EvmInformant { + + fn color(instruction: Instruction, name: &str) -> String { + let c = instruction as usize % 6; + let colors = [31, 34, 33, 32, 35, 36]; + format!("\x1B[1;{}m{}\x1B[0m", colors[c], name) + } + + fn as_micro(duration: &Duration) -> u64 { + let mut sec = duration.as_secs(); + let subsec = duration.subsec_nanos() as u64; + sec = sec.saturating_mul(1_000_000u64); + sec += subsec / 1_000; + sec + } + + pub fn new(depth: usize) -> Self { + EvmInformant { + spacing: iter::repeat(".").take(depth).collect(), + last_instruction: Instant::now(), + stats: HashMap::new(), + } + } + + pub fn before_instruction(&mut self, pc: usize, instruction: Instruction, info: &InstructionInfo, current_gas: &Cost, stack: &Stack) { + let time = self.last_instruction.elapsed(); + self.last_instruction = Instant::now(); + + print(format!("{}[0x{:<3x}][{:>19}(0x{:<2x}) Gas Left: {:6?} (Previous took: {:10}μs)", + &self.spacing, + pc, + Self::color(instruction, info.name), + instruction, + current_gas, + Self::as_micro(&time), + )); + + if info.args > 0 { + for (idx, item) in stack.peek_top(info.args).iter().enumerate() { + print(format!("{} |{:2}: {:?}", self.spacing, idx, item)); + } + } + } + + pub fn after_instruction(&mut self, instruction: Instruction) { + let mut stats = self.stats.entry(instruction).or_insert_with(|| Stats::default()); + let took = self.last_instruction.elapsed(); + stats.note(took); + } + + pub fn done(&mut self) { + // Print out stats + let infos = &*INSTRUCTIONS; + + let mut stats: Vec<(_,_)> = self.stats.drain().collect(); + stats.sort_by(|ref a, ref b| b.1.avg().cmp(&a.1.avg())); + + print(format!("\n{}-------OPCODE STATS:", self.spacing)); + for (instruction, stats) in stats.into_iter() { + let info = infos[instruction as usize]; + print(format!("{}-------{:>19}(0x{:<2x}) count: {:4}, avg: {:10}μs", + self.spacing, + Self::color(instruction, info.name), + instruction, + stats.count, + stats.avg(), + )); + } + } + + } + + struct Stats { + count: u64, + total_duration: Duration, + } + + impl Default for Stats { + fn default() -> Self { + Stats { + count: 0, + total_duration: Duration::from_secs(0), + } + } + } + + impl Stats { + fn note(&mut self, took: Duration) { + self.count += 1; + self.total_duration += took; + } + + fn avg(&self) -> u64 { + EvmInformant::as_micro(&self.total_duration) / self.count + } + } +} diff --git a/ethcore/src/evm/interpreter/mod.rs b/ethcore/src/evm/interpreter/mod.rs index 2a6ab8460..fdf99876a 100644 --- a/ethcore/src/evm/interpreter/mod.rs +++ b/ethcore/src/evm/interpreter/mod.rs @@ -16,18 +16,8 @@ //! Rust VM implementation -#[cfg(not(feature = "evm-debug"))] -macro_rules! evm_debug { - ($x: expr) => {} -} - -#[cfg(feature = "evm-debug")] -macro_rules! evm_debug { - ($x: expr) => { - $x - } -} - +#[macro_use] +mod informant; mod gasometer; mod stack; mod memory; @@ -45,13 +35,6 @@ use super::instructions::{self, Instruction, InstructionInfo}; use evm::{self, MessageCallResult, ContractCreateResult, GasLeft, CostType}; use bit_set::BitSet; -#[cfg(feature = "evm-debug")] -fn color(instruction: Instruction, name: &'static str) -> String { - let c = instruction as usize % 6; - let colors = [31, 34, 33, 32, 35, 36]; - format!("\x1B[1;{}m{}\x1B[0m", colors[c], name) -} - type CodePosition = usize; type ProgramCounter = usize; @@ -74,6 +57,15 @@ struct CodeReader<'a> { #[cfg_attr(feature="dev", allow(len_without_is_empty))] impl<'a> CodeReader<'a> { + + /// Create new code reader - starting at position 0. + fn new(code: &'a Bytes) -> Self { + CodeReader { + position: 0, + code: code, + } + } + /// Get `no_of_bytes` from code and convert to U256. Move PC fn read(&mut self, no_of_bytes: usize) -> U256 { let pos = self.position; @@ -110,15 +102,14 @@ impl evm::Evm for Interpreter { fn exec(&mut self, params: ActionParams, ext: &mut evm::Ext) -> evm::Result { self.mem.clear(); + let mut informant = informant::EvmInformant::new(ext.depth()); + let code = ¶ms.code.as_ref().unwrap(); let valid_jump_destinations = self.cache.jump_destinations(¶ms.code_hash, code); let mut gasometer = Gasometer::::new(try!(Cost::from_u256(params.gas))); let mut stack = VecStack::with_capacity(ext.schedule().stack_limit, U256::zero()); - let mut reader = CodeReader { - position: 0, - code: code - }; + let mut reader = CodeReader::new(code); let infos = &*instructions::INSTRUCTIONS; while reader.position < code.len() { @@ -138,15 +129,7 @@ impl evm::Evm for Interpreter { gasometer.current_mem_gas = mem_gas; gasometer.current_gas = gasometer.current_gas - gas_cost; - evm_debug!({ - println!("[0x{:x}][{}(0x{:x}) Gas: {:?}\n Gas Before: {:?}", - reader.position, - color(instruction, info.name), - instruction, - gas_cost, - gasometer.current_gas + gas_cost - ); - }); + evm_debug!({ informant.before_instruction(reader.position, instruction, &info, &gasometer.current_gas, &stack) }); let (mem_written, store_written) = match trace_executed { true => (Self::mem_written(instruction, &stack), Self::store_written(instruction, &stack)), @@ -158,6 +141,8 @@ impl evm::Evm for Interpreter { gasometer.current_gas, ¶ms, ext, instruction, &mut reader, &mut stack )); + evm_debug!({ informant.after_instruction(instruction) }); + if trace_executed { ext.trace_executed(gasometer.current_gas.as_u256(), stack.peek_top(info.ret), mem_written.map(|(o, s)| (o, &(self.mem[o..(o + s)]))), store_written); } @@ -179,12 +164,13 @@ impl evm::Evm for Interpreter { reader.position = pos; }, InstructionResult::StopExecutionNeedsReturn(gas, off, size) => { + informant.done(); return Ok(GasLeft::NeedsReturn(gas.as_u256(), self.mem.read_slice(off, size))); }, InstructionResult::StopExecution => break, } } - + informant.done(); Ok(GasLeft::Known(gasometer.current_gas.as_u256())) } } diff --git a/ethcore/src/evm/interpreter/stack.rs b/ethcore/src/evm/interpreter/stack.rs index 98adf8539..0d7ef4dbb 100644 --- a/ethcore/src/evm/interpreter/stack.rs +++ b/ethcore/src/evm/interpreter/stack.rs @@ -34,7 +34,7 @@ pub trait Stack { /// Get number of elements on Stack fn size(&self) -> usize; /// Returns all data on stack. - fn peek_top(&mut self, no_of_elems: usize) -> &[T]; + fn peek_top(&self, no_of_elems: usize) -> &[T]; } pub struct VecStack { @@ -68,12 +68,7 @@ impl Stack for VecStack { fn pop_back(&mut self) -> S { let val = self.stack.pop(); match val { - Some(x) => { - evm_debug!({ - println!(" POP: {}", x) - }); - x - }, + Some(x) => x, None => panic!("Tried to pop from empty stack.") } } @@ -88,9 +83,6 @@ impl Stack for VecStack { } fn push(&mut self, elem: S) { - evm_debug!({ - println!(" PUSH: {}", elem) - }); self.stack.push(elem); } @@ -98,7 +90,7 @@ impl Stack for VecStack { self.stack.len() } - fn peek_top(&mut self, no_from_top: usize) -> &[S] { + fn peek_top(&self, no_from_top: usize) -> &[S] { assert!(self.stack.len() >= no_from_top, "peek_top asked for more items than exist."); &self.stack[self.stack.len() - no_from_top .. self.stack.len()] }