Skip to content

Refactor logging in sync and stage loop for improved performance tracking #709

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
ilovers wants to merge 1 commit into
base: dev
Choose a base branch
from
+22 −11
Open

Refactor logging in sync and stage loop for improved performance tracking #709

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
21 changes: 15 additions & 6 deletions eth/stagedsync/sync.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -487,9 +487,9 @@ func (s *Sync) PrintTimings() []interface{} {
var logCtx []interface{}
count := 0
for i := range s.timings {
if s.timings[i].took < 50*time.Millisecond {
continue
}
//if s.timings[i].took < 50*time.Millisecond {
// continue
//}
count++
if count == 50 {
break
Expand Down Expand Up @@ -564,9 +564,18 @@ func (s *Sync) runStage(stage *Stage, db kv.RwDB, txc wrap.TxContainer, firstCyc

took := time.Since(start)
logPrefix := s.LogPrefix()
if took > 60*time.Second {
s.logger.Info(fmt.Sprintf("[%s] DONE", logPrefix), "in", took)
} else {

// 根据不同耗时范围打印不同级别的日志
switch {
case took > 60*time.Second:
s.logger.Error(fmt.Sprintf("[%s] DONE - CRITICAL SLOW", logPrefix), "in", took)
case took > 30*time.Second:
s.logger.Warn(fmt.Sprintf("[%s] DONE - VERY SLOW", logPrefix), "in", took)
case took > 10*time.Second:
s.logger.Warn(fmt.Sprintf("[%s] DONE - SLOW", logPrefix), "in", took)
case took > 3*time.Second:
s.logger.Info(fmt.Sprintf("[%s] DONE - TAKES TIME", logPrefix), "in", took)
default:
s.logger.Debug(fmt.Sprintf("[%s] DONE", logPrefix), "in", took)
}
s.timings = append(s.timings, Timing{stage: stage.ID, took: took})
Expand Down
12 changes: 7 additions & 5 deletions turbo/stages/stageloop.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -71,7 +71,7 @@ func StageLoop(ctx context.Context,

// Estimate the current top height seen from the peer
err := StageLoopIteration(ctx, db, wrap.TxContainer{}, sync, initialCycle, logger, blockReader, hook, forcePartialCommit)

log.Info(fmt.Sprintf("StageLoopIteration cost=%dms, err=%v", time.Since(start).Milliseconds(), err))
if err != nil {
if errors.Is(err, libcommon.ErrStopped) || errors.Is(err, context.Canceled) {
return
Expand Down Expand Up @@ -105,7 +105,7 @@ func StageLoopIteration(ctx context.Context, db kv.RwDB, txc wrap.TxContainer, s
err = fmt.Errorf("%+v, trace: %s", rec, dbg.Stack())
}
}() // avoid crash because Erigon's core does many things

start := time.Now()
externalTx := txc.Tx != nil
headersProgressBefore, borProgressBefore, finishProgressBefore, err := stagesHeadersAndFinish(db, txc.Tx)
if err != nil {
Expand Down Expand Up @@ -152,6 +152,7 @@ func StageLoopIteration(ctx context.Context, db kv.RwDB, txc wrap.TxContainer, s
defer txc.Tx.Rollback()
}
_, err = sync.Run(db, txc, initialCycle)
log.Info(fmt.Sprintf("SyncRun cost=%dms, err=%v", time.Since(start).Milliseconds(), err))
if err != nil {
return err
}
Expand Down Expand Up @@ -179,14 +180,15 @@ func StageLoopIteration(ctx context.Context, db kv.RwDB, txc wrap.TxContainer, s
}
}
}
if canRunCycleInOneTransaction && !externalTx && commitTime > 500*time.Millisecond {
if canRunCycleInOneTransaction && !externalTx {
logger.Info("Commit cycle", "in", commitTime)
}
//if len(logCtx) > 0 { // No printing of timings or table sizes if there were no progress
readMemStart := time.Now()
var m runtime.MemStats
dbg.ReadMemStats(&m)
logCtx = append(logCtx, "alloc", libcommon.ByteCount(m.Alloc), "sys", libcommon.ByteCount(m.Sys))
logger.Info("Timings (slower than 50ms)", logCtx...)
logCtx = append(logCtx, "alloc", libcommon.ByteCount(m.Alloc), "sys", libcommon.ByteCount(m.Sys), "cost time(ms)", time.Since(readMemStart).Milliseconds())
logger.Info("SyncRun timings", logCtx...)

// -- send notifications END

Expand Down