reduce debug logs amount (#19399)

as a preparation for 3.4 release

Author: AskAlexSharov

cl/rpc/peer_selection.go

@@ -135,11 +135,12 @@ func (c *columnDataPeers) refreshPeers(ctx context.Context) {
 		c.peersQueue = newPeers
 		c.peersIndex = 0
 		c.peersMutex.Unlock()
-		custodies := []uint64{}
-		for _, peer := range newPeers {
-			custodies = append(custodies, uint64(len(peer.mask)))
-		}
-		log.Debug("[peerSelector] updated peers", "totalPeers", len(peers.Peers), "peerCount", len(newPeers), "custodies", custodies, "elapsedTime", time.Since(begin))
+		//custodies := []uint64{}
+		//for _, peer := range newPeers {
+		//	custodies = append(custodies, uint64(len(peer.mask)))
+		//}
+		//log.Debug("[peerSelector] updated peers", "totalPeers", len(peers.Peers), "peerCount", len(newPeers), "custodies", custodies, "elapsedTime", time.Since(begin))
+		log.Debug("[peerSelector] updated peers", "totalPeers", len(peers.Peers), "peerCount", len(newPeers), "elapsedTime", time.Since(begin))
 	}
 
 	// begin

db/kv/prune/prune.go

@@ -235,13 +235,13 @@ func TableScanningPrune(
 
 	var pairs, valLen uint64
 
-	defer func() {
-		logger.Debug("scan pruning res", "name", name, "txFrom", txFrom, "txTo", txTo, "limit", limit, "keys",
-			stat.PruneCountTx, "vals", stat.PruneCountValues, "all vals", valLen, "dups", stat.DupsDeleted,
-			"spent ms", time.Since(start).Milliseconds(),
-			"key prune status", stat.KeyProgress.String(),
-			"val prune status", stat.ValueProgress.String())
-	}()
+	//defer func() {
+	//	logger.Debug("scan pruning res", "name", name, "txFrom", txFrom, "txTo", txTo, "limit", limit, "keys",
+	//		stat.PruneCountTx, "vals", stat.PruneCountValues, "all vals", valLen, "dups", stat.DupsDeleted,
+	//		"spent ms", time.Since(start).Milliseconds(),
+	//		"key prune status", stat.KeyProgress.String(),
+	//		"val prune status", stat.ValueProgress.String())
+	//}()
 	if prevStat.KeyProgress != Done {
 		txnb := common.Copy(keyCursorPosition.StartKey)
 		// This deletion iterator goes last to preserve invariant: if some `txNum=N` pruned - it's pruned Fully

db/state/domain.go

@@ -1904,8 +1904,7 @@ func (dt *DomainRoTx) prune(ctx context.Context, rwTx kv.RwTx, step kv.Step, txF
 	if limit == 0 {
 		limit = math.MaxUint64
 	}
-	st := time.Now()
-	defer mxPruneTookDomain.ObserveDuration(st)
+	defer mxPruneTookDomain.ObserveDuration(time.Now())
 	stat = &DomainPruneStat{MinStep: math.MaxUint64}
 	if stat.History, err = dt.ht.Prune(ctx, rwTx, txFrom, txTo, limit, false, logEvery); err != nil {
 		return nil, fmt.Errorf("prune history at step %d [%d, %d): %w", step, txFrom, txTo, err)
@@ -1919,13 +1918,9 @@ func (dt *DomainRoTx) prune(ctx context.Context, rwTx kv.RwTx, step kv.Step, txF
 		return stat, nil
 	}
 
-	defer func() {
-		dt.d.logger.Debug("scan domain pruning res", "name", dt.name, "txFrom", txFrom, "txTo", txTo, "limit", limit, "vals", stat.Values, "spent ms", time.Since(st).Milliseconds())
-	}()
-
 	mxPruneInProgress.Inc()
 	defer mxPruneInProgress.Dec()
-	defer func(t time.Time) { mxPruneTookDomain.ObserveDuration(t) }(time.Now())
+	defer mxPruneTookDomain.ObserveDuration(time.Now())
 	var valsCursor kv.PseudoDupSortRwCursor
 	var mode prune.StorageMode
 	if dt.d.LargeValues {

execution/commitment/commitment.go

@@ -28,7 +28,6 @@ import (
 	"strings"
 	"sync"
 	"sync/atomic"
-	"time"
 	"unsafe"
 
 	"github.com/google/btree"
@@ -441,10 +440,6 @@ func ApplyDeferredBranchUpdates(
 	numWorkers int,
 	putBranch func(prefix []byte, data []byte, prevData []byte, prevStep kv.Step) error,
 ) (int, error) {
-	start := time.Now()
-	defer func() {
-		log.Debug("ApplyDeferredBranchUpdates completed", "updates", len(deferred), "took", time.Since(start))
-	}()
 	if len(deferred) == 0 {
 		return 0, nil
 	}

execution/commitment/warmuper.go

@@ -164,7 +164,6 @@ func (w *Warmuper) Start() {
 		return
 	}
 
-	w.startTime = time.Now()
 	w.work = make(chan warmupWorkItem, w.numWorkers*64)
 	w.g, w.ctx = errgroup.WithContext(w.ctx)
 
@@ -289,13 +288,6 @@ func (w *Warmuper) Wait() error {
 	close(w.work)
 	w.g.Wait()
 
-	log.Debug(fmt.Sprintf("[%s][warmup] completed", w.logPrefix),
-		"keys", common.PrettyCounter(int(w.keysProcessed.Load())),
-		"maxDepth", w.maxDepth,
-		"workers", w.numWorkers,
-		"spent", time.Since(w.startTime),
-	)
-
 	return nil
 }
 

execution/stagedsync/exec3.go

@@ -207,7 +207,7 @@ func ExecV3(ctx context.Context,
 	isChainTip := maxBlockNum == startBlockNum
 	// Do it only for chain-tip blocks!
 	doms.EnableWarmupCache(isChainTip)
-	log.Debug("Warmup Cache", "enabled", isChainTip)
+	//log.Debug("Warmup Cache", "enabled", isChainTip)
 	postValidator := newBlockPostExecutionValidator()
 	doms.SetDeferCommitmentUpdates(false)
 	if isChainTip {

execution/stagedsync/sync.go

@@ -491,7 +491,7 @@ func (s *Sync) PrintTimings() []any {
 
 func (s *Sync) runStage(stage *Stage, doms *execctx.SharedDomains, rwTx kv.TemporalRwTx, initialCycle, firstCycle bool, badBlockUnwind bool) (bool, error) {
 	start := time.Now()
-	s.logger.Debug(fmt.Sprintf("[%s] Starting Stage run", s.LogPrefix()))
+	//s.logger.Debug(fmt.Sprintf("[%s] Starting Stage run", s.LogPrefix()))
 	stageState, err := s.StageState(stage.ID, rwTx, initialCycle, firstCycle)
 	if err != nil {
 		return false, err

p2p/discover/table_reval.go

@@ -168,7 +168,7 @@ func (tr *tableRevalidation) handleResponse(tab *Table, resp revalidationRespons
 		if n.livenessChecks <= 0 {
 			tab.deleteInBucket(b, n.ID())
 		} else {
-			tab.log.Debug("Node revalidation failed", "b", b.index, "id", n.ID(), "checks", n.livenessChecks, "q", n.revalList.name)
+			tab.log.Debug("[p2p] Node revalidation failed", "b", b.index, "id", n.ID(), "checks", n.livenessChecks, "q", n.revalList.name)
 			tr.moveToList(&tr.fast, n, now, &tab.rand)
 		}
 		return
@@ -177,7 +177,7 @@ func (tr *tableRevalidation) handleResponse(tab *Table, resp revalidationRespons
 	// The node responded.
 	n.livenessChecks++
 	n.isValidatedLive = true
-	tab.log.Debug("Node revalidated", "b", b.index, "id", n.ID(), "checks", n.livenessChecks, "q", n.revalList.name)
+	tab.log.Debug("[p2p] Node revalidated", "b", b.index, "id", n.ID(), "checks", n.livenessChecks, "q", n.revalList.name)
 	var endpointChanged bool
 	if resp.newRecord != nil {
 		_, endpointChanged = tab.bumpInBucket(b, resp.newRecord, false)

p2p/discover/v5_udp.go

@@ -753,7 +753,7 @@ func (t *UDPv5) handlePacket(rawpacket []byte, fromAddr netip.AddrPort) error {
 			t.unhandled <- up
 			return nil
 		}
-		t.log.Debug("Bad discv5 packet", "id", fromID, "addr", addr, "err", err)
+		t.log.Trace("Bad discv5 packet", "id", fromID, "addr", addr, "err", err)
 		return err
 	}
 	if fromNode != nil {
@@ -774,15 +774,15 @@ func (t *UDPv5) handlePacket(rawpacket []byte, fromAddr netip.AddrPort) error {
 func (t *UDPv5) handleCallResponse(fromID enode.ID, fromAddr netip.AddrPort, p v5wire.Packet) bool {
 	ac := t.activeCallByNode[fromID]
 	if ac == nil || !bytes.Equal(p.RequestID(), ac.reqid) {
-		t.log.Debug(fmt.Sprintf("Unsolicited/late %s response", p.Name()), "id", fromID, "addr", fromAddr)
+		t.log.Debug(fmt.Sprintf("[p2p] Unsolicited/late %s response", p.Name()), "id", fromID, "addr", fromAddr)
 		return false
 	}
 	if fromAddr != ac.addr {
-		t.log.Debug(fmt.Sprintf("%s from wrong endpoint", p.Name()), "id", fromID, "addr", fromAddr)
+		t.log.Debug(fmt.Sprintf("[p2p] %s from wrong endpoint", p.Name()), "id", fromID, "addr", fromAddr)
 		return false
 	}
 	if p.Kind() != ac.responseType {
-		t.log.Debug(fmt.Sprintf("Wrong discv5 response type %s", p.Name()), "id", fromID, "addr", fromAddr)
+		t.log.Debug(fmt.Sprintf("[p2p] Wrong discv5 response type %s", p.Name()), "id", fromID, "addr", fromAddr)
 		return false
 	}
 	t.startResponseTimeout(ac)
@@ -840,7 +840,7 @@ func (t *UDPv5) handleUnknown(p *v5wire.Unknown, fromID enode.ID, fromAddr netip
 		// them which handshake attempt they need to complete. We tell them to use the
 		// existing handshake attempt since the response to that one might still be in
 		// transit.
-		t.log.Debug("Repeating discv5 handshake challenge", "id", fromID, "addr", fromAddr)
+		t.log.Debug("[p2p] Repeating discv5 handshake challenge", "id", fromID, "addr", fromAddr)
 		t.sendResponse(fromID, fromAddr, currentChallenge)
 		return
 	}
@@ -864,13 +864,13 @@ var (
 func (t *UDPv5) handleWhoareyou(p *v5wire.Whoareyou, fromID enode.ID, fromAddr netip.AddrPort) {
 	c, err := t.matchWithCall(fromID, p.Nonce)
 	if err != nil {
-		t.log.Debug("Invalid "+p.Name(), "addr", fromAddr, "err", err)
+		t.log.Trace("[p2p] Invalid "+p.Name(), "addr", fromAddr, "err", err)
 		return
 	}
 
 	if c.node == nil {
 		// Can't perform handshake because we don't have the ENR.
-		t.log.Debug("Can't handle "+p.Name(), "addr", fromAddr, "err", "call has no ENR")
+		t.log.Debug("[p2p] Can't handle "+p.Name(), "addr", fromAddr, "err", "call has no ENR")
 		c.err <- errors.New("remote wants handshake, but call has no ENR")
 		return
 	}