From 37761ebd83dbbcde34595397f0785f6d12101e1d Mon Sep 17 00:00:00 2001 From: petricadaipegsp <155911522+petricadaipegsp@users.noreply.github.com> Date: Wed, 13 Nov 2024 18:36:49 +0100 Subject: [PATCH] Log frame age (#351) --- node/consensus/data/consensus_frames.go | 11 ++++++++++- node/consensus/data/data_clock_consensus_engine.go | 5 +++++ node/consensus/data/main_data_loop.go | 4 ++++ .../intrinsics/token/token_execution_engine.go | 2 ++ node/internal/frametime/frametime.go | 12 ++++++++++++ 5 files changed, 33 insertions(+), 1 deletion(-) create mode 100644 node/internal/frametime/frametime.go diff --git a/node/consensus/data/consensus_frames.go b/node/consensus/data/consensus_frames.go index bb71b06..a905179 100644 --- a/node/consensus/data/consensus_frames.go +++ b/node/consensus/data/consensus_frames.go @@ -9,7 +9,9 @@ import ( "source.quilibrium.com/quilibrium/monorepo/node/config" "source.quilibrium.com/quilibrium/monorepo/node/consensus" "source.quilibrium.com/quilibrium/monorepo/node/consensus/data/internal" + "source.quilibrium.com/quilibrium/monorepo/node/internal/frametime" + "github.com/libp2p/go-libp2p/core/peer" "github.com/pkg/errors" "go.uber.org/zap" "google.golang.org/grpc" @@ -45,6 +47,7 @@ func (e *DataClockConsensusEngine) collect( e.logger.Info( "returning leader frame", zap.Uint64("frame_number", latest.FrameNumber), + zap.Duration("frame_age", frametime.Since(latest)), ) return latest, nil @@ -271,7 +274,12 @@ func (e *DataClockConsensusEngine) sync( e.syncingStatus = SyncStatusSynchronizing defer func() { e.syncingStatus = SyncStatusNotSyncing }() latest := currentLatest - e.logger.Info("polling peer for new frames", zap.Binary("peer_id", peerId)) + e.logger.Info( + "polling peer for new frames", + zap.String("peer_id", peer.ID(peerId).String()), + zap.Uint64("current_frame", latest.FrameNumber), + zap.Uint64("max_frame", maxFrame), + ) cc, err := e.pubSub.GetDirectChannel(peerId, "sync") if err != nil { e.logger.Debug( @@ -344,6 +352,7 @@ func (e *DataClockConsensusEngine) sync( e.logger.Info( "received new leading frame", zap.Uint64("frame_number", response.ClockFrame.FrameNumber), + zap.Duration("frame_age", frametime.Since(response.ClockFrame)), ) if !e.IsInProverTrie( response.ClockFrame.GetPublicKeySignatureEd448().PublicKey.KeyValue, diff --git a/node/consensus/data/data_clock_consensus_engine.go b/node/consensus/data/data_clock_consensus_engine.go index bef5356..d34a718 100644 --- a/node/consensus/data/data_clock_consensus_engine.go +++ b/node/consensus/data/data_clock_consensus_engine.go @@ -27,6 +27,7 @@ import ( qcrypto "source.quilibrium.com/quilibrium/monorepo/node/crypto" "source.quilibrium.com/quilibrium/monorepo/node/execution" "source.quilibrium.com/quilibrium/monorepo/node/internal/cas" + "source.quilibrium.com/quilibrium/monorepo/node/internal/frametime" "source.quilibrium.com/quilibrium/monorepo/node/keys" "source.quilibrium.com/quilibrium/monorepo/node/p2p" "source.quilibrium.com/quilibrium/monorepo/node/protobufs" @@ -418,6 +419,7 @@ func (e *DataClockConsensusEngine) Start() <-chan error { e.logger.Info( "preparing peer announce", zap.Uint64("frame_number", frame.FrameNumber), + zap.Duration("frame_age", frametime.Since(frame)), ) e.peerMapMx.Lock() @@ -461,6 +463,7 @@ func (e *DataClockConsensusEngine) Start() <-chan error { e.logger.Info( "broadcasting peer info", zap.Uint64("frame_number", frame.FrameNumber), + zap.Duration("frame_age", frametime.Since(frame)), ) if err := e.publishMessage(e.infoFilter, list); err != nil { @@ -542,6 +545,8 @@ func (e *DataClockConsensusEngine) PerformTimeProof( "creating data shard ring proof", zap.Int("ring", ring), zap.Int("active_workers", len(actives)), + zap.Uint64("frame_number", frame.FrameNumber), + zap.Duration("frame_age", frametime.Since(frame)), ) wg := sync.WaitGroup{} diff --git a/node/consensus/data/main_data_loop.go b/node/consensus/data/main_data_loop.go index c987c6c..92ef5d7 100644 --- a/node/consensus/data/main_data_loop.go +++ b/node/consensus/data/main_data_loop.go @@ -9,6 +9,7 @@ import ( "go.uber.org/zap" "source.quilibrium.com/quilibrium/monorepo/node/consensus" "source.quilibrium.com/quilibrium/monorepo/node/internal/cas" + "source.quilibrium.com/quilibrium/monorepo/node/internal/frametime" "source.quilibrium.com/quilibrium/monorepo/node/protobufs" "source.quilibrium.com/quilibrium/monorepo/node/tries" ) @@ -98,6 +99,7 @@ func (e *DataClockConsensusEngine) processFrame( e.logger.Info( "current frame head", zap.Uint64("frame_number", dataFrame.FrameNumber), + zap.Duration("frame_age", frametime.Since(dataFrame)), ) var err error if !e.GetFrameProverTries()[0].Contains(e.provingKeyBytes) { @@ -249,6 +251,8 @@ func (e *DataClockConsensusEngine) processFrame( "submitting data proof", zap.Int("ring", ring), zap.Int("active_workers", len(outputs)), + zap.Uint64("frame_number", latestFrame.FrameNumber), + zap.Duration("frame_age", frametime.Since(latestFrame)), ) e.publishMessage(e.txFilter, &protobufs.TokenRequest{ diff --git a/node/execution/intrinsics/token/token_execution_engine.go b/node/execution/intrinsics/token/token_execution_engine.go index 69b440f..2cbfc26 100644 --- a/node/execution/intrinsics/token/token_execution_engine.go +++ b/node/execution/intrinsics/token/token_execution_engine.go @@ -26,6 +26,7 @@ import ( qcrypto "source.quilibrium.com/quilibrium/monorepo/node/crypto" "source.quilibrium.com/quilibrium/monorepo/node/execution" "source.quilibrium.com/quilibrium/monorepo/node/execution/intrinsics/token/application" + "source.quilibrium.com/quilibrium/monorepo/node/internal/frametime" "source.quilibrium.com/quilibrium/monorepo/node/keys" "source.quilibrium.com/quilibrium/monorepo/node/p2p" "source.quilibrium.com/quilibrium/monorepo/node/protobufs" @@ -509,6 +510,7 @@ func (e *TokenExecutionEngine) ProcessFrame( "frame_number", frame.FrameNumber, ), + zap.Duration("frame_age", frametime.Since(frame)), ) app, err := application.MaterializeApplicationFromFrame( e.provingKey, diff --git a/node/internal/frametime/frametime.go b/node/internal/frametime/frametime.go new file mode 100644 index 0000000..a0d795f --- /dev/null +++ b/node/internal/frametime/frametime.go @@ -0,0 +1,12 @@ +package frametime + +import ( + "time" + + "source.quilibrium.com/quilibrium/monorepo/node/protobufs" +) + +// Since returns the time elapsed since the given frame was created. +func Since(frame *protobufs.ClockFrame) time.Duration { + return time.Since(time.UnixMilli(frame.Timestamp)) +}