diff --git a/etcdserver/v3_server.go b/etcdserver/v3_server.go index e96f9660d442..7bc28ed5e2c9 100644 --- a/etcdserver/v3_server.go +++ b/etcdserver/v3_server.go @@ -19,6 +19,7 @@ import ( "context" "encoding/base64" "encoding/binary" + "strconv" "time" "go.etcd.io/etcd/v3/auth" @@ -715,6 +716,9 @@ func (s *EtcdServer) linearizableReadLoop() { return } + // as a single loop is can unlock multiple reads, it is not very useful + // to propagate the trace from Txn or Range. + trace := traceutil.New("linearizableReadLoop", s.lg) nextnr := newNotifier() s.readMu.Lock() @@ -775,6 +779,9 @@ func (s *EtcdServer) linearizableReadLoop() { if !done { continue } + trace.Step("read index received") + trace.AddField(traceutil.Field{Key: "appliedIndex", Value: strconv.FormatUint(s.appliedIndex, 10)}) + trace.AddField(traceutil.Field{Key: "readStateIndex", Value: rs.Index}) if ai := s.getAppliedIndex(); ai < rs.Index { select { @@ -785,6 +792,9 @@ func (s *EtcdServer) linearizableReadLoop() { } // unblock all l-reads requested at indices before rs.Index nr.notify(nil) + trace.Step("applied index is now lower than readState.Index") + + trace.LogAllStepsIfLong(traceThreshold) } } diff --git a/pkg/traceutil/trace.go b/pkg/traceutil/trace.go index cbe2cfbf0a08..87cf91b80d83 100644 --- a/pkg/traceutil/trace.go +++ b/pkg/traceutil/trace.go @@ -157,6 +157,13 @@ func (t *Trace) LogIfLong(threshold time.Duration) { } } +// LogAllStepsIfLong dumps all logs if the duration is longer than threshold +func (t *Trace) LogAllStepsIfLong(threshold time.Duration) { + if time.Since(t.startTime) > threshold { + t.LogWithStepThreshold(0) + } +} + // LogWithStepThreshold only dumps step whose duration is longer than step threshold func (t *Trace) LogWithStepThreshold(threshold time.Duration) { msg, fs := t.logInfo(threshold)