Stats for testeth

Simple listener support added to testeth. Stats class implements the Listener interface and collects tests execution times. Try options: --stats or --stats=full.

Closes ethereum/cpp-ethereum#1285

5 files changed, 74 insertions, 52 deletions

diff --git a/CMakeLists.txt b/CMakeLists.txt
index d7761b8d..ef292c2b 100644
--- a/CMakeLists.txt
+++ b/CMakeLists.txt
@@ -19,10 +19,10 @@ include_directories(${JSON_RPC_CPP_INCLUDE_DIRS})
 
 file(GLOB HEADERS "*.h")
 add_executable(testeth ${SRC_LIST} ${HEADERS})
-add_executable(createRandomVMTest createRandomVMTest.cpp vm.cpp TestHelper.cpp)
-add_executable(createRandomStateTest createRandomStateTest.cpp TestHelper.cpp)
-add_executable(checkRandomVMTest checkRandomVMTest.cpp vm.cpp TestHelper.cpp)
-add_executable(checkRandomStateTest checkRandomStateTest.cpp TestHelper.cpp)
+add_executable(createRandomVMTest createRandomVMTest.cpp vm.cpp TestHelper.cpp Stats.cpp)
+add_executable(createRandomStateTest createRandomStateTest.cpp TestHelper.cpp Stats.cpp)
+add_executable(checkRandomVMTest checkRandomVMTest.cpp vm.cpp TestHelper.cpp Stats.cpp)
+add_executable(checkRandomStateTest checkRandomStateTest.cpp TestHelper.cpp Stats.cpp)
 
 target_link_libraries(testeth ${Boost_UNIT_TEST_FRAMEWORK_LIBRARIES})
 target_link_libraries(testeth ${CURL_LIBRARIES})
diff --git a/TestHelper.cpp b/TestHelper.cpp
index ddc929e4..72fecf59 100644
--- a/TestHelper.cpp
+++ b/TestHelper.cpp
@@ -551,6 +551,10 @@ Options::Options()
 			vmtrace = true;
 		else if (arg == "--filltests")
 			fillTests = true;
+		else if (arg == "--stats")
+			stats = true;
+		else if (arg == "--stats=full")
+			stats = statsFull = true;
 		else if (arg == "--performance")
 			performance = true;
 		else if (arg == "--quadratic")
@@ -578,6 +582,7 @@ Options const& Options::get()
 	return instance;
 }
 
+
 LastHashes lastHashes(u256 _currentBlockNumber)
 {
 	LastHashes ret;
@@ -586,4 +591,27 @@ LastHashes lastHashes(u256 _currentBlockNumber)
 	return ret;
 }
 
+
+namespace
+{
+	Listener* g_listener;
+}
+
+void Listener::registerListener(Listener& _listener)
+{
+	g_listener = &_listener;
+}
+
+void Listener::notifyTestStarted(std::string const& _name)
+{
+	if (g_listener)
+		g_listener->testStarted(_name);
+}
+
+void Listener::notifyTestFinished()
+{
+	if (g_listener)
+		g_listener->testFinished();
+}
+
 } } // namespaces
diff --git a/TestHelper.h b/TestHelper.h
index 9efed0fa..ade20f5e 100644
--- a/TestHelper.h
+++ b/TestHelper.h
@@ -162,8 +162,9 @@ class Options
 public:
 	bool jit = false;		///< Use JIT
 	bool vmtrace = false;	///< Create EVM execution tracer // TODO: Link with log verbosity?
-	bool showTimes = false;	///< Print test groups execution times
 	bool fillTests = false; ///< Create JSON test files from execution results
+	bool stats = false;		///< Execution time stats
+	bool statsFull = false; ///< Output full stats - execution times for every test
 
 	/// Test selection
 	/// @{
@@ -183,5 +184,32 @@ private:
 	Options(Options const&) = delete;
 };
 
+/// Allows observing test execution process.
+/// This class also provides methods for registering and notifying the listener
+class Listener
+{
+public:
+	virtual ~Listener() = default;
+
+	virtual void testStarted(std::string const& _name) = 0;
+	virtual void testFinished() = 0;
+
+	static void registerListener(Listener& _listener);
+	static void notifyTestStarted(std::string const& _name);
+	static void notifyTestFinished();
+
+	/// Test started/finished notification RAII helper
+	class ExecTimeGuard
+	{
+	public:
+		ExecTimeGuard(std::string const& _testName) { notifyTestStarted(_testName);	}
+		~ExecTimeGuard() { notifyTestFinished(); }
+		ExecTimeGuard(ExecTimeGuard const&) = delete;
+		ExecTimeGuard& operator=(ExecTimeGuard) = delete;
+	};
+};
+
+
+
 }
 }
diff --git a/state.cpp b/state.cpp
index d6790029..8c191aa7 100644
--- a/state.cpp
+++ b/state.cpp
@@ -31,6 +31,7 @@
 #include <libethereum/Defaults.h>
 #include <libevm/VM.h>
 #include "TestHelper.h"
+#include "Stats.h"
 
 using namespace std;
 using namespace json_spirit;
@@ -41,7 +42,8 @@ namespace dev {  namespace test {
 
 void doStateTests(json_spirit::mValue& v, bool _fillin)
 {
-	Options::get(); // process command line options
+	if (Options::get().stats)
+		Listener::registerListener(Stats::get());
 
 	for (auto& i: v.get_obj())
 	{
@@ -60,6 +62,7 @@ void doStateTests(json_spirit::mValue& v, bool _fillin)
 
 		try
 		{
+			Listener::ExecTimeGuard guard{i.first};
 			theState.execute(lastHashes(importer.m_environment.currentBlock.number), tx, &output);
 		}
 		catch (Exception const& _e)
@@ -178,29 +181,13 @@ BOOST_AUTO_TEST_CASE(stBlockHashTest)
 BOOST_AUTO_TEST_CASE(stQuadraticComplexityTest)
 {
 	if (test::Options::get().quadratic)
-	{
-		auto start = chrono::steady_clock::now();
-
 		dev::test::executeTests("stQuadraticComplexityTest", "/StateTests", dev::test::doStateTests);
-
-		auto end = chrono::steady_clock::now();
-		auto duration(chrono::duration_cast<chrono::milliseconds>(end - start));
-		cnote << "test duration: " << duration.count() << " milliseconds.\n";
-	}
 }
 
 BOOST_AUTO_TEST_CASE(stMemoryStressTest)
 {
 	if (test::Options::get().memory)
-	{
-		auto start = chrono::steady_clock::now();
-
 		dev::test::executeTests("stMemoryStressTest", "/StateTests", dev::test::doStateTests);
-
-		auto end = chrono::steady_clock::now();
-		auto duration(chrono::duration_cast<chrono::milliseconds>(end - start));
-		cnote << "test duration: " << duration.count() << " milliseconds.\n";
-	}
 }
 
 BOOST_AUTO_TEST_CASE(stSolidityTest)
diff --git a/vm.cpp b/vm.cpp
index 4433a60e..24ae4e06 100644
--- a/vm.cpp
+++ b/vm.cpp
@@ -20,13 +20,12 @@
  * vm test functions.
  */
 
-#include <chrono>
-
 #include <boost/filesystem.hpp>
 
 #include <libethereum/Executive.h>
 #include <libevm/VMFactory.h>
 #include "vm.h"
+#include "Stats.h"
 
 using namespace std;
 using namespace json_spirit;
@@ -312,7 +311,8 @@ namespace dev { namespace test {
 
 void doVMTests(json_spirit::mValue& v, bool _fillin)
 {
-	Options::get(); // process command line options // TODO: We need to control the main() function
+	if (Options::get().stats)
+		Listener::registerListener(Stats::get());
 
 	for (auto& i: v.get_obj())
 	{
@@ -340,12 +340,16 @@ void doVMTests(json_spirit::mValue& v, bool _fillin)
 		bytes output;
 		u256 gas;
 		bool vmExceptionOccured = false;
-		auto startTime = std::chrono::high_resolution_clock::now();
 		try
 		{
 			auto vm = eth::VMFactory::create(fev.gas);
 			auto vmtrace = Options::get().vmtrace ? fev.simpleTrace() : OnOpFunc{};
-			output = vm->go(fev, vmtrace).toBytes();
+			auto outputRef = bytesConstRef{};
+			{
+				Listener::ExecTimeGuard guard{i.first};
+				outputRef = vm->go(fev, vmtrace);
+			}
+			output = outputRef.toBytes();
 			gas = vm->gas();
 		}
 		catch (VMException const&)
@@ -364,15 +368,6 @@ void doVMTests(json_spirit::mValue& v, bool _fillin)
 			BOOST_ERROR("Failed VM Test with Exception: " << _e.what());
 		}
 
-		auto endTime = std::chrono::high_resolution_clock::now();
-		if (Options::get().showTimes)
-		{
-			auto testDuration = endTime - startTime;
-			cnote << "Execution time: "
-				  << std::chrono::duration_cast<std::chrono::milliseconds>(testDuration).count()
-				  << " ms";
-		}
-
 		// delete null entries in storage for the sake of comparison
 
 		for (auto  &a: fev.addresses)
@@ -513,29 +508,13 @@ BOOST_AUTO_TEST_CASE(vmSystemOperationsTest)
 BOOST_AUTO_TEST_CASE(vmPerformanceTest)
 {
 	if (test::Options::get().performance)
-	{
-		auto start = chrono::steady_clock::now();
-
 		dev::test::executeTests("vmPerformanceTest", "/VMTests", dev::test::doVMTests);
-
-		auto end = chrono::steady_clock::now();
-		auto duration(chrono::duration_cast<chrono::milliseconds>(end - start));
-		cnote << "test duration: " << duration.count() << " milliseconds.\n";
-	}
 }
 
 BOOST_AUTO_TEST_CASE(vmInputLimitsTest1)
 {
 	if (test::Options::get().inputLimits)
-	{
-		auto start = chrono::steady_clock::now();
-
 		dev::test::executeTests("vmInputLimits1", "/VMTests", dev::test::doVMTests);
-
-		auto end = chrono::steady_clock::now();
-		auto duration(chrono::duration_cast<chrono::milliseconds>(end - start));
-		cnote << "test duration: " << duration.count() << " milliseconds.\n";
-	}
 }
 
 BOOST_AUTO_TEST_CASE(vmInputLimitsTest2)