From f203843114a192dee037aad2a5a614e1bb3b5b38 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Pawe=C5=82=20Bylica?= Date: Thu, 5 Feb 2015 16:04:54 +0100 Subject: [PATCH] Stats for execution states times --- evmjit/libevmjit/Cache.cpp | 29 +++++++---- evmjit/libevmjit/Cache.h | 7 +-- evmjit/libevmjit/ExecStats.cpp | 77 ++++++++++++++++++++++++++-- evmjit/libevmjit/ExecStats.h | 27 +++++++--- evmjit/libevmjit/ExecutionEngine.cpp | 67 +++++------------------- evmjit/libevmjit/ExecutionEngine.h | 35 ++++++++++--- 6 files changed, 153 insertions(+), 89 deletions(-) diff --git a/evmjit/libevmjit/Cache.cpp b/evmjit/libevmjit/Cache.cpp index 0e6fb517a..305b97d5c 100644 --- a/evmjit/libevmjit/Cache.cpp +++ b/evmjit/libevmjit/Cache.cpp @@ -7,6 +7,7 @@ #include #include #include +#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; - return &objectCache; + llvm::MemoryBuffer* g_lastObject; + ExecutionEngineListener* g_listener; } -namespace +ObjectCache* Cache::getObjectCache(ExecutionEngineListener* _listener) { - llvm::MemoryBuffer* lastObject; + static ObjectCache objectCache; + g_listener = _listener; + return &objectCache; } std::unique_ptr 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 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(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 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; - lastObject = nullptr; + auto o = g_lastObject; + g_lastObject = nullptr; return o; } diff --git a/evmjit/libevmjit/Cache.h b/evmjit/libevmjit/Cache.h index 1cad537cd..d7b32c651 100644 --- a/evmjit/libevmjit/Cache.h +++ b/evmjit/libevmjit/Cache.h @@ -1,7 +1,6 @@ #pragma once #include -#include #include @@ -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> m_map; }; class Cache { public: - static ObjectCache* getObjectCache(); + static ObjectCache* getObjectCache(ExecutionEngineListener* _listener); static std::unique_ptr getObject(std::string const& id); }; diff --git a/evmjit/libevmjit/ExecStats.cpp b/evmjit/libevmjit/ExecStats.cpp index e3f5293f8..deb322521 100644 --- a/evmjit/libevmjit/ExecStats.cpp +++ b/evmjit/libevmjit/ExecStats.cpp @@ -1,4 +1,7 @@ #include "ExecStats.h" +#include +#include +#include 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; } -void ExecStats::execEnded() +namespace { - execTime = std::chrono::high_resolution_clock::now() - m_tp; +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(tot).count() + << std::setw(10) << std::right << std::chrono::duration_cast(avg).count() + << std::setw(10) << std::right << std::chrono::duration_cast(min).count() + << std::setw(10) << std::right << std::chrono::duration_cast(max).count() + << std::endl; + } +}; + +char const* getExecStateName(ExecState _state) +{ + 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); + } } } diff --git a/evmjit/libevmjit/ExecStats.h b/evmjit/libevmjit/ExecStats.h index 3ee730836..284ecad7b 100644 --- a/evmjit/libevmjit/ExecStats.h +++ b/evmjit/libevmjit/ExecStats.h @@ -2,6 +2,7 @@ #include #include +#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; - std::chrono::high_resolution_clock::duration codegenTime; - std::chrono::high_resolution_clock::duration cacheLoadTime; - std::chrono::high_resolution_clock::duration execTime; + duration time[(int)ExecState::Finished] = {}; - void execStarted(); - void execEnded(); + void stateChanged(ExecState _state) override; private: - std::chrono::high_resolution_clock::time_point m_tp; + ExecState m_state = {}; + time_point m_tp = {}; + +}; + + +class StatsCollector +{ +public: + std::vector> stats; + ~StatsCollector(); }; } diff --git a/evmjit/libevmjit/ExecutionEngine.cpp b/evmjit/libevmjit/ExecutionEngine.cpp index bc1202e79..dd545cd03 100644 --- a/evmjit/libevmjit/ExecutionEngine.cpp +++ b/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 @@ -83,50 +84,6 @@ bool showInfo() return show; } -class StatsCollector -{ -public: - std::vector> 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(total).count(); - auto nAverage = std::chrono::duration_cast(total / stats.size()).count(); - auto nMax = std::chrono::duration_cast(max).count(); - auto nMin = std::chrono::duration_cast(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) - collectStats(); + std::unique_ptr listener{new ExecStats}; + 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 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) - m_stats->execStarted(); - + listener->stateChanged(ExecState::Execution); auto returnCode = runEntryFunc(entryFuncPtr, &runtime); - - if (m_stats) - m_stats->execEnded(); + listener->stateChanged(ExecState::Return); 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; } diff --git a/evmjit/libevmjit/ExecutionEngine.h b/evmjit/libevmjit/ExecutionEngine.h index e12f86af4..101475b11 100644 --- a/evmjit/libevmjit/ExecutionEngine.h +++ b/evmjit/libevmjit/ExecutionEngine.h @@ -2,7 +2,6 @@ #include #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 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 m_stats; }; }