Merge pull request #486 from ewasm/benchmarking

Benchmarking instrumentation

Author: axic

README.md

@@ -66,6 +66,7 @@ These are to be used via EVMC `set_option`:
 
 - `engine=<engine>` will select the underlying WebAssembly engine, where the only accepted values currently are `binaryen`, `wabt`, and `wavm`
 - `metering=true` will enable metering of bytecode at deployment using the [Sentinel system contract] (set to `false` by default)
+- `benchmark=true` will produce execution timings and output it to both standard error output and `hera_benchmarks.log` file.
 - `evm1mode=<evm1mode>` will select how EVM1 bytecode is handled
 - `sys:<alias/address>=file.wasm` will override the code executing at the specified address with code loaded from a filepath at runtime. This option supports aliases for system contracts as well, such that `sys:sentinel=file.wasm` and `sys:evm2wasm=file.wasm` are both valid. **This option is intended for debugging purposes.**
 

circle.yml

@@ -139,7 +139,7 @@ defaults:
         SO=$([ $(uname) = Darwin ] && echo dylib || echo so)
         if [[ $PRELOAD_ASAN ]]; then export LD_PRELOAD=/usr/lib/clang/8/lib/linux/libclang_rt.asan-x86_64.so; fi
         testeth --version
-        testeth -t GeneralStateTests/stEWASMTests -- --testpath tests --vm ~/build/src/libhera.$SO --singlenet Byzantium --evmc engine=binaryen
+        testeth -t GeneralStateTests/stEWASMTests -- --testpath tests --vm ~/build/src/libhera.$SO --singlenet Byzantium --evmc engine=binaryen $TESTETH_OPTIONS
 
   test-wabt: &test-wabt
     run:
@@ -148,7 +148,7 @@ defaults:
         SO=$([ $(uname) = Darwin ] && echo dylib || echo so)
         if [[ $PRELOAD_ASAN ]]; then export LD_PRELOAD=/usr/lib/clang/8/lib/linux/libclang_rt.asan-x86_64.so; fi
         testeth --version
-        testeth -t GeneralStateTests/stEWASMTests -- --testpath tests --vm ~/build/src/libhera.$SO --singlenet Byzantium --evmc engine=wabt
+        testeth -t GeneralStateTests/stEWASMTests -- --testpath tests --vm ~/build/src/libhera.$SO --singlenet Byzantium --evmc engine=wabt $TESTETH_OPTIONS
 
   test-wavm: &test-wavm
     run:
@@ -158,7 +158,7 @@ defaults:
         SO=$([ $(uname) = Darwin ] && echo dylib || echo so)
         if [[ $PRELOAD_ASAN ]]; then export LD_PRELOAD=/usr/lib/clang/8/lib/linux/libclang_rt.asan-x86_64.so; fi
         testeth --version
-        testeth -t GeneralStateTests/stEWASMTests -- --testpath tests --vm ~/build/src/libhera.$SO --singlenet Byzantium --evmc engine=wavm
+        testeth -t GeneralStateTests/stEWASMTests -- --testpath tests --vm ~/build/src/libhera.$SO --singlenet Byzantium --evmc engine=wavm $TESTETH_OPTIONS
 
   evmc-test: &evmc-test
     run:
@@ -249,6 +249,7 @@ jobs:
       - GENERATOR: Ninja
       - BUILD_PARALLEL_JOBS: 4
       - CMAKE_OPTIONS: -DCOVERAGE=ON -DBUILD_SHARED_LIBS=ON -DHERA_DEBUGGING=ON -DHERA_BINARYEN=ON
+      - TESTETH_OPTIONS: --evmc benchmark=true
     docker:
       - image: ethereum/cpp-build-env:9
     steps:

src/binaryen.cpp

@@ -479,6 +479,7 @@ ExecutionResult BinaryenEngine::execute(
   evmc_message const& msg,
   bool meterInterfaceGas
 ) {
+  instantiationStarted();
   wasm::Module module;
 
   // Load module
@@ -497,6 +498,8 @@ ExecutionResult BinaryenEngine::execute(
   BinaryenEthereumInterface interface(context, state_code, msg, result, meterInterfaceGas);
   wasm::ModuleInstance instance(module, &interface);
 
+  executionStarted();
+
   try {
     wasm::Name main = wasm::Name("main");
     wasm::LiteralList args;
@@ -506,6 +509,7 @@ ExecutionResult BinaryenEngine::execute(
     // It is only a clutch for POSIX style exit()
   }
 
+  executionFinished();
   return result;
 }
 

src/eei.cpp

@@ -15,10 +15,11 @@
  */
 
 #include <array>
-#include <vector>
-#include <sstream>
-#include <iostream>
+#include <fstream>
 #include <iomanip>
+#include <iostream>
+#include <sstream>
+#include <vector>
 
 #include "debugging.h"
 #include "eei.h"
@@ -45,6 +46,26 @@ bool exceedsUint128(evmc_uint256be const& value) noexcept
 }
 }  // namespace
 
+bool WasmEngine::benchmarkingEnabled = false;
+
+void WasmEngine::collectBenchmarkingData()
+{
+  // Convert duration to string with microsecond units.
+  constexpr auto to_us_str = [](clock::duration d) {
+    return std::to_string(std::chrono::duration_cast<std::chrono::microseconds>(d).count());
+  };
+
+  const auto now = clock::now();
+  const auto instantiationDuration = executionStartTime - instantiationStartTime;
+  const auto executionDuration = now - executionStartTime;
+
+  const auto log = "Time [us]: " + to_us_str(instantiationDuration + executionDuration) +
+                   " (instantiation: " + to_us_str(instantiationDuration) +
+                   ", execution: " + to_us_str(executionDuration) + ")\n";
+  std::cerr << log;
+  std::ofstream{"hera_benchmarks.log", std::ios::out | std::ios::app} << log;
+}
+
 #if HERA_DEBUGGING
   void EthereumInterface::debugPrintMem(bool useHex, uint32_t offset, uint32_t length)
   {

src/eei.h

@@ -16,6 +16,7 @@
 
 #pragma once
 
+#include <chrono>
 #include <vector>
 
 #include <evmc/evmc.h>
@@ -47,6 +48,35 @@ class WasmEngine {
   ) = 0;
 
   virtual void verifyContract(std::vector<uint8_t> const& code) = 0;
+
+  static void enableBenchmarking() noexcept { benchmarkingEnabled = true; }
+
+protected:
+  void instantiationStarted() noexcept
+  {
+    if (benchmarkingEnabled)
+      instantiationStartTime = clock::now();
+  }
+
+  void executionStarted() noexcept
+  {
+    if (benchmarkingEnabled)
+      executionStartTime = clock::now();
+  }
+
+  void executionFinished()
+  {
+    if (benchmarkingEnabled)
+      collectBenchmarkingData();
+  }
+
+private:
+  void collectBenchmarkingData();
+
+  using clock = std::chrono::high_resolution_clock;
+  static bool benchmarkingEnabled;
+  clock::time_point instantiationStartTime;
+  clock::time_point executionStartTime;
 };
 
 class EthereumInterface {

src/hera.cpp

@@ -413,6 +413,14 @@ evmc_set_option_result hera_set_option(
     return EVMC_SET_OPTION_SUCCESS;
   }
 
+  if (strcmp(name, "benchmark") == 0) {
+    if (strcmp(value, "true") == 0) {
+      WasmEngine::enableBenchmarking();
+      return EVMC_SET_OPTION_SUCCESS;
+    }
+    return EVMC_SET_OPTION_INVALID_VALUE;
+  }
+
   if (strcmp(name, "engine") == 0) {
     auto it = wasm_engine_map.find(value);
     if (it != wasm_engine_map.end()) {

src/wabt.cpp

@@ -78,6 +78,7 @@ ExecutionResult WabtEngine::execute(
   evmc_message const& msg,
   bool meterInterfaceGas
 ) {
+  instantiationStarted();
   HERA_DEBUG << "Executing with wabt...\n";
 
   // Set up the wabt Environment, which includes the Wasm store
@@ -650,6 +651,8 @@ ExecutionResult WabtEngine::execute(
   // FIXME: really bad design
   interface.setWasmMemory(env.GetMemory(0));
 
+  executionStarted();
+
   // Execute main
   try {
     interp::ExecResult wabtResult = executor.RunExport(mainFunction, interp::TypedValues{}); // second arg is empty since no args
@@ -660,6 +663,7 @@ ExecutionResult WabtEngine::execute(
     // It is only a clutch for POSIX style exit()
   }
 
+  executionFinished();
   return result;
 }
 

src/wavm.cpp

@@ -285,9 +285,11 @@ ExecutionResult WavmEngine::execute(
   bool meterInterfaceGas
 ) {
   try {
+    instantiationStarted();
     ExecutionResult result = internalExecute(context, code, state_code, msg, meterInterfaceGas);
     // And clean up mess left by this run.
     Runtime::collectGarbage();
+    executionFinished();
     return result;
   } catch (exception const&) {
     // And clean up mess left by this run.
@@ -373,6 +375,8 @@ ExecutionResult WavmEngine::internalExecute(
   Runtime::GCPointer<Runtime::FunctionInstance> mainFunction = asFunctionNullable(Runtime::getInstanceExport(moduleInstance, "main"));
   ensureCondition(mainFunction, ContractValidationFailure, "\"main\" not found");
 
+  executionStarted();
+
   // this is how WAVM's try/catch for exceptions
   Runtime::catchRuntimeExceptions(
     [&] {