sstable: cpu optimize Iterator.Close

[jbowens]

In the pebble ycsb/C benchmarks, singleLevelIterator.Close is 16% of CPU:

ROUTINE ======================== github.com/cockroachdb/pebble/sstable.(*singleLevelIterator[go.shape.struct { github.com/cockroachdb/pebble/sstable/rowblk.iter github.com/cockroachdb/pebble/sstable/rowblk.Iter },go.shape.*github.com/cockroachdb/pebble/sstable/rowblk.IndexIter,go.shape.eb7c958227f421b2b34e33f9383baa8eb4cd132ad8ad1af0ac397c32eec3846d,go.shape.*github.com/cockroachdb/pebble/sstable/rowblk.Iter]).Close in sstable/reader_iter_single_lvl.go
   1.73hrs   19.17hrs (flat, cum) 16.27% of Total
    68.56s     68.59s   1575:func (i *singleLevelIterator[I, PI, D, PD]) Close() error {
    42.62s   12.05hrs   1576:	err := i.closeInternal()
    23.75s     23.75s   1577:	pool := i.pool
   1.55hrs    6.34hrs   1578:	*i = i.resetForReuse()
   320.83s    320.83s   1579:	if pool != nil {
   130.74s   2326.77s   1580:		pool.Put(i)
         .          .   1581:	}
    68.21s     68.21s   1582:	return err
         .          .   1583:}

ROUTINE ======================== github.com/cockroachdb/pebble/sstable.(*singleLevelIterator[go.shape.struct { github.com/cockroachdb/pebble/sstable/rowblk.iter github.com/cockroachdb/pebble/sstable/rowblk.Iter },go.shape.*github.com/cockroachdb/pebble/sstable/rowblk.IndexIter,go.shape.eb7c958227f421b2b34e33f9383baa8eb4cd132ad8ad1af0ac397c32eec3846d,go.shape.*github.com/cockroachdb/pebble/sstable/rowblk.Iter]).closeInternal in sstable/reader_iter_single_lvl.go
  1261.62s   12.04hrs (flat, cum) 10.22% of Total
   101.06s    101.06s   1585:func (i *singleLevelIterator[I, PI, D, PD]) closeInternal() error {
         .          .   1586:	if invariants.Enabled && i.inPool {
         .          .   1587:		panic("Close called on interator in pool")
         .          .   1588:	}
     580ms    7.19hrs   1589:	i.iterStats.close()
         .          .   1590:	var err error
   150.34s    150.34s   1591:	if i.closeHook != nil {
   147.22s    1.81hrs   1592:		err = firstError(err, i.closeHook(i))
         .          .   1593:	}
   185.85s   2493.31s   1594:	err = firstError(err, PD(&i.data).Close())
   109.30s    1.03hrs   1595:	err = firstError(err, PI(&i.index).Close())
    40.14s     40.14s   1596:	if i.indexFilterRH != nil {
     1.69s    380.25s   1597:		err = firstError(err, i.indexFilterRH.Close())
   104.75s    104.92s   1598:		i.indexFilterRH = nil
         .          .   1599:	}
    26.26s     26.26s   1600:	if i.dataRH != nil {
    42.60s    409.55s   1601:		err = firstError(err, i.dataRH.Close())
   107.04s    107.28s   1602:		i.dataRH = nil
         .          .   1603:	}
    35.80s     36.05s   1604:	err = firstError(err, i.err)
    58.18s     58.18s   1605:	if i.bpfs != nil {
     160ms      3165s   1606:		releaseBlockPropertiesFilterer(i.bpfs)
         .          .   1607:	}
    47.44s     47.44s   1608:	if i.vbReader != nil {
         .          .   1609:		i.vbReader.close()
         .          .   1610:	}
    34.87s     34.87s   1611:	if i.vbRH != nil {
         .          .   1612:		err = firstError(err, i.vbRH.Close())
         .          .   1613:		i.vbRH = nil
         .          .   1614:	}
    68.34s     68.34s   1615:	return err
         .          .   1616:}

Jira issue: PEBBLE-278

[jbowens]

     580ms    7.19hrs   1589:	i.iterStats.close()

The iterator stats collection is prominent because of its mutex acquisitions, and that it's performed once per sstable. I think this could be improved with some indirection so that a pebble.Iterator aggregates stats from its sstable.Readers without synchronization, reporting them once the Iterator is closed. Other sources of sstable iterators will need to supply a different implementation that immediately reports stats on Close.

[jbowens]

With recent improvements elsewhere, Close is up to 21% of ycsb/C/values=64 😵

Showing nodes accounting for 16.33hrs, 69.36% of 23.54hrs total
Dropped 841 nodes (cum <= 0.12hrs)
Showing top 40 nodes out of 133
      flat  flat%   sum%        cum   cum%
   3.72hrs 15.80% 15.80%    3.72hrs 15.80%  sync/atomic.(*Int32).Add (inline)
   1.21hrs  5.12% 20.92%    5.11hrs 21.70%  github.com/cockroachdb/pebble.(*Iterator).Close
   1.20hrs  5.08% 26.00%    1.20hrs  5.08%  cmpbody
   0.88hrs  3.76% 29.76%    3.09hrs 13.13%  github.com/cockroachdb/pebble/internal/cache.(*shard).Get
   0.67hrs  2.83% 32.59%    3.87hrs 16.44%  github.com/cockroachdb/pebble.(*tableCacheShard).newPointIter
   0.45hrs  1.91% 34.50%    0.86hrs  3.67%  sync.(*Mutex).lockSlow
   0.44hrs  1.88% 36.39%    1.12hrs  4.77%  github.com/cockroachdb/pebble/sstable/colblk.(*IndexIter).SeekGE
   0.42hrs  1.80% 38.18%    0.68hrs  2.90%  github.com/cockroachdb/pebble/internal/crdbtest.Compare
   0.42hrs  1.78% 39.97%    0.42hrs  1.78%  github.com/cockroachdb/pebble/internal/cache.(*Cache).getShard
   0.42hrs  1.78% 41.75%    1.51hrs  6.43%  github.com/cockroachdb/pebble/sstable/colblk.(*PrefixBytes).Search
   0.38hrs  1.61% 43.36%    1.98hrs  8.43%  github.com/cockroachdb/pebble/sstable.(*CategoryStatsCollector).reportStats
   0.37hrs  1.59% 44.95%   22.73hrs 96.53%  main.(*ycsb).read
   0.37hrs  1.58% 46.54%    1.63hrs  6.90%  github.com/cockroachdb/pebble.(*tableCacheShard).findNodeInternal
   0.36hrs  1.53% 48.07%    0.56hrs  2.37%  github.com/cockroachdb/pebble/sstable/colblk.(*DataBlockIter).decodeRow
   0.35hrs  1.47% 49.54%    0.47hrs  2.02%  github.com/cockroachdb/pebble.(*tableCacheShard).findNodeInternal.func1
   0.30hrs  1.29% 50.82%    0.30hrs  1.29%  runtime.duffcopy
   0.29hrs  1.23% 52.06%    6.34hrs 26.94%  github.com/cockroachdb/pebble.(*levelIter).loadFile
   0.29hrs  1.22% 53.28%    1.64hrs  6.98%  github.com/cockroachdb/pebble.(*DB).newIter
   0.28hrs  1.20% 54.48%    0.40hrs  1.72%  github.com/cockroachdb/pebble/sstable/colblk.(*DataBlockIter).InitHandle
   0.26hrs  1.11% 55.58%    0.52hrs  2.22%  runtime.lock2
   0.22hrs  0.95% 56.53%    0.22hrs  0.95%  runtime.procyield
   0.22hrs  0.94% 57.47%    0.22hrs  0.94%  runtime.nanotime (inline)
   0.21hrs  0.89% 58.36%    0.21hrs  0.89%  github.com/cockroachdb/pebble/sstable/colblk.UnsafeOffsets.At2 (inline)
   0.18hrs  0.78% 59.15%    0.25hrs  1.06%  github.com/cockroachdb/pebble.(*Iterator).maybeSampleRead
   0.18hrs  0.78% 59.93%    0.24hrs  1.04%  github.com/cockroachdb/pebble/objstorage/objstorageprovider.(*vfsReadHandle).init (inline)
   0.17hrs  0.73% 60.66%    0.36hrs  1.53%  github.com/cockroachdb/swiss.(*Map[go.shape.struct { github.com/cockroachdb/pebble/internal/cache.fileKey; github.com/cockroachdb/pebble/internal/cache.offset uint64 },go.shape.*uint8]).Get
   0.17hrs  0.73% 61.39%    0.78hrs  3.31%  github.com/cockroachdb/pebble.(*Iterator).constructPointIter
   0.17hrs   0.7% 62.09%    0.72hrs  3.07%  github.com/cockroachdb/pebble/internal/manifest.(*iterator).seek
   0.16hrs  0.67% 62.76%    0.52hrs  2.20%  github.com/cockroachdb/pebble/internal/manifest.(*LevelIterator).SeekGE.func1
   0.16hrs  0.66% 63.42%   14.81hrs 62.90%  github.com/cockroachdb/pebble.(*Iterator).SeekGEWithLimit
   0.16hrs  0.66% 64.08%    0.17hrs  0.71%  strconv.formatBits
   0.15hrs  0.65% 64.73%    3.20hrs 13.57%  github.com/cockroachdb/pebble/sstable.(*singleLevelIterator[go.shape.40697c713c64688a6479c45892a3792b8dee21dd3e7319916a125d72ded7c6e6,go.shape.*github.com/cockroachdb/pebble/sstable/colblk.IndexIter,go.shape.e2f2af5f05ed3123741742e1e3c5de40660eda49976c2ab5f0372bb184789e53,go.shape.*github.com/cockroachdb/pebble/sstable/colblk.DataBlockIter]).loadDataBlock
   0.15hrs  0.62% 65.35%    0.15hrs  0.62%  github.com/cockroachdb/swiss.(*ctrlGroup).matchH2 (inline)
   0.14hrs  0.61% 65.96%    0.14hrs  0.61%  time.Now
   0.14hrs  0.61% 66.57%    0.45hrs  1.91%  sync.(*Mutex).Unlock (inline)
   0.14hrs  0.57% 67.14%    0.14hrs  0.57%  github.com/cockroachdb/pebble/internal/cache.Handle.RawBuffer (inline)
   0.13hrs  0.57% 67.71%    3.77hrs 16.00%  github.com/cockroachdb/pebble/sstable.(*Reader).readBlockInternal
   0.13hrs  0.56% 68.27%    0.35hrs  1.49%  sync.(*Pool).Get
   0.13hrs  0.55% 68.82%    0.38hrs  1.63%  sync.(*Pool).Put
   0.13hrs  0.54% 69.36%    0.91hrs  3.86%  github.com/cockroachdb/pebble.finishInitializingIter

[jbowens]

With #4095 in, master is back down to ~15% spent on Close:

(pprof) top20
Showing nodes accounting for 65.36hrs, 57.25% of 114.16hrs total
Dropped 1165 nodes (cum <= 0.57hrs)
Showing top 20 nodes out of 117
      flat  flat%   sum%        cum   cum%
  18.92hrs 16.57% 16.57%   18.93hrs 16.58%  sync/atomic.(*Int32).Add (inline)
   7.03hrs  6.15% 22.72%   16.78hrs 14.69%  github.com/cockroachdb/pebble.(*Iterator).Close
   5.90hrs  5.17% 27.89%    5.90hrs  5.17%  cmpbody
   3.67hrs  3.22% 31.11%   13.14hrs 11.51%  github.com/cockroachdb/pebble/internal/cache.(*shard).Get
   3.03hrs  2.66% 33.77%   18.24hrs 15.97%  github.com/cockroachdb/pebble.(*tableCacheShard).newPointIter
   2.54hrs  2.22% 35.99%    4.21hrs  3.69%  github.com/cockroachdb/pebble/internal/crdbtest.Compare
   2.33hrs  2.04% 38.03%    6.22hrs  5.45%  github.com/cockroachdb/pebble/sstable/colblk.(*IndexIter).SeekGE
   2.32hrs  2.03% 40.06%  109.69hrs 96.08%  main.(*ycsb).read
   2.18hrs  1.91% 41.97%    7.38hrs  6.46%  github.com/cockroachdb/pebble/sstable/colblk.(*PrefixBytes).Search
   2.08hrs  1.82% 43.79%    2.08hrs  1.82%  github.com/cockroachdb/pebble/internal/cache.(*Cache).getShard
   2.07hrs  1.82% 45.61%   13.14hrs 11.51%  github.com/cockroachdb/pebble.(*DB).newIter
   1.92hrs  1.68% 47.28%    7.87hrs  6.90%  github.com/cockroachdb/pebble.(*tableCacheShard).findNodeInternal
   1.67hrs  1.46% 48.75%    2.71hrs  2.38%  github.com/cockroachdb/pebble/sstable/colblk.(*DataBlockIter).decodeRow
   1.61hrs  1.41% 50.16%    2.23hrs  1.96%  github.com/cockroachdb/pebble.(*tableCacheShard).findNodeInternal.func1
   1.58hrs  1.38% 51.54%    1.58hrs  1.38%  runtime.duffcopy
   1.45hrs  1.27% 52.81%    6.37hrs  5.58%  github.com/cockroachdb/pebble.(*Iterator).constructPointIter
   1.34hrs  1.18% 53.99%    1.34hrs  1.18%  runtime.nanotime
   1.32hrs  1.16% 55.14%    1.73hrs  1.51%  github.com/cockroachdb/pebble.(*Iterator).maybeSampleRead
   1.26hrs  1.10% 56.24%    7.65hrs  6.70%  github.com/cockroachdb/pebble.finishInitializingIter
   1.15hrs  1.01% 57.25%   29.67hrs 25.99%  github.com/cockroachdb/pebble.(*levelIter).loadFile

[jbowens]

Some of the top-level Iterator.Close aspects of this issue are resolved in #4187