IS 862 add more statistics

skalenetwork · Sep 20, 2023 · 2cbe090 · 2cbe090
1 parent bd483e9
commit 2cbe090
Show file tree

Hide file tree

Showing 5 changed files with 39 additions and 17 deletions.
diff --git a/libethereum/Block.cpp b/libethereum/Block.cpp
@@ -528,6 +528,11 @@ tuple< TransactionReceipts, unsigned > Block::syncEveryone(
             clog( VerbosityError, "block" ) << "FAILED transaction after consensus! " << ex.what();
         }
     }
+    clog( Verbosity::VerbosityInfo, "execute" ) << "EWT:" << executeTime;
+    clog( Verbosity::VerbosityInfo, "execute" ) << "COMWT:" << commitTime;
+
+    executeTime = 0;
+    commitTime = 0;
 
 #ifdef HISTORIC_STATE
     m_state.mutableHistoricState().saveRootForBlock( m_currentBlock.number() );
@@ -839,6 +844,8 @@ ExecutionResult Block::execute(
             throw -1;  // will catch below
 
         resultReceipt = stateSnapshot.execute( envInfo, *m_sealEngine, _t, _p, _onOp );
+        commitTime += stateSnapshot.getCommitTime();
+        executeTime += stateSnapshot.getExecuteTime();
 
         // use fake receipt created above if execution throws!!
     } catch ( const TransactionException& ex ) {

diff --git a/libethereum/Block.h b/libethereum/Block.h
@@ -343,6 +343,9 @@ class Block {
     Logger m_logger{ createLogger( VerbosityDebug, "block" ) };
     Logger m_loggerDetailed{ createLogger( VerbosityTrace, "block" ) };
 
+    boost::chrono::duration< long, boost::ratio< 1, 1000 > >::rep commitTime = 0;
+    boost::chrono::duration< long, boost::ratio< 1, 1000 > >::rep executeTime = 0;
+
     Counter< Block > c;
     ;
 

diff --git a/libethereum/BlockChain.cpp b/libethereum/BlockChain.cpp
@@ -1252,8 +1252,6 @@ uint64_t BlockChain::getTotalCacheMemory() {
 }
 
 void BlockChain::garbageCollect( bool _force ) {
-    boost::chrono::high_resolution_clock::time_point gcTimeStart =
-        boost::chrono::high_resolution_clock::now();
     updateStats();
 
     if ( !_force && chrono::system_clock::now() < m_lastCollection + c_collectionDuration &&
@@ -1265,8 +1263,6 @@ void BlockChain::garbageCollect( bool _force ) {
 
     m_lastCollection = chrono::system_clock::now();
 
-    boost::chrono::high_resolution_clock::time_point gcTimeCycleStart =
-        boost::chrono::high_resolution_clock::now();
     while ( m_lastStats.memTotal() >= c_maxCacheSize ) {
         Guard l( x_cacheUsage );
         for ( CacheID const& id : m_cacheUsage.back() ) {
@@ -1316,13 +1312,6 @@ void BlockChain::garbageCollect( bool _force ) {
         m_cacheUsage.push_front( std::unordered_set< CacheID >{} );
         updateStats();
     }
-    boost::chrono::high_resolution_clock::time_point gcTimeCycleFinish =
-        boost::chrono::high_resolution_clock::now();
-    clog( VerbosityInfo, "bc" ) << "GCCT:"
-                                << boost::chrono::duration_cast< boost::chrono::milliseconds >(
-                                       gcTimeCycleFinish - gcTimeCycleStart )
-                                       .count();
-
 
     {
         WriteGuard l( x_blockHashes );
@@ -1334,12 +1323,6 @@ void BlockChain::garbageCollect( bool _force ) {
             assert( m_blockHashes.size() == 4096 );
         }
     }
-    boost::chrono::high_resolution_clock::time_point gcTimeFinish =
-        boost::chrono::high_resolution_clock::now();
-    clog( VerbosityInfo, "bc" ) << "GCT:"
-                                << boost::chrono::duration_cast< boost::chrono::milliseconds >(
-                                       gcTimeFinish - gcTimeStart )
-                                       .count();
 }
 
 void BlockChain::clearCaches() {

diff --git a/libskale/State.cpp b/libskale/State.cpp
@@ -1015,7 +1015,14 @@ std::pair< ExecutionResult, TransactionReceipt > State::execute( EnvInfo const&
         onOp = e.simpleTrace();
 #endif
     u256 const startGasUsed = _envInfo.gasUsed();
+    boost::chrono::high_resolution_clock::time_point executeTimeStart =
+        boost::chrono::high_resolution_clock::now();
     bool const statusCode = executeTransaction( e, _t, onOp );
+    boost::chrono::high_resolution_clock::time_point executeTimeFinish =
+        boost::chrono::high_resolution_clock::now();
+    executeTime = boost::chrono::duration_cast< boost::chrono::milliseconds >(
+        executeTimeFinish - executeTimeStart )
+                      .count();
 
     std::string strRevertReason;
     if ( res.excepted == dev::eth::TransactionException::RevertInstruction ) {
@@ -1056,8 +1063,15 @@ std::pair< ExecutionResult, TransactionReceipt > State::execute( EnvInfo const&
         m_fs_ptr->commit();
 
         removeEmptyAccounts = _envInfo.number() >= _sealEngine.chainParams().EIP158ForkBlock;
+        boost::chrono::high_resolution_clock::time_point commitTimeStart =
+            boost::chrono::high_resolution_clock::now();
         commit( removeEmptyAccounts ? dev::eth::CommitBehaviour::RemoveEmptyAccounts :
                                       dev::eth::CommitBehaviour::KeepEmptyAccounts );
+        boost::chrono::high_resolution_clock::time_point commitTimeFinish =
+            boost::chrono::high_resolution_clock::now();
+        commitTime = boost::chrono::duration_cast< boost::chrono::milliseconds >(
+            commitTimeFinish - commitTimeStart )
+                         .count();
 
         break;
     }

diff --git a/libskale/State.h b/libskale/State.h
@@ -400,6 +400,18 @@ class State {
         contractStorageLimit_ = _contractStorageLimit;
     };  // only for tests
 
+    auto getExecuteTime() {
+        auto val = executeTime;
+        executeTime = 0;
+        return val;
+    }
+
+    auto getCommitTime() {
+        auto val = commitTime;
+        commitTime = 0;
+        return val;
+    }
+
 
 private:
     void updateToLatestVersion();
@@ -497,6 +509,9 @@ class State {
     dev::s256 totalStorageUsed_ = 0;
     dev::s256 currentStorageUsed_ = 0;
 
+    boost::chrono::duration< long, boost::ratio< 1, 1000 > >::rep commitTime = 0;
+    boost::chrono::duration< long, boost::ratio< 1, 1000 > >::rep executeTime = 0;
+
 #ifdef HISTORIC_STATE
     dev::eth::HistoricState m_historicState;