diff --git a/etcdserver/v3_server.go b/etcdserver/v3_server.go index 072cb5cd5..2f50f0f0e 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" @@ -718,6 +719,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.getLogger()) nextnr := newNotifier() s.readMu.Lock() @@ -778,16 +782,26 @@ func (s *EtcdServer) linearizableReadLoop() { if !done { continue } + trace.Step("read index received") - if ai := s.getAppliedIndex(); ai < rs.Index { + index := rs.Index + trace.AddField(traceutil.Field{Key: "readStateIndex", Value: index}) + + ai := s.getAppliedIndex() + trace.AddField(traceutil.Field{Key: "appliedIndex", Value: strconv.FormatUint(ai, 10)}) + + if ai < index { select { - case <-s.applyWait.Wait(rs.Index): + case <-s.applyWait.Wait(index): case <-s.stopping: return } } // 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 680a35f47..bdd8e9b66 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)