Session stats improvements (#1746)

* Detailed session stats for work time and storage stat cache

* Bring back the old session state file writing

Author: SpyCheese

crypto/block/transaction.cpp

@@ -1710,12 +1710,12 @@ bool Transaction::run_precompiled_contract(const ComputePhaseConfig& cfg, precom
   ComputePhase& cp = *compute_phase;
   CHECK(cp.precompiled_gas_usage);
   td::uint64 gas_usage = cp.precompiled_gas_usage.value();
-  td::Timer timer;
+  td::RealCpuTimer timer;
   auto result =
       impl.run(my_addr, now, start_lt, balance, new_data, *in_msg_body, in_msg, msg_balance_remaining, in_msg_extern,
                compute_vm_libraries(cfg), cfg.global_version, cfg.max_vm_data_depth, new_code,
                cfg.unpacked_config_tuple, due_payment.not_null() ? due_payment : td::zero_refint(), gas_usage);
-  double elapsed = timer.elapsed();
+  time_tvm = timer.elapsed_both();
   cp.vm_init_state_hash = td::Bits256::zero();
   cp.exit_code = result.exit_code;
   cp.out_of_gas = false;
@@ -1726,15 +1726,15 @@ bool Transaction::run_precompiled_contract(const ComputePhaseConfig& cfg, precom
   cp.success = (cp.accepted && result.committed);
   LOG(INFO) << "Running precompiled smart contract " << impl.get_name() << ": exit_code=" << result.exit_code
             << " accepted=" << result.accepted << " success=" << cp.success << " gas_used=" << gas_usage
-            << " time=" << elapsed << "s";
+            << " time=" << time_tvm.real << "s cpu_time=" << time_tvm.cpu;
   if (cp.accepted & use_msg_state) {
     was_activated = true;
     acc_status = Account::acc_active;
   }
   if (cfg.with_vm_log) {
     cp.vm_log = PSTRING() << "Running precompiled smart contract " << impl.get_name()
                           << ": exit_code=" << result.exit_code << " accepted=" << result.accepted
-                          << " success=" << cp.success << " gas_used=" << gas_usage << " time=" << elapsed << "s";
+                          << " success=" << cp.success << " gas_used=" << gas_usage << " time=" << time_tvm.real << "s";
   }
   if (cp.success) {
     cp.new_data = impl.get_c4();
@@ -1943,9 +1943,9 @@ bool Transaction::prepare_compute_phase(const ComputePhaseConfig& cfg) {
 
   LOG(DEBUG) << "starting VM";
   cp.vm_init_state_hash = vm.get_state_hash();
-  td::Timer timer;
+  td::RealCpuTimer timer;
   cp.exit_code = ~vm.run();
-  double elapsed = timer.elapsed();
+  time_tvm = timer.elapsed_both();
   LOG(DEBUG) << "VM terminated with exit code " << cp.exit_code;
   cp.out_of_gas = (cp.exit_code == ~(int)vm::Excno::out_of_gas);
   cp.vm_final_state_hash = vm.get_final_state_hash(cp.exit_code);
@@ -1971,7 +1971,7 @@ bool Transaction::prepare_compute_phase(const ComputePhaseConfig& cfg) {
   LOG(INFO) << "steps: " << vm.get_steps_count() << " gas: used=" << gas.gas_consumed() << ", max=" << gas.gas_max
             << ", limit=" << gas.gas_limit << ", credit=" << gas.gas_credit;
   LOG(INFO) << "out_of_gas=" << cp.out_of_gas << ", accepted=" << cp.accepted << ", success=" << cp.success
-            << ", time=" << elapsed << "s";
+            << ", time=" << time_tvm.real << "s, cpu_time=" << time_tvm.cpu;
   if (logger != nullptr) {
     cp.vm_log = logger->get_log();
   }
@@ -3196,7 +3196,13 @@ td::Status Transaction::check_state_limits(const SizeLimitsConfig& size_limits,
   }
   {
     TD_PERF_COUNTER(transaction_storage_stat_a);
-    td::Timer timer;
+    td::RealCpuTimer timer;
+    SCOPE_EXIT {
+      LOG_IF(INFO, timer.elapsed_real() > 0.1) << "Compute used storage (1) took " << timer.elapsed_real() << "s";
+      if (is_account_stat) {
+        time_storage_stat += timer.elapsed_both();
+      }
+    };
     if (is_account_stat && compute_phase) {
       storage_stat.add_hint(compute_phase->vm_loaded_cells);
     }
@@ -3208,9 +3214,6 @@ td::Status Transaction::check_state_limits(const SizeLimitsConfig& size_limits,
       storage_stat_updates.push_back(new_library);
     }
     TRY_STATUS(storage_stat.replace_roots({new_code, new_data, new_library}, /* check_merkle_depth = */ true));
-    if (timer.elapsed() > 0.1) {
-      LOG(INFO) << "Compute used storage (1) took " << timer.elapsed() << "s";
-    }
   }
 
   if (storage_stat.get_total_cells() > size_limits.max_acc_state_cells ||
@@ -3511,9 +3514,11 @@ bool Transaction::compute_state(const SerializeConfig& cfg) {
     auto roots = new_storage_for_stat->prefetch_all_refs();
     storage_stat_updates.insert(storage_stat_updates.end(), roots.begin(), roots.end());
     {
+      td::RealCpuTimer timer;
       StorageStatCalculationContext context{true};
       StorageStatCalculationContext::Guard guard{&context};
       td::Status S = stats.replace_roots(roots);
+      time_storage_stat += timer.elapsed_both();
       if (S.is_error()) {
         LOG(ERROR) << "Cannot recompute storage stats for account " << account.addr.to_hex() << ": " << S.move_as_error();
         return false;

crypto/block/transaction.h

@@ -399,6 +399,7 @@ struct Transaction {
   td::optional<td::Bits256> new_storage_dict_hash;
   bool gas_limit_overridden{false};
   std::vector<Ref<vm::Cell>> storage_stat_updates;
+  td::RealCpuTimer::Time time_tvm, time_storage_stat;
   Transaction(const Account& _account, int ttype, ton::LogicalTime req_start_lt, ton::UnixTime _now,
               Ref<vm::Cell> _inmsg = {});
   bool unpack_input_msg(bool ihr_delivered, const ActionPhaseConfig* cfg);

tdutils/td/utils/Timer.h

@@ -81,6 +81,52 @@ class ThreadCpuTimer {
   bool is_paused_{false};
 };
 
+class RealCpuTimer {
+ public:
+  RealCpuTimer() : RealCpuTimer(false) {
+  }
+  explicit RealCpuTimer(bool is_paused) : real_(is_paused), cpu_(is_paused) {
+  }
+  RealCpuTimer(const RealCpuTimer &other) = default;
+  RealCpuTimer &operator=(const RealCpuTimer &other) = default;
+
+  double elapsed_real() const {
+    return real_.elapsed();
+  }
+  double elapsed_cpu() const {
+    return cpu_.elapsed();
+  }
+  struct Time {
+    double real = 0.0, cpu = 0.0;
+    double get(bool is_cpu) const {
+      return is_cpu ? cpu : real;
+    }
+    Time &operator+=(const Time &other) {
+      real += other.real;
+      cpu += other.cpu;
+      return *this;
+    }
+    Time operator-(const Time &other) const {
+      return {.real = real - other.real, .cpu = cpu - other.cpu};
+    }
+  };
+  Time elapsed_both() const {
+    return {.real = real_.elapsed(), .cpu = cpu_.elapsed()};
+  }
+  void pause() {
+    real_.pause();
+    cpu_.pause();
+  }
+  void resume() {
+    real_.resume();
+    cpu_.resume();
+  }
+
+ private:
+  Timer real_;
+  ThreadCpuTimer cpu_;
+};
+
 class PerfLog;
 struct EmptyDeleter {
   template <class T>

tl/generate/scheme/ton_api.tl

@@ -955,21 +955,35 @@ validatorStats.blockStats
     ext_msgs:validatorStats.blockStats.extMsgsStats transactions:int shard_configuration:(vector tonNode.blockIdExt)
     old_out_msg_queue_size:long new_out_msg_queue_size:long msg_queue_cleaned:int
     neighbors:(vector validatorStats.blockStats.neighborStats) = validatorStats.BlockStats;
+validatorStats.collateWorkTimeStats
+    total:double queue_cleanup:double prelim_storage_stat:double trx_tvm:double trx_storage_stat:double
+    trx_other:double final_storage_stat:double create_block:double create_collated_data:double create_block_candidate:double
+    = validatorStats.CollateWorkTimeStats;
+validatorStats.storageStatCacheStats
+    small_cnt:long small_cells:long hit_cnt:long hit_cells:long miss_cnt:long miss_cells:long = validatorStats.StorageStatCacheStats;
 
 validatorStats.collatedBlock
     block_id:tonNode.blockIdExt collated_data_hash:int256 cc_seqno:int collated_at:double
     bytes:int collated_data_bytes:int attempt:int
     self:int256 is_validator:Bool
     total_time:double work_time:double cpu_work_time:double time_stats:string
+    work_time_real_stats:validatorStats.collateWorkTimeStats
+    work_time_cpu_stats:validatorStats.collateWorkTimeStats
     block_limits:validatorStats.blockLimitsStatus
-    block_stats:validatorStats.blockStats = validatorSession.stats.CollatedBlock;
+    block_stats:validatorStats.blockStats
+    storage_stat_cache:validatorStats.storageStatCacheStats = validatorSession.stats.CollatedBlock;
 
+validatorStats.validateWorkTimeStats
+    total:double trx_tvm:double trx_storage_stat:double trx_other:double = validatorStats.ValidateWorkTimeStats;
 validatorStats.validatedBlock
     block_id:tonNode.blockIdExt collated_data_hash:int256 validated_at:double
     self:int256
     valid:Bool comment:string
     bytes:int collated_data_bytes:int
-    total_time:double work_time:double cpu_work_time:double = validatorStats.ValidatedBlock;
+    total_time:double work_time:double cpu_work_time:double
+    work_time_real_stats:validatorStats.validateWorkTimeStats
+    work_time_cpu_stats:validatorStats.validateWorkTimeStats
+    storage_stat_cache:validatorStats.storageStatCacheStats = validatorStats.ValidatedBlock;
 
 validatorStats.newValidatorGroup.node id:int256 pubkey:PublicKey adnl_id:int256 weight:long = validatorStats.newValidatorGroup.Node;
 validatorStats.newValidatorGroup session_id:int256 shard:tonNode.shardId cc_seqno:int

tl/generate/scheme/ton_api.tlo

@@ -118,7 +118,7 @@ class Collator final : public td::actor::Actor {
       Ref<vm::Cell> msg_root, block::Account* acc, UnixTime utime, LogicalTime lt,
       block::StoragePhaseConfig* storage_phase_cfg, block::ComputePhaseConfig* compute_phase_cfg,
       block::ActionPhaseConfig* action_phase_cfg, block::SerializeConfig* serialize_cfg, bool external,
-      LogicalTime after_lt);
+      LogicalTime after_lt, CollationStats* stats = nullptr);
 
  private:
   void start_up() override;
@@ -404,8 +404,7 @@ class Collator final : public td::actor::Actor {
   static td::uint32 get_skip_externals_queue_size();
 
  private:
-  td::Timer work_timer_{true};
-  td::ThreadCpuTimer cpu_work_timer_{true};
+  td::RealCpuTimer work_timer_{true};
   CollationStats stats_;
 
   void finalize_stats();