kvserver: improve logging for follower reads

Release note: None

pkg/kv/kvserver/replica_follower_read.go

@@ -12,6 +12,7 @@ package kvserver
 
 import (
 	"context"
+	"time"
 
 	"github.com/cockroachdb/cockroach/pkg/kv/kvserver/closedts/ctpb"
 	ctstorage "github.com/cockroachdb/cockroach/pkg/kv/kvserver/closedts/storage"
@@ -40,6 +41,7 @@ func (r *Replica) canServeFollowerRead(
 	ctx context.Context, ba *roachpb.BatchRequest, pErr *roachpb.Error,
 ) *roachpb.Error {
 	canServeFollowerRead := false
+	var tsDiff time.Duration
 	if lErr, ok := pErr.GetDetail().(*roachpb.NotLeaseHolderError); ok &&
 		lErr.LeaseHolder != nil && lErr.Lease.Type() == roachpb.LeaseEpoch &&
 		(!ba.IsLocking() && ba.IsAllTransactional()) && // followerreadsccl.batchCanBeEvaluatedOnFollower
@@ -67,10 +69,13 @@ func (r *Replica) canServeFollowerRead(
 
 		maxClosed, _ := r.maxClosed(ctx)
 		canServeFollowerRead = ts.LessEq(maxClosed)
+		tsDiff = ts.GoTime().Sub(maxClosed.GoTime())
 		if !canServeFollowerRead {
 			// We can't actually serve the read based on the closed timestamp.
 			// Signal the clients that we want an update so that future requests can succeed.
 			r.store.cfg.ClosedTimestamp.Clients.Request(lErr.LeaseHolder.NodeID, r.RangeID)
+			log.Eventf(ctx, "can't serve follower read; closed timestamp too low by: %s; maxClosed: %s ts: %s maxTS: %s",
+				tsDiff, maxClosed, ba.Timestamp, ba.Txn.MaxTimestamp)
 
 			if false {
 				// NB: this can't go behind V(x) because the log message created by the
@@ -93,7 +98,7 @@ func (r *Replica) canServeFollowerRead(
 	//
 	// TODO(tschottdorf): once a read for a timestamp T has been served, the replica may
 	// serve reads for that and smaller timestamps forever.
-	log.Event(ctx, "serving via follower read")
+	log.Eventf(ctx, "serving via follower read; query timestamp below closed timestamp by %s", -tsDiff)
 	r.store.metrics.FollowerReadsCount.Inc(1)
 	return nil
 }