From c81db206e9380b3972314405a68d3a388cccee8a Mon Sep 17 00:00:00 2001
From: Aleksey Kladov <aleksey.kladov@gmail.com>
Date: Fri, 5 Mar 2021 13:16:20 +0300
Subject: [PATCH] feat: improve visibility for runtime performance

tracing::span records how long it took to run a block of code and prints
this into into log.

See

https://github.com/near/nearcore/blob/ff01c544ce2675fadbf0284af52b356a383b27a8/docs/architecture.md#runtimenear-vm-runner

for the info on the tracing infra
---
 Cargo.lock                 | 1 +
 runtime/runtime/Cargo.toml | 1 +
 runtime/runtime/src/lib.rs | 8 ++++++++
 3 files changed, 10 insertions(+)

diff --git a/Cargo.lock b/Cargo.lock
index 0dbb4e6ec93..b27005a75a8 100644
--- a/Cargo.lock
+++ b/Cargo.lock
@@ -3818,6 +3818,7 @@ dependencies = [
  "tempfile",
  "testlib",
  "thiserror",
+ "tracing",
 ]
 
 [[package]]
diff --git a/runtime/runtime/Cargo.toml b/runtime/runtime/Cargo.toml
index 135ff87283b..1ac525514c9 100644
--- a/runtime/runtime/Cargo.toml
+++ b/runtime/runtime/Cargo.toml
@@ -9,6 +9,7 @@ byteorder = "1.2"
 serde = { version = "1", features = ["derive"] }
 serde_json = "1.0"
 log = "0.4"
+tracing = "0.1.13"
 rand = "0.7"
 lazy_static = "1.4"
 num-rational = "0.3"
diff --git a/runtime/runtime/src/lib.rs b/runtime/runtime/src/lib.rs
index b552cc5648c..c85b316ebe9 100644
--- a/runtime/runtime/src/lib.rs
+++ b/runtime/runtime/src/lib.rs
@@ -217,7 +217,10 @@ impl Runtime {
         signed_transaction: &SignedTransaction,
         stats: &mut ApplyStats,
     ) -> Result<(Receipt, ExecutionOutcomeWithId), RuntimeError> {
+        let _span =
+            tracing::debug_span!(target: "runtime", "Runtime::process_transaction").entered();
         near_metrics::inc_counter(&metrics::TRANSACTION_PROCESSED_TOTAL);
+
         match verify_and_charge_transaction(
             &apply_state.config,
             state_update,
@@ -817,6 +820,8 @@ impl Runtime {
         stats: &mut ApplyStats,
         epoch_info_provider: &dyn EpochInfoProvider,
     ) -> Result<Option<ExecutionOutcomeWithId>, RuntimeError> {
+        let _span = tracing::debug_span!(target: "runtime", "Runtime::process_receipt").entered();
+
         let account_id = &receipt.receiver_id;
         match receipt.receipt {
             ReceiptEnum::Data(ref data_receipt) => {
@@ -1156,9 +1161,12 @@ impl Runtime {
         epoch_info_provider: &dyn EpochInfoProvider,
         states_to_patch: Option<Vec<StateRecord>>,
     ) -> Result<ApplyResult, RuntimeError> {
+        let _span = tracing::debug_span!(target: "runtime", "Runtime::apply").entered();
+
         if states_to_patch.is_some() && !cfg!(feature = "sandbox") {
             panic!("Can only patch state in sandbox mode");
         }
+
         let trie = Rc::new(trie);
         let initial_state = TrieUpdate::new(trie.clone(), root);
         let mut state_update = TrieUpdate::new(trie.clone(), root);