Better EVM informant & Slow transactions warning (#2436)

* EVM informant. Slow transactions tracking

* Additional feature for tests

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"

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"]

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 error::{Error, BlockError, TransactionError};
-use state_db::StateDB;
-use verification::PreverifiedBlock;
-use trace::FlatTrace;
 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
+#[inline(always)]
-#[cfg_attr(feature="dev", allow(too_many_arguments))]
+#[cfg(not(feature = "slow-blocks"))]
-pub fn enact_bytes(
+fn push_transactions(block: &mut OpenBlock, transactions: &[SignedTransaction]) -> Result<(), Error> {
-	block_bytes: &[u8],
+	for t in transactions {
-	engine: &Engine,
+		try!(block.push_transaction(t.clone(), None));
-	tracing: bool,
+	}
-	db: StateDB,
+	Ok(())
-	parent: &Header,
+}
-	last_hashes: Arc<LastHashes>,
+
-	factories: Factories,
+#[cfg(feature = "slow-blocks")]
-) -> Result<LockedBlock, Error> {
+fn push_transactions(block: &mut OpenBlock, transactions: &[SignedTransaction]) -> Result<(), Error> {
-	let block = BlockView::new(block_bytes);
+	use std::time;
-	let header = block.header();
+
-	enact(&header, &block.transactions(), &block.uncles(), engine, tracing, db, parent, last_hashes, factories)
+	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,9 +579,34 @@ pub fn enact_verified(
 	enact(&block.header, &block.transactions, &view.uncles(), engine, tracing, db, parent, last_hashes, factories)
 }
 
+#[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<LastHashes>,
+		factories: Factories,
+	) -> Result<LockedBlock, Error> {
+		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))]
-pub fn enact_and_seal(
+	fn enact_and_seal(
 		block_bytes: &[u8],
 		engine: &Engine,
 		tracing: bool,
@@ -569,12 +619,6 @@ pub fn enact_and_seal(
 		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::*;
-
 	#[test]
 	fn open_block() {
 		use spec::*;

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 <http://www.gnu.org/licenses/>.
+
+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<Instruction, Stats>,
+	}
+
+	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<Cost: CostType>(&mut self, pc: usize, instruction: Instruction, info: &InstructionInfo, current_gas: &Cost, stack: &Stack<U256>) {
+			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
+		}
+	}
+}

ethcore/src/evm/interpreter/mod.rs

@@ -16,18 +16,8 @@
 
 //! Rust VM implementation
 
-#[cfg(not(feature = "evm-debug"))]
+#[macro_use]
-macro_rules! evm_debug {
+mod informant;
-	($x: expr) => {}
-}
-
-#[cfg(feature = "evm-debug")]
-macro_rules! evm_debug {
-	($x: expr) => {
-		$x
-	}
-}
-
 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<Cost: CostType> evm::Evm for Interpreter<Cost> {
 	fn exec(&mut self, params: ActionParams, ext: &mut evm::Ext) -> evm::Result<GasLeft> {
 		self.mem.clear();
 
+		let mut informant = informant::EvmInformant::new(ext.depth());
+
 		let code = &params.code.as_ref().unwrap();
 		let valid_jump_destinations = self.cache.jump_destinations(&params.code_hash, code);
 
 		let mut gasometer = Gasometer::<Cost>::new(try!(Cost::from_u256(params.gas)));
 		let mut stack = VecStack::with_capacity(ext.schedule().stack_limit, U256::zero());
-		let mut reader = CodeReader {
+		let mut reader = CodeReader::new(code);
-			position: 0,
-			code: code
-		};
 		let infos = &*instructions::INSTRUCTIONS;
 
 		while reader.position < code.len() {
@@ -138,15 +129,7 @@ impl<Cost: CostType> evm::Evm for Interpreter<Cost> {
 			gasometer.current_mem_gas = mem_gas;
 			gasometer.current_gas = gasometer.current_gas - gas_cost;
 
-			evm_debug!({
+			evm_debug!({ informant.before_instruction(reader.position, instruction, &info, &gasometer.current_gas, &stack) });
-				println!("[0x{:x}][{}(0x{:x}) Gas: {:?}\n  Gas Before: {:?}",
-					reader.position,
-					color(instruction, info.name),
-					instruction,
-					gas_cost,
-					gasometer.current_gas + gas_cost
-				);
-			});
 
 			let (mem_written, store_written) = match trace_executed {
 				true => (Self::mem_written(instruction, &stack), Self::store_written(instruction, &stack)),
@@ -158,6 +141,8 @@ impl<Cost: CostType> evm::Evm for Interpreter<Cost> {
 				gasometer.current_gas, &params, 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<Cost: CostType> evm::Evm for Interpreter<Cost> {
 					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()))
 	}
 }

ethcore/src/evm/interpreter/stack.rs

@@ -34,7 +34,7 @@ pub trait Stack<T> {
 	/// 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<S> {
@@ -68,12 +68,7 @@ impl<S : fmt::Display> Stack<S> for VecStack<S> {
 	fn pop_back(&mut self) -> S {
 		let val = self.stack.pop();
 		match val {
-			Some(x) => {
+			Some(x) => x,
-				evm_debug!({
-					println!("   POP: {}", x)
-				});
-				x
-			},
 			None => panic!("Tried to pop from empty stack.")
 		}
 	}
@@ -88,9 +83,6 @@ impl<S : fmt::Display> Stack<S> for VecStack<S> {
 	}
 
 	fn push(&mut self, elem: S) {
-		evm_debug!({
-			println!("  PUSH: {}", elem)
-		});
 		self.stack.push(elem);
 	}
 
@@ -98,7 +90,7 @@ impl<S : fmt::Display> Stack<S> for VecStack<S> {
 		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()]
 	}