tortoise: use zap directly and make logging cheaper (spacemeshos#4524)

noticed that our wrapper, string formatting for fixed float, and logger initialization make tortoise unnecessarily slow during restarts. flamegraph below explains the problem

log/logtest/log.go

@@ -4,6 +4,7 @@ import (
 	"os"
 	"testing"
 
+	"go.uber.org/zap"
 	"go.uber.org/zap/zapcore"
 	"go.uber.org/zap/zaptest"
 
@@ -12,6 +13,10 @@ import (
 
 const testLogLevel = "TEST_LOG_LEVEL"
 
+func Zap(tb testing.TB, override ...zapcore.Level) *zap.Logger {
+	return New(tb, override...).Zap()
+}
+
 // New creates log.Log instance that will use testing.TB.Log internally.
 func New(tb testing.TB, override ...zapcore.Level) log.Log {
 	var level zapcore.Level

log/zap.go

@@ -104,6 +104,10 @@ func ShortStringer(name string, val ShortString) Field {
 	return Field(zap.Stringer(name, shortStringAdapter{val: val}))
 }
 
+func ZShortStringer(name string, val ShortString) zap.Field {
+	return zap.Stringer(name, shortStringAdapter{val: val})
+}
+
 // Binary will encode binary content in base64 when logged.
 func Binary(name string, val []byte) Field {
 	return Field(zap.Binary(name, val))
@@ -183,6 +187,10 @@ func Context(ctx context.Context) Field {
 	return Field(zap.Inline(&marshalledContext{Context: ctx}))
 }
 
+func ZContext(ctx context.Context) zap.Field {
+	return zap.Inline(&marshalledContext{Context: ctx})
+}
+
 func Any(key string, value any) Field {
 	return Field(zap.Any(key, value))
 }

tortoise/algorithm.go

@@ -6,6 +6,8 @@ import (
 	"sync"
 	"time"
 
+	"go.uber.org/zap"
+
 	"github.com/spacemeshos/go-spacemesh/common/types"
 	"github.com/spacemeshos/go-spacemesh/common/types/result"
 	"github.com/spacemeshos/go-spacemesh/log"
@@ -40,7 +42,7 @@ func DefaultConfig() Config {
 
 // Tortoise is a thread safe verifying tortoise wrapper, it just locks all actions.
 type Tortoise struct {
-	logger log.Log
+	logger *zap.Logger
 	ctx    context.Context
 	cfg    Config
 
@@ -55,7 +57,7 @@ type Opt func(t *Tortoise)
 // WithLogger defines logger for tortoise.
 func WithLogger(logger log.Log) Opt {
 	return func(t *Tortoise) {
-		t.logger = logger
+		t.logger = logger.Zap()
 	}
 }
 
@@ -77,16 +79,16 @@ func WithTracer(opts ...TraceOpt) Opt {
 func New(opts ...Opt) (*Tortoise, error) {
 	t := &Tortoise{
 		ctx:    context.Background(),
-		logger: log.NewNop(),
+		logger: log.NewNop().Zap(),
 		cfg:    DefaultConfig(),
 	}
 	for _, opt := range opts {
 		opt(t)
 	}
 	if t.cfg.Hdist < t.cfg.Zdist {
-		t.logger.With().Panic("hdist must be >= zdist",
-			log.Uint32("hdist", t.cfg.Hdist),
-			log.Uint32("zdist", t.cfg.Zdist),
+		t.logger.Panic("hdist must be >= zdist",
+			zap.Uint32("hdist", t.cfg.Hdist),
+			zap.Uint32("zdist", t.cfg.Zdist),
 		)
 	}
 	t.trtl = newTurtle(t.logger, t.cfg)
@@ -115,10 +117,10 @@ func (t *Tortoise) LatestComplete() types.LayerID {
 func (t *Tortoise) OnWeakCoin(lid types.LayerID, coin bool) {
 	t.mu.Lock()
 	defer t.mu.Unlock()
-	t.logger.With().Debug("on weakcoin",
-		log.Uint32("layer_id", lid.Uint32()),
-		log.Uint32("evicted", t.trtl.evicted.Uint32()),
-		log.Bool("coin", coin),
+	t.logger.Debug("on weakcoin",
+		zap.Uint32("layer_id", lid.Uint32()),
+		zap.Uint32("evicted", t.trtl.evicted.Uint32()),
+		zap.Bool("coin", coin),
 	)
 	if lid <= t.trtl.evicted {
 		return
@@ -138,10 +140,10 @@ func (t *Tortoise) OnBeacon(eid types.EpochID, beacon types.Beacon) {
 	t.mu.Lock()
 	defer t.mu.Unlock()
 	firstInWindow := t.trtl.evicted.Add(1).GetEpoch()
-	t.logger.With().Debug("on beacon",
-		log.Uint32("epoch id", eid.Uint32()),
-		log.Uint32("first epoch", firstInWindow.Uint32()),
-		log.Stringer("beacon", beacon),
+	t.logger.Debug("on beacon",
+		zap.Uint32("epoch id", eid.Uint32()),
+		zap.Uint32("first epoch", firstInWindow.Uint32()),
+		zap.Stringer("beacon", beacon),
 	)
 	if eid < firstInWindow {
 		return
@@ -265,7 +267,9 @@ func (t *Tortoise) OnBallot(ballot *types.BallotTortoiseData) {
 	err := t.trtl.onBallot(ballot)
 	if err != nil {
 		errorsCounter.Inc()
-		t.logger.With().Error("failed to save state from ballot", ballot.ID, log.Err(err))
+		t.logger.Error("failed to save state from ballot",
+			zap.Stringer("ballot", ballot.ID),
+			zap.Error(err))
 	}
 	if t.tracer != nil {
 		t.tracer.On(&BallotTrace{Ballot: ballot})
@@ -383,10 +387,10 @@ func (t *Tortoise) Updates() []result.Layer {
 	}
 	rst, err := t.results(t.trtl.pending, t.trtl.processed)
 	if err != nil {
-		t.logger.With().Panic("unexpected error",
-			log.Uint32("pending", t.trtl.pending.Uint32()),
-			log.Uint32("processed", t.trtl.pending.Uint32()),
-			log.Err(err),
+		t.logger.Panic("unexpected error",
+			zap.Uint32("pending", t.trtl.pending.Uint32()),
+			zap.Uint32("processed", t.trtl.pending.Uint32()),
+			zap.Error(err),
 		)
 	}
 	t.trtl.pending = 0

tortoise/full.go

@@ -3,8 +3,9 @@ package tortoise
 import (
 	"time"
 
+	"go.uber.org/zap"
+
 	"github.com/spacemeshos/go-spacemesh/common/types"
-	"github.com/spacemeshos/go-spacemesh/log"
 )
 
 func newFullTortoise(config Config, state *state) *full {
@@ -29,7 +30,7 @@ type full struct {
 	delayed map[types.LayerID][]*ballotInfo
 }
 
-func (f *full) countBallot(logger log.Log, ballot *ballotInfo) {
+func (f *full) countBallot(logger *zap.Logger, ballot *ballotInfo) {
 	start := time.Now()
 	if f.shouldBeDelayed(logger, ballot) {
 		return
@@ -58,13 +59,6 @@ func (f *full) countBallot(logger log.Log, ballot *ballotInfo) {
 			case against:
 				block.margin = block.margin.Sub(ballot.weight)
 			}
-			logger.With().Debug("counted votes from ballot",
-				log.Stringer("id", ballot.id),
-				log.Uint32("lid", ballot.layer.Uint32()),
-				log.Stringer("block", block.id),
-				log.Stringer("vote", vote),
-				log.Stringer("margin", block.margin),
-			)
 		}
 		if empty {
 			layer.empty = layer.empty.Add(ballot.weight)
@@ -96,19 +90,19 @@ func (f *full) countForLateBlock(block *blockInfo) {
 	lateBlockDuration.Observe(float64(time.Since(start).Nanoseconds()))
 }
 
-func (f *full) countDelayed(logger log.Log, lid types.LayerID) {
+func (f *full) countDelayed(logger *zap.Logger, lid types.LayerID) {
 	delayed, exist := f.delayed[lid]
 	if !exist {
 		return
 	}
 	delete(f.delayed, lid)
 	for _, ballot := range delayed {
 		delayedBallots.Dec()
-		f.countBallot(logger.WithFields(log.Bool("delayed", true)), ballot)
+		f.countBallot(logger, ballot)
 	}
 }
 
-func (f *full) countVotes(logger log.Log) {
+func (f *full) countVotes(logger *zap.Logger) {
 	for lid := f.counted.Add(1); !lid.After(f.processed); lid = lid.Add(1) {
 		for _, ballot := range f.ballots[lid] {
 			f.countBallot(logger, ballot)
@@ -117,32 +111,28 @@ func (f *full) countVotes(logger log.Log) {
 	f.counted = f.processed
 }
 
-func (f *full) verify(logger log.Log, lid types.LayerID) bool {
+func (f *full) verify(logger *zap.Logger, lid types.LayerID) bool {
 	threshold := f.globalThreshold(f.Config, lid)
 	layer := f.state.layer(lid)
 	empty := crossesThreshold(layer.empty, threshold) == support
 
-	logger = logger.WithFields(
-		log.String("verifier", "full"),
-		log.Stringer("counted layer", f.counted),
-		log.Stringer("candidate layer", lid),
-		log.Stringer("local threshold", f.localThreshold),
-		log.Stringer("global threshold", threshold),
-		log.Stringer("empty weight", layer.empty),
-		log.Bool("is empty", empty),
-	)
 	if len(layer.blocks) == 0 {
 		if empty {
-			logger.With().Debug("candidate layer is empty")
+			logger.Debug("candidate layer is empty",
+				zap.Uint32("candidate layer", lid.Uint32()),
+				zap.Float64("global threshold", threshold.Float()),
+				zap.Float64("empty weight", layer.empty.Float()),
+			)
 		} else {
-			logger.With().Debug("margin is too low to terminate layer as empty",
-				lid,
-				log.Stringer("margin", layer.empty),
+			logger.Debug("margin is too low to terminate layer as empty",
+				zap.Uint32("candidate layer", lid.Uint32()),
+				zap.Float64("global threshold", threshold.Float()),
+				zap.Float64("empty weight", layer.empty.Float()),
 			)
 		}
 		return empty
 	}
-	return verifyLayer(
+	rst, changes := verifyLayer(
 		logger,
 		layer.blocks,
 		func(block *blockInfo) sign {
@@ -153,20 +143,33 @@ func (f *full) verify(logger log.Log, lid types.LayerID) bool {
 			return decision
 		},
 	)
+	if changes {
+		logger.Info("candidate layer is verified",
+			zapBlocks(layer.blocks),
+			zap.String("verifier", "full"),
+			zap.Uint32("counted layer", f.counted.Uint32()),
+			zap.Uint32("candidate layer", lid.Uint32()),
+			zap.Float64("local threshold", f.localThreshold.Float()),
+			zap.Float64("global threshold", threshold.Float()),
+			zap.Float64("empty weight", layer.empty.Float()),
+			zap.Bool("is empty", empty),
+		)
+	}
+	return rst
 }
 
-func (f *full) shouldBeDelayed(logger log.Log, ballot *ballotInfo) bool {
+func (f *full) shouldBeDelayed(logger *zap.Logger, ballot *ballotInfo) bool {
 	if !ballot.conditions.badBeacon {
 		return false
 	}
 	delay := ballot.layer.Add(f.BadBeaconVoteDelayLayers)
 	if !delay.After(f.last) {
 		return false
 	}
-	logger.With().Debug("ballot is delayed",
-		log.Stringer("id", ballot.id),
-		log.Uint32("ballot lid", ballot.layer.Uint32()),
-		log.Uint32("counted at", delay.Uint32()),
+	logger.Debug("ballot is delayed",
+		zap.Stringer("id", ballot.id),
+		zap.Uint32("ballot lid", ballot.layer.Uint32()),
+		zap.Uint32("counted at", delay.Uint32()),
 	)
 	delayedBallots.Inc()
 	f.delayed[delay] = append(f.delayed[delay], ballot)

tortoise/full_test.go

@@ -61,7 +61,7 @@ func TestFullBallotFilter(t *testing.T) {
 			config := Config{}
 			config.BadBeaconVoteDelayLayers = tc.distance
 			require.Equal(t, tc.expect, newFullTortoise(config, state).shouldBeDelayed(
-				logtest.New(t), &tc.ballot))
+				logtest.Zap(t), &tc.ballot))
 		})
 	}
 }
@@ -321,7 +321,7 @@ func TestFullCountVotes(t *testing.T) {
 	} {
 		tc := tc
 		t.Run(tc.desc, func(t *testing.T) {
-			logger := logtest.New(t)
+			logger := logtest.Zap(t)
 			tortoise := defaultAlgorithm(t)
 			var activeset []types.ATXID
 			for i := range tc.activeset {
@@ -544,7 +544,7 @@ func TestFullVerify(t *testing.T) {
 				}
 				layer.blocks = append(layer.blocks, block)
 			}
-			require.Equal(t, tc.validity != nil, full.verify(logtest.New(t), target))
+			require.Equal(t, tc.validity != nil, full.verify(logtest.Zap(t), target))
 			if tc.validity != nil {
 				for i, expect := range tc.validity {
 					require.Equal(t, expect, layer.blocks[i].validity)