Skip to content

Commit c66a003

Browse files
colinlyguocolinlyguo
authored
feat: add logs to track tx and block propagation delay (#1184)
1 parent ad6cced commit c66a003

File tree

5 files changed

+24
-17
lines changed

5 files changed

+24
-17
lines changed

‎eth/fetcher/tx_fetcher.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -794,7 +794,7 @@ func (f *TxFetcher) scheduleFetches(timer *mclock.Timer, timeout chan struct{},
794794
return true // continue in the for-each
795795
})
796796

797-
log.Debug("Scheduling transaction retrieval", "peer", peer, "len(f.announces[peer])", len(f.announces[peer]), "len(hashes)", len(hashes))
797+
log.Trace("Scheduling transaction retrieval", "peer", peer, "len(f.announces[peer])", len(f.announces[peer]), "len(hashes)", len(hashes))
798798
peerAnnounceTxsLenGauge.Update(int64(len(f.announces[peer])))
799799
peerRetrievalTxsLenGauge.Update(int64(len(hashes)))
800800

‎eth/handler.go

Lines changed: 7 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -455,6 +455,8 @@ func (h *handler) BroadcastBlock(block *types.Block, propagate bool) {
455455
hash := block.Hash()
456456
peers := onlyShadowForkPeers(h.shadowForkPeerIDs, h.peers.peersWithoutBlock(hash))
457457

458+
log.Debug("Broadcasting block", "hash", hash.Hex(), "number", block.NumberU64(), "size", block.Size())
459+
458460
// If propagation is requested, send to a subset of the peer
459461
if propagate {
460462
// Calculate the TD of the block (it's not imported yet, so block.Td is not valid)
@@ -470,15 +472,15 @@ func (h *handler) BroadcastBlock(block *types.Block, propagate bool) {
470472
for _, peer := range transfer {
471473
peer.AsyncSendNewBlock(block, td)
472474
}
473-
log.Trace("Propagated block", "hash", hash, "recipients", len(transfer), "duration", common.PrettyDuration(time.Since(block.ReceivedAt)))
475+
log.Trace("Propagated block", "hash", hash.Hex(), "recipients", len(transfer), "duration", common.PrettyDuration(time.Since(block.ReceivedAt)))
474476
return
475477
}
476478
// Otherwise if the block is indeed in out own chain, announce it
477479
if h.chain.HasBlock(hash, block.NumberU64()) {
478480
for _, peer := range peers {
479481
peer.AsyncSendNewBlockHash(block)
480482
}
481-
log.Trace("Announced block", "hash", hash, "recipients", len(peers), "duration", common.PrettyDuration(time.Since(block.ReceivedAt)))
483+
log.Trace("Announced block", "hash", hash.Hex(), "recipients", len(peers), "duration", common.PrettyDuration(time.Since(block.ReceivedAt)))
482484
}
483485
}
484486

@@ -503,6 +505,7 @@ func (h *handler) BroadcastTransactions(txs types.Transactions) {
503505
if tx.IsL1MessageTx() {
504506
continue
505507
}
508+
log.Debug("Broadcasting transaction", "hash", tx.Hash().Hex(), "size", tx.Size())
506509
peers := onlyShadowForkPeers(h.shadowForkPeerIDs, h.peers.peersWithoutTransaction(tx.Hash()))
507510
// Send the tx unconditionally to a subset of our peers
508511
numDirect := int(math.Sqrt(float64(len(peers))))
@@ -518,13 +521,13 @@ func (h *handler) BroadcastTransactions(txs types.Transactions) {
518521
directPeers++
519522
directCount += len(hashes)
520523
peer.AsyncSendTransactions(hashes)
521-
log.Debug("Transactions being broadcasted to", "peer", peer.String(), "len", len(hashes))
524+
log.Trace("Transactions being broadcasted to", "peer", peer.String(), "len", len(hashes))
522525
}
523526
for peer, hashes := range annos {
524527
annoPeers++
525528
annoCount += len(hashes)
526529
peer.AsyncSendPooledTransactionHashes(hashes)
527-
log.Debug("Transactions being announced to", "peer", peer.String(), "len", len(hashes))
530+
log.Trace("Transactions being announced to", "peer", peer.String(), "len", len(hashes))
528531
}
529532
log.Debug("Transaction broadcast", "txs", len(txs),
530533
"announce packs", annoPeers, "announced hashes", annoCount,

‎eth/protocols/eth/handlers.go

Lines changed: 14 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -294,6 +294,7 @@ func handleNewBlock(backend Backend, msg Decoder, peer *Peer) error {
294294

295295
// Mark the peer as owning the block
296296
peer.markBlock(ann.Block.Hash())
297+
log.Debug("Received new block via gossip", "blockHash", ann.Block.Hash().Hex(), "blockNumber", ann.Block.NumberU64(), "peer", peer.String())
297298

298299
return backend.Handle(peer, ann)
299300
}
@@ -362,12 +363,12 @@ func handleNewPooledTransactionHashes(backend Backend, msg Decoder, peer *Peer)
362363
}
363364
ann := new(NewPooledTransactionHashesPacket)
364365
if err := msg.Decode(ann); err != nil {
365-
log.Debug("Failed to decode `NewPooledTransactionHashesPacket`", "peer", peer.String(), "err", err)
366+
log.Trace("Failed to decode `NewPooledTransactionHashesPacket`", "peer", peer.String(), "err", err)
366367
newPooledTxHashesFailMeter.Mark(1)
367368
return fmt.Errorf("%w: message %v: %v", errDecode, msg, err)
368369
}
369370
// Schedule all the unknown hashes for retrieval
370-
log.Debug("handleNewPooledTransactionHashes", "peer", peer.String(), "len(ann)", len(*ann))
371+
log.Trace("handleNewPooledTransactionHashes", "peer", peer.String(), "len(ann)", len(*ann))
371372
newPooledTxHashesLenGauge.Update(int64(len(*ann)))
372373
for _, hash := range *ann {
373374
peer.markTransaction(hash)
@@ -379,12 +380,15 @@ func handleGetPooledTransactions66(backend Backend, msg Decoder, peer *Peer) err
379380
// Decode the pooled transactions retrieval message
380381
var query GetPooledTransactionsPacket66
381382
if err := msg.Decode(&query); err != nil {
382-
log.Debug("Failed to decode `GetPooledTransactionsPacket66`", "peer", peer.String(), "err", err)
383+
log.Trace("Failed to decode `GetPooledTransactionsPacket66`", "peer", peer.String(), "err", err)
383384
getPooledTxsFailMeter.Mark(1)
384385
return fmt.Errorf("%w: message %v: %v", errDecode, msg, err)
385386
}
386387
hashes, txs := answerGetPooledTransactions(backend, query.GetPooledTransactionsPacket, peer)
387-
log.Debug("handleGetPooledTransactions", "peer", peer.String(), "RequestId", query.RequestId, "len(query)", len(query.GetPooledTransactionsPacket), "retrieved", len(hashes))
388+
log.Trace("handleGetPooledTransactions", "peer", peer.String(), "RequestId", query.RequestId, "len(query)", len(query.GetPooledTransactionsPacket), "retrieved", len(hashes))
389+
for _, hash := range hashes {
390+
log.Debug("Received new pooled transaction", "hash", hash.Hex(), "peer", peer.String())
391+
}
388392
getPooledTxsQueryLenGauge.Update(int64(len(query.GetPooledTransactionsPacket)))
389393
getPooledTxsRetrievedLenGauge.Update(int64(len(hashes)))
390394
return peer.ReplyPooledTransactionsRLP(query.RequestId, hashes, txs)
@@ -427,16 +431,16 @@ func handleTransactions(backend Backend, msg Decoder, peer *Peer) error {
427431
var txs TransactionsPacket
428432
if err := msg.Decode(&txs); err != nil {
429433
handleTxsFailMeter.Mark(1)
430-
log.Debug("Failed to decode `TransactionsPacket`", "peer", peer.String(), "err", err)
434+
log.Trace("Failed to decode `TransactionsPacket`", "peer", peer.String(), "err", err)
431435
return fmt.Errorf("%w: message %v: %v", errDecode, msg, err)
432436
}
433-
log.Debug("handleTransactions", "peer", peer.String(), "len(txs)", len(txs))
437+
log.Trace("handleTransactions", "peer", peer.String(), "len(txs)", len(txs))
434438
handleTxsLenGauge.Update(int64(len(txs)))
435439
for i, tx := range txs {
436440
// Validate and mark the remote transaction
437441
if tx == nil {
438442
handleTxsNilMeter.Mark(1)
439-
log.Debug("handleTransactions: transaction is nil", "peer", peer.String(), "i", i)
443+
log.Trace("handleTransactions: transaction is nil", "peer", peer.String(), "i", i)
440444
return fmt.Errorf("%w: transaction %d is nil", errDecode, i)
441445
}
442446
peer.markTransaction(tx.Hash())
@@ -453,16 +457,16 @@ func handlePooledTransactions66(backend Backend, msg Decoder, peer *Peer) error
453457
var txs PooledTransactionsPacket66
454458
if err := msg.Decode(&txs); err != nil {
455459
pooledTxs66FailMeter.Mark(1)
456-
log.Debug("Failed to decode `PooledTransactionsPacket66`", "peer", peer.String(), "err", err)
460+
log.Trace("Failed to decode `PooledTransactionsPacket66`", "peer", peer.String(), "err", err)
457461
return fmt.Errorf("%w: message %v: %v", errDecode, msg, err)
458462
}
459-
log.Debug("handlePooledTransactions66", "peer", peer.String(), "len(txs)", len(txs.PooledTransactionsPacket))
463+
log.Trace("handlePooledTransactions66", "peer", peer.String(), "len(txs)", len(txs.PooledTransactionsPacket))
460464
pooledTxs66LenGauge.Update(int64(len(txs.PooledTransactionsPacket)))
461465
for i, tx := range txs.PooledTransactionsPacket {
462466
// Validate and mark the remote transaction
463467
if tx == nil {
464468
pooledTxs66NilMeter.Mark(1)
465-
log.Debug("handlePooledTransactions: transaction is nil", "peer", peer.String(), "i", i)
469+
log.Trace("handlePooledTransactions: transaction is nil", "peer", peer.String(), "i", i)
466470
return fmt.Errorf("%w: transaction %d is nil", errDecode, i)
467471
}
468472
peer.markTransaction(tx.Hash())

‎eth/protocols/eth/peer.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -436,7 +436,7 @@ func (p *Peer) RequestTxs(hashes []common.Hash) error {
436436
p.Log().Debug("Fetching batch of transactions", "count", len(hashes))
437437
id := rand.Uint64()
438438

439-
log.Debug("Requesting transactions", "RequestId", id, "Peer.id", p.id, "count", len(hashes))
439+
log.Trace("Requesting transactions", "RequestId", id, "Peer.id", p.id, "count", len(hashes))
440440
peerRequestTxsCntGauge.Update(int64(len(hashes)))
441441

442442
requestTracker.Track(p.id, p.version, GetPooledTransactionsMsg, PooledTransactionsMsg, id)

‎params/version.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -24,7 +24,7 @@ import (
2424
const (
2525
VersionMajor = 5 // Major version component of the current release
2626
VersionMinor = 8 // Minor version component of the current release
27-
VersionPatch = 47 // Patch version component of the current release
27+
VersionPatch = 48 // Patch version component of the current release
2828
VersionMeta = "mainnet" // Version metadata to append to the version string
2929
)
3030

0 commit comments

Comments
 (0)