From ca64cab2fbda8aef698de73d72eb1d5fc5df2149 Mon Sep 17 00:00:00 2001 From: Lin Huang Date: Tue, 1 Oct 2024 13:35:19 -0400 Subject: [PATCH 1/5] Set default value of start_time in block_report constructor to now --- libraries/chain/include/eosio/chain/controller.hpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/libraries/chain/include/eosio/chain/controller.hpp b/libraries/chain/include/eosio/chain/controller.hpp index eb911caa81..210af042d9 100644 --- a/libraries/chain/include/eosio/chain/controller.hpp +++ b/libraries/chain/include/eosio/chain/controller.hpp @@ -186,7 +186,7 @@ namespace eosio::chain { size_t total_net_usage = 0; size_t total_cpu_usage_us = 0; fc::microseconds total_elapsed_time{}; - fc::time_point start_time; + fc::time_point start_time{fc::time_point::now()}; }; void assemble_and_complete_block( block_report& br, const signer_callback_type& signer_callback ); From 2ea937d1605b2266309fdb78a197c43579be0b25 Mon Sep 17 00:00:00 2001 From: Lin Huang Date: Tue, 1 Oct 2024 13:37:55 -0400 Subject: [PATCH 2/5] Use producing time for Produced block and applying time for Received block --- libraries/chain/controller.cpp | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/libraries/chain/controller.cpp b/libraries/chain/controller.cpp index c2269f2da6..98b6855c15 100644 --- a/libraries/chain/controller.cpp +++ b/libraries/chain/controller.cpp @@ -3459,7 +3459,7 @@ struct controller_impl { fc::time_point now = fc::time_point::now(); ilog("Produced block ${id}... #${n} @ ${t} signed by ${p} " - "[trxs: ${count}, lib: ${lib}${confs}, net: ${net}, cpu: ${cpu}, elapsed: ${et} us, time: ${tt} us]", + "[trxs: ${count}, lib: ${lib}${confs}, net: ${net}, cpu: ${cpu}, elapsed: ${et} us, producing time: ${tt} us]", ("p", new_b->producer)("id", id.str().substr(8, 16))("n", new_b->block_num())("t", new_b->timestamp) ("count", new_b->transactions.size())("lib", chain_head.irreversible_blocknum())("net", br.total_net_usage) ("cpu", br.total_cpu_usage_us)("et", br.total_elapsed_time)("tt", now - br.start_time) @@ -3623,7 +3623,7 @@ struct controller_impl { fc::time_point now = fc::time_point::now(); if (now - bsp->timestamp() < fc::minutes(5) || (bsp->block_num() % 1000 == 0)) { ilog("Received block ${id}... #${n} @ ${t} signed by ${p} " // "Received" instead of "Applied" so it matches existing log output - "[trxs: ${count}, lib: ${lib}, net: ${net}, cpu: ${cpu}, elapsed: ${elapsed} us, time: ${time} us, latency: ${latency} ms]", + "[trxs: ${count}, lib: ${lib}, net: ${net}, cpu: ${cpu}, elapsed: ${elapsed} us, applying time: ${time} us, latency: ${latency} ms]", ("p", bsp->producer())("id", bsp->id().str().substr(8, 16))("n", bsp->block_num())("t", bsp->timestamp()) ("count", bsp->block->transactions.size())("lib", bsp->irreversible_blocknum()) ("net", br.total_net_usage)("cpu", br.total_cpu_usage_us) From eced7d9ca46b7322452ac2554e7ba4b2fd157371 Mon Sep 17 00:00:00 2001 From: Lin Huang Date: Tue, 1 Oct 2024 13:40:01 -0400 Subject: [PATCH 3/5] Add time unit us to the end of reported CPU time --- libraries/chain/controller.cpp | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/libraries/chain/controller.cpp b/libraries/chain/controller.cpp index 98b6855c15..3aabb50115 100644 --- a/libraries/chain/controller.cpp +++ b/libraries/chain/controller.cpp @@ -3459,7 +3459,7 @@ struct controller_impl { fc::time_point now = fc::time_point::now(); ilog("Produced block ${id}... #${n} @ ${t} signed by ${p} " - "[trxs: ${count}, lib: ${lib}${confs}, net: ${net}, cpu: ${cpu}, elapsed: ${et} us, producing time: ${tt} us]", + "[trxs: ${count}, lib: ${lib}${confs}, net: ${net}, cpu: ${cpu} us, elapsed: ${et} us, producing time: ${tt} us]", ("p", new_b->producer)("id", id.str().substr(8, 16))("n", new_b->block_num())("t", new_b->timestamp) ("count", new_b->transactions.size())("lib", chain_head.irreversible_blocknum())("net", br.total_net_usage) ("cpu", br.total_cpu_usage_us)("et", br.total_elapsed_time)("tt", now - br.start_time) @@ -3623,7 +3623,7 @@ struct controller_impl { fc::time_point now = fc::time_point::now(); if (now - bsp->timestamp() < fc::minutes(5) || (bsp->block_num() % 1000 == 0)) { ilog("Received block ${id}... #${n} @ ${t} signed by ${p} " // "Received" instead of "Applied" so it matches existing log output - "[trxs: ${count}, lib: ${lib}, net: ${net}, cpu: ${cpu}, elapsed: ${elapsed} us, applying time: ${time} us, latency: ${latency} ms]", + "[trxs: ${count}, lib: ${lib}, net: ${net}, cpu: ${cpu} us, elapsed: ${elapsed} us, applying time: ${time} us, latency: ${latency} ms]", ("p", bsp->producer())("id", bsp->id().str().substr(8, 16))("n", bsp->block_num())("t", bsp->timestamp()) ("count", bsp->block->transactions.size())("lib", bsp->irreversible_blocknum()) ("net", br.total_net_usage)("cpu", br.total_cpu_usage_us) From 116512c0b12c3eb1c3faf21b86e55bb2ae4d132e Mon Sep 17 00:00:00 2001 From: Lin Huang Date: Tue, 1 Oct 2024 14:01:43 -0400 Subject: [PATCH 4/5] Set start_time for producing a block in correct place --- libraries/chain/controller.cpp | 3 +++ 1 file changed, 3 insertions(+) diff --git a/libraries/chain/controller.cpp b/libraries/chain/controller.cpp index 3aabb50115..2d9be5aeb8 100644 --- a/libraries/chain/controller.cpp +++ b/libraries/chain/controller.cpp @@ -5244,6 +5244,8 @@ transaction_trace_ptr controller::start_block( block_timestamp_type when, } void controller::assemble_and_complete_block( block_report& br, const signer_callback_type& signer_callback ) { + fc::time_point start_time = fc::time_point::now(); // want to report total time of producing a block + validate_db_available_size(); my->assemble_block(false, {}, nullptr); @@ -5257,6 +5259,7 @@ void controller::assemble_and_complete_block( block_report& br, const signer_cal valid_block_signing_authority); br = my->pending->_block_report; + br.start_time = start_time; } void controller::commit_block(block_report& br) { From ebbf8d58a51d48f26f2911274d4b94162d89493b Mon Sep 17 00:00:00 2001 From: Lin Huang Date: Tue, 1 Oct 2024 15:06:20 -0400 Subject: [PATCH 5/5] Use pending block_report.start_time for producing time calculation --- libraries/chain/controller.cpp | 3 --- 1 file changed, 3 deletions(-) diff --git a/libraries/chain/controller.cpp b/libraries/chain/controller.cpp index 2d9be5aeb8..3aabb50115 100644 --- a/libraries/chain/controller.cpp +++ b/libraries/chain/controller.cpp @@ -5244,8 +5244,6 @@ transaction_trace_ptr controller::start_block( block_timestamp_type when, } void controller::assemble_and_complete_block( block_report& br, const signer_callback_type& signer_callback ) { - fc::time_point start_time = fc::time_point::now(); // want to report total time of producing a block - validate_db_available_size(); my->assemble_block(false, {}, nullptr); @@ -5259,7 +5257,6 @@ void controller::assemble_and_complete_block( block_report& br, const signer_cal valid_block_signing_authority); br = my->pending->_block_report; - br.start_time = start_time; } void controller::commit_block(block_report& br) {