Repository: cockroachdb/pebble

Issue:
db: better observability for slow ingests
An ingest produces a `TableIngestInfo` for the `EventListener`, that in CockroachDB is directed to the Pebble log. When an ingest operation is slow, it is not obvious why it was slow. We should measure and include these durations in the `TableIngestInfo` event. For example:
- how long did it spend waiting for memtable flushes: this would have made diagnosing https://github.com/cockroachdb/pebble/issues/4944 trivial.
- The total time spent in reading blocks for the various iterators it opened, as represented by the sum of `InternalIteratorStats.BlockReadDuration`, and the number of blocks read `InternalIteratorStats.BlockBytes-InternalIteratorStats.BlockBytesInCache`.
- The time spent in updating the MANIFEST.

We were unable to diagnose the root cause of https://github.com/cockroachdb/cockroach/issues/148337#issuecomment-2993053472, and having the above would have helped.

Jira issue: PEBBLE-506

Hints from issue comments:

Solution patch:
diff --git a/blob_rewrite.go b/blob_rewrite.go
index db77ceec..cb13ce58 100644
--- a/blob_rewrite.go
+++ b/blob_rewrite.go
@@ -175,7 +175,7 @@ func (c *blobFileRewriteCompaction) Execute(jobID JobID, d *DB) error {
 		info.Output.DiskFileNum = ve.NewBlobFiles[0].Physical.FileNum
 		info.Output.Size = ve.NewBlobFiles[0].Physical.Size
 		info.Output.ValueSize = ve.NewBlobFiles[0].Physical.ValueSize
-		err = d.mu.versions.UpdateVersionLocked(func() (versionUpdate, error) {
+		_, err = d.mu.versions.UpdateVersionLocked(func() (versionUpdate, error) {
 			// It's possible that concurrent compactions removed references to
 			// the blob file while the blob file rewrite compaction was running.
 			// Now that we have the manifest lock, check if the blob file is
diff --git a/compaction.go b/compaction.go
index 9d18d0ef..955a48cb 100644
--- a/compaction.go
+++ b/compaction.go
@@ -1739,7 +1739,7 @@ func (d *DB) flush1() (bytesFlushed uint64, err error) {
 		ve, stats, compactionErr = d.runCompaction(jobID, c)
 	}
 
-	err = d.mu.versions.UpdateVersionLocked(func() (versionUpdate, error) {
+	_, err = d.mu.versions.UpdateVersionLocked(func() (versionUpdate, error) {
 		err := compactionErr
 		if c.kind == compactionKindIngestedFlushable {
 			ve, err = d.runIngestFlush(c)
@@ -2697,7 +2697,7 @@ func (d *DB) compact1(jobID JobID, c *tableCompaction) (err error) {
 	info.Duration = d.timeNow().Sub(startTime)
 	if err == nil {
 		validateVersionEdit(ve, d.opts.Comparer.ValidateKey, d.opts.Comparer.FormatKey, d.opts.Logger)
-		err = d.mu.versions.UpdateVersionLocked(func() (versionUpdate, error) {
+		_, err = d.mu.versions.UpdateVersionLocked(func() (versionUpdate, error) {
 			// Check if this compaction had a conflicting operation (eg. a d.excise())
 			// that necessitates it restarting from scratch. Note that since we hold
 			// the manifest lock, we don't expect this bool to change its value
diff --git a/event.go b/event.go
index 8c1c85c7..3006f5b1 100644
--- a/event.go
+++ b/event.go
@@ -535,6 +535,18 @@ type TableIngestInfo struct {
 	// flushable.
 	flushable bool
 	Err       error
+	// WaitFlushDuration is the time spent waiting for memtable flushes to
+	// complete, given that an overlap between ingesting sstables and memtables
+	// exists.
+	WaitFlushDuration time.Duration
+	// ManifestUpdateDuration is the time spent updating the manifest.
+	ManifestUpdateDuration time.Duration
+	// BlockReadDuration is the total time spent reading blocks for the ingested
+	// sstable.
+	BlockReadDuration time.Duration
+	// BlockReadBytes is the total number of bytes from blocks read for the
+	// ingested sstable. This does not include bytes read from the block cache.
+	BlockReadBytes uint64
 }
 
 func (i TableIngestInfo) String() string {
@@ -549,7 +561,8 @@ func (i TableIngestInfo) SafeFormat(w redact.SafePrinter, _ rune) {
 	}
 
 	if i.flushable {
-		w.Printf("[JOB %d] ingested as flushable", redact.Safe(i.JobID))
+		w.Printf("[JOB %d] ingested as flushable, memtable flushes took %.1fs:", redact.Safe(i.JobID),
+			redact.Safe(i.WaitFlushDuration.Seconds()))
 	} else {
 		w.Printf("[JOB %d] ingested", redact.Safe(i.JobID))
 	}
@@ -566,6 +579,9 @@ func (i TableIngestInfo) SafeFormat(w redact.SafePrinter, _ rune) {
 		w.Printf(" %s%s (%s)", redact.Safe(levelStr), t.FileNum,
 			redact.Safe(humanize.Bytes.Uint64(t.Size)))
 	}
+	w.Printf("; manifest update took %.1fs; block reads took %.1fs with %s block bytes read",
+		redact.Safe(i.ManifestUpdateDuration.Seconds()), redact.Safe(i.BlockReadDuration.Seconds()),
+		redact.Safe(humanize.Bytes.Uint64(i.BlockReadBytes)))
 }
 
 // TableStatsInfo contains the info for a table stats loaded event.
diff --git a/format_major_version.go b/format_major_version.go
index b37f53f6..fedcbfec 100644
--- a/format_major_version.go
+++ b/format_major_version.go
@@ -612,7 +612,7 @@ func (d *DB) markFilesLocked(findFn findFilesFunc) error {
 
 	// Lock the manifest for a coherent view of the LSM. The database lock has
 	// been re-acquired by the defer within the above anonymous function.
-	return d.mu.versions.UpdateVersionLocked(func() (versionUpdate, error) {
+	_, err = d.mu.versions.UpdateVersionLocked(func() (versionUpdate, error) {
 		vers := d.mu.versions.currentVersion()
 		for l, filesToMark := range files {
 			if len(filesToMark) == 0 {
@@ -653,4 +653,5 @@ func (d *DB) markFilesLocked(findFn findFilesFunc) error {
 			InProgressCompactionsFn: func() []compactionInfo { return d.getInProgressCompactionInfoLocked(nil) },
 		}, nil
 	})
+	return err
 }
diff --git a/ingest.go b/ingest.go
index 3d1fd997..408f1b52 100644
--- a/ingest.go
+++ b/ingest.go
@@ -11,6 +11,7 @@ import (
 	"sort"
 	"time"
 
+	"github.com/cockroachdb/crlib/crtime"
 	"github.com/cockroachdb/errors"
 	"github.com/cockroachdb/pebble/internal/base"
 	"github.com/cockroachdb/pebble/internal/cache"
@@ -258,7 +259,12 @@ func ingestLoad1(
 	cacheHandle *cache.Handle,
 	tableNum base.TableNum,
 	rangeKeyValidator rangeKeyIngestValidator,
-) (meta *manifest.TableMetadata, lastRangeKey keyspan.Span, err error) {
+) (
+	meta *manifest.TableMetadata,
+	lastRangeKey keyspan.Span,
+	blockReadStats base.BlockReadStats,
+	err error,
+) {
 	o := opts.MakeReaderOptions()
 	o.CacheOpts = sstableinternal.CacheOptions{
 		CacheHandle: cacheHandle,
@@ -266,36 +272,36 @@ func ingestLoad1(
 	}
 	r, err := sstable.NewReader(ctx, readable, o)
 	if err != nil {
-		return nil, keyspan.Span{}, errors.CombineErrors(err, readable.Close())
+		return nil, keyspan.Span{}, base.BlockReadStats{}, errors.CombineErrors(err, readable.Close())
 	}
 	defer func() { _ = r.Close() }()
 
 	// Avoid ingesting tables with format versions this DB doesn't support.
 	tf, err := r.TableFormat()
 	if err != nil {
-		return nil, keyspan.Span{}, err
+		return nil, keyspan.Span{}, base.BlockReadStats{}, err
 	}
 	if tf < fmv.MinTableFormat() || tf > fmv.MaxTableFormat() {
-		return nil, keyspan.Span{}, errors.Newf(
+		return nil, keyspan.Span{}, base.BlockReadStats{}, errors.Newf(
 			"pebble: table format %s is not within range supported at DB format major version %d, (%s,%s)",
 			tf, fmv, fmv.MinTableFormat(), fmv.MaxTableFormat(),
 		)
 	}
 
 	if r.Attributes.Has(sstable.AttributeBlobValues) {
-		return nil, keyspan.Span{}, errors.Newf(
+		return nil, keyspan.Span{}, base.BlockReadStats{}, errors.Newf(
 			"pebble: ingesting tables with blob references is not supported")
 	}
 
 	props, err := r.ReadPropertiesBlock(ctx, nil /* buffer pool */)
 	if err != nil {
-		return nil, keyspan.Span{}, err
+		return nil, keyspan.Span{}, base.BlockReadStats{}, err
 	}
 
 	// If this is a columnar block, read key schema name from properties block.
 	if tf.BlockColumnar() {
 		if _, ok := opts.KeySchemas[props.KeySchemaName]; !ok {
-			return nil, keyspan.Span{}, errors.Newf(
+			return nil, keyspan.Span{}, base.BlockReadStats{}, errors.Newf(
 				"pebble: table uses key schema %q unknown to the database",
 				props.KeySchemaName)
 		}
@@ -318,55 +324,71 @@ func ingestLoad1(
 	// calculating stats before we can remove the original link.
 	maybeSetStatsFromProperties(meta.PhysicalMeta(), &props, opts.Logger)
 
+	var iterStats base.InternalIteratorStats
+	env := sstable.ReadEnv{
+		Block: block.ReadEnv{
+			Stats: &iterStats,
+		},
+	}
 	{
-		iter, err := r.NewIter(sstable.NoTransforms, nil /* lower */, nil /* upper */, sstable.AssertNoBlobHandles)
+		iterOpts := sstable.IterOptions{
+			Lower:                nil,
+			Upper:                nil,
+			Transforms:           sstable.NoTransforms,
+			Filterer:             nil,
+			FilterBlockSizeLimit: sstable.AlwaysUseFilterBlock,
+			Env:                  env,
+			ReaderProvider:       sstable.MakeTrivialReaderProvider(r),
+			BlobContext:          sstable.AssertNoBlobHandles,
+		}
+		iter, err := r.NewPointIter(ctx, iterOpts)
 		if err != nil {
-			return nil, keyspan.Span{}, err
+			return nil, keyspan.Span{}, base.BlockReadStats{}, err
 		}
 		defer func() { _ = iter.Close() }()
 		var smallest InternalKey
 		if kv := iter.First(); kv != nil {
 			if err := ingestValidateKey(opts, &kv.K); err != nil {
-				return nil, keyspan.Span{}, err
+				return nil, keyspan.Span{}, base.BlockReadStats{}, err
 			}
 			smallest = kv.K.Clone()
 		}
 		if err := iter.Error(); err != nil {
-			return nil, keyspan.Span{}, err
+			return nil, keyspan.Span{}, base.BlockReadStats{}, err
 		}
 		if kv := iter.Last(); kv != nil {
 			if err := ingestValidateKey(opts, &kv.K); err != nil {
-				return nil, keyspan.Span{}, err
+				return nil, keyspan.Span{}, base.BlockReadStats{}, err
 			}
 			meta.ExtendPointKeyBounds(opts.Comparer.Compare, smallest, kv.K.Clone())
 		}
 		if err := iter.Error(); err != nil {
-			return nil, keyspan.Span{}, err
+			return nil, keyspan.Span{}, base.BlockReadStats{}, err
 		}
 	}
 
-	iter, err := r.NewRawRangeDelIter(ctx, sstable.NoFragmentTransforms, sstable.NoReadEnv)
+	iter, err := r.NewRawRangeDelIter(ctx, sstable.NoFragmentTransforms, env)
 	if err != nil {
-		return nil, keyspan.Span{}, err
+		return nil, keyspan.Span{}, base.BlockReadStats{}, err
 	}
 	if iter != nil {
 		defer iter.Close()
 		var smallest InternalKey
 		if s, err := iter.First(); err != nil {
-			return nil, keyspan.Span{}, err
+			return nil, keyspan.Span{}, base.BlockReadStats{}, err
 		} else if s != nil {
 			key := s.SmallestKey()
 			if err := ingestValidateKey(opts, &key); err != nil {
-				return nil, keyspan.Span{}, err
+				return nil, keyspan.Span{}, base.BlockReadStats{}, err
 			}
 			smallest = key.Clone()
 		}
 		if s, err := iter.Last(); err != nil {
-			return nil, keyspan.Span{}, err
+			return nil, keyspan.Span{}, base.BlockReadStats{}, err
 		} else if s != nil {
 			k := s.SmallestKey()
 			if err := ingestValidateKey(opts, &k); err != nil {
-				return nil, keyspan.Span{}, err
+				return nil, keyspan.Span{}, base.BlockReadStats{}, err
 			}
 			largest := s.LargestKey().Clone()
 			meta.ExtendPointKeyBounds(opts.Comparer.Compare, smallest, largest)
@@ -375,34 +397,34 @@ func ingestLoad1(
 
 	// Update the range-key bounds for the table.
 	{
-		iter, err := r.NewRawRangeKeyIter(ctx, sstable.NoFragmentTransforms, sstable.NoReadEnv)
+		iter, err := r.NewRawRangeKeyIter(ctx, sstable.NoFragmentTransforms, env)
 		if err != nil {
-			return nil, keyspan.Span{}, err
+			return nil, keyspan.Span{}, base.BlockReadStats{}, err
 		}
 		if iter != nil {
 			defer iter.Close()
 			var smallest InternalKey
 			if s, err := iter.First(); err != nil {
-				return nil, keyspan.Span{}, err
+				return nil, keyspan.Span{}, base.BlockReadStats{}, err
 			} else if s != nil {
 				key := s.SmallestKey()
 				if err := ingestValidateKey(opts, &key); err != nil {
-					return nil, keyspan.Span{}, err
+					return nil, keyspan.Span{}, base.BlockReadStats{}, err
 				}
 				smallest = key.Clone()
 				// Range keys need some additional validation as we need to ensure they
 				// defragment cleanly with the lastRangeKey from the previous file.
 				if err := rangeKeyValidator.Validate(s); err != nil {
-					return nil, keyspan.Span{}, err
+					return nil, keyspan.Span{}, base.BlockReadStats{}, err
 				}
 			}
 			lastRangeKey = keyspan.Span{}
 			if s, err := iter.Last(); err != nil {
-				return nil, keyspan.Span{}, err
+				return nil, keyspan.Span{}, base.BlockReadStats{}, err
 			} else if s != nil {
 				k := s.SmallestKey()
 				if err := ingestValidateKey(opts, &k); err != nil {
-					return nil, keyspan.Span{}, err
+					return nil, keyspan.Span{}, base.BlockReadStats{}, err
 				}
 				// As range keys are fragmented, the end key of the last range key in
 				// the table provides the upper bound for the table.
@@ -412,27 +434,27 @@ func ingestLoad1(
 			} else {
 				// s == nil.
 				if err := rangeKeyValidator.Validate(nil /* nextFileSmallestKey */); err != nil {
-					return nil, keyspan.Span{}, err
+					return nil, keyspan.Span{}, base.BlockReadStats{}, err
 				}
 			}
 		} else {
 			if err := rangeKeyValidator.Validate(nil /* nextFileSmallestKey */); err != nil {
-				return nil, keyspan.Span{}, err
+				return nil, keyspan.Span{}, base.BlockReadStats{}, err
 			}
 			lastRangeKey = keyspan.Span{}
 		}
 	}
 
 	if !meta.HasPointKeys && !meta.HasRangeKeys {
-		return nil, keyspan.Span{}, nil
+		return nil, keyspan.Span{}, base.BlockReadStats{}, nil
 	}
 
 	// Sanity check that the various bounds on the file were set consistently.
 	if err := meta.Validate(opts.Comparer.Compare, opts.Comparer.FormatKey); err != nil {
-		return nil, keyspan.Span{}, err
+		return nil, keyspan.Span{}, base.BlockReadStats{}, err
 	}
 
-	return meta, lastRangeKey, nil
+	return meta, lastRangeKey, iterStats.TotalBlockReads(), nil
 }
 
 type ingestLoadResult struct {
@@ -441,6 +463,7 @@ type ingestLoadResult struct {
 	external []ingestExternalMeta
 
 	externalFilesHaveLevel bool
+	blockReadStats         base.BlockReadStats
 }
 
 type ingestLocalMeta struct {
@@ -484,6 +507,7 @@ func ingestLoad(
 	var result ingestLoadResult
 	result.local = make([]ingestLocalMeta, 0, len(paths))
 	var lastRangeKey keyspan.Span
+	var blockReadStats base.BlockReadStats
 	// NB: we disable range key boundary assertions if we have shared or external files
 	// present in this ingestion. This is because a suffixed range key in a local file
 	// can possibly defragment with a suffixed range key in a shared or external file.
@@ -507,7 +531,7 @@ func ingestLoad(
 		if !shouldDisableRangeKeyChecks {
 			rangeKeyValidator = validateSuffixedBoundaries(opts.Comparer, lastRangeKey)
 		}
-		m, lastRangeKey, err = ingestLoad1(ctx, opts, fmv, readable, cacheHandle, localFileNums[i], rangeKeyValidator)
+		m, lastRangeKey, blockReadStats, err = ingestLoad1(ctx, opts, fmv, readable, cacheHandle, localFileNums[i], rangeKeyValidator)
 		if err != nil {
 			return ingestLoadResult{}, err
 		}
@@ -516,6 +540,7 @@ func ingestLoad(
 				TableMetadata: m,
 				path:          paths[i],
 			})
+			result.blockReadStats = blockReadStats
 		}
 	}
 
@@ -1454,7 +1479,8 @@ func (d *DB) ingest(ctx context.Context, args ingestArgs) (IngestOperationStats,
 
 	// Load the metadata for all the files being ingested. This step detects
 	// and elides empty sstables.
-	loadResult, err := ingestLoad(ctx, d.opts, d.FormatMajorVersion(), paths, shared, external, d.cacheHandle, pendingOutputs)
+	loadResult, err := ingestLoad(ctx, d.opts, d.FormatMajorVersion(), paths, shared, external,
+		d.cacheHandle, pendingOutputs)
 	if err != nil {
 		return IngestOperationStats{}, err
 	}
@@ -1499,6 +1525,7 @@ func (d *DB) ingest(ctx context.Context, args ingestArgs) (IngestOperationStats,
 	var mut *memTable
 	// asFlushable indicates whether the sstable was ingested as a flushable.
 	var asFlushable bool
+	var waitFlushStart crtime.Mono
 	prepare := func(seqNum base.SeqNum) {
 		// Note that d.commit.mu is held by commitPipeline when calling prepare.
 
@@ -1607,7 +1634,6 @@ func (d *DB) ingest(ctx context.Context, args ingestArgs) (IngestOperationStats,
 				d.mu.log.manager.ElevateWriteStallThresholdForFailover()) &&
 			!d.opts.Experimental.DisableIngestAsFlushable() && !hasRemoteFiles &&
 			(!args.ExciseSpan.Valid() || d.FormatMajorVersion() >= FormatFlushableIngestExcises)
-
 		if !canIngestFlushable {
 			// We're not able to ingest as a flushable,
 			// so we must synchronously flush.
@@ -1628,6 +1654,7 @@ func (d *DB) ingest(ctx context.Context, args ingestArgs) (IngestOperationStats,
 			mut = d.mu.mem.mutable
 			mut.writerRef()
 			mem.flushForced = true
+			waitFlushStart = crtime.NowMono()
 			d.maybeScheduleFlush()
 			return
 		}
@@ -1642,6 +1669,8 @@ func (d *DB) ingest(ctx context.Context, args ingestArgs) (IngestOperationStats,
 	}
 
 	var ve *manifest.VersionEdit
+	var waitFlushDuration time.Duration
+	var manifestUpdateDuration time.Duration
 	apply := func(seqNum base.SeqNum) {
 		if err != nil || asFlushable {
 			// An error occurred during prepare.
@@ -1683,11 +1712,12 @@ func (d *DB) ingest(ctx context.Context, args ingestArgs) (IngestOperationStats,
 		// finish.
 		if mem != nil {
 			<-mem.flushed
+			waitFlushDuration = waitFlushStart.Elapsed()
 		}
 
 		// Assign the sstables to the correct level in the LSM and apply the
 		// version edit.
-		ve, err = d.ingestApply(ctx, jobID, loadResult, mut, args.ExciseSpan, args.ExciseBoundsPolicy, seqNum)
+		ve, manifestUpdateDuration, err = d.ingestApply(ctx, jobID, loadResult, mut, args.ExciseSpan, args.ExciseBoundsPolicy, seqNum)
 	}
 
 	// Only one ingest can occur at a time because if not, one would block waiting
@@ -1724,9 +1754,13 @@ func (d *DB) ingest(ctx context.Context, args ingestArgs) (IngestOperationStats,
 	var stats IngestOperationStats
 	if loadResult.fileCount() > 0 {
 		info := TableIngestInfo{
-			JobID:     int(jobID),
-			Err:       err,
-			flushable: asFlushable,
+			JobID:                  int(jobID),
+			Err:                    err,
+			flushable:              asFlushable,
+			WaitFlushDuration:      waitFlushDuration,
+			ManifestUpdateDuration: manifestUpdateDuration,
+			BlockReadDuration:      loadResult.blockReadStats.BlockReadDuration,
+			BlockReadBytes:         loadResult.blockReadStats.BlockBytes - loadResult.blockReadStats.BlockBytesInCache,
 		}
 		if len(loadResult.local) > 0 {
 			info.GlobalSeqNum = loadResult.local[0].SmallestSeqNum
@@ -1905,7 +1939,7 @@ func (d *DB) ingestApply(
 	exciseSpan KeyRange,
 	exciseBoundsPolicy exciseBoundsPolicy,
 	exciseSeqNum base.SeqNum,
-) (*manifest.VersionEdit, error) {
+) (*manifest.VersionEdit, time.Duration, error) {
 	d.mu.Lock()
 	defer d.mu.Unlock()
 
@@ -1921,7 +1955,7 @@ func (d *DB) ingestApply(
 	// concurrent ingestion jobs from using the same version to determine the
 	// target level, and also provides serialization with concurrent compaction
 	// and flush jobs.
-	err := d.mu.versions.UpdateVersionLocked(func() (versionUpdate, error) {
+	manifestUpdateDuration, err := d.mu.versions.UpdateVersionLocked(func() (versionUpdate, error) {
 		if mut != nil {
 			// Unref the mutable memtable to allows its flush to proceed. Now that we've
 			// acquired the manifest lock, we can be certain that if the mutable
@@ -2164,9 +2198,8 @@ func (d *DB) ingestApply(
 		}, nil
 	})
 	if err != nil {
-		return nil, err
+		return nil, 0, err
 	}
-
 	// Check for any EventuallyFileOnlySnapshots that could be watching for
 	// an excise on this span. There should be none as the
 	// computePossibleOverlaps steps should have forced these EFOS to transition
@@ -2211,7 +2244,8 @@ func (d *DB) ingestApply(
 		}
 	}
 	d.maybeValidateSSTablesLocked(toValidate)
-	return ve, nil
+
+	return ve, manifestUpdateDuration, nil
 }
 
 // maybeValidateSSTablesLocked adds the slice of newTableEntrys to the pending
diff --git a/internal/strparse/strparse.go b/internal/strparse/strparse.go
index ab7aed04..a91789e7 100644
--- a/internal/strparse/strparse.go
+++ b/internal/strparse/strparse.go
@@ -175,7 +175,7 @@ func (p *Parser) Uint32() uint32 {
 	return uint32(x)
 }
 
-// Uint64 parses the next token as a sequence number.
+// SeqNum parses the next token as a sequence number.
 func (p *Parser) SeqNum() base.SeqNum {
 	return base.ParseSeqNum(p.Next())
 }
diff --git a/open.go b/open.go
index ba5a6220..1ce1a849 100644
--- a/open.go
+++ b/open.go
@@ -850,7 +850,7 @@ func (d *DB) replayIngestedFlushable(
 			return nil, errors.Wrap(err, "pebble: error when opening flushable ingest files")
 		}
 		// NB: ingestLoad1 will close readable.
-		meta[i], lastRangeKey, err = ingestLoad1(context.TODO(), d.opts, d.FormatMajorVersion(),
+		meta[i], lastRangeKey, _, err = ingestLoad1(context.TODO(), d.opts, d.FormatMajorVersion(),
 			readable, d.cacheHandle, base.PhysicalTableFileNum(n), disableRangeKeyChecks())
 		if err != nil {
 			return nil, errors.Wrap(err, "pebble: error when loading flushable ingest files")
diff --git a/version_set.go b/version_set.go
index 26efdc79..467cbbaa 100644
--- a/version_set.go
+++ b/version_set.go
@@ -9,7 +9,9 @@ import (
 	"io"
 	"sync"
 	"sync/atomic"
+	"time"
 
+	"github.com/cockroachdb/crlib/crtime"
 	"github.com/cockroachdb/errors"
 	"github.com/cockroachdb/pebble/internal/base"
 	"github.com/cockroachdb/pebble/internal/invariants"
@@ -437,7 +439,9 @@ type versionUpdate struct {
 	ForceManifestRotation   bool
 }
 
-// UpdateVersionLocked is used to update the current version.
+// UpdateVersionLocked is used to update the current version, returning the
+// duration of the manifest update. If the manifest update is unsuccessful, the
+// duration will be unset (0).
 //
 // DB.mu must be held. UpdateVersionLocked first waits for any other version
 // update to complete, releasing and reacquiring DB.mu.
@@ -459,19 +463,22 @@ type versionUpdate struct {
 //
 // If updateFn returns an error, no update is applied and that same error is returned.
 // If versionUpdate.VE is nil, the no update is applied (and no error is returned).
-func (vs *versionSet) UpdateVersionLocked(updateFn func() (versionUpdate, error)) error {
+func (vs *versionSet) UpdateVersionLocked(
+	updateFn func() (versionUpdate, error),
+) (time.Duration, error) {
 	vs.logLock()
 	defer vs.logUnlockAndInvalidatePickedCompactionCache()
 
 	vu, err := updateFn()
 	if err != nil || vu.VE == nil {
-		return err
+		return 0, err
 	}
 
 	if !vs.writing {
 		vs.opts.Logger.Fatalf("MANIFEST not locked for writing")
 	}
 
+	updateManifestStart := crtime.NowMono()
 	ve := vu.VE
 	if ve.MinUnflushedLogNum != 0 {
 		if ve.MinUnflushedLogNum < vs.minUnflushedLogNum ||
@@ -669,7 +676,7 @@ func (vs *versionSet) UpdateVersionLocked(updateFn func() (versionUpdate, error)
 		// certain manifest / WAL operations become retryable. For more context, see
 		// #1159 and #1792.
 		vs.opts.Logger.Fatalf("%s", err)
-		return err
+		return 0, err
 	}
 
 	if requireRotation {
@@ -780,7 +787,8 @@ func (vs *versionSet) UpdateVersionLocked(updateFn func() (versionUpdate, error)
 	if !vs.dynamicBaseLevel {
 		vs.picker.forceBaseLevel1()
 	}
-	return nil
+
+	return updateManifestStart.Elapsed(), nil
 }
 
 func (vs *versionSet) setCompactionPicker(picker *compactionPickerByScore) {



Test patch:
diff --git a/data_test.go b/data_test.go
index 3c6462c8..92cfb66f 100644
--- a/data_test.go
+++ b/data_test.go
@@ -1186,7 +1186,7 @@ func runDBDefineCmdReuseFS(td *datadriven.TestData, opts *Options) (*DB, error)
 		}
 
 		jobID := d.newJobIDLocked()
-		err = d.mu.versions.UpdateVersionLocked(func() (versionUpdate, error) {
+		_, err = d.mu.versions.UpdateVersionLocked(func() (versionUpdate, error) {
 			return versionUpdate{
 				VE:                      ve,
 				JobID:                   jobID,
diff --git a/event_listener_test.go b/event_listener_test.go
index 97f31ea5..030a9c77 100644
--- a/event_listener_test.go
+++ b/event_listener_test.go
@@ -55,6 +55,15 @@ func TestEventListener(t *testing.T) {
 				info.InputBytes = 100
 				flushEnd(info)
 			}
+			tableIngested := lel.TableIngested
+			lel.TableIngested = func(info TableIngestInfo) {
+				// Make deterministic.
+				info.WaitFlushDuration = 200 * time.Millisecond
+				info.ManifestUpdateDuration = 100 * time.Millisecond
+				info.BlockReadDuration = 300 * time.Millisecond
+				info.BlockReadBytes = 7894
+				tableIngested(info)
+			}
 			opts := &Options{
 				// The table stats collector runs asynchronously and its
 				// timing is less predictable. It increments nextJobID, which
diff --git a/file_cache_test.go b/file_cache_test.go
index d421721e..56d2998d 100644
--- a/file_cache_test.go
+++ b/file_cache_test.go
@@ -406,7 +406,7 @@ func TestVirtualReadsWiring(t *testing.T) {
 	}
 
 	applyVE := func(ve *manifest.VersionEdit) error {
-		err := d.mu.versions.UpdateVersionLocked(func() (versionUpdate, error) {
+		_, err := d.mu.versions.UpdateVersionLocked(func() (versionUpdate, error) {
 			return versionUpdate{
 				VE:                      ve,
 				JobID:                   d.newJobIDLocked(),
diff --git a/replay/testdata/collect/start_stop b/replay/testdata/collect/start_stop
index 72d8f247..4ce96633 100644
--- a/replay/testdata/collect/start_stop
+++ b/replay/testdata/collect/start_stop
@@ -14,7 +14,7 @@ ingest
 created src/000002.sst
 created src/000003.sst
 created src/000004.sst
-[JOB 0] ingested L0:000002 (10KB), L0:000003 (10KB), L0:000004 (10KB)
+[JOB 0] ingested L0:000002 (10KB), L0:000003 (10KB), L0:000004 (10KB); manifest update took 0.1s; block reads took 0.3s with 7.7KB block bytes read
 
 
 wait
diff --git a/replay/workload_capture_test.go b/replay/workload_capture_test.go
index 93e647fb..d19ef111 100644
--- a/replay/workload_capture_test.go
+++ b/replay/workload_capture_test.go
@@ -128,6 +128,12 @@ func TestWorkloadCollector(t *testing.T) {
 					_, err = currentManifest.Write(randData(25))
 					require.NoError(t, err)
 				}
+				// Override the default duration values for TableIngestInfo to
+				// ensure deterministic output.
+				ingestInfo.WaitFlushDuration = 200 * time.Millisecond
+				ingestInfo.ManifestUpdateDuration = 100 * time.Millisecond
+				ingestInfo.BlockReadDuration = 300 * time.Millisecond
+				ingestInfo.BlockReadBytes = 7894
 				fmt.Fprint(&buf, ingestInfo.String())
 				c.onTableIngest(ingestInfo)
 				return buf.String()
diff --git a/testdata/event_listener b/testdata/event_listener
index 8c9c10e0..b06a82ce 100644
--- a/testdata/event_listener
+++ b/testdata/event_listener
@@ -238,7 +238,7 @@ sync: db
 remove: db/MANIFEST-000011
 [JOB 10] MANIFEST deleted 000011
 remove: ext/0
-[JOB 10] ingested L0:000015 (757B)
+[JOB 10] ingested L0:000015 (757B); manifest update took 0.1s; block reads took 0.3s with 7.7KB block bytes read
 
 metrics
 ----
@@ -350,7 +350,7 @@ sync: wal
 [JOB 13] WAL created 000020
 remove: ext/a
 remove: ext/b
-[JOB 11] ingested as flushable 000017 (757B), 000018 (757B)
+[JOB 11] ingested as flushable, memtable flushes took 0.2s: 000017 (757B), 000018 (757B); manifest update took 0.1s; block reads took 0.3s with 7.7KB block bytes read
 sync-data: wal/000020.log
 close: wal/000020.log
 create: wal/000021.log
diff --git a/version_set_test.go b/version_set_test.go
index 2fbf451a..c9c9ca8f 100644
--- a/version_set_test.go
+++ b/version_set_test.go
@@ -159,7 +159,7 @@ func TestVersionSet(t *testing.T) {
 			}
 
 			mu.Lock()
-			err = vs.UpdateVersionLocked(func() (versionUpdate, error) {
+			_, err = vs.UpdateVersionLocked(func() (versionUpdate, error) {
 				return versionUpdate{
 					VE:                      ve,
 					Metrics:                 fileMetrics,