From 3db765e0f108ad301b9c8063a20a124a4ece71a4 Mon Sep 17 00:00:00 2001 From: Kevin Heifner Date: Tue, 31 Jan 2023 07:39:26 -0600 Subject: [PATCH 1/3] GH-588 Remove +1 to number of blocks latency calculation. With it 0 latency indicates 1 block latency. --- plugins/net_plugin/net_plugin.cpp | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/plugins/net_plugin/net_plugin.cpp b/plugins/net_plugin/net_plugin.cpp index 5e8909cb91..68a968a4c1 100644 --- a/plugins/net_plugin/net_plugin.cpp +++ b/plugins/net_plugin/net_plugin.cpp @@ -1792,8 +1792,8 @@ namespace eosio { } // number of blocks syncing node is behind from a peer node uint32_t nblk_behind_by_net_latency = static_cast(network_latency_ns / block_interval_ns); - // 2x for time it takes for message to reach back to peer node, +1 to compensate for integer division truncation - uint32_t nblk_combined_latency = 2 * nblk_behind_by_net_latency + 1; + // 2x for time it takes for message to reach back to peer node + uint32_t nblk_combined_latency = 2 * nblk_behind_by_net_latency; // message in the log below is used in p2p_high_latency_test.py test peer_dlog(c, "Network latency is ${lat}ms, ${num} blocks discrepancy by network latency, ${tot_num} blocks discrepancy expected once message received", ("lat", network_latency_ns/1000000)("num", nblk_behind_by_net_latency)("tot_num", nblk_combined_latency)); From f347ab534ebe3e881df5cdd183845404e38990bb Mon Sep 17 00:00:00 2001 From: Kevin Heifner Date: Wed, 1 Feb 2023 13:42:13 -0600 Subject: [PATCH 2/3] GH-588 Add additional logging that would be helpful for debugging --- plugins/net_plugin/net_plugin.cpp | 27 +++++++++++++++------------ 1 file changed, 15 insertions(+), 12 deletions(-) diff --git a/plugins/net_plugin/net_plugin.cpp b/plugins/net_plugin/net_plugin.cpp index 68a968a4c1..9bbad79e4f 100644 --- a/plugins/net_plugin/net_plugin.cpp +++ b/plugins/net_plugin/net_plugin.cpp @@ -1776,7 +1776,6 @@ namespace eosio { if( c->is_transactions_only_connection() ) return; uint32_t lib_num = 0; - uint32_t peer_lib = msg.last_irreversible_block_num; uint32_t head = 0; block_id_type head_id; std::tie( lib_num, std::ignore, head, @@ -1813,8 +1812,8 @@ namespace eosio { //----------------------------- if (head_id == msg.head_id) { - peer_ilog( c, "handshake lib ${lib}, head ${head}, head id ${id}.. sync 0", - ("lib", msg.last_irreversible_block_num)("head", msg.head_num)("id", msg.head_id.str().substr(8,16)) ); + peer_ilog( c, "handshake lib ${lib}, head ${head}, head id ${id}.. sync 0, lib ${l}", + ("lib", msg.last_irreversible_block_num)("head", msg.head_num)("id", msg.head_id.str().substr(8,16))("l", lib_num) ); c->syncing = false; notice_message note; note.known_blocks.mode = none; @@ -1823,9 +1822,10 @@ namespace eosio { c->enqueue( note ); return; } - if (head < peer_lib) { - peer_ilog( c, "handshake lib ${lib}, head ${head}, head id ${id}.. sync 1", - ("lib", msg.last_irreversible_block_num)("head", msg.head_num)("id", msg.head_id.str().substr(8,16)) ); + if (head < msg.last_irreversible_block_num) { + peer_ilog( c, "handshake lib ${lib}, head ${head}, head id ${id}.. sync 1, head ${h}, lib ${l}", + ("lib", msg.last_irreversible_block_num)("head", msg.head_num)("id", msg.head_id.str().substr(8,16)) + ("h", head)("l", lib_num) ); c->syncing = false; if (c->sent_handshake_count > 0) { c->send_handshake(); @@ -1833,8 +1833,9 @@ namespace eosio { return; } if (lib_num > msg.head_num + nblk_combined_latency) { - peer_ilog( c, "handshake lib ${lib}, head ${head}, head id ${id}.. sync 2", - ("lib", msg.last_irreversible_block_num)("head", msg.head_num)("id", msg.head_id.str().substr(8,16)) ); + peer_ilog( c, "handshake lib ${lib}, head ${head}, head id ${id}.. sync 2, head ${h}, lib ${l}", + ("lib", msg.last_irreversible_block_num)("head", msg.head_num)("id", msg.head_id.str().substr(8,16)) + ("h", head)("l", lib_num) ); if (msg.generation > 1 || c->protocol_version > proto_base) { notice_message note; note.known_trx.pending = lib_num; @@ -1848,14 +1849,16 @@ namespace eosio { } if (head + nblk_combined_latency < msg.head_num ) { - peer_ilog( c, "handshake lib ${lib}, head ${head}, head id ${id}.. sync 3", - ("lib", msg.last_irreversible_block_num)("head", msg.head_num)("id", msg.head_id.str().substr(8,16)) ); + peer_ilog( c, "handshake lib ${lib}, head ${head}, head id ${id}.. sync 3, head ${h}, lib ${l}", + ("lib", msg.last_irreversible_block_num)("head", msg.head_num)("id", msg.head_id.str().substr(8,16)) + ("h", head)("l", lib_num) ); c->syncing = false; verify_catchup(c, msg.head_num, msg.head_id); return; } else if(head >= msg.head_num + nblk_combined_latency) { - peer_ilog( c, "handshake lib ${lib}, head ${head}, head id ${id}.. sync 4", - ("lib", msg.last_irreversible_block_num)("head", msg.head_num)("id", msg.head_id.str().substr(8,16)) ); + peer_ilog( c, "handshake lib ${lib}, head ${head}, head id ${id}.. sync 4, head ${h}, lib ${l}", + ("lib", msg.last_irreversible_block_num)("head", msg.head_num)("id", msg.head_id.str().substr(8,16)) + ("h", head)("l", lib_num) ); if (msg.generation > 1 || c->protocol_version > proto_base) { notice_message note; note.known_trx.mode = none; From ec27d3d1f3eb29a5cab6518e24eee1c62adaa0bc Mon Sep 17 00:00:00 2001 From: Kevin Heifner Date: Wed, 1 Feb 2023 15:10:23 -0600 Subject: [PATCH 3/3] GH-588 Round using lround instead of the original hardcoded +1 --- plugins/net_plugin/net_plugin.cpp | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/plugins/net_plugin/net_plugin.cpp b/plugins/net_plugin/net_plugin.cpp index 9bbad79e4f..61b61fdd35 100644 --- a/plugins/net_plugin/net_plugin.cpp +++ b/plugins/net_plugin/net_plugin.cpp @@ -26,6 +26,7 @@ #include #include +#include #include using namespace eosio::chain::plugin_interface; @@ -1789,8 +1790,8 @@ namespace eosio { peer_wlog(c, "Peer sent a handshake with a timestamp skewed by at least ${t}ms", ("t", network_latency_ns/1000000)); network_latency_ns = 0; } - // number of blocks syncing node is behind from a peer node - uint32_t nblk_behind_by_net_latency = static_cast(network_latency_ns / block_interval_ns); + // number of blocks syncing node is behind from a peer node, round up + uint32_t nblk_behind_by_net_latency = std::lround( static_cast(network_latency_ns) / static_cast(block_interval_ns) ); // 2x for time it takes for message to reach back to peer node uint32_t nblk_combined_latency = 2 * nblk_behind_by_net_latency; // message in the log below is used in p2p_high_latency_test.py test