P2PServer: log time it took to relay a block

src/p2p_server.cpp

@@ -741,7 +741,10 @@ void P2PServer::broadcast(const PoolBlock& block, const PoolBlock* parent)
 		return;
 	}
 
-	Broadcast* data = new Broadcast();
+	Broadcast* data = new Broadcast{};
+
+	data->id = block.m_sidechainId;
+	data->received_timestamp = block.m_receivedTimestamp;
 
 	int outputs_offset, outputs_blob_size;
 	const std::vector<uint8_t> mainchain_data = block.serialize_mainchain_data(nullptr, nullptr, &outputs_offset, &outputs_blob_size);
@@ -857,13 +860,6 @@ void P2PServer::on_broadcast()
 		return;
 	}
 
-	ON_SCOPE_LEAVE([&broadcast_queue]()
-		{
-			for (const Broadcast* data : broadcast_queue) {
-				delete data;
-			}
-		});
-
 	for (P2PClient* client = static_cast<P2PClient*>(m_connectedClientsList->m_next); client != m_connectedClientsList; client = static_cast<P2PClient*>(client->m_next)) {
 		if (!client->is_good()) {
 			continue;
@@ -936,6 +932,12 @@ void P2PServer::on_broadcast()
 			}
 		}
 	}
+
+	for (const Broadcast* data : broadcast_queue) {
+		const double t = static_cast<double>(microseconds_since_epoch() - data->received_timestamp) * 1e-3;
+		LOGINFO(5, "Block " << data->id << " took " << t << " ms to process and relay to other peers");
+		delete data;
+	}
 }
 
 uint64_t P2PServer::get_random64()
@@ -995,7 +997,7 @@ int P2PServer::external_listen_port() const
 	return params.m_p2pExternalPort ? params.m_p2pExternalPort : m_listenPort;
 }
 
-int P2PServer::deserialize_block(const uint8_t* buf, uint32_t size, bool compact)
+int P2PServer::deserialize_block(const uint8_t* buf, uint32_t size, bool compact, uint64_t received_timestamp)
 {
 	int result;
 
@@ -1010,6 +1012,7 @@ int P2PServer::deserialize_block(const uint8_t* buf, uint32_t size, bool compact
 		m_lookForMissingBlocks = true;
 	}
 
+	m_block->m_receivedTimestamp = received_timestamp;
 	return result;
 }
 
@@ -1928,11 +1931,13 @@ bool P2PServer::P2PClient::on_block_response(const uint8_t* buf, uint32_t size,
 		return true;
 	}
 
+	const uint64_t received_timestamp = microseconds_since_epoch();
+
 	P2PServer* server = static_cast<P2PServer*>(m_owner);
 
 	MutexLock lock(server->m_blockLock);
 
-	const int result = server->deserialize_block(buf, size, false);
+	const int result = server->deserialize_block(buf, size, false, received_timestamp);
 	if (result != 0) {
 		LOGWARN(3, "peer " << static_cast<char*>(m_addrString) << " sent an invalid block, error " << result);
 		return false;
@@ -1973,11 +1978,13 @@ bool P2PServer::P2PClient::on_block_broadcast(const uint8_t* buf, uint32_t size,
 		return false;
 	}
 
+	const uint64_t received_timestamp = microseconds_since_epoch();
+
 	P2PServer* server = static_cast<P2PServer*>(m_owner);
 
 	MutexLock lock(server->m_blockLock);
 
-	const int result = server->deserialize_block(buf, size, compact);
+	const int result = server->deserialize_block(buf, size, compact, received_timestamp);
 	if (result != 0) {
 		LOGWARN(3, "peer " << static_cast<char*>(m_addrString) << " sent an invalid block, error " << result);
 		return false;

src/p2p_server.h

@@ -163,7 +163,7 @@ public:
 	void set_max_outgoing_peers(uint32_t n) { m_maxOutgoingPeers = std::min(std::max(n, 10U), 450U); }
 	void set_max_incoming_peers(uint32_t n) { m_maxIncomingPeers = std::min(std::max(n, 10U), 450U); }
 
-	int deserialize_block(const uint8_t* buf, uint32_t size, bool compact);
+	int deserialize_block(const uint8_t* buf, uint32_t size, bool compact, uint64_t received_timestamp);
 	const PoolBlock* get_block() const { return m_block; }
 
 private:
@@ -226,6 +226,9 @@ private:
 
 	struct Broadcast
 	{
+		hash id;
+		uint64_t received_timestamp;
+
 		std::vector<uint8_t> blob;
 		std::vector<uint8_t> pruned_blob;
 		std::vector<uint8_t> compact_blob;

src/pool_block.cpp

@@ -53,6 +53,7 @@ PoolBlock::PoolBlock()
 	, m_wantBroadcast(false)
 	, m_precalculated(false)
 	, m_localTimestamp(seconds_since_epoch())
+	, m_receivedTimestamp(0)
 {
 }
 
@@ -102,6 +103,7 @@ PoolBlock& PoolBlock::operator=(const PoolBlock& b)
 	m_precalculated = b.m_precalculated;
 
 	m_localTimestamp = seconds_since_epoch();
+	m_receivedTimestamp = b.m_receivedTimestamp;
 
 	return *this;
 }
@@ -266,6 +268,7 @@ void PoolBlock::reset_offchain_data()
 	m_precalculated = false;
 
 	m_localTimestamp = seconds_since_epoch();
+	m_receivedTimestamp = 0;
 }
 
 bool PoolBlock::get_pow_hash(RandomX_Hasher_Base* hasher, uint64_t height, const hash& seed_hash, hash& pow_hash)

src/pool_block.h

@@ -133,6 +133,7 @@ struct PoolBlock
 	bool m_precalculated;
 
 	uint64_t m_localTimestamp;
+	uint64_t m_receivedTimestamp;
 
 	std::vector<uint8_t> serialize_mainchain_data(size_t* header_size = nullptr, size_t* miner_tx_size = nullptr, int* outputs_offset = nullptr, int* outputs_blob_size = nullptr, const uint32_t* nonce = nullptr, const uint32_t* extra_nonce = nullptr) const;
 	std::vector<uint8_t> serialize_sidechain_data() const;

src/util.h

@@ -227,6 +227,12 @@ FORCEINLINE uint64_t seconds_since_epoch()
 	return duration_cast<seconds>(steady_clock::now().time_since_epoch()).count();
 }
 
+FORCEINLINE uint64_t microseconds_since_epoch()
+{
+	using namespace std::chrono;
+	return duration_cast<microseconds>(steady_clock::now().time_since_epoch()).count();
+}
+
 uint64_t bsr_reference(uint64_t x);
 
 #ifdef HAVE_BUILTIN_CLZLL