sql: add MVCC steps and seeks to EXPLAIN ANALYZE

This commit adds 4 new fields to EXPLAIN ANALYZE for each operator that
reads data from disk: MVCC steps and seeks, as well as MVCC "internal"
steps and seeks when verbose mode is toggled.

MVCC steps is the number of times that the underlying storage iterator
stepped forward during the work to serve the operator's reads, including
stepping over MVCC keys that were too old for user in a scan. MVCC seeks
is the number of times that the underlying storage iterator jumped
(seeked) to a different data location. Seeks are more expensive than
steps.

Comparing MVCC steps 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

@@ -1519,3 +1519,14 @@ 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: stepped %d times (%d internal); seeked %d times (%d internal)",
+		s.NumInterfaceSteps, s.NumInternalSteps, s.NumInterfaceSeeks, s.NumInternalSeeks)
+}
+
+// String implements fmt.Stringer.
+func (s *ScanStats) String() string {
+	return redact.StringWithoutMarkers(s)
+}

pkg/roachpb/api.proto

@@ -2245,3 +2245,14 @@ 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_interface_seeks = 1;
+  uint64 num_internal_seeks = 2;
+  uint64 num_interface_steps = 3;
+  uint64 num_internal_steps = 4;
+}

pkg/sql/colexecop/operator.go

@@ -72,6 +72,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

@@ -19,6 +19,7 @@ import (
 	"github.com/cockroachdb/cockroach/pkg/sql/colexecerror"
 	"github.com/cockroachdb/cockroach/pkg/sql/colexecop"
 	"github.com/cockroachdb/cockroach/pkg/sql/colflow/colrpc"
+	"github.com/cockroachdb/cockroach/pkg/sql/execinfra"
 	"github.com/cockroachdb/cockroach/pkg/sql/execinfrapb"
 	"github.com/cockroachdb/cockroach/pkg/util"
 	"github.com/cockroachdb/cockroach/pkg/util/mon"
@@ -212,6 +213,8 @@ 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()
+		execinfra.PopulateKVMVCCStats(&s.KV, &scanStats)
 	} else {
 		s.Exec.ExecTime.Set(time)
 	}

pkg/sql/execinfra/stats.go

@@ -15,6 +15,8 @@ import (
 	"time"
 
 	"github.com/cockroachdb/cockroach/pkg/roachpb"
+	"github.com/cockroachdb/cockroach/pkg/sql/execinfrapb"
+	"github.com/cockroachdb/cockroach/pkg/util/optional"
 	"github.com/cockroachdb/cockroach/pkg/util/tracing"
 	pbtypes "github.com/gogo/protobuf/types"
 )
@@ -50,3 +52,44 @@ func GetCumulativeContentionTime(ctx context.Context) time.Duration {
 	}
 	return cumulativeContentionTime
 }
+
+type ScanStats struct {
+	NumInterfaceSteps uint64
+	NumInternalSteps  uint64
+	NumInterfaceSeeks uint64
+	NumInternalSeeks  uint64
+}
+
+// PopulateKVMVCCStats adds data from the input ScanStats to the input KVStats.
+func PopulateKVMVCCStats(kvStats *execinfrapb.KVStats, ss *ScanStats) {
+	kvStats.NumInterfaceSteps = optional.MakeUint(ss.NumInterfaceSteps)
+	kvStats.NumInternalSteps = optional.MakeUint(ss.NumInternalSteps)
+	kvStats.NumInterfaceSeeks = optional.MakeUint(ss.NumInterfaceSeeks)
+	kvStats.NumInternalSeeks = optional.MakeUint(ss.NumInternalSeeks)
+}
+
+// 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, _ time.Time) {
+			if !pbtypes.Is(any, &ev) {
+				return
+			}
+			if err := pbtypes.UnmarshalAny(any, &ev); err != nil {
+				return
+			}
+
+			ss.NumInterfaceSteps += ev.NumInterfaceSteps
+			ss.NumInternalSteps += ev.NumInternalSteps
+			ss.NumInterfaceSeeks += ev.NumInterfaceSeeks
+			ss.NumInternalSeeks += ev.NumInternalSeeks
+		})
+	}
+	return ss
+}

pkg/sql/execinfrapb/component_stats.go

@@ -151,6 +151,12 @@ func (s *ComponentStats) formatStats(fn func(suffix string, value interface{}))
 	if s.KV.BytesRead.HasValue() {
 		fn("KV bytes read", humanize.IBytes(s.KV.BytesRead.Value()))
 	}
+	if s.KV.NumInterfaceSteps.HasValue() {
+		fn("MVCC step count", humanizeutil.Count(s.KV.NumInterfaceSeeks.Value()))
+	}
+	if s.KV.NumInterfaceSeeks.HasValue() {
+		fn("MVCC seek count", humanizeutil.Count(s.KV.NumInterfaceSeeks.Value()))
+	}
 
 	// Exec stats.
 	if s.Exec.ExecTime.HasValue() {
@@ -217,6 +223,18 @@ func (s *ComponentStats) Union(other *ComponentStats) *ComponentStats {
 	if !result.KV.ContentionTime.HasValue() {
 		result.KV.ContentionTime = other.KV.ContentionTime
 	}
+	if !result.KV.NumInterfaceSteps.HasValue() {
+		result.KV.NumInterfaceSteps = other.KV.NumInterfaceSteps
+	}
+	if !result.KV.NumInternalSteps.HasValue() {
+		result.KV.NumInternalSteps = other.KV.NumInternalSteps
+	}
+	if !result.KV.NumInterfaceSeeks.HasValue() {
+		result.KV.NumInterfaceSeeks = other.KV.NumInterfaceSeeks
+	}
+	if !result.KV.NumInternalSeeks.HasValue() {
+		result.KV.NumInternalSeeks = other.KV.NumInternalSeeks
+	}
 	if !result.KV.TuplesRead.HasValue() {
 		result.KV.TuplesRead = other.KV.TuplesRead
 	}
@@ -306,6 +324,10 @@ func (s *ComponentStats) MakeDeterministic() {
 	// KV.
 	timeVal(&s.KV.KVTime)
 	timeVal(&s.KV.ContentionTime)
+	resetUint(&s.KV.NumInterfaceSteps)
+	resetUint(&s.KV.NumInternalSteps)
+	resetUint(&s.KV.NumInterfaceSeeks)
+	resetUint(&s.KV.NumInternalSeeks)
 	if s.KV.BytesRead.HasValue() {
 		// BytesRead is overridden to a useful value for tests.
 		s.KV.BytesRead.Set(8 * s.KV.TuplesRead.Value())