Stats for execution states times

evmjit/libevmjit/Cache.cpp

@@ -7,6 +7,7 @@
 #include <llvm/Support/Path.h>
 #include <llvm/Support/FileSystem.h>
 #include <llvm/Support/raw_os_ostream.h>
+#include "ExecutionEngine.h"
 
 namespace dev
 {
@@ -18,20 +19,25 @@ namespace jit
 //#define LOG(...) std::cerr << "CACHE "
 #define LOG(...) std::ostream(nullptr)
 
-ObjectCache* Cache::getObjectCache()
+namespace
 {
-	static ObjectCache objectCache;
+	llvm::MemoryBuffer* g_lastObject;
-	return &objectCache;
+	ExecutionEngineListener* g_listener;
 }
 
-namespace
+ObjectCache* Cache::getObjectCache(ExecutionEngineListener* _listener)
 {
-	llvm::MemoryBuffer* lastObject;
+	static ObjectCache objectCache;
+	g_listener = _listener;
+	return &objectCache;
 }
 
 std::unique_ptr<llvm::Module> Cache::getObject(std::string const& id)
 {
-	assert(!lastObject);
+	if (g_listener)
+		g_listener->stateChanged(ExecState::CacheLoad);
+
+	assert(!g_lastObject);
 	llvm::SmallString<256> cachePath;
 	llvm::sys::path::system_temp_directory(false, cachePath);
 	llvm::sys::path::append(cachePath, "evm_objs", id);
@@ -51,11 +57,11 @@ std::unique_ptr<llvm::Module> Cache::getObject(std::string const& id)
 #endif
 
 	if (auto r = llvm::MemoryBuffer::getFile(cachePath.str(), -1, false))
-		lastObject = llvm::MemoryBuffer::getMemBufferCopy(r.get()->getBuffer());
+		g_lastObject = llvm::MemoryBuffer::getMemBufferCopy(r.get()->getBuffer());
 	else if (r.getError() != std::make_error_code(std::errc::no_such_file_or_directory))
 		std::cerr << r.getError().message(); // TODO: Add log
 
-	if (lastObject)  // if object found create fake module
+	if (g_lastObject)  // if object found create fake module
 	{
 		auto module = std::unique_ptr<llvm::Module>(new llvm::Module(id, llvm::getGlobalContext()));
 		auto mainFuncType = llvm::FunctionType::get(llvm::IntegerType::get(llvm::getGlobalContext(), 32), {}, false);
@@ -67,6 +73,9 @@ std::unique_ptr<llvm::Module> Cache::getObject(std::string const& id)
 
 void ObjectCache::notifyObjectCompiled(llvm::Module const* _module, llvm::MemoryBuffer const* _object)
 {
+	if (g_listener)
+		g_listener->stateChanged(ExecState::CacheWrite);
+
 	auto&& id = _module->getModuleIdentifier();
 	llvm::SmallString<256> cachePath;
 	llvm::sys::path::system_temp_directory(false, cachePath);
@@ -84,8 +93,8 @@ void ObjectCache::notifyObjectCompiled(llvm::Module const* _module, llvm::Memory
 
 llvm::MemoryBuffer* ObjectCache::getObject(llvm::Module const*)
 {
-	auto o = lastObject;
+	auto o = g_lastObject;
-	lastObject = nullptr;
+	g_lastObject = nullptr;
 	return o;
 }
 

evmjit/libevmjit/Cache.h

@@ -1,7 +1,6 @@
 #pragma once
 
 #include <memory>
-#include <unordered_map>
 #include <llvm/ExecutionEngine/ObjectCache.h>
 
 
@@ -11,6 +10,7 @@ namespace eth
 {
 namespace jit
 {
+class ExecutionEngineListener;
 
 class ObjectCache : public llvm::ObjectCache
 {
@@ -23,16 +23,13 @@ public:
 	/// not available. The caller owns both the MemoryBuffer returned by this
 	/// and the memory it references.
 	virtual llvm::MemoryBuffer* getObject(llvm::Module const* _module) final override;
-
-private:
-	std::unordered_map<std::string, std::unique_ptr<llvm::MemoryBuffer>> m_map;
 };
 
 
 class Cache
 {
 public:
-	static ObjectCache* getObjectCache();
+	static ObjectCache* getObjectCache(ExecutionEngineListener* _listener);
 	static std::unique_ptr<llvm::Module> getObject(std::string const& id);
 };
 

evmjit/libevmjit/ExecStats.cpp

@@ -1,4 +1,7 @@
 #include "ExecStats.h"
+#include <iostream>
+#include <iomanip>
+#include <cassert>
 
 namespace dev
 {
@@ -7,14 +10,80 @@ namespace eth
 namespace jit
 {
 
-void ExecStats::execStarted()
+void ExecStats::stateChanged(ExecState _state)
 {
-	m_tp = std::chrono::high_resolution_clock::now();
+	assert(m_state != ExecState::Finished);
+	auto now = clock::now();
+	if (_state != ExecState::Started)
+	{
+		assert(time[(int)m_state] == ExecStats::duration::zero());
+		time[(int)m_state] = now - m_tp;
+	}
+	m_state = _state;
+	m_tp = now;
+}
+
+namespace
+{
+struct StatsAgg
+{
+	using unit = std::chrono::microseconds;
+	ExecStats::duration tot = ExecStats::duration::zero();
+	ExecStats::duration min = ExecStats::duration::max();
+	ExecStats::duration max = ExecStats::duration::zero();
+	size_t count = 0;
+
+	void update(ExecStats::duration _d)
+	{
+		++count;
+		tot += _d;
+		min = _d < min ? _d : min;
+		max = _d > max ? _d : max;
+	}
+
+	void output(char const* _name, std::ostream& _os)
+	{
+		auto avg = tot / count;
+		_os << std::setw(12) << std::left  << _name
+			<< std::setw(10) << std::right << std::chrono::duration_cast<unit>(tot).count()
+			<< std::setw(10) << std::right << std::chrono::duration_cast<unit>(avg).count()
+			<< std::setw(10) << std::right << std::chrono::duration_cast<unit>(min).count()
+			<< std::setw(10) << std::right << std::chrono::duration_cast<unit>(max).count()
+			<< std::endl;
 	}
+};
 
-void ExecStats::execEnded()
+char const* getExecStateName(ExecState _state)
 {
-	execTime = std::chrono::high_resolution_clock::now() - m_tp;
+	switch (_state)
+	{
+	case ExecState::Started: return "Start";
+	case ExecState::CacheLoad: return "CacheLoad";
+	case ExecState::CacheWrite: return "CacheWrite";
+	case ExecState::Compilation: return "Compilation";
+	case ExecState::CodeGen: return "CodeGen";
+	case ExecState::Execution: return "Execution";
+	case ExecState::Return: return "Return";
+	case ExecState::Finished: return "Finish";
+	}
+	return nullptr;
+}
+}
+
+StatsCollector::~StatsCollector()
+{
+	if (stats.empty())
+		return;
+
+	std::cout << "        [us]     total       avg       min       max\n";
+	for (int i = 0; i < (int)ExecState::Finished; ++i)
+	{
+		StatsAgg agg;
+		for (auto&& s : stats)
+			agg.update(s->time[i]);
+
+		agg.output(getExecStateName(ExecState(i)), std::cout);
+	}
 }
 
 }

evmjit/libevmjit/ExecStats.h

@@ -2,6 +2,7 @@
 
 #include <string>
 #include <chrono>
+#include "ExecutionEngine.h"
 
 namespace dev
 {
@@ -10,21 +11,31 @@ namespace eth
 namespace jit
 {
 
-class ExecStats
+class ExecStats : public ExecutionEngineListener
 {
 public:
+	using clock = std::chrono::high_resolution_clock;
+	using duration = clock::duration;
+	using time_point = clock::time_point;
+
 	std::string id;
-	std::chrono::high_resolution_clock::duration compileTime;
+	duration time[(int)ExecState::Finished] = {};
-	std::chrono::high_resolution_clock::duration codegenTime;
-	std::chrono::high_resolution_clock::duration cacheLoadTime;
-	std::chrono::high_resolution_clock::duration execTime;
 
-	void execStarted();
+	void stateChanged(ExecState _state) override;
-	void execEnded();
 
 private:
-	std::chrono::high_resolution_clock::time_point m_tp;
+	ExecState m_state = {};
+	time_point m_tp = {};
+
+};
+
+
+class StatsCollector
+{
+public:
+	std::vector<std::unique_ptr<ExecStats>> stats;
 
+	~StatsCollector();
 };
 
 }

evmjit/libevmjit/ExecutionEngine.cpp

@@ -19,6 +19,7 @@
 #include "Runtime.h"
 #include "Compiler.h"
 #include "Cache.h"
+#include "ExecStats.h"
 #include "BuildInfo.gen.h"
 
 #include <iostream>
@@ -83,50 +84,6 @@ bool showInfo()
 	return show;
 }
 
-class StatsCollector
-{
-public:
-	std::vector<std::unique_ptr<ExecStats>> stats;
-
-	~StatsCollector()
-	{
-		if (stats.empty())
-			return;
-
-		using d = decltype(ExecStats{}.execTime);
-		d total = d::zero();
-		d max = d::zero();
-		d min = d::max();
-
-		for (auto&& s : stats)
-		{
-			auto t = s->execTime;
-			total += t;
-			if (t < min)
-				min = t;
-			if (t > max)
-				max = t;
-		}
-
-		using u = std::chrono::microseconds;
-		auto nTotal = std::chrono::duration_cast<u>(total).count();
-		auto nAverage = std::chrono::duration_cast<u>(total / stats.size()).count();
-		auto nMax = std::chrono::duration_cast<u>(max).count();
-		auto nMin = std::chrono::duration_cast<u>(min).count();
-
-		std::cout << "Total  exec time: " << nTotal << " us" << std::endl
-				  << "Averge exec time: " << nAverage << " us" << std::endl
-				  << "Min    exec time: " << nMin << " us" << std::endl
-				  << "Max    exec time: " << nMax << " us" << std::endl;
-	}
-};
-
-}
-
-void ExecutionEngine::collectStats()
-{
-	if (!m_stats)
-		m_stats.reset(new ExecStats);
 }
 
 ReturnCode ExecutionEngine::run(RuntimeData* _data, Env* _env)
@@ -140,8 +97,8 @@ ReturnCode ExecutionEngine::run(RuntimeData* _data, Env* _env)
 
 	static StatsCollector statsCollector;
 
-	if (statsCollectingEnabled)
+	std::unique_ptr<ExecStats> listener{new ExecStats};
-		collectStats();
+	listener->stateChanged(ExecState::Started);
 
 	auto codeBegin = _data->code;
 	auto codeEnd = codeBegin + _data->codeSize;
@@ -155,12 +112,15 @@ ReturnCode ExecutionEngine::run(RuntimeData* _data, Env* _env)
 	}
 	else
 	{
-		auto objectCache = objectCacheEnabled ? Cache::getObjectCache() : nullptr;
+		auto objectCache = objectCacheEnabled ? Cache::getObjectCache(listener.get()) : nullptr;
 		std::unique_ptr<llvm::Module> module;
 		if (objectCache)
 			module = Cache::getObject(mainFuncName);
 		if (!module)
+		{
+			listener->stateChanged(ExecState::Compilation);
 			module = Compiler({}).compile(codeBegin, codeEnd, mainFuncName);
+		}
 		if (debugDumpModule)
 			module->dump();
 		if (!ee)
@@ -190,6 +150,7 @@ ReturnCode ExecutionEngine::run(RuntimeData* _data, Env* _env)
 
 			if (objectCache)
 				ee->setObjectCache(objectCache);
+			listener->stateChanged(ExecState::CodeGen);
 			entryFuncPtr = (EntryFuncPtr)ee->getFunctionAddress(mainFuncName);
 		}
 		else
@@ -198,28 +159,26 @@ ReturnCode ExecutionEngine::run(RuntimeData* _data, Env* _env)
 			{
 				ee->addModule(module.get());
 				module.release();
+				listener->stateChanged(ExecState::CodeGen);
 				entryFuncPtr = (EntryFuncPtr)ee->getFunctionAddress(mainFuncName);
 			}
 		}
 	}
 	assert(entryFuncPtr);
 
-	if (m_stats)
+	listener->stateChanged(ExecState::Execution);
-		m_stats->execStarted();
-
 	auto returnCode = runEntryFunc(entryFuncPtr, &runtime);
-
+	listener->stateChanged(ExecState::Return);
-	if (m_stats)
-		m_stats->execEnded();
 
 	if (returnCode == ReturnCode::Return)
 	{
 		returnData = runtime.getReturnData();     // Save reference to return data
 		std::swap(m_memory, runtime.getMemory()); // Take ownership of memory
 	}
+	listener->stateChanged(ExecState::Finished);
 
 	if (statsCollectingEnabled)
-		statsCollector.stats.push_back(std::move(m_stats));
+		statsCollector.stats.push_back(std::move(listener));
 
 	return returnCode;
 }

evmjit/libevmjit/ExecutionEngine.h

@@ -2,7 +2,6 @@
 
 #include <memory>
 #include "RuntimeData.h"
-#include "ExecStats.h"
 
 namespace dev
 {
@@ -11,19 +10,41 @@ namespace eth
 namespace jit
 {
 
+enum class ExecState
+{
+	Started,
+	CacheLoad,
+	CacheWrite,
+	Compilation,
+	CodeGen,
+	Execution,
+	Return,
+	Finished
+};
+
+class ExecutionEngineListener
+{
+public:
+	ExecutionEngineListener() = default;
+	ExecutionEngineListener(ExecutionEngineListener const&) = delete;
+	ExecutionEngineListener& operator=(ExecutionEngineListener) = delete;
+	virtual ~ExecutionEngineListener() {}
+
+	virtual void executionStarted() {}
+	virtual void executionEnded() {}
+
+	virtual void stateChanged(ExecState) {}
+};
+
 class ExecutionEngine
 {
 public:
 	ExecutionEngine() = default;
 	ExecutionEngine(ExecutionEngine const&) = delete;
-	void operator=(ExecutionEngine) = delete;
+	ExecutionEngine& operator=(ExecutionEngine) = delete;
 
 	EXPORT ReturnCode run(RuntimeData* _data, Env* _env);
 
-	void collectStats();
-
-	std::unique_ptr<ExecStats> getStats();
-
 	/// Reference to returned data (RETURN opcode used)
 	bytes_ref returnData;
 
@@ -31,8 +52,6 @@ private:
 	/// After execution, if RETURN used, memory is moved there
 	/// to allow client copy the returned data
 	bytes m_memory;
-
-	std::unique_ptr<ExecStats> m_stats;
 };
 
 }