sql: add MVCC steps and seeks to EXPLAIN ANALYZE

[jordanlewis]

Updates #57322. It doesn't track number of bytes scanned over, not sure how to efficiently do that.

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.

[cockroach-teamcity]

This change is 

[sumeerbhola]

Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @jordanlewis)

---

pkg/storage/pebble_mvcc_scanner.go, line 149 at r2 (raw file):

	// numSeeks is the number of times that this scanner had to seek due to
	// exceeding its itersBeforeSeek configuration value for a given key.
	numSeeks uint64

Thanks for starting on this! We really need to expose more iteration stats, and this is a good start.

I'm going to nit-pick about a few things here:

• numMVCCKeysRead is being incremented in iterNext and there are many reasons that is being called, not just "read and then skip due to having too-old ...". There are a variable number of MVCCIterator.Next calls that happen in iterNext, while this is counting once per iterNext.
• This instrumentation for seeks is somewhat fragile since it is happening at the caller and not the callee. And pebbleMVCCScanner is not the only place where we incur read costs.
• The instrumentation for reverse scan is partial. The SeekLTs are being counted, but I don't see the p.parent.Prev calls being counted. I think this relates to the above fragility.

I would prefer a lower-level instrumentation point to which we can add more over time.

• Add numSeeks, numNexts, numPrevs to the existing storage.IteratorStats,
• Change pebbleIterator to track these and reset these on Close (even if the iterator is reusable).
• The one other real implementation of MVCCIterator (other than pebbleIterator) is intentInterleavingIter. It uses an MVCCIterator and an EngineIterator both of which are implemented by pebbleIterator. We can add the Stats method to the EngineIterator interface, and sum the two stats when returning to the caller.

[jordanlewis]

Thanks for the review! Definitely it makes sense that these basic counters are too simplistic. I think it would make sense for you or one of the storage team members to take on the task of doing the iteration stats correctly - I don't really know what is going on too well at this part of the stack. I'm happy to keep banging away on this on Fridays but realistically it will take a long time that way :)

I wonder, is there some kind of low hanging fruit that could start stats collection off on the right foot but still provide some basic metrics to the user of whether the scan was slower than expected due to MVCC garbage?

[sumeerbhola]

I wonder, is there some kind of low hanging fruit that could start stats collection off on the right foot but still provide some basic metrics to the user of whether the scan was slower than expected due to MVCC garbage?

I added some stuff to Pebble in cockroachdb/pebble#1129. I'll follow that up with a change to the MVCCIterator implementations. And then I am hoping you can rebase this PR to use those.

The way I am currently thinking about this is that if the number of seeks or steps on the pebble.Iterator is high compared to the number of keys returned in the MVCCScan, then the likely cause is a high number of versions (we switch from doing next to doing seek in a dynamic manner based on the number of versions we are seeing). And if the number of steps on the lower-level iterator (internalIterator) in Pebble is high that suggests we are encountering a lot of deletes or stale Pebble versions that have not been compacted away (this has also been a problem sometimes, in production). None of this is precise counting of the number of versions (MVCC or Pebble) but should give strong hints regarding the source of the problem when encountering slowness.

[jordanlewis]

Very awesome, thank you for turning this around in Pebble so quickly. Will be happy to rebase to use your work soon.

The heuristic you describe makes some sense to me. Perhaps we could expose these quantities as multipliers, and if the multiplier is high enough, perhaps we could emit some kind of warning.

[sumeerbhola]

Hopefully

cockroach/pkg/storage/engine.go

Lines 90 to 105 in f5b21cf

	// Iteration stats. We directly expose pebble.IteratorStats. Callers
	// may want to aggregate and interpret these in the following manner:
	// - Aggregate {Forward,Reverse}SeekCount, {Forward,Reverse}StepCount.
	// - Interpret the four aggregated stats as follows:
	// - {SeekCount,StepCount}[InterfaceCall]: We can refer to these simply as
	// {SeekCount,StepCount} in logs/metrics/traces. These represents
	// explicit calls by the implementation of MVCCIterator, in response to
	// the caller of MVCCIterator. A high count relative to the unique MVCC
	// keys returned suggests there are many versions for the same key.
	// - {SeekCount,StepCount}[InternalIterCall]: We can refer to these simply
	// as {InternalSeekCount,InternalStepCount}. If these are significantly
	// larger than the ones in the preceding bullet, it suggests that there
	// are lots of uncompacted deletes or stale Pebble-versions (not to be
	// confused with MVCC versions) that need to be compacted away. This
	// should be very rare, but has been observed.
	Stats pebble.IteratorStats

, which just merged, can unblock you.

Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @jordanlewis)

[jordanlewis]

Thanks for the updated stats @sumeerbhola! I redid this commit based on your recommendations. So far, we don't attempt any heuristics to determine when to display steps/seeks - we always display the "interface" steps/seeks, and display the "internal" steps/seeks when the verbose flag is used.

We'll probably want to do better here, but for now it's good to get the data out there at least, I think.

[sumeerbhola]

Looks good, with some minor comments, plus why the seek and step stats are all 0.
I didn't look very carefully at the plumbing.

Reviewed 1 of 25 files at r3, 10 of 25 files at r4.
Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @jordanlewis)

---

pkg/roachpb/api.go, line 1542 at r4 (raw file):

// SafeFormat implements redact.SafeFormatter.
func (s *ScanStats) SafeFormat(w redact.SafePrinter, _ rune) {
	w.Printf("scan stats: stepped %d times (%d internal); sought %d times (%d internal)",

seeked?
sought will be confusing I think.

---

pkg/sql/execinfrapb/component_stats.proto, line 134 at r4 (raw file):

  optional util.optional.Duration contention_time = 4 [(gogoproto.nullable) = false];

  optional util.optional.Uint num_interface_steps = 5 [(gogoproto.nullable) = false];

can we just embed roachpb.ScanStats here?

---

pkg/sql/logictest/testdata/logic_test/dist_vectorize, line 74 at r4 (raw file):

      KV rows read: 5
      KV bytes read: 40 B
      MVCC step count: 0

do you know why these counts are 0? We must have done at least 1 seek to position the pebble.Iterator. Perhaps something wrong in the plumbing?

[Azhng]

Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @jordanlewis)

---

pkg/sql/execinfra/stats.go, line 64 at r4 (raw file):

// PopulateKVStats adds data from the input ScanStats to the input KVStats.
func PopulateKVStats(kvStats *execinfrapb.KVStats, ss *ScanStats) {

nit: perhaps 'PopulateKVScanStats' or 'PopulateKVMVCCStats' ?

---

pkg/sql/execinfrapb/component_stats.go, line 325 at r4 (raw file):

	timeVal(&s.KV.KVTime)
	timeVal(&s.KV.ContentionTime)
	resetUint(&s.KV.StepCount)

Are these stats something non-deterministic? If so, perhaps we should override it with a useful value like what we do with s.KV.BytesRead

---

pkg/sql/row/kv_fetcher.go, line 143 at r4 (raw file):

		f.newSpan = true
		nBytes := len(f.batchResponse)
		for i := range f.kvs {

Hmm, is this change related to tracking MVCC stats? Or it's a bug fix to our accoutning for bytesRead ?

[jordanlewis]

Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @Azhng, @jordanlewis, and @sumeerbhola)

---

pkg/sql/logictest/testdata/logic_test/dist_vectorize, line 74 at r4 (raw file):

Previously, sumeerbhola wrote…

do you know why these counts are 0? We must have done at least 1 seek to position the pebble.Iterator. Perhaps something wrong in the plumbing?

We set values like this to 0 in test output because it's nondeterministic when run in a logic test.

---

pkg/sql/row/kv_fetcher.go, line 143 at r4 (raw file):

Previously, Azhng (Archer Zhang) wrote…

Hmm, is this change related to tracking MVCC stats? Or it's a bug fix to our accoutning for bytesRead ?

It was just a small improvement to the way we were tracking bytesRead. I think it's a small bugfix too, but most of the time we don't use the old kvs format so things were right before.

[jordanlewis]

Dismissed @sumeerbhola from a discussion.
Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @Azhng and @sumeerbhola)

---

pkg/roachpb/api.go, line 1542 at r4 (raw file):

Previously, sumeerbhola wrote…

seeked?
sought will be confusing I think.

Done. Yeah this was sort of silly.

---

pkg/sql/execinfra/stats.go, line 64 at r4 (raw file):

Previously, Azhng (Archer Zhang) wrote…

nit: perhaps 'PopulateKVScanStats' or 'PopulateKVMVCCStats' ?

Done.

---

pkg/sql/execinfrapb/component_stats.go, line 325 at r4 (raw file):

Previously, Azhng (Archer Zhang) wrote…

Are these stats something non-deterministic? If so, perhaps we should override it with a useful value like what we do with s.KV.BytesRead

Yes, these are non-deterministic in logic tests. Not sure what useful value we'd have here.

---

pkg/sql/execinfrapb/component_stats.proto, line 134 at r4 (raw file):

Previously, sumeerbhola wrote…

can we just embed roachpb.ScanStats here?

Unfortunately we can't, assuming we want to follow the pattern in this file, because the roachpb.ScanStats use ordinary primitive uint32s, whereas things in this protobuf use this util.optional.Uint thing which as I understand gets around the inability to distinguish 0 from not-present in protobuf otherwise.

[sumeerbhola]

Reviewed 1 of 26 files at r6.
Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @Azhng, @jordanlewis, and @sumeerbhola)

---

pkg/sql/logictest/testdata/logic_test/dist_vectorize, line 74 at r4 (raw file):

Previously, jordanlewis (Jordan Lewis) wrote…

We set values like this to 0 in test output because it's nondeterministic when run in a logic test.

Is there any test that validates that the end-to-end plumbing is working ok? If not, I think it is worth having one test.
And was there a particular count you were seeing the non-determinism in? I would expect that a single node setup with a simple table with a single version for each key should be deterministic for these counts -- these are not really affected by the shape of the LSM since they are generated by operations in the top-level iterator which does not see the details of the underlying merging iterator.

[jordanlewis]

Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @Azhng and @sumeerbhola)

---

pkg/sql/logictest/testdata/logic_test/dist_vectorize, line 74 at r4 (raw file):

Previously, sumeerbhola wrote…

Is there any test that validates that the end-to-end plumbing is working ok? If not, I think it is worth having one test.
And was there a particular count you were seeing the non-determinism in? I would expect that a single node setup with a simple table with a single version for each key should be deterministic for these counts -- these are not really affected by the shape of the LSM since they are generated by operations in the top-level iterator which does not see the details of the underlying merging iterator.

Yeah, I've added a test.

The non-determinism comes into play because these tests are run on several different configurations of distribution. Agreed, on a fixed cluster type there should be no nondeterminism.

[jordanlewis]

Thanks for the reviews!

[Azhng]

Reviewable status: complete! 0 of 0 LGTMs obtained (and 1 stale) (waiting on @jordanlewis, @RaduBerinde, and @sumeerbhola)

---

pkg/sql/explain_test.go, line 345 at r11 (raw file):

	foundSteps, foundSeeks := getMVCCStats(t, r)

	assert.Equal(t, expectedSteps, foundSteps)

Seems like we are having a mix of assert.Equal() vs require.Equal() in our testing code, is there a preference for one over another?

[jordanlewis]

bors r+

[craig]

Build succeeded:

• GitHub CI (Cockroach)

[yuzefovich]

Reviewable status: complete! 0 of 0 LGTMs obtained (and 1 stale)

---

pkg/sql/rowexec/joinreader.go, line 886 at r14 (raw file):

func (jr *joinReader) close() {
	// Make sure to clone any tracing span so that stats can pick it up later.

I don't understand why we're fetching the scan stats in different places in the row-by-row processors - I would expect for all four disk-reading processors we would have exactly the same new logic, why is this not the case?