sql: add MVCC keys read; seeks to EXPLAIN ANALYZE

This commit adds 2 new fields to EXPLAIN ANALYZE for each operator that
reads data from disk: MVCC keys read, and MVCC seeks. MVCC keys read is
a metric that counts the number of MVCC keys that were iterated to,
including MVCC keys that were too old for use in a scan. MVCC seeks is
a metric that counts the number of times that the MVCC iterator had to
"jump" to a new data location.

Comparing MVCC keys read to KVs read helps indicate to a user when a
scan might be slower than expected due to MVCC garbage in the middle of
the keyspace being scanned. A high number of MVCC seeks might also
indicate a lot of skipped MVCC garbage, especially when doing a
sequential scan.

Release note (sql change): EXPLAIN ANALYZE now contains more information
about the MVCC behavior of operators that scan data from disk. See
commit message for more details.

pkg/roachpb/api.go

@@ -1500,3 +1500,13 @@ func (c *ContentionEvent) SafeFormat(w redact.SafePrinter, _ rune) {
 func (c *ContentionEvent) String() string {
 	return redact.StringWithoutMarkers(c)
 }
+
+// SafeFormat implements redact.SafeFormatter.
+func (s *ScanStats) SafeFormat(w redact.SafePrinter, _ rune) {
+	w.Printf("scan stats: skipped %d keys; sought %d times", s.NumMvccKeys, s.NumSeeks)
+}
+
+// String implements fmt.Stringer.
+func (s *ScanStats) String() string {
+	return redact.StringWithoutMarkers(s)
+}

pkg/roachpb/api.proto

@@ -105,6 +105,10 @@ message ResponseHeader {
   // measures the bytes in the timestamps, keys, and values of the returned
   // rows.
   int64 num_bytes = 8;
+
+  // The total number of keys that were read, including keys that were skipped
+  // because they were too old to care about MVCC-wise.
+  int64 num_keys_read = 9;
   reserved 6;
 }
 
@@ -2253,3 +2257,12 @@ message ContentionEvent {
   google.protobuf.Duration duration = 3 [(gogoproto.nullable) = false,
                                          (gogoproto.stdduration) = true];
 }
+
+// ScanStats is a message that will be attached to BatchResponses containing
+// information about what happened during each scan and get in the request.
+message ScanStats {
+  option (gogoproto.goproto_stringer) = false;
+
+  uint64 num_mvcc_keys = 1;
+  uint64 num_seeks = 2;
+}

pkg/sql/colexecop/operator.go

@@ -73,6 +73,9 @@ type KVReader interface {
 	// GetCumulativeContentionTime returns the amount of time KV reads spent
 	// contending. It must be safe for concurrent use.
 	GetCumulativeContentionTime() time.Duration
+	// GetScanStats returns statistics about the scan that happened during the
+	// KV reads. It must be safe for concurrent use.
+	GetScanStats() execinfra.ScanStats
 }
 
 // ZeroInputNode is an execinfra.OpNode with no inputs.

pkg/sql/colfetcher/colbatch_scan.go

@@ -156,6 +156,11 @@ func (s *ColBatchScan) GetCumulativeContentionTime() time.Duration {
 	return execinfra.GetCumulativeContentionTime(s.Ctx)
 }
 
+// GetScanStats is part of the colexecop.KVReader interface.
+func (s *ColBatchScan) GetScanStats() execinfra.ScanStats {
+	return execinfra.GetScanStats(s.Ctx)
+}
+
 var colBatchScanPool = sync.Pool{
 	New: func() interface{} {
 		return &ColBatchScan{}

pkg/sql/colflow/stats.go

@@ -212,6 +212,9 @@ func (vsc *vectorizedStatsCollectorImpl) GetStats() *execinfrapb.ComponentStats
 		s.KV.TuplesRead.Set(uint64(vsc.kvReader.GetRowsRead()))
 		s.KV.BytesRead.Set(uint64(vsc.kvReader.GetBytesRead()))
 		s.KV.ContentionTime.Set(vsc.kvReader.GetCumulativeContentionTime())
+		scanStats := vsc.kvReader.GetScanStats()
+		s.KV.NumMvccKeys.Set(scanStats.NumMVCCKeys)
+		s.KV.NumSeeks.Set(scanStats.NumSeeks)
 	} else {
 		s.Exec.ExecTime.Set(time)
 	}

pkg/sql/execinfra/stats.go

@@ -50,3 +50,32 @@ func GetCumulativeContentionTime(ctx context.Context) time.Duration {
 	}
 	return cumulativeContentionTime
 }
+
+type ScanStats struct {
+	NumMVCCKeys uint64
+	NumSeeks    uint64
+}
+
+// GetScanStats is a helper function to calculate scan stats from the tracing
+// span from the context.
+func GetScanStats(ctx context.Context) (ss ScanStats) {
+	recording := GetTraceData(ctx)
+	if recording == nil {
+		return ScanStats{}
+	}
+	var ev roachpb.ScanStats
+	for i := range recording {
+		recording[i].Structured(func(any *pbtypes.Any) {
+			if !pbtypes.Is(any, &ev) {
+				return
+			}
+			if err := pbtypes.UnmarshalAny(any, &ev); err != nil {
+				return
+			}
+
+			ss.NumMVCCKeys += ev.NumMvccKeys
+			ss.NumSeeks += ev.NumSeeks
+		})
+	}
+	return ss
+}

pkg/sql/execinfrapb/component_stats.go

@@ -142,6 +142,12 @@ func (s *ComponentStats) formatStats(fn func(suffix string, value interface{}))
 	if s.KV.ContentionTime.HasValue() {
 		fn("KV contention time", humanizeutil.Duration(s.KV.ContentionTime.Value()))
 	}
+	if s.KV.NumMvccKeys.HasValue() {
+		fn("KV mvcc keys read", humanizeutil.Count(s.KV.NumMvccKeys.Value()))
+	}
+	if s.KV.NumSeeks.HasValue() {
+		fn("KV mvcc seeks", humanizeutil.Count(s.KV.NumSeeks.Value()))
+	}
 	if s.KV.TuplesRead.HasValue() {
 		fn("KV rows read", humanizeutil.Count(s.KV.TuplesRead.Value()))
 	}
@@ -214,6 +220,12 @@ func (s *ComponentStats) Union(other *ComponentStats) *ComponentStats {
 	if !result.KV.ContentionTime.HasValue() {
 		result.KV.ContentionTime = other.KV.ContentionTime
 	}
+	if !result.KV.NumMvccKeys.HasValue() {
+		result.KV.NumMvccKeys = other.KV.NumMvccKeys
+	}
+	if !result.KV.NumSeeks.HasValue() {
+		result.KV.NumSeeks = other.KV.NumSeeks
+	}
 	if !result.KV.TuplesRead.HasValue() {
 		result.KV.TuplesRead = other.KV.TuplesRead
 	}
@@ -303,6 +315,8 @@ func (s *ComponentStats) MakeDeterministic() {
 	// KV.
 	timeVal(&s.KV.KVTime)
 	timeVal(&s.KV.ContentionTime)
+	resetUint(&s.KV.NumMvccKeys)
+	resetUint(&s.KV.NumSeeks)
 	if s.KV.BytesRead.HasValue() {
 		// BytesRead is overridden to a useful value for tests.
 		s.KV.BytesRead.Set(8 * s.KV.TuplesRead.Value())