Basic log is generated.

libraries/chain/CMakeLists.txt

@@ -18,6 +18,7 @@ add_library( steem_chain
 
              util/reward.cpp
              util/impacted.cpp
+             util/advanced_benchmark_dumper.cpp
 
              ${HEADERS}
            )

libraries/chain/database.cpp

@@ -113,6 +113,8 @@ void database::open( const open_args& args )
             init_genesis( args.initial_supply );
          });
 
+      benchmark_dumper.set_enabled( args.benchmark_is_enabled );
+
       _block_log.open( args.data_dir / "block_log" );
 
       auto log_head = _block_log.head();
@@ -2987,7 +2989,19 @@ void database::apply_operation(const operation& op)
 {
    operation_notification note(op);
    notify_pre_apply_operation( note );
+
+   if( benchmark_dumper.is_enabled() )
+   {
+      benchmark_dumper.begin();
+   }
+
    _my->_evaluator_registry.get_evaluator( op ).apply( op );
+
+   if( benchmark_dumper.is_enabled() )
+   {
+      benchmark_dumper.end( _my->_evaluator_registry.get_evaluator( op ).get_name( op ) );
+   }
+
    notify_post_apply_operation( note );
 }
 

libraries/chain/include/steem/chain/database.hpp

@@ -13,6 +13,8 @@
 #include <steem/protocol/protocol.hpp>
 #include <steem/protocol/hardfork.hpp>
 
+#include <steem/chain/util/advanced_benchmark_dumper.hpp>
+
 #include <fc/signals.hpp>
 
 #include <fc/log/logger.hpp>
@@ -35,6 +37,9 @@ namespace steem { namespace chain {
       struct comment_reward_context;
    }
 
+   namespace util {
+      struct advanced_benchmark_dumper;
+   }
    /**
     *   @class database
     *   @brief tracks the blockchain state in an extensible manner
@@ -81,6 +86,7 @@ namespace steem { namespace chain {
             uint64_t shared_file_size = 0;
             uint32_t chainbase_flags = 0;
             bool do_validate_invariants = false;
+            bool benchmark_is_enabled = false;
 
             // The following fields are only used on reindexing
             uint32_t stop_replay_at = 0;
@@ -522,6 +528,8 @@ namespace steem { namespace chain {
 
          flat_map< std::string, std::shared_ptr< custom_operation_interpreter > >   _custom_operation_interpreters;
          std::string                       _json_schema;
+
+         util::advanced_benchmark_dumper     benchmark_dumper;
    };
 
 } }

libraries/chain/include/steem/chain/evaluator.hpp

@@ -12,6 +12,7 @@ class evaluator
    public:
       virtual void apply(const OperationType& op) = 0;
       virtual int get_type()const = 0;
+      virtual std::string get_name( const OperationType& op ) = 0;
 };
 
 template< typename EvaluatorType, typename OperationType=steem::protocol::operation >
@@ -33,6 +34,13 @@ class evaluator_impl : public evaluator<OperationType>
 
       virtual int get_type()const override { return OperationType::template tag< typename EvaluatorType::operation_type >::value; }
 
+      virtual std::string get_name( const OperationType& o ) override
+      {
+         const auto& op = o.template get< typename EvaluatorType::operation_type >();
+
+         return boost::core::demangle( typeid( op ).name() );
+      }
+
       database& db() { return _db; }
 
    protected:

libraries/chain/include/steem/chain/util/advanced_benchmark_dumper.hpp

@@ -0,0 +1,71 @@
+#pragma once
+
+#include <fc/time.hpp>
+#include <fc/variant.hpp>
+#include <fc/reflect/variant.hpp>
+#include <fc/exception/exception.hpp>
+#include <fc/io/json.hpp>
+
+#include <sys/time.h>
+
+namespace steem { namespace chain { namespace util {
+
+class advanced_benchmark_dumper
+{                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                           
+   public:
+
+      class item
+      {
+         public:
+
+            std::string op_name;
+            mutable uint64_t time;
+
+            item( std::string _op_name, uint64_t _time )
+            : op_name( _op_name ), time( _time )
+            {
+
+            }
+
+            bool operator<( const item& obj ) const
+            {
+               return op_name < obj.op_name;
+            }
+
+            void change_time( uint64_t _time ) const
+            {
+               time += _time;
+            }
+      };
+
+   private:
+
+      static uint32_t cnt;
+
+      bool enabled = false;
+
+      uint32_t flush_cnt = 0;
+      uint32_t flush_max = 50000;
+
+      uint64_t time_begin = 0;
+
+      std::string file_name;
+
+      std::set< item > items;
+
+   public:
+
+      advanced_benchmark_dumper();
+      ~advanced_benchmark_dumper();
+
+      void set_enabled( bool val ) { enabled = val; }
+      bool is_enabled() { return enabled; }
+
+      void begin();
+      void end( const std::string& str );
+      void dump();
+};
+
+} } } // steem::chain::util
+
+FC_REFLECT( steem::chain::util::advanced_benchmark_dumper::item, (op_name)(time) )

libraries/chain/util/advanced_benchmark_dumper.cpp

@@ -0,0 +1,58 @@
+
+#include <steem/chain/util/advanced_benchmark_dumper.hpp>
+#include <chrono>
+
+namespace steem { namespace chain { namespace util {
+
+   uint32_t advanced_benchmark_dumper::cnt = 0;
+
+   advanced_benchmark_dumper::advanced_benchmark_dumper()
+   {
+      if( cnt == 0 )
+         file_name = "advanced_benchmark.json";
+      else
+         file_name = std::to_string( cnt ) + "_advanced_benchmark.json";
+
+      ++cnt;
+   }
+
+   advanced_benchmark_dumper::~advanced_benchmark_dumper()
+   {
+      dump();
+   }
+
+   void advanced_benchmark_dumper::begin()
+   {
+      time_begin = std::chrono::duration_cast<std::chrono::milliseconds>( std::chrono::system_clock::now().time_since_epoch() ).count();
+   }
+
+   void advanced_benchmark_dumper::end( const std::string& str )
+   {
+      uint64_t time = std::chrono::duration_cast<std::chrono::milliseconds>( std::chrono::system_clock::now().time_since_epoch() ).count() - time_begin;
+      std::pair< std::set< item >::iterator, bool > res = items.emplace( item( str, time ) );
+      if( !res.second )
+         res.first->change_time( time );
+
+      ++flush_cnt;
+      if( flush_cnt >= flush_max )
+      {
+         flush_cnt = 0;
+         dump();
+      }
+   }
+
+   void advanced_benchmark_dumper::dump()
+   {
+      const fc::path path( file_name.c_str() );
+      try
+      {
+         fc::json::save_to_file( items, path );
+      }
+      catch ( const fc::exception& except )
+      {
+         elog( "error writing benchmark data to file ${filename}: ${error}",
+               ( "filename", path )("error", except.to_detail_string() ) );
+      }
+   }
+
+} } } // steem::chain::util

libraries/plugins/chain/chain_plugin.cpp

@@ -26,6 +26,7 @@ class chain_plugin_impl
       bool                             readonly = false;
       bool                             check_locks = false;
       bool                             validate_invariants = false;
+      bool                             benchmark_is_enabled =false;
       uint32_t                         stop_replay_at = 0;
       uint32_t                         benchmark_interval = 0;
       uint32_t                         flush_interval = 0;
@@ -58,6 +59,7 @@ void chain_plugin::set_program_options(options_description& cli, options_descrip
          ("replay-blockchain", bpo::bool_switch()->default_value(false), "clear chain database and replay all blocks" )
          ("resync-blockchain", bpo::bool_switch()->default_value(false), "clear chain database and block log" )
          ("stop-replay-at-block", bpo::value<uint32_t>(), "Stop and exit after reaching given block number")
+         ("advanced-benchmark", bpo::bool_switch()->default_value(false), "Make profiling for every plugin.")
          ("set-benchmark-interval", bpo::value<uint32_t>(), "Print time and memory usage every given number of blocks")
          ("check-locks", bpo::bool_switch()->default_value(false), "Check correctness of chainbase locking" )
          ("validate-database-invariants", bpo::bool_switch()->default_value(false), "Validate all supply invariants check out" )
@@ -105,6 +107,9 @@ void chain_plugin::plugin_initialize(const variables_map& options) {
       }
    }
 
+   if( options.count("advanced-benchmark") )
+      my->benchmark_is_enabled = options.at( "advanced-benchmark" ).as<bool>();
+
 #ifdef IS_TEST_NET
    if( options.count( "chain-id" ) )
       my->db.set_chain_id( options.at("chain-id").as< std::string >() );
@@ -134,6 +139,7 @@ void chain_plugin::plugin_startup()
    db_open_args.shared_file_size = my->shared_memory_size;
    db_open_args.do_validate_invariants = my->validate_invariants;
    db_open_args.stop_replay_at = my->stop_replay_at;
+   db_open_args.benchmark_is_enabled = my->benchmark_is_enabled;
 
    if(my->replay)
    {