storage,roachpb: surface iterator {cached,} block counts in traces

DEPS.bzl

@@ -1347,10 +1347,10 @@ def go_deps():
         patches = [
             "@com_github_cockroachdb_cockroach//build/patches:com_github_cockroachdb_pebble.patch",
         ],
-        sha256 = "d9f3208c0bb38558acffd03addd6a057891665dc58c47c07ef0a4c8c6bfbb130",
-        strip_prefix = "github.com/cockroachdb/pebble@v0.0.0-20220523221036-bb2c1501ac23",
+        sha256 = "f03791e985a1a9c15577211970ffda2774af31f84a04779404131784a7aaff08",
+        strip_prefix = "github.com/cockroachdb/pebble@v0.0.0-20220527214922-41ca3d28dd09",
         urls = [
-            "https://storage.googleapis.com/cockroach-godeps/gomod/github.com/cockroachdb/pebble/com_github_cockroachdb_pebble-v0.0.0-20220523221036-bb2c1501ac23.zip",
+            "https://storage.googleapis.com/cockroach-godeps/gomod/github.com/cockroachdb/pebble/com_github_cockroachdb_pebble-v0.0.0-20220527214922-41ca3d28dd09.zip",
         ],
     )
     go_repository(
@@ -4001,10 +4001,10 @@ def go_deps():
         name = "com_github_hdrhistogram_hdrhistogram_go",
         build_file_proto_mode = "disable_global",
         importpath = "github.com/HdrHistogram/hdrhistogram-go",
-        sha256 = "12281e93a8cf983caec3286e00eadb1475bddad684226015ab96979012f55ac9",
-        strip_prefix = "github.com/HdrHistogram/hdrhistogram-go@v1.1.0",
+        sha256 = "bbc1d64d3179248c78ffa3729ad2ab696ed1ff14874f37d8d4fc4a5a235fa77f",
+        strip_prefix = "github.com/HdrHistogram/hdrhistogram-go@v1.1.2",
         urls = [
-            "https://storage.googleapis.com/cockroach-godeps/gomod/github.com/HdrHistogram/hdrhistogram-go/com_github_hdrhistogram_hdrhistogram_go-v1.1.0.zip",
+            "https://storage.googleapis.com/cockroach-godeps/gomod/github.com/HdrHistogram/hdrhistogram-go/com_github_hdrhistogram_hdrhistogram_go-v1.1.2.zip",
         ],
     )
     go_repository(

build/bazelutil/distdir_files.bzl

@@ -43,7 +43,7 @@ DISTDIR_FILES = {
     "https://storage.googleapis.com/cockroach-godeps/gomod/github.com/DataDog/zstd/com_github_datadog_zstd-v1.5.0.zip": "00989c1f3f3426aa6ed41f641193ff6a0d81031ba0b7fd81250e7e923d2f18a4",
     "https://storage.googleapis.com/cockroach-godeps/gomod/github.com/GeertJohan/go.incremental/com_github_geertjohan_go_incremental-v1.0.0.zip": "ce46b3b717f8d2927046bcfb99c6f490b1b547a681e6b23240ac2c2292a891e8",
     "https://storage.googleapis.com/cockroach-godeps/gomod/github.com/GeertJohan/go.rice/com_github_geertjohan_go_rice-v1.0.0.zip": "2fc48b9422bf356c18ed3fe32ec52f6a8b87ac168f83d2eed249afaebcc3eeb8",
-    "https://storage.googleapis.com/cockroach-godeps/gomod/github.com/HdrHistogram/hdrhistogram-go/com_github_hdrhistogram_hdrhistogram_go-v1.1.0.zip": "12281e93a8cf983caec3286e00eadb1475bddad684226015ab96979012f55ac9",
+    "https://storage.googleapis.com/cockroach-godeps/gomod/github.com/HdrHistogram/hdrhistogram-go/com_github_hdrhistogram_hdrhistogram_go-v1.1.2.zip": "bbc1d64d3179248c78ffa3729ad2ab696ed1ff14874f37d8d4fc4a5a235fa77f",
     "https://storage.googleapis.com/cockroach-godeps/gomod/github.com/Joker/hpp/com_github_joker_hpp-v1.0.0.zip": "790dc3cfb8e51ff22f29d74b5b58782999e267e86290bc2b52485ccf9c8d2792",
     "https://storage.googleapis.com/cockroach-godeps/gomod/github.com/Joker/jade/com_github_joker_jade-v1.0.1-0.20190614124447-d475f43051e7.zip": "3fc31c80e93cb053cd4fce60a7288e3760f9fe5c571ec4c2d32c4f9bf6c487e7",
     "https://storage.googleapis.com/cockroach-godeps/gomod/github.com/Julusian/godocdown/com_github_julusian_godocdown-v0.0.0-20170816220326-6d19f8ff2df8.zip": "1bd26f1d29b20d40b3eb0a5678691a2e6e153c473efe079b8b1bbd97a7cc1f57",
@@ -179,7 +179,7 @@ DISTDIR_FILES = {
     "https://storage.googleapis.com/cockroach-godeps/gomod/github.com/cockroachdb/go-test-teamcity/com_github_cockroachdb_go_test_teamcity-v0.0.0-20191211140407-cff980ad0a55.zip": "bac30148e525b79d004da84d16453ddd2d5cd20528e9187f1d7dac708335674b",
     "https://storage.googleapis.com/cockroach-godeps/gomod/github.com/cockroachdb/gostdlib/com_github_cockroachdb_gostdlib-v1.13.0.zip": "b3d43d8f95edf65f73a5348f29e1159823cac64b148f8d3bb48340bf55d70872",
     "https://storage.googleapis.com/cockroach-godeps/gomod/github.com/cockroachdb/logtags/com_github_cockroachdb_logtags-v0.0.0-20211118104740-dabe8e521a4f.zip": "1972c3f171f118add3fd9e64bcea6cbb9959a3b7fa0ada308e8a7310813fea74",
-    "https://storage.googleapis.com/cockroach-godeps/gomod/github.com/cockroachdb/pebble/com_github_cockroachdb_pebble-v0.0.0-20220523221036-bb2c1501ac23.zip": "d9f3208c0bb38558acffd03addd6a057891665dc58c47c07ef0a4c8c6bfbb130",
+    "https://storage.googleapis.com/cockroach-godeps/gomod/github.com/cockroachdb/pebble/com_github_cockroachdb_pebble-v0.0.0-20220527214922-41ca3d28dd09.zip": "f03791e985a1a9c15577211970ffda2774af31f84a04779404131784a7aaff08",
     "https://storage.googleapis.com/cockroach-godeps/gomod/github.com/cockroachdb/redact/com_github_cockroachdb_redact-v1.1.3.zip": "7778b1e4485e4f17f35e5e592d87eb99c29e173ac9507801d000ad76dd0c261e",
     "https://storage.googleapis.com/cockroach-godeps/gomod/github.com/cockroachdb/returncheck/com_github_cockroachdb_returncheck-v0.0.0-20200612231554-92cdbca611dd.zip": "ce92ba4352deec995b1f2eecf16eba7f5d51f5aa245a1c362dfe24c83d31f82b",
     "https://storage.googleapis.com/cockroach-godeps/gomod/github.com/cockroachdb/sentry-go/com_github_cockroachdb_sentry_go-v0.6.1-cockroachdb.2.zip": "fbb2207d02aecfdd411b1357efe1192dbb827959e36b7cab7491731ac55935c9",

go.mod

@@ -47,7 +47,7 @@ require (
 	github.com/cockroachdb/go-test-teamcity v0.0.0-20191211140407-cff980ad0a55
 	github.com/cockroachdb/gostdlib v1.13.0
 	github.com/cockroachdb/logtags v0.0.0-20211118104740-dabe8e521a4f
-	github.com/cockroachdb/pebble v0.0.0-20220523221036-bb2c1501ac23
+	github.com/cockroachdb/pebble v0.0.0-20220527214922-41ca3d28dd09
 	github.com/cockroachdb/redact v1.1.3
 	github.com/cockroachdb/returncheck v0.0.0-20200612231554-92cdbca611dd
 	github.com/cockroachdb/stress v0.0.0-20220310203902-58fb4627376e
@@ -186,6 +186,7 @@ require (
 	github.com/Azure/go-autorest/autorest/validation v0.3.1 // indirect
 	github.com/Azure/go-autorest/logger v0.2.1 // indirect
 	github.com/Azure/go-autorest/tracing v0.6.0 // indirect
+	github.com/HdrHistogram/hdrhistogram-go v1.1.2 // indirect
 	github.com/Masterminds/goutils v1.1.0 // indirect
 	github.com/Masterminds/semver v1.5.0 // indirect
 	github.com/Masterminds/sprig v2.22.0+incompatible // indirect

go.sum

@@ -170,6 +170,8 @@ github.com/DataDog/zstd v1.5.0/go.mod h1:g4AWEaM3yOg3HYfnJ3YIawPnVdXJh9QME85blwS
 github.com/GeertJohan/go.incremental v1.0.0/go.mod h1:6fAjUhbVuX1KcMD3c8TEgVUqmo4seqhv0i0kdATSkM0=
 github.com/GeertJohan/go.rice v1.0.0/go.mod h1:eH6gbSOAUv07dQuZVnBmoDP8mgsM1rtixis4Tib9if0=
 github.com/HdrHistogram/hdrhistogram-go v1.1.0/go.mod h1:yDgFjdqOqDEKOvasDdhWNXYg9BVp4O+o5f6V/ehm6Oo=
+github.com/HdrHistogram/hdrhistogram-go v1.1.2 h1:5IcZpTvzydCQeHzK4Ef/D5rrSqwxob0t8PQPMybUNFM=
+github.com/HdrHistogram/hdrhistogram-go v1.1.2/go.mod h1:yDgFjdqOqDEKOvasDdhWNXYg9BVp4O+o5f6V/ehm6Oo=
 github.com/Joker/hpp v1.0.0/go.mod h1:8x5n+M1Hp5hC0g8okX3sR3vFQwynaX/UgSOM9MeBKzY=
 github.com/Joker/jade v1.0.1-0.20190614124447-d475f43051e7/go.mod h1:6E6s8o2AE4KhCrqr6GRJjdC/gNfTdxkIXvuGZZda2VM=
 github.com/Julusian/godocdown v0.0.0-20170816220326-6d19f8ff2df8/go.mod h1:INZr5t32rG59/5xeltqoCJoNY7e5x/3xoY9WSWVWg74=
@@ -453,8 +455,8 @@ github.com/cockroachdb/gostdlib v1.13.0/go.mod h1:eXX95p9QDrYwJfJ6AgeN9QnRa/lqqi
 github.com/cockroachdb/logtags v0.0.0-20190617123548-eb05cc24525f/go.mod h1:i/u985jwjWRlyHXQbwatDASoW0RMlZ/3i9yJHE2xLkI=
 github.com/cockroachdb/logtags v0.0.0-20211118104740-dabe8e521a4f h1:6jduT9Hfc0njg5jJ1DdKCFPdMBrp/mdZfCpa5h+WM74=
 github.com/cockroachdb/logtags v0.0.0-20211118104740-dabe8e521a4f/go.mod h1:Vz9DsVWQQhf3vs21MhPMZpMGSht7O/2vFW2xusFUVOs=
-github.com/cockroachdb/pebble v0.0.0-20220523221036-bb2c1501ac23 h1:/Pvbuwd61qRxNCIpSIWbx7Oqy1tinfErdetF91DU9gQ=
-github.com/cockroachdb/pebble v0.0.0-20220523221036-bb2c1501ac23/go.mod h1:buxOO9GBtOcq1DiXDpIPYrmxY020K2A8lOrwno5FetU=
+github.com/cockroachdb/pebble v0.0.0-20220527214922-41ca3d28dd09 h1:R3H3yArk8mtbqa06fqnA6he9ESDUYo7ulHENEE5/rfc=
+github.com/cockroachdb/pebble v0.0.0-20220527214922-41ca3d28dd09/go.mod h1:pr479tNxFRmcfDyklTqoRMDDVmRlEbL+d7a7rhKnrI4=
 github.com/cockroachdb/redact v1.0.8/go.mod h1:BVNblN9mBWFyMyqK1k3AAiSxhvhfK2oOZZ2lK+dpvRg=
 github.com/cockroachdb/redact v1.1.3 h1:AKZds10rFSIj7qADf0g46UixK8NNLwWTNdCIGS5wfSQ=
 github.com/cockroachdb/redact v1.1.3/go.mod h1:BVNblN9mBWFyMyqK1k3AAiSxhvhfK2oOZZ2lK+dpvRg=
@@ -2781,6 +2783,7 @@ gonum.org/v1/gonum v0.0.0-20180816165407-929014505bf4/go.mod h1:Y+Yx5eoAFn32cQvJ
 gonum.org/v1/gonum v0.0.0-20181121035319-3f7ecaa7e8ca/go.mod h1:Y+Yx5eoAFn32cQvJDxZx5Dpnq+c3wtXuadVZAcxbbBo=
 gonum.org/v1/gonum v0.0.0-20190331200053-3d26580ed485/go.mod h1:2ltnJ7xHfj0zHS40VVPYEAAMTa3ZGguvHGBSJeRWqE0=
 gonum.org/v1/gonum v0.6.0/go.mod h1:9mxDZsDKxgMAuccQkewq682L+0eCu4dCN2yonUJTCLU=
+gonum.org/v1/gonum v0.8.2 h1:CCXrcPKiGGotvnN6jfUsKk4rRqm7q09/YbKb5xCEvtM=
 gonum.org/v1/gonum v0.8.2/go.mod h1:oe/vMfY3deqTw+1EZJhuvEW2iwGF1bW9wwu7XCu0+v0=
 gonum.org/v1/netlib v0.0.0-20181029234149-ec6d1f5cefe6/go.mod h1:wa6Ws7BG/ESfp6dHfk7C6KdzKA7wR7u/rKwOGE66zvw=
 gonum.org/v1/netlib v0.0.0-20190313105609-8cb42192e0e0/go.mod h1:wa6Ws7BG/ESfp6dHfk7C6KdzKA7wR7u/rKwOGE66zvw=

pkg/kv/kvserver/concurrency/concurrency_manager.go

@@ -125,6 +125,7 @@ type Config struct {
 	// Metrics.
 	TxnWaitMetrics *txnwait.Metrics
 	SlowLatchGauge *metric.Gauge
+	LatchWaitTime  *metric.Histogram
 	// Configs + Knobs.
 	MaxLockTableSize  int64
 	DisableTxnPushing bool
@@ -151,6 +152,7 @@ func NewManager(cfg Config) Manager {
 			m: spanlatch.Make(
 				cfg.Stopper,
 				cfg.SlowLatchGauge,
+				cfg.LatchWaitTime,
 			),
 		},
 		lt: lt,

pkg/kv/kvserver/metrics.go

@@ -1248,6 +1248,13 @@ A nonzero value indicates range or replica unavailability, and should be investi
 		Unit:        metric.Unit_COUNT,
 	}
 
+	metaLatchWaitLatency = metric.Metadata{
+		Name:        "requests.latch.wait_time",
+		Help:        "Latency histogram of time spent waiting for latch acquisitions",
+		Measurement: "Latch wait time",
+		Unit:        metric.Unit_NANOSECONDS,
+	}
+
 	// Backpressure metrics.
 	metaBackpressuredOnSplitRequests = metric.Metadata{
 		Name: "requests.backpressure.split",
@@ -1618,6 +1625,9 @@ type StoreMetrics struct {
 	SlowLeaseRequests *metric.Gauge
 	SlowRaftRequests  *metric.Gauge
 
+	// Latch wait time.
+	LatchWaitTime *metric.Histogram
+
 	// Backpressure counts.
 	BackpressuredOnSplitRequests *metric.Gauge
 
@@ -2090,6 +2100,8 @@ func newStoreMetrics(histogramWindow time.Duration) *StoreMetrics {
 		SlowLeaseRequests: metric.NewGauge(metaSlowLeaseRequests),
 		SlowRaftRequests:  metric.NewGauge(metaSlowRaftRequests),
 
+		LatchWaitTime: metric.NewLatency(metaLatchWaitLatency, histogramWindow),
+
 		// Backpressure counters.
 		BackpressuredOnSplitRequests: metric.NewGauge(metaBackpressuredOnSplitRequests),
 

pkg/kv/kvserver/replica_init.go

@@ -87,6 +87,7 @@ func newUnloadedReplica(
 			IntentResolver:    store.intentResolver,
 			TxnWaitMetrics:    store.txnWaitMetrics,
 			SlowLatchGauge:    store.metrics.SlowLatchRequests,
+			LatchWaitTime:     store.metrics.LatchWaitTime,
 			DisableTxnPushing: store.TestingKnobs().DontPushOnWriteIntentError,
 			TxnWaitKnobs:      store.TestingKnobs().TxnWaitKnobs,
 		}),

pkg/kv/kvserver/spanlatch/manager.go

@@ -13,6 +13,7 @@ package spanlatch
 import (
 	"context"
 	"fmt"
+	"time"
 	"unsafe"
 
 	"github.com/cockroachdb/cockroach/pkg/base"
@@ -61,8 +62,9 @@ type Manager struct {
 	idAlloc uint64
 	scopes  [spanset.NumSpanScope]scopedManager
 
-	stopper  *stop.Stopper
-	slowReqs *metric.Gauge
+	stopper       *stop.Stopper
+	slowReqs      *metric.Gauge
+	latchWaitTime *metric.Histogram
 }
 
 // scopedManager is a latch manager scoped to either local or global keys.
@@ -74,10 +76,11 @@ type scopedManager struct {
 
 // Make returns an initialized Manager. Using this constructor is optional as
 // the type's zero value is valid to use directly.
-func Make(stopper *stop.Stopper, slowReqs *metric.Gauge) Manager {
+func Make(stopper *stop.Stopper, slowReqs *metric.Gauge, latchWaitTime *metric.Histogram) Manager {
 	return Manager{
-		stopper:  stopper,
-		slowReqs: slowReqs,
+		stopper:       stopper,
+		slowReqs:      slowReqs,
+		latchWaitTime: latchWaitTime,
 	}
 }
 
@@ -506,6 +509,7 @@ func (m *Manager) iterAndWait(
 	wait *latch,
 	ignore ignoreFn,
 ) error {
+	recordLatchWaitTime := m.latchWaitTime != nil
 	for it.FirstOverlap(wait); it.Valid(); it.NextOverlap(wait) {
 		held := it.Cur()
 		if held.done.signaled() {
@@ -514,9 +518,17 @@ func (m *Manager) iterAndWait(
 		if ignore(wait.ts, held.ts) {
 			continue
 		}
+
+		var tBegin time.Time
+		if recordLatchWaitTime {
+			tBegin = timeutil.Now()
+		}
 		if err := m.waitForSignal(ctx, t, pp, waitType, heldType, wait, held); err != nil {
 			return err
 		}
+		if recordLatchWaitTime {
+			m.latchWaitTime.RecordValue(timeutil.Since(tBegin).Nanoseconds())
+		}
 	}
 	return nil
 }

pkg/roachpb/api.go

@@ -12,6 +12,7 @@ package roachpb
 
 import (
 	"fmt"
+	"strings"
 
 	"github.com/cockroachdb/cockroach/pkg/kv/kvserver/concurrency/lock"
 	"github.com/cockroachdb/cockroach/pkg/util/hlc"
@@ -1762,22 +1763,24 @@ func (c *TenantConsumption) Sub(other *TenantConsumption) {
 	}
 }
 
-func humanizePointCount(n uint64) redact.SafeString {
-	return redact.SafeString(humanize.SI(float64(n), ""))
+func humanizeCount(n uint64) redact.SafeString {
+	return redact.SafeString(strings.TrimSpace(humanize.SI(float64(n), "")))
 }
 
 // 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); "+
-		"block-bytes: (total %s, cached %s); "+
+		"blocks: (count %s, cached-count %s, bytes %s, cached-bytes %s); "+
 		"points: (count %s, key-bytes %s, value-bytes %s, tombstoned: %s)",
 		s.NumInterfaceSteps, s.NumInternalSteps, s.NumInterfaceSeeks, s.NumInternalSeeks,
+		humanizeCount(s.Blocks),
+		humanizeCount(s.BlocksInCache),
 		humanizeutil.IBytes(int64(s.BlockBytes)),
 		humanizeutil.IBytes(int64(s.BlockBytesInCache)),
-		humanizePointCount(s.PointCount),
+		humanizeCount(s.PointCount),
 		humanizeutil.IBytes(int64(s.KeyBytes)),
 		humanizeutil.IBytes(int64(s.ValueBytes)),
-		humanizePointCount(s.PointsCoveredByRangeTombstones))
+		humanizeCount(s.PointsCoveredByRangeTombstones))
 }
 
 // String implements fmt.Stringer.

pkg/roachpb/api.proto

@@ -3013,10 +3013,14 @@ message ScanStats {
   uint64 num_internal_steps = 4;
   // Lower-level stats for the scan. See pebble.InternalIteratorStats for the
   // meaning of these.
+  uint64 blocks = 11;
   uint64 block_bytes = 5;
+  uint64 blocks_in_cache = 12;
   uint64 block_bytes_in_cache = 6;
   uint64 key_bytes = 7;
   uint64 value_bytes = 8;
   uint64 point_count = 9;
   uint64 points_covered_by_range_tombstones = 10;
+
+  // NEXTID: 13.
 }

pkg/sql/execstats/stats.go

@@ -56,8 +56,9 @@ func GetCumulativeContentionTime(ctx context.Context) time.Duration {
 // 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.
-// TODO(sql-observability): include other fields that are in roachpb.ScanStats,
-// here and in execinfrapb.KVStats.
+// TODO(sql-observability): Include other fields that are in roachpb.ScanStats,
+// here and in execinfrapb.KVStats. Perhaps embed roachpb.ScanStats directly
+// instead.
 type ScanStats struct {
 	// NumInterfaceSteps is the number of times the MVCC step function was called
 	// to satisfy a scan.

pkg/storage/mvcc.go

@@ -2285,7 +2285,9 @@ func recordIteratorStats(traceSpan *tracing.Span, iteratorStats IteratorStats) {
 			NumInternalSeeks:               uint64(internalSeeks),
 			NumInterfaceSteps:              uint64(steps),
 			NumInternalSteps:               uint64(internalSteps),
+			Blocks:                         stats.InternalStats.Blocks,
 			BlockBytes:                     stats.InternalStats.BlockBytes,
+			BlocksInCache:                  stats.InternalStats.BlocksInCache,
 			BlockBytesInCache:              stats.InternalStats.BlockBytesInCache,
 			KeyBytes:                       stats.InternalStats.KeyBytes,
 			ValueBytes:                     stats.InternalStats.ValueBytes,

pkg/ts/catalog/chart_catalog.go

@@ -1005,6 +1005,11 @@ var charts = []sectionDescription{
 				Rate:        DescribeDerivative_NON_NEGATIVE_DERIVATIVE,
 				Metrics:     []string{"kv.replica_circuit_breaker.num_tripped_events"},
 			},
+			{
+				Title:     "Latency histogram of time spent waiting for latch acquisitions",
+				Metrics:   []string{"requests.latch.wait_time"},
+				AxisLabel: "Latch Wait Time",
+			},
 		},
 	},
 	{