etcdserver: add more detailed traces on linearized reading

To improve debuggability of `agreement among raft nodes before
linearized reading`, we added some tracing inside
`linearizableReadLoop`.

This will allow us to know the timing of `s.r.ReadIndex` vs
`s.applyWait.Wait(rs.Index)`.

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)
 	}
 }
 

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)