Skip to content

Commit

Permalink
sql: add MVCC steps and seeks to EXPLAIN ANALYZE
Browse files Browse the repository at this point in the history
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.
  • Loading branch information
jordanlewis committed Sep 10, 2021
1 parent 562d860 commit 77d424a
Show file tree
Hide file tree
Showing 28 changed files with 1,368 additions and 660 deletions.
11 changes: 11 additions & 0 deletions pkg/roachpb/api.go
Original file line number Diff line number Diff line change
Expand Up @@ -1628,3 +1628,14 @@ func (c *TenantConsumption) Sub(other *TenantConsumption) {
c.SQLPodsCPUSeconds -= other.SQLPodsCPUSeconds
}
}

// 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)
}
1,380 changes: 806 additions & 574 deletions pkg/roachpb/api.pb.go

Large diffs are not rendered by default.

11 changes: 11 additions & 0 deletions pkg/roachpb/api.proto
Original file line number Diff line number Diff line change
Expand Up @@ -2577,3 +2577,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;
}
3 changes: 3 additions & 0 deletions pkg/sql/colexecop/operator.go
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
5 changes: 5 additions & 0 deletions pkg/sql/colfetcher/colbatch_scan.go
Original file line number Diff line number Diff line change
Expand Up @@ -169,6 +169,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{}
Expand Down
5 changes: 5 additions & 0 deletions pkg/sql/colfetcher/index_join.go
Original file line number Diff line number Diff line change
Expand Up @@ -514,6 +514,11 @@ func adjustMemEstimate(estimate int64) int64 {
return estimate*memEstimateMultiplier + memEstimateAdditive
}

// GetScanStats is part of the colexecop.KVReader interface.
func (s *ColIndexJoin) GetScanStats() execinfra.ScanStats {
return execinfra.GetScanStats(s.Ctx)
}

// Release implements the execinfra.Releasable interface.
func (s *ColIndexJoin) Release() {
s.rf.Release()
Expand Down
3 changes: 3 additions & 0 deletions pkg/sql/colflow/stats.go
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down Expand Up @@ -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)
}
Expand Down
54 changes: 54 additions & 0 deletions pkg/sql/execinfra/stats.go
Original file line number Diff line number Diff line change
Expand Up @@ -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"
)
Expand Down Expand Up @@ -50,3 +52,55 @@ func GetCumulativeContentionTime(ctx context.Context) time.Duration {
}
return cumulativeContentionTime
}

// ScanStats contains statistics on the internal MVCC operators used to satisfy
// a scan. See storage/engine.go for a more thorough discussion of the meaning
// of each stat.
type ScanStats struct {
// NumInterfaceSteps is the number of times the MVCC step function was called
// to satisfy a scan.
NumInterfaceSteps uint64
// NumInternalSteps is the number of times that MVCC step was invoked
// internally, including to step over internal, uncompacted Pebble versions.
NumInternalSteps uint64
// NumInterfaceSeeks is the number of times the MVCC seek function was called
// to satisfy a scan.
NumInterfaceSeeks uint64
// NumInternalSeeks is the number of times that MVCC seek was invoked
// internally, including to step over internal, uncompacted Pebble versions.
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
}
30 changes: 30 additions & 0 deletions pkg/sql/execinfrapb/component_stats.go
Original file line number Diff line number Diff line change
Expand Up @@ -151,6 +151,20 @@ 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 (ext/int)",
fmt.Sprintf("%s/%s",
humanizeutil.Count(s.KV.NumInterfaceSteps.Value()),
humanizeutil.Count(s.KV.NumInternalSteps.Value())),
)
}
if s.KV.NumInterfaceSeeks.HasValue() {
fn("MVCC seek count (ext/int)",
fmt.Sprintf("%s/%s",
humanizeutil.Count(s.KV.NumInterfaceSeeks.Value()),
humanizeutil.Count(s.KV.NumInternalSeeks.Value())),
)
}

// Exec stats.
if s.Exec.ExecTime.HasValue() {
Expand Down Expand Up @@ -217,6 +231,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
}
Expand Down Expand Up @@ -306,6 +332,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())
Expand Down
Loading

0 comments on commit 77d424a

Please sign in to comment.