X zodb/cache: Speedup checkpoint

Compared to 0abecd63 (X Split IStorage -> IStorage, IStorageDriver) we
now reach a point where adding cache on top of storage for
'cache-always-missed' scenario adds ~ 0.5-1-3µs of overhead, which is
not ideal but is acceptable for now.

The full timing diff is below. Note that thermal throttling was
activating near end of each dataset run and this way go vs zhash.go-P16
timings or something around it might be not very representative.

The cache size is reduces because we currently benchmark on dataset size 8M
(wczblk1-8) and 6M (prod1-1024), which if cache size is 16M fully fit
into it and so whole benchmark measures cache startup overhead, not its
steady state it will reach soon after program startup.

512K is enough to prefetch 128·4K entries.

old = goclientcache=off
new = goclientcache=on

The patch to turn go client cache off was:

---- 8< ----
--- a/go/zodb/open.go
+++ b/go/zodb/open.go
@@ -102,6 +102,7 @@ type storage struct {
 // loading always goes through cache - this way prefetching can work

 func (s *storage) Load(ctx context.Context, xid Xid) (*Buf, Tid, error) {
+       return s.IStorageDriver.Load(ctx, xid)
        return s.l1cache.Load(ctx, xid)
 }
---- 8< ----

name                                           old time/object  new time/object  delta
dataset:wczblk1-8
deco/fs1/zhash.py                                  14.9µs ± 1%      14.9µs ± 2%     ~     (p=0.905 n=5+5)
deco/fs1/zhash.py-P16                               124µs ±30%       119µs ±22%     ~     (p=0.336 n=16+16)
deco/fs1/zhash.go                                  1.50µs ± 0%      2.20µs ± 0%  +46.67%  (p=0.008 n=5+5)
deco/fs1/zhash.go+prefetch128                      3.18µs ± 7%      3.14µs ± 5%     ~     (p=0.857 n=5+5)
deco/fs1/zhash.go-P16                             4.64µs ±109%      8.55µs ±94%  +84.12%  (p=0.001 n=16+16)
deco/zeo/zhash.py                                   314µs ±11%       299µs ±11%     ~     (p=0.421 n=5+5)
deco/zeo/zhash.py-P16                              2.61ms ± 9%      2.62ms ± 9%     ~     (p=0.897 n=16+16)
deco/neo/py/sqlite/zhash.py                         322µs ± 6%       315µs ± 4%     ~     (p=0.548 n=5+5)
deco/neo/py/sqlite/zhash.py-P16                    2.88ms ± 1%      2.84ms ± 2%   -1.19%  (p=0.000 n=15+16)
deco/neo/py/sqlite/zhash.go                         228µs ± 1%       234µs ± 1%   +2.57%  (p=0.008 n=5+5)
deco/neo/py/sqlite/zhash.go+prefetch128             350µs ± 1%       120µs ± 2%  -65.67%  (p=0.008 n=5+5)
deco/neo/py/sqlite/zhash.go-P16                    1.78ms ±14%      1.99ms ± 0%  +11.83%  (p=0.021 n=16+13)
deco/neo/py(!log)/sqlite/zhash.py                   300µs ± 4%       288µs ± 0%     ~     (p=0.063 n=5+4)
deco/neo/py(!log)/sqlite/zhash.py-P16              2.82ms ± 3%      2.83ms ± 4%     ~     (p=0.762 n=15+16)
deco/neo/py(!log)/sqlite/zhash.go                   212µs ± 3%       215µs ± 3%     ~     (p=0.095 n=5+5)
deco/neo/py(!log)/sqlite/zhash.go+prefetch128       321µs ± 1%       110µs ± 3%  -65.88%  (p=0.008 n=5+5)
deco/neo/py(!log)/sqlite/zhash.go-P16              1.82ms ± 0%      1.86ms ± 0%   +1.94%  (p=0.000 n=14+15)
deco/neo/py/sql/zhash.py                            354µs ± 5%       344µs ± 4%     ~     (p=0.343 n=4+4)
deco/neo/py/sql/zhash.py-P16                       3.89ms ± 0%      3.87ms ± 0%   -0.31%  (p=0.001 n=15+15)
deco/neo/py/sql/zhash.go                            273µs ± 3%       281µs ± 3%     ~     (p=0.095 n=5+5)
deco/neo/py/sql/zhash.go+prefetch128                457µs ± 1%       177µs ± 3%  -61.26%  (p=0.008 n=5+5)
deco/neo/py/sql/zhash.go-P16                       2.79ms ± 0%      2.87ms ± 0%   +2.76%  (p=0.000 n=14+14)
deco/neo/py(!log)/sql/zhash.py                      323µs ± 3%       331µs ± 3%     ~     (p=0.200 n=4+4)
deco/neo/py(!log)/sql/zhash.py-P16                 3.65ms ± 1%      3.61ms ± 0%   -0.97%  (p=0.000 n=15+14)
deco/neo/py(!log)/sql/zhash.go                      256µs ± 1%       259µs ± 1%   +1.09%  (p=0.008 n=5+5)
deco/neo/py(!log)/sql/zhash.go+prefetch128          410µs ± 1%       153µs ± 4%  -62.70%  (p=0.008 n=5+5)
deco/neo/py(!log)/sql/zhash.go-P16                 2.50ms ± 0%      2.46ms ± 0%   -1.71%  (p=0.000 n=16+14)
deco/neo/go/zhash.py                                165µs ± 6%       167µs ± 4%     ~     (p=0.841 n=5+5)
deco/neo/go/zhash.py-P16                           1.64ms ± 9%      1.64ms ±11%     ~     (p=0.926 n=16+16)
deco/neo/go/zhash.go                               32.1µs ± 1%      34.0µs ± 1%   +5.92%  (p=0.008 n=5+5)
deco/neo/go/zhash.go+prefetch128                   49.3µs ± 1%      18.0µs ± 5%  -63.57%  (p=0.008 n=5+5)
deco/neo/go/zhash.go-P16                            234µs ±16%       247µs ±15%   +5.78%  (p=0.019 n=15+16)
deco/neo/go(!sha1)/zhash.go                        20.1µs ± 2%      22.5µs ± 1%  +11.84%  (p=0.008 n=5+5)
deco/neo/go(!sha1)/zhash.go+prefetch128            31.3µs ± 2%      12.0µs ± 5%  -61.84%  (p=0.008 n=5+5)
deco/neo/go(!sha1)/zhash.go-P16                     145µs ±17%       166µs ±11%  +15.15%  (p=0.000 n=16+15)

dataset:prod1-1024
deco/fs1/zhash.py                                  11.9µs ± 3%      11.9µs ± 1%     ~     (p=0.508 n=5+5)
deco/fs1/zhash.py-P16                               104µs ± 9%       102µs ±12%     ~     (p=0.505 n=14+16)
deco/fs1/zhash.go                                  1.10µs ± 0%      1.80µs ± 0%  +63.64%  (p=0.008 n=5+5)
deco/fs1/zhash.go+prefetch128                      2.90µs ±14%      2.60µs ±23%     ~     (p=0.087 n=5+5)
deco/fs1/zhash.go-P16                             3.12µs ±131%      5.21µs ±92%  +66.93%  (p=0.005 n=16+16)
deco/zeo/zhash.py                                   277µs ± 5%       291µs ± 7%     ~     (p=0.151 n=5+5)
deco/zeo/zhash.py-P16                              2.61ms ± 4%      2.59ms ± 6%     ~     (p=0.854 n=14+16)
deco/neo/py/sqlite/zhash.py                         289µs ± 6%       283µs ± 3%     ~     (p=0.421 n=5+5)
deco/neo/py/sqlite/zhash.py-P16                    2.84ms ± 1%      2.79ms ± 1%   -1.77%  (p=0.000 n=16+16)
deco/neo/py/sqlite/zhash.go                         146µs ± 2%       149µs ± 2%   +2.22%  (p=0.024 n=5+5)
deco/neo/py/sqlite/zhash.go+prefetch128             267µs ± 1%       113µs ± 2%  -57.81%  (p=0.008 n=5+5)
deco/neo/py/sqlite/zhash.go-P16                    2.02ms ± 0%      2.01ms ± 0%   -0.70%  (p=0.000 n=15+14)
deco/neo/py(!log)/sqlite/zhash.py                   270µs ± 3%       266µs ± 2%     ~     (p=0.151 n=5+5)
deco/neo/py(!log)/sqlite/zhash.py-P16              2.59ms ± 2%      2.58ms ± 2%     ~     (p=0.564 n=16+16)
deco/neo/py(!log)/sqlite/zhash.go                   134µs ± 0%       136µs ± 2%     ~     (p=0.143 n=4+5)
deco/neo/py(!log)/sqlite/zhash.go+prefetch128       233µs ± 0%        96µs ± 1%  -59.00%  (p=0.008 n=5+5)
deco/neo/py(!log)/sqlite/zhash.go-P16              1.73ms ± 0%      1.71ms ± 0%   -1.49%  (p=0.000 n=14+15)
deco/neo/py/sql/zhash.py                            314µs ± 4%       322µs ± 4%     ~     (p=0.343 n=4+4)
deco/neo/py/sql/zhash.py-P16                       3.70ms ± 0%      3.60ms ± 0%   -2.74%  (p=0.000 n=15+16)
deco/neo/py/sql/zhash.go                            194µs ± 0%       197µs ± 2%     ~     (p=0.159 n=4+5)
deco/neo/py/sql/zhash.go+prefetch128                358µs ± 1%       159µs ± 1%  -55.50%  (p=0.008 n=5+5)
deco/neo/py/sql/zhash.go-P16                       2.63ms ± 0%      2.67ms ± 0%   +1.46%  (p=0.000 n=14+13)
deco/neo/py(!log)/sql/zhash.py                      300µs ± 5%       298µs ± 2%     ~     (p=1.000 n=4+4)
deco/neo/py(!log)/sql/zhash.py-P16                 3.47ms ± 0%      3.35ms ± 0%   -3.29%  (p=0.000 n=15+13)
deco/neo/py(!log)/sql/zhash.go                      175µs ± 0%       180µs ± 0%   +2.64%  (p=0.008 n=5+5)
deco/neo/py(!log)/sql/zhash.go+prefetch128          316µs ± 1%       137µs ± 1%  -56.61%  (p=0.008 n=5+5)
deco/neo/py(!log)/sql/zhash.go-P16                 2.33ms ± 0%      2.37ms ± 0%   +1.74%  (p=0.000 n=13+15)
deco/neo/go/zhash.py                                158µs ± 4%       155µs ± 4%     ~     (p=0.421 n=5+5)
deco/neo/go/zhash.py-P16                           1.64ms ± 8%      1.67ms ± 5%   +2.32%  (p=0.018 n=15+15)
deco/neo/go/zhash.go                               24.1µs ± 1%      26.0µs ± 1%   +7.97%  (p=0.008 n=5+5)
deco/neo/go/zhash.go+prefetch128                   37.1µs ± 2%      12.3µs ± 3%  -66.72%  (p=0.008 n=5+5)
deco/neo/go/zhash.go-P16                            228µs ±11%       253µs ± 9%  +10.77%  (p=0.000 n=15+14)
deco/neo/go(!sha1)/zhash.go                        19.1µs ± 1%      21.5µs ± 2%  +12.59%  (p=0.008 n=5+5)
deco/neo/go(!sha1)/zhash.go+prefetch128            29.3µs ± 3%      10.0µs ± 3%  -65.82%  (p=0.008 n=5+5)
deco/neo/go(!sha1)/zhash.go-P16                     171µs ± 8%       209µs ±15%  +22.59%  (p=0.000 n=15+16)

go/zodb/cache.go

@@ -34,6 +34,7 @@ import (
 
 // XXX managing LRU under 1 big gcMu might be bad for scalability.
 // TODO maintain nhit / nmiss + way to read cache stats
+// TODO optimize cache more so that miss overhead becomes negligible
 
 // Cache provides RAM caching layer that can be used over a storage.
 type Cache struct {

go/zodb/open.go

@@ -82,7 +82,7 @@ func OpenStorage(ctx context.Context, storageURL string, opt *OpenOptions) (ISto
 		IStorageDriver: storDriver,
 
 		// small cache so that prefetch can work for loading
-		l1cache: NewCache(storDriver, 16 << 20),	// XXX 16MB hardcoded
+		l1cache: NewCache(storDriver, 128 * 4*1024),	// XXX 512K hardcoded (= ~ 128 · 4K-entries)
 	}, nil
 }