From e242fb224b4431e369c6dcd3f89727d364ebcfe9 Mon Sep 17 00:00:00 2001 From: Andrei Matei Date: Thu, 16 Jul 2020 17:22:03 -0400 Subject: [PATCH] kvserver: improve logging for follower reads Release note: None --- pkg/kv/kvserver/replica_follower_read.go | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/pkg/kv/kvserver/replica_follower_read.go b/pkg/kv/kvserver/replica_follower_read.go index 45e84b8cb8e6..0993dba453f1 100644 --- a/pkg/kv/kvserver/replica_follower_read.go +++ b/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 }