Commits · 87b1102c6f3707e19c5d45933f669fe851b3766e · Stefane Fermigier / neo

09 Jan, 2018 3 commits

X zodb: Move Buf to lab.nexedi.com/kirr/go123/mem · 87b1102c
Kirill Smelkov authored Jan 09, 2018

87b1102c

Merge remote-tracking branch 'origin/master' into t · 75a71514

Kirill Smelkov authored Jan 09, 2018

* origin/master:
  debug: add helper to run code outside the signal handler
  Preserve 'packed' flag on import/iteration
  fixup! storage: speed up replication by not getting object next_serial for nothing
  client: fix accounting of cache size
  doc: comments, fixups

75a71514

X zodb/cache: Speedup checkpoint · 64ede21c

Kirill Smelkov authored Jan 09, 2018

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)

64ede21c

08 Jan, 2018 3 commits

X zodb/cache: Allocate OCE from freelist · fbca5755

Kirill Smelkov authored Jan 08, 2018

This avoid 2 allocations (for oidCacheEntry and for its .revv) for NoHit
cache in steady state, speeding things up a bit via lowering pressure on
go gc.

Startup time increase could be either ignored (because it is only when
N(access) < N(cache-size)) or handled later via explicitly preallocating
OCE pool on cache creation.

---- 8< ----

name old time/op new time/op delta
NoopStorage 56.6ns ± 1% 57.0ns ± 0% +0.77% (p=0.100 n=3+3)
NoopStorage-4 56.4ns ± 0% 57.1ns ± 0% +1.24% (p=0.100 n=3+3)
CacheStartup 1.95µs ± 2% 1.91µs ±10% ~ (p=0.700 n=3+3)
CacheStartup-4 1.31µs ± 5% 1.47µs ± 2% +11.48% (p=0.100 n=3+3)
CacheNoHit/size=0 590ns ± 1% 502ns ± 1% -14.81% (p=0.100 n=3+3)
CacheNoHit/size=0-4 591ns ± 1% 502ns ± 0% -15.06% (p=0.100 n=3+3)
CacheNoHit/size=16 707ns ± 0% 622ns ± 1% -11.98% (p=0.100 n=3+3)
CacheNoHit/size=16-4 711ns ± 1% 623ns ± 1% -12.34% (p=0.100 n=3+3)
CacheNoHit/size=128 717ns ± 0% 624ns ± 0% -12.88% (p=0.100 n=3+3)
CacheNoHit/size=128-4 716ns ± 0% 630ns ± 1% -12.10% (p=0.100 n=3+3)
CacheNoHit/size=512 737ns ± 0% 645ns ± 0% -12.40% (p=0.100 n=3+3)
CacheNoHit/size=512-4 721ns ± 0% 636ns ± 1% -11.84% (p=0.100 n=3+3)
CacheNoHit/size=4096 946ns ± 1% 782ns ± 0% -17.30% (p=0.100 n=3+3)
CacheNoHit/size=4096-4 780ns ± 1% 680ns ± 0% -12.86% (p=0.100 n=3+3)
CacheHit/size=0 589ns ± 1% 507ns ± 0% -13.98% (p=0.100 n=3+3)
CacheHit/size=0-4 588ns ± 0% 503ns ± 1% -14.50% (p=0.100 n=3+3)
CacheHit/size=16 122ns ± 1% 121ns ± 1% ~ (p=0.500 n=3+3)
CacheHit/size=16-4 123ns ± 1% 124ns ± 2% ~ (p=1.000 n=3+3)
CacheHit/size=128 127ns ± 2% 124ns ± 1% ~ (p=0.200 n=3+3)
CacheHit/size=128-4 126ns ± 1% 126ns ± 1% ~ (p=0.600 n=3+3)
CacheHit/size=512 128ns ± 2% 127ns ± 1% ~ (p=0.300 n=3+3)
CacheHit/size=512-4 127ns ± 1% 126ns ± 0% -1.05% (p=0.100 n=3+3)
CacheHit/size=4096 130ns ± 0% 130ns ± 3% ~ (p=0.700 n=3+3)
CacheHit/size=4096-4 130ns ± 1% 129ns ± 1% ~ (p=0.300 n=3+3)
NoopStoragePar 59.7ns ± 3% 57.0ns ± 0% -4.47% (p=0.100 n=3+3)
NoopStoragePar-4 31.3ns ± 8% 30.7ns ± 5% ~ (p=1.000 n=3+3)
CacheStartupPar 1.97µs ±13% 2.19µs ±10% ~ (p=0.400 n=3+3)
CacheStartupPar-4 1.49µs ± 4% 1.71µs ± 4% +14.44% (p=0.100 n=3+3)
CacheNoHitPar/size=0 591ns ± 0% 510ns ± 0% -13.65% (p=0.100 n=3+3)
CacheNoHitPar/size=0-4 811ns ± 0% 726ns ± 0% -10.40% (p=0.100 n=3+3)
CacheNoHitPar/size=16 713ns ± 0% 621ns ± 0% -12.95% (p=0.100 n=3+3)
CacheNoHitPar/size=16-4 924ns ± 0% 826ns ± 0% -10.67% (p=0.100 n=3+3)
CacheNoHitPar/size=128 717ns ± 0% 629ns ± 0% -12.23% (p=0.100 n=3+3)
CacheNoHitPar/size=128-4 953ns ± 0% 848ns ± 0% -11.02% (p=0.100 n=3+3)
CacheNoHitPar/size=512 733ns ± 0% 645ns ± 0% -12.00% (p=0.100 n=3+3)
CacheNoHitPar/size=512-4 972ns ± 0% 881ns ± 0% -9.36% (p=0.100 n=3+3)
CacheNoHitPar/size=4096 941ns ± 0% 788ns ± 0% -16.29% (p=0.100 n=3+3)
CacheNoHitPar/size=4096-4 1.07µs ± 0% 0.96µs ± 0% -10.30% (p=0.100 n=3+3)
CacheHitPar/size=0 587ns ± 0% 509ns ± 0% -13.23% (p=0.100 n=3+3)
CacheHitPar/size=0-4 805ns ± 0% 722ns ± 0% -10.31% (p=0.100 n=3+3)
CacheHitPar/size=16 122ns ± 1% 123ns ± 2% ~ (p=1.000 n=3+3)
CacheHitPar/size=16-4 236ns ± 1% 216ns ± 0% -8.74% (p=0.100 n=3+3)
CacheHitPar/size=128 125ns ± 1% 125ns ± 1% ~ (p=1.000 n=3+3)
CacheHitPar/size=128-4 220ns ± 0% 207ns ± 0% -6.06% (p=0.100 n=3+3)
CacheHitPar/size=512 127ns ± 2% 127ns ± 1% ~ (p=0.600 n=3+3)
CacheHitPar/size=512-4 219ns ± 0% 228ns ± 5% ~ (p=0.600 n=3+3)
CacheHitPar/size=4096 129ns ± 1% 129ns ± 0% ~ (p=1.000 n=3+3)
CacheHitPar/size=4096-4 223ns ± 5% 223ns ± 4% ~ (p=1.000 n=3+3)
NoopStorageProc 54.7ns ± 0% 55.1ns ± 0% +0.67% (p=0.100 n=3+3)
NoopStorageProc-4 31.8ns ± 4% 29.5ns ± 1% -7.14% (p=0.100 n=3+3)
CacheStartupProc 1.88µs ±11% 2.15µs ±11% ~ (p=0.400 n=3+3)
CacheStartupProc-4 1.13µs ± 3% 1.23µs ± 4% +9.04% (p=0.100 n=3+3)
CacheNoHitProc/size=0 598ns ± 0% 500ns ± 0% -16.33% (p=0.100 n=3+3)
CacheNoHitProc/size=0-4 309ns ± 0% 297ns ± 1% -3.89% (p=0.100 n=3+3)
CacheNoHitProc/size=16 711ns ± 0% 615ns ± 0% -13.55% (p=0.100 n=3+3)
CacheNoHitProc/size=16-4 356ns ± 0% 314ns ± 0% -11.88% (p=0.100 n=3+3)
CacheNoHitProc/size=128 722ns ± 1% 622ns ± 0% -13.90% (p=0.100 n=3+3)
CacheNoHitProc/size=128-4 363ns ± 0% 311ns ± 0% -14.25% (p=0.100 n=3+3)
CacheNoHitProc/size=512 741ns ± 1% 640ns ± 0% -13.67% (p=0.100 n=3+3)
CacheNoHitProc/size=512-4 394ns ± 0% 331ns ± 0% -16.06% (p=0.100 n=3+3)
CacheNoHitProc/size=4096 943ns ± 0% 782ns ± 1% -17.04% (p=0.100 n=3+3)
CacheNoHitProc/size=4096-4 565ns ± 0% 462ns ± 0% -18.28% (p=0.100 n=3+3)
CacheHitProc/size=0 598ns ± 0% 498ns ± 0% -16.67% (p=0.100 n=3+3)
CacheHitProc/size=0-4 310ns ± 0% 291ns ± 0% -5.92% (p=0.100 n=3+3)
CacheHitProc/size=16 120ns ± 1% 120ns ± 1% ~ (p=0.600 n=3+3)
CacheHitProc/size=16-4 57.5ns ± 2% 57.2ns ± 1% ~ (p=1.000 n=3+3)
CacheHitProc/size=128 123ns ± 1% 123ns ± 1% ~ (p=1.000 n=3+3)
CacheHitProc/size=128-4 58.1ns ± 0% 57.9ns ± 0% ~ (p=0.200 n=3+3)
CacheHitProc/size=512 126ns ± 2% 126ns ± 1% ~ (p=1.000 n=3+3)
CacheHitProc/size=512-4 58.6ns ± 0% 58.6ns ± 0% ~ (p=1.000 n=3+3)
CacheHitProc/size=4096 128ns ± 1% 127ns ± 1% ~ (p=1.000 n=3+3)
CacheHitProc/size=4096-4 69.8ns ± 0% 70.6ns ± 1% +1.15% (p=0.100 n=3+3)

name old alloc/op new alloc/op delta
NoopStorage 0.00B 0.00B ~ (all equal)
NoopStorage-4 0.00B 0.00B ~ (all equal)
CacheStartup 285B ± 0% 285B ± 0% ~ (all equal)
CacheStartup-4 285B ± 0% 285B ± 0% ~ (all equal)
CacheNoHit/size=0 152B ± 0% 96B ± 0% -36.84% (p=0.100 n=3+3)
CacheNoHit/size=0-4 152B ± 0% 96B ± 0% -36.84% (p=0.100 n=3+3)
CacheNoHit/size=16 153B ± 0% 97B ± 0% -36.60% (p=0.100 n=3+3)
CacheNoHit/size=16-4 153B ± 0% 97B ± 0% -36.60% (p=0.100 n=3+3)
CacheNoHit/size=128 153B ± 0% 97B ± 0% -36.60% (p=0.100 n=3+3)
CacheNoHit/size=128-4 153B ± 0% 97B ± 0% -36.60% (p=0.100 n=3+3)
CacheNoHit/size=512 153B ± 0% 97B ± 0% -36.46% (p=0.100 n=3+3)
CacheNoHit/size=512-4 153B ± 0% 97B ± 0% -36.60% (p=0.100 n=3+3)
CacheNoHit/size=4096 153B ± 0% 97B ± 0% -36.60% (p=0.100 n=3+3)
CacheNoHit/size=4096-4 153B ± 0% 97B ± 0% -36.46% (p=0.100 n=3+3)
CacheHit/size=0 152B ± 0% 96B ± 0% -36.84% (p=0.100 n=3+3)
CacheHit/size=0-4 152B ± 0% 96B ± 0% -36.84% (p=0.100 n=3+3)
CacheHit/size=16 0.00B 0.00B ~ (all equal)
CacheHit/size=16-4 0.00B 0.00B ~ (all equal)
CacheHit/size=128 0.00B 0.00B ~ (all equal)
CacheHit/size=128-4 0.00B 0.00B ~ (all equal)
CacheHit/size=512 0.00B 0.00B ~ (all equal)
CacheHit/size=512-4 0.00B 0.00B ~ (all equal)
CacheHit/size=4096 0.00B 0.00B ~ (all equal)
CacheHit/size=4096-4 0.00B 0.00B ~ (all equal)
NoopStoragePar 0.00B 0.00B ~ (all equal)
NoopStoragePar-4 0.00B 0.00B ~ (all equal)
CacheStartupPar 285B ± 0% 285B ± 0% ~ (all equal)
CacheStartupPar-4 282B ± 0% 282B ± 1% ~ (p=1.000 n=3+3)
CacheNoHitPar/size=0 152B ± 0% 96B ± 0% -36.84% (p=0.100 n=3+3)
CacheNoHitPar/size=0-4 152B ± 0% 96B ± 0% -36.84% (p=0.100 n=3+3)
CacheNoHitPar/size=16 153B ± 0% 97B ± 0% -36.60% (p=0.100 n=3+3)
CacheNoHitPar/size=16-4 154B ± 0% 98B ± 0% -36.36% (p=0.100 n=3+3)
CacheNoHitPar/size=128 153B ± 0% 97B ± 0% -36.60% (p=0.100 n=3+3)
CacheNoHitPar/size=128-4 153B ± 0% 97B ± 0% -36.60% (p=0.100 n=3+3)
CacheNoHitPar/size=512 153B ± 0% 97B ± 1% -36.82% (p=0.100 n=3+3)
CacheNoHitPar/size=512-4 153B ± 0% 97B ± 0% -36.60% (p=0.100 n=3+3)
CacheNoHitPar/size=4096 153B ± 0% 97B ± 0% -36.60% (p=0.100 n=3+3)
CacheNoHitPar/size=4096-4 153B ± 0% 97B ± 0% -36.60% (p=0.100 n=3+3)
CacheHitPar/size=0 152B ± 0% 96B ± 0% -36.84% (p=0.100 n=3+3)
CacheHitPar/size=0-4 152B ± 0% 96B ± 0% -36.84% (p=0.100 n=3+3)
CacheHitPar/size=16 0.00B 0.00B ~ (all equal)
CacheHitPar/size=16-4 0.00B 0.00B ~ (all equal)
CacheHitPar/size=128 0.00B 0.00B ~ (all equal)
CacheHitPar/size=128-4 0.00B 0.00B ~ (all equal)
CacheHitPar/size=512 0.00B 0.00B ~ (all equal)
CacheHitPar/size=512-4 0.00B 0.00B ~ (all equal)
CacheHitPar/size=4096 0.00B 0.00B ~ (all equal)
CacheHitPar/size=4096-4 0.00B 0.00B ~ (all equal)
NoopStorageProc 0.00B 0.00B ~ (all equal)
NoopStorageProc-4 0.00B 0.00B ~ (all equal)
CacheStartupProc 285B ± 0% 285B ± 0% ~ (all equal)
CacheStartupProc-4 285B ± 0% 285B ± 0% ~ (all equal)
CacheNoHitProc/size=0 152B ± 0% 96B ± 0% -36.84% (p=0.100 n=3+3)
CacheNoHitProc/size=0-4 152B ± 0% 96B ± 0% -36.84% (p=0.100 n=3+3)
CacheNoHitProc/size=16 153B ± 0% 97B ± 0% -36.60% (p=0.100 n=3+3)
CacheNoHitProc/size=16-4 153B ± 0% 97B ± 0% -36.60% (p=0.100 n=3+3)
CacheNoHitProc/size=128 153B ± 0% 97B ± 0% -36.60% (p=0.100 n=3+3)
CacheNoHitProc/size=128-4 153B ± 0% 97B ± 0% -36.60% (p=0.100 n=3+3)
CacheNoHitProc/size=512 153B ± 0% 96B ± 1% -37.04% (p=0.100 n=3+3)
CacheNoHitProc/size=512-4 153B ± 0% 97B ± 0% -36.60% (p=0.100 n=3+3)
CacheNoHitProc/size=4096 153B ± 0% 97B ± 0% -36.60% (p=0.100 n=3+3)
CacheNoHitProc/size=4096-4 153B ± 0% 97B ± 0% -36.60% (p=0.100 n=3+3)
CacheHitProc/size=0 152B ± 0% 96B ± 0% -36.84% (p=0.100 n=3+3)
CacheHitProc/size=0-4 152B ± 0% 96B ± 0% -36.84% (p=0.100 n=3+3)
CacheHitProc/size=16 0.00B 0.00B ~ (all equal)
CacheHitProc/size=16-4 0.00B 0.00B ~ (all equal)
CacheHitProc/size=128 0.00B 0.00B ~ (all equal)
CacheHitProc/size=128-4 0.00B 0.00B ~ (all equal)
CacheHitProc/size=512 0.00B 0.00B ~ (all equal)
CacheHitProc/size=512-4 0.00B 0.00B ~ (all equal)
CacheHitProc/size=4096 0.00B 0.00B ~ (all equal)
CacheHitProc/size=4096-4 0.00B 0.00B ~ (all equal)

name old allocs/op new allocs/op delta
NoopStorage 0.00 0.00 ~ (all equal)
NoopStorage-4 0.00 0.00 ~ (all equal)
CacheStartup 5.00 ± 0% 5.00 ± 0% ~ (all equal)
CacheStartup-4 5.00 ± 0% 5.00 ± 0% ~ (all equal)
CacheNoHit/size=0 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheNoHit/size=0-4 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheNoHit/size=16 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheNoHit/size=16-4 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheNoHit/size=128 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheNoHit/size=128-4 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheNoHit/size=512 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheNoHit/size=512-4 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheNoHit/size=4096 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheNoHit/size=4096-4 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheHit/size=0 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheHit/size=0-4 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheHit/size=16 0.00 0.00 ~ (all equal)
CacheHit/size=16-4 0.00 0.00 ~ (all equal)
CacheHit/size=128 0.00 0.00 ~ (all equal)
CacheHit/size=128-4 0.00 0.00 ~ (all equal)
CacheHit/size=512 0.00 0.00 ~ (all equal)
CacheHit/size=512-4 0.00 0.00 ~ (all equal)
CacheHit/size=4096 0.00 0.00 ~ (all equal)
CacheHit/size=4096-4 0.00 0.00 ~ (all equal)
NoopStoragePar 0.00 0.00 ~ (all equal)
NoopStoragePar-4 0.00 0.00 ~ (all equal)
CacheStartupPar 5.00 ± 0% 5.00 ± 0% ~ (all equal)
CacheStartupPar-4 4.00 ± 0% 4.33 ±15% ~ (p=1.000 n=3+3)
CacheNoHitPar/size=0 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheNoHitPar/size=0-4 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheNoHitPar/size=16 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheNoHitPar/size=16-4 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheNoHitPar/size=128 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheNoHitPar/size=128-4 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheNoHitPar/size=512 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheNoHitPar/size=512-4 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheNoHitPar/size=4096 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheNoHitPar/size=4096-4 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheHitPar/size=0 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheHitPar/size=0-4 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheHitPar/size=16 0.00 0.00 ~ (all equal)
CacheHitPar/size=16-4 0.00 0.00 ~ (all equal)
CacheHitPar/size=128 0.00 0.00 ~ (all equal)
CacheHitPar/size=128-4 0.00 0.00 ~ (all equal)
CacheHitPar/size=512 0.00 0.00 ~ (all equal)
CacheHitPar/size=512-4 0.00 0.00 ~ (all equal)
CacheHitPar/size=4096 0.00 0.00 ~ (all equal)
CacheHitPar/size=4096-4 0.00 0.00 ~ (all equal)
NoopStorageProc 0.00 0.00 ~ (all equal)
NoopStorageProc-4 0.00 0.00 ~ (all equal)
CacheStartupProc 5.00 ± 0% 5.00 ± 0% ~ (all equal)
CacheStartupProc-4 5.00 ± 0% 5.00 ± 0% ~ (all equal)
CacheNoHitProc/size=0 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheNoHitProc/size=0-4 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheNoHitProc/size=16 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheNoHitProc/size=16-4 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheNoHitProc/size=128 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheNoHitProc/size=128-4 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheNoHitProc/size=512 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheNoHitProc/size=512-4 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheNoHitProc/size=4096 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheNoHitProc/size=4096-4 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheHitProc/size=0 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheHitProc/size=0-4 3.00 ± 0% 1.00 ± 0% -66.67% (p=0.100 n=3+3)
CacheHitProc/size=16 0.00 0.00 ~ (all equal)
CacheHitProc/size=16-4 0.00 0.00 ~ (all equal)
CacheHitProc/size=128 0.00 0.00 ~ (all equal)
CacheHitProc/size=128-4 0.00 0.00 ~ (all equal)
CacheHitProc/size=512 0.00 0.00 ~ (all equal)
CacheHitProc/size=512-4 0.00 0.00 ~ (all equal)
CacheHitProc/size=4096 0.00 0.00 ~ (all equal)
CacheHitProc/size=4096-4 0.00 0.00 ~ (all equal)

fbca5755

X zodb/cache: Kill cache-gc tracepoint · 13f149f0

Kirill Smelkov authored Jan 08, 2018

On NoHit workloads gc is invoked for every load and since cache's goal
is to provide minimum slowdown the tracepoint overhead becomes visible.

Cache gc tracepoints were initially added for testing - to be able to
wait for gc to start/finish - when gc was running in its own goroutine,
but now, after 0e2be3b3 (X zodb/cache: Performing GC in separate
goroutine was actually a bad idea), when gc is running synchronously
there is need for this tracing events even from testing point of view.

So remove them.

---- 8< ----

name old time/op new time/op delta
NoopStorage 57.9ns ± 1% 56.6ns ± 1% -2.30% (p=0.100 n=3+3)
NoopStorage-4 57.4ns ± 1% 56.4ns ± 0% -1.68% (p=0.100 n=3+3)
CacheStartup 2.13µs ±16% 1.95µs ± 2% ~ (p=0.700 n=3+3)
CacheStartup-4 1.29µs ± 4% 1.31µs ± 5% ~ (p=0.700 n=3+3)
CacheNoHit/size=0 677ns ± 1% 590ns ± 1% -12.86% (p=0.100 n=3+3)
CacheNoHit/size=0-4 664ns ± 1% 591ns ± 1% -11.04% (p=0.100 n=3+3)
CacheNoHit/size=16 792ns ± 0% 707ns ± 0% -10.81% (p=0.100 n=3+3)
CacheNoHit/size=16-4 788ns ± 0% 711ns ± 1% -9.85% (p=0.100 n=3+3)
CacheNoHit/size=128 796ns ± 0% 717ns ± 0% -9.93% (p=0.100 n=3+3)
CacheNoHit/size=128-4 795ns ± 1% 716ns ± 0% -9.86% (p=0.100 n=3+3)
CacheNoHit/size=512 816ns ± 0% 737ns ± 0% -9.69% (p=0.100 n=3+3)
CacheNoHit/size=512-4 803ns ± 0% 721ns ± 0% -10.25% (p=0.100 n=3+3)
CacheNoHit/size=4096 1.05µs ± 1% 0.95µs ± 1% -10.13% (p=0.100 n=3+3)
CacheNoHit/size=4096-4 856ns ± 0% 780ns ± 1% -8.91% (p=0.100 n=3+3)
CacheHit/size=0 664ns ± 0% 589ns ± 1% -11.34% (p=0.100 n=3+3)
CacheHit/size=0-4 660ns ± 0% 588ns ± 0% -10.86% (p=0.100 n=3+3)
CacheHit/size=16 123ns ± 4% 122ns ± 1% ~ (p=0.800 n=3+3)
CacheHit/size=16-4 121ns ± 1% 123ns ± 1% ~ (p=0.300 n=3+3)
CacheHit/size=128 124ns ± 1% 127ns ± 2% +2.70% (p=0.100 n=3+3)
CacheHit/size=128-4 124ns ± 1% 126ns ± 1% +2.16% (p=0.100 n=3+3)
CacheHit/size=512 126ns ± 1% 128ns ± 2% ~ (p=0.400 n=3+3)
CacheHit/size=512-4 125ns ± 1% 127ns ± 1% +1.60% (p=0.100 n=3+3)
CacheHit/size=4096 127ns ± 1% 130ns ± 0% +2.09% (p=0.100 n=3+3)
CacheHit/size=4096-4 128ns ± 1% 130ns ± 1% +1.56% (p=0.100 n=3+3)
NoopStoragePar 59.2ns ± 1% 59.7ns ± 3% ~ (p=1.000 n=3+3)
NoopStoragePar-4 31.2ns ± 8% 31.3ns ± 8% ~ (p=1.000 n=3+3)
CacheStartupPar 2.04µs ± 6% 1.97µs ±13% ~ (p=1.000 n=3+3)
CacheStartupPar-4 1.48µs ± 3% 1.49µs ± 4% ~ (p=0.700 n=3+3)
CacheNoHitPar/size=0 670ns ± 0% 591ns ± 0% -11.75% (p=0.100 n=3+3)
CacheNoHitPar/size=0-4 904ns ± 0% 811ns ± 0% -10.32% (p=0.100 n=3+3)
CacheNoHitPar/size=16 789ns ± 0% 713ns ± 0% -9.63% (p=0.100 n=3+3)
CacheNoHitPar/size=16-4 1.03µs ± 0% 0.92µs ± 0% -10.06% (p=0.100 n=3+3)
CacheNoHitPar/size=128 800ns ± 0% 717ns ± 0% -10.45% (p=0.100 n=3+3)
CacheNoHitPar/size=128-4 1.04µs ± 0% 0.95µs ± 0% -8.63% (p=0.100 n=3+3)
CacheNoHitPar/size=512 818ns ± 0% 733ns ± 0% -10.35% (p=0.100 n=3+3)
CacheNoHitPar/size=512-4 1.07µs ± 0% 0.97µs ± 0% -9.04% (p=0.100 n=3+3)
CacheNoHitPar/size=4096 1.06µs ± 1% 0.94µs ± 0% -11.50% (p=0.100 n=3+3)
CacheNoHitPar/size=4096-4 1.17µs ± 1% 1.07µs ± 0% -7.89% (p=0.100 n=3+3)
CacheHitPar/size=0 665ns ± 0% 587ns ± 0% -11.69% (p=0.100 n=3+3)
CacheHitPar/size=0-4 903ns ± 1% 805ns ± 0% -10.85% (p=0.100 n=3+3)
CacheHitPar/size=16 124ns ± 1% 122ns ± 1% ~ (p=0.200 n=3+3)
CacheHitPar/size=16-4 217ns ± 1% 236ns ± 1% +8.74% (p=0.100 n=3+3)
CacheHitPar/size=128 125ns ± 0% 125ns ± 1% ~ (p=1.000 n=3+3)
CacheHitPar/size=128-4 215ns ± 1% 220ns ± 0% +2.48% (p=0.100 n=3+3)
CacheHitPar/size=512 127ns ± 1% 127ns ± 2% ~ (p=0.600 n=3+3)
CacheHitPar/size=512-4 241ns ± 0% 219ns ± 0% -9.14% (p=0.100 n=3+3)
CacheHitPar/size=4096 129ns ± 0% 129ns ± 1% ~ (p=1.000 n=3+3)
CacheHitPar/size=4096-4 236ns ± 4% 223ns ± 5% ~ (p=0.200 n=3+3)
NoopStorageProc 56.1ns ± 0% 54.7ns ± 0% -2.44% (p=0.100 n=3+3)
NoopStorageProc-4 37.1ns ±10% 31.8ns ± 4% -14.45% (p=0.100 n=3+3)
CacheStartupProc 1.79µs ± 3% 1.88µs ±11% ~ (p=0.700 n=3+3)
CacheStartupProc-4 1.08µs ± 7% 1.13µs ± 3% ~ (p=0.400 n=3+3)
CacheNoHitProc/size=0 669ns ± 0% 598ns ± 0% -10.66% (p=0.100 n=3+3)
CacheNoHitProc/size=0-4 414ns ±15% 309ns ± 0% -25.38% (p=0.100 n=3+3)
CacheNoHitProc/size=16 792ns ± 0% 711ns ± 0% -10.27% (p=0.100 n=3+3)
CacheNoHitProc/size=16-4 440ns ± 7% 356ns ± 0% -19.02% (p=0.100 n=3+3)
CacheNoHitProc/size=128 808ns ± 0% 722ns ± 1% -10.61% (p=0.100 n=3+3)
CacheNoHitProc/size=128-4 467ns ± 8% 363ns ± 0% -22.29% (p=0.100 n=3+3)
CacheNoHitProc/size=512 834ns ± 1% 741ns ± 1% -11.08% (p=0.100 n=3+3)
CacheNoHitProc/size=512-4 499ns ± 9% 394ns ± 0% -20.98% (p=0.100 n=3+3)
CacheNoHitProc/size=4096 1.07µs ± 0% 0.94µs ± 0% -11.71% (p=0.100 n=3+3)
CacheNoHitProc/size=4096-4 629ns ± 3% 565ns ± 0% -10.12% (p=0.100 n=3+3)
CacheHitProc/size=0 669ns ± 0% 598ns ± 0% -10.61% (p=0.100 n=3+3)
CacheHitProc/size=0-4 381ns ± 2% 310ns ± 0% -18.72% (p=0.100 n=3+3)
CacheHitProc/size=16 121ns ± 1% 120ns ± 1% ~ (p=0.400 n=3+3)
CacheHitProc/size=16-4 65.0ns ± 3% 57.5ns ± 2% -11.59% (p=0.100 n=3+3)
CacheHitProc/size=128 124ns ± 0% 123ns ± 1% ~ (p=0.700 n=3+3)
CacheHitProc/size=128-4 74.9ns ± 3% 58.1ns ± 0% -22.44% (p=0.100 n=3+3)
CacheHitProc/size=512 125ns ± 1% 126ns ± 2% ~ (p=0.600 n=3+3)
CacheHitProc/size=512-4 71.5ns ± 2% 58.6ns ± 0% -17.96% (p=0.100 n=3+3)
CacheHitProc/size=4096 132ns ± 6% 128ns ± 1% ~ (p=0.600 n=3+3)
CacheHitProc/size=4096-4 80.5ns ± 7% 69.8ns ± 0% -13.30% (p=0.100 n=3+3)

name old alloc/op new alloc/op delta
NoopStorage 0.00B 0.00B ~ (all equal)
NoopStorage-4 0.00B 0.00B ~ (all equal)
CacheStartup 285B ± 0% 285B ± 0% ~ (all equal)
CacheStartup-4 285B ± 0% 285B ± 0% ~ (all equal)
CacheNoHit/size=0 152B ± 0% 152B ± 0% ~ (all equal)
CacheNoHit/size=0-4 152B ± 0% 152B ± 0% ~ (all equal)
CacheNoHit/size=16 153B ± 0% 153B ± 0% ~ (all equal)
CacheNoHit/size=16-4 153B ± 0% 153B ± 0% ~ (all equal)
CacheNoHit/size=128 153B ± 0% 153B ± 0% ~ (all equal)
CacheNoHit/size=128-4 153B ± 0% 153B ± 0% ~ (all equal)
CacheNoHit/size=512 153B ± 0% 153B ± 0% ~ (p=1.000 n=3+3)
CacheNoHit/size=512-4 153B ± 0% 153B ± 0% ~ (all equal)
CacheNoHit/size=4096 153B ± 0% 153B ± 0% ~ (all equal)
CacheNoHit/size=4096-4 152B ± 0% 153B ± 0% ~ (p=1.000 n=3+3)
CacheHit/size=0 152B ± 0% 152B ± 0% ~ (all equal)
CacheHit/size=0-4 152B ± 0% 152B ± 0% ~ (all equal)
CacheHit/size=16 0.00B 0.00B ~ (all equal)
CacheHit/size=16-4 0.00B 0.00B ~ (all equal)
CacheHit/size=128 0.00B 0.00B ~ (all equal)
CacheHit/size=128-4 0.00B 0.00B ~ (all equal)
CacheHit/size=512 0.00B 0.00B ~ (all equal)
CacheHit/size=512-4 0.00B 0.00B ~ (all equal)
CacheHit/size=4096 0.00B 0.00B ~ (all equal)
CacheHit/size=4096-4 0.00B 0.00B ~ (all equal)
NoopStoragePar 0.00B 0.00B ~ (all equal)
NoopStoragePar-4 0.00B 0.00B ~ (all equal)
CacheStartupPar 285B ± 0% 285B ± 0% ~ (all equal)
CacheStartupPar-4 281B ± 0% 282B ± 0% ~ (p=0.300 n=3+3)
CacheNoHitPar/size=0 152B ± 0% 152B ± 0% ~ (all equal)
CacheNoHitPar/size=0-4 152B ± 0% 152B ± 0% ~ (all equal)
CacheNoHitPar/size=16 153B ± 0% 153B ± 0% ~ (all equal)
CacheNoHitPar/size=16-4 155B ± 0% 154B ± 0% ~ (p=0.400 n=3+3)
CacheNoHitPar/size=128 153B ± 0% 153B ± 0% ~ (all equal)
CacheNoHitPar/size=128-4 153B ± 0% 153B ± 0% ~ (all equal)
CacheNoHitPar/size=512 153B ± 0% 153B ± 0% ~ (all equal)
CacheNoHitPar/size=512-4 153B ± 0% 153B ± 0% ~ (all equal)
CacheNoHitPar/size=4096 153B ± 0% 153B ± 0% ~ (all equal)
CacheNoHitPar/size=4096-4 153B ± 0% 153B ± 0% ~ (all equal)
CacheHitPar/size=0 152B ± 0% 152B ± 0% ~ (all equal)
CacheHitPar/size=0-4 152B ± 0% 152B ± 0% ~ (all equal)
CacheHitPar/size=16 0.00B 0.00B ~ (all equal)
CacheHitPar/size=16-4 0.00B 0.00B ~ (all equal)
CacheHitPar/size=128 0.00B 0.00B ~ (all equal)
CacheHitPar/size=128-4 0.00B 0.00B ~ (all equal)
CacheHitPar/size=512 0.00B 0.00B ~ (all equal)
CacheHitPar/size=512-4 0.00B 0.00B ~ (all equal)
CacheHitPar/size=4096 0.00B 0.00B ~ (all equal)
CacheHitPar/size=4096-4 0.00B 0.00B ~ (all equal)
NoopStorageProc 0.00B 0.00B ~ (all equal)
NoopStorageProc-4 0.00B 0.00B ~ (all equal)
CacheStartupProc 285B ± 0% 285B ± 0% ~ (all equal)
CacheStartupProc-4 285B ± 0% 285B ± 0% ~ (all equal)
CacheNoHitProc/size=0 152B ± 0% 152B ± 0% ~ (all equal)
CacheNoHitProc/size=0-4 152B ± 0% 152B ± 0% ~ (all equal)
CacheNoHitProc/size=16 153B ± 0% 153B ± 0% ~ (all equal)
CacheNoHitProc/size=16-4 153B ± 0% 153B ± 0% ~ (all equal)
CacheNoHitProc/size=128 153B ± 0% 153B ± 0% ~ (all equal)
CacheNoHitProc/size=128-4 153B ± 0% 153B ± 0% ~ (all equal)
CacheNoHitProc/size=512 153B ± 0% 153B ± 0% ~ (p=1.000 n=3+3)
CacheNoHitProc/size=512-4 153B ± 0% 153B ± 0% ~ (all equal)
CacheNoHitProc/size=4096 153B ± 0% 153B ± 0% ~ (all equal)
CacheNoHitProc/size=4096-4 153B ± 0% 153B ± 0% ~ (all equal)
CacheHitProc/size=0 152B ± 0% 152B ± 0% ~ (all equal)
CacheHitProc/size=0-4 152B ± 0% 152B ± 0% ~ (all equal)
CacheHitProc/size=16 0.00B 0.00B ~ (all equal)
CacheHitProc/size=16-4 0.00B 0.00B ~ (all equal)
CacheHitProc/size=128 0.00B 0.00B ~ (all equal)
CacheHitProc/size=128-4 0.00B 0.00B ~ (all equal)
CacheHitProc/size=512 0.00B 0.00B ~ (all equal)
CacheHitProc/size=512-4 0.00B 0.00B ~ (all equal)
CacheHitProc/size=4096 0.00B 0.00B ~ (all equal)
CacheHitProc/size=4096-4 0.00B 0.00B ~ (all equal)

name old allocs/op new allocs/op delta
NoopStorage 0.00 0.00 ~ (all equal)
NoopStorage-4 0.00 0.00 ~ (all equal)
CacheStartup 5.00 ± 0% 5.00 ± 0% ~ (all equal)
CacheStartup-4 5.00 ± 0% 5.00 ± 0% ~ (all equal)
CacheNoHit/size=0 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHit/size=0-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHit/size=16 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHit/size=16-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHit/size=128 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHit/size=128-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHit/size=512 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHit/size=512-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHit/size=4096 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHit/size=4096-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheHit/size=0 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheHit/size=0-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheHit/size=16 0.00 0.00 ~ (all equal)
CacheHit/size=16-4 0.00 0.00 ~ (all equal)
CacheHit/size=128 0.00 0.00 ~ (all equal)
CacheHit/size=128-4 0.00 0.00 ~ (all equal)
CacheHit/size=512 0.00 0.00 ~ (all equal)
CacheHit/size=512-4 0.00 0.00 ~ (all equal)
CacheHit/size=4096 0.00 0.00 ~ (all equal)
CacheHit/size=4096-4 0.00 0.00 ~ (all equal)
NoopStoragePar 0.00 0.00 ~ (all equal)
NoopStoragePar-4 0.00 0.00 ~ (all equal)
CacheStartupPar 5.00 ± 0% 5.00 ± 0% ~ (all equal)
CacheStartupPar-4 4.00 ± 0% 4.00 ± 0% ~ (all equal)
CacheNoHitPar/size=0 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitPar/size=0-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitPar/size=16 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitPar/size=16-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitPar/size=128 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitPar/size=128-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitPar/size=512 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitPar/size=512-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitPar/size=4096 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitPar/size=4096-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheHitPar/size=0 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheHitPar/size=0-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheHitPar/size=16 0.00 0.00 ~ (all equal)
CacheHitPar/size=16-4 0.00 0.00 ~ (all equal)
CacheHitPar/size=128 0.00 0.00 ~ (all equal)
CacheHitPar/size=128-4 0.00 0.00 ~ (all equal)
CacheHitPar/size=512 0.00 0.00 ~ (all equal)
CacheHitPar/size=512-4 0.00 0.00 ~ (all equal)
CacheHitPar/size=4096 0.00 0.00 ~ (all equal)
CacheHitPar/size=4096-4 0.00 0.00 ~ (all equal)
NoopStorageProc 0.00 0.00 ~ (all equal)
NoopStorageProc-4 0.00 0.00 ~ (all equal)
CacheStartupProc 5.00 ± 0% 5.00 ± 0% ~ (all equal)
CacheStartupProc-4 5.00 ± 0% 5.00 ± 0% ~ (all equal)
CacheNoHitProc/size=0 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitProc/size=0-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitProc/size=16 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitProc/size=16-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitProc/size=128 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitProc/size=128-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitProc/size=512 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitProc/size=512-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitProc/size=4096 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitProc/size=4096-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheHitProc/size=0 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheHitProc/size=0-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheHitProc/size=16 0.00 0.00 ~ (all equal)
CacheHitProc/size=16-4 0.00 0.00 ~ (all equal)
CacheHitProc/size=128 0.00 0.00 ~ (all equal)
CacheHitProc/size=128-4 0.00 0.00 ~ (all equal)
CacheHitProc/size=512 0.00 0.00 ~ (all equal)
CacheHitProc/size=512-4 0.00 0.00 ~ (all equal)
CacheHitProc/size=4096 0.00 0.00 ~ (all equal)
CacheHitProc/size=4096-4 0.00 0.00 ~ (all equal)

13f149f0

X zodb/cache: Performing GC in separate goroutine was actually a bad idea · 0e2be3b3

Kirill Smelkov authored Jan 08, 2018

Probably channel signalling + goroutine scheduling overhead was taking
too much - see appendix for timings.

Once again - as in 521d3ae5 (X zodb/cache: Also free OCE entries on GC)
we can ignore *Hit/size=0 increase as /size=0 won't happen in practice
and we mostly care about NoHit overhead for which /size=0 also improves.
The HitProc/* increase, as in 521d3ae5, is also withing noise.

---- 8< ----

name old time/op new time/op delta
NoopStorage 56.6ns ± 0% 57.9ns ± 1% +2.36% (p=0.100 n=3+3)
NoopStorage-4 56.9ns ± 1% 57.4ns ± 1% ~ (p=0.200 n=3+3)
CacheStartup 1.97µs ± 3% 2.13µs ±16% ~ (p=0.600 n=3+3)
CacheStartup-4 1.29µs ± 4% 1.29µs ± 4% ~ (p=1.000 n=3+3)
CacheNoHit/size=0 1.34µs ± 1% 0.68µs ± 1% -49.43% (p=0.100 n=3+3)
CacheNoHit/size=0-4 941ns ± 1% 664ns ± 1% -29.38% (p=0.100 n=3+3)
CacheNoHit/size=16 1.38µs ± 3% 0.79µs ± 0% -42.49% (p=0.100 n=3+3)
CacheNoHit/size=16-4 939ns ± 2% 788ns ± 0% -16.02% (p=0.100 n=3+3)
CacheNoHit/size=128 1.32µs ± 2% 0.80µs ± 0% -39.55% (p=0.100 n=3+3)
CacheNoHit/size=128-4 946ns ± 1% 795ns ± 1% -16.03% (p=0.100 n=3+3)
CacheNoHit/size=512 1.37µs ± 3% 0.82µs ± 0% -40.33% (p=0.100 n=3+3)
CacheNoHit/size=512-4 977ns ± 2% 803ns ± 0% -17.75% (p=0.100 n=3+3)
CacheNoHit/size=4096 1.37µs ± 4% 1.05µs ± 1% -23.03% (p=0.100 n=3+3)
CacheNoHit/size=4096-4 1.07µs ± 0% 0.86µs ± 0% -19.94% (p=0.100 n=3+3)
CacheHit/size=0 164ns ±29% 664ns ± 0% +305.08% (p=0.100 n=3+3)
CacheHit/size=0-4 251ns ± 6% 660ns ± 0% +162.95% (p=0.100 n=3+3)
CacheHit/size=16 120ns ± 1% 123ns ± 4% ~ (p=0.700 n=3+3)
CacheHit/size=16-4 121ns ± 2% 121ns ± 1% ~ (p=1.000 n=3+3)
CacheHit/size=128 123ns ± 1% 124ns ± 1% ~ (p=1.000 n=3+3)
CacheHit/size=128-4 124ns ± 0% 124ns ± 1% ~ (p=1.000 n=3+3)
CacheHit/size=512 125ns ± 0% 126ns ± 1% ~ (p=0.400 n=3+3)
CacheHit/size=512-4 126ns ± 1% 125ns ± 1% ~ (p=0.400 n=3+3)
CacheHit/size=4096 128ns ± 1% 127ns ± 1% ~ (p=1.000 n=3+3)
CacheHit/size=4096-4 128ns ± 1% 128ns ± 1% ~ (p=1.000 n=3+3)
NoopStoragePar 56.5ns ± 0% 59.2ns ± 1% +4.84% (p=0.100 n=3+3)
NoopStoragePar-4 33.1ns ± 3% 31.2ns ± 8% ~ (p=0.400 n=3+3)
CacheStartupPar 2.01µs ±14% 2.04µs ± 6% ~ (p=0.800 n=3+3)
CacheStartupPar-4 1.47µs ± 4% 1.48µs ± 3% ~ (p=1.000 n=3+3)
CacheNoHitPar/size=0 1.35µs ± 3% 0.67µs ± 0% -50.25% (p=0.100 n=3+3)
CacheNoHitPar/size=0-4 1.04µs ± 0% 0.90µs ± 0% -12.83% (p=0.100 n=3+3)
CacheNoHitPar/size=16 1.32µs ± 2% 0.79µs ± 0% -40.36% (p=0.100 n=3+3)
CacheNoHitPar/size=16-4 1.04µs ± 0% 1.03µs ± 0% -1.28% (p=0.100 n=3+3)
CacheNoHitPar/size=128 1.33µs ± 1% 0.80µs ± 0% -40.02% (p=0.100 n=3+3)
CacheNoHitPar/size=128-4 1.03µs ± 1% 1.04µs ± 0% ~ (p=0.400 n=3+3)
CacheNoHitPar/size=512 1.34µs ± 2% 0.82µs ± 0% -38.79% (p=0.100 n=3+3)
CacheNoHitPar/size=512-4 1.07µs ± 2% 1.07µs ± 0% ~ (p=0.600 n=3+3)
CacheNoHitPar/size=4096 1.36µs ± 4% 1.06µs ± 1% -21.87% (p=0.100 n=3+3)
CacheNoHitPar/size=4096-4 1.16µs ± 2% 1.17µs ± 1% ~ (p=0.700 n=3+3)
CacheHitPar/size=0 163ns ± 3% 665ns ± 0% +306.94% (p=0.100 n=3+3)
CacheHitPar/size=0-4 394ns ± 3% 903ns ± 1% +129.08% (p=0.100 n=3+3)
CacheHitPar/size=16 121ns ± 0% 124ns ± 1% +2.20% (p=0.100 n=3+3)
CacheHitPar/size=16-4 213ns ± 0% 217ns ± 1% +2.03% (p=0.100 n=3+3)
CacheHitPar/size=128 124ns ± 1% 125ns ± 0% ~ (p=0.400 n=3+3)
CacheHitPar/size=128-4 208ns ± 0% 215ns ± 1% +3.21% (p=0.100 n=3+3)
CacheHitPar/size=512 126ns ± 1% 127ns ± 1% ~ (p=0.300 n=3+3)
CacheHitPar/size=512-4 205ns ± 0% 241ns ± 0% +17.40% (p=0.100 n=3+3)
CacheHitPar/size=4096 127ns ± 0% 129ns ± 0% +1.57% (p=0.100 n=3+3)
CacheHitPar/size=4096-4 201ns ± 0% 236ns ± 4% +17.58% (p=0.100 n=3+3)
NoopStorageProc 54.8ns ± 0% 56.1ns ± 0% +2.43% (p=0.100 n=3+3)
NoopStorageProc-4 32.6ns ± 4% 37.1ns ±10% +14.02% (p=0.100 n=3+3)
CacheStartupProc 1.91µs ± 7% 1.79µs ± 3% ~ (p=0.400 n=3+3)
CacheStartupProc-4 1.13µs ± 1% 1.08µs ± 7% ~ (p=0.400 n=3+3)
CacheNoHitProc/size=0 1.32µs ± 1% 0.67µs ± 0% -49.38% (p=0.100 n=3+3)
CacheNoHitProc/size=0-4 649ns ± 1% 414ns ±15% -36.23% (p=0.100 n=3+3)
CacheNoHitProc/size=16 1.33µs ± 3% 0.79µs ± 0% -40.23% (p=0.100 n=3+3)
CacheNoHitProc/size=16-4 650ns ± 2% 440ns ± 7% -32.34% (p=0.100 n=3+3)
CacheNoHitProc/size=128 1.31µs ± 5% 0.81µs ± 0% -38.41% (p=0.100 n=3+3)
CacheNoHitProc/size=128-4 663ns ± 1% 467ns ± 8% -29.58% (p=0.100 n=3+3)
CacheNoHitProc/size=512 1.30µs ± 2% 0.83µs ± 1% -35.72% (p=0.100 n=3+3)
CacheNoHitProc/size=512-4 685ns ± 1% 499ns ± 9% -27.12% (p=0.100 n=3+3)
CacheNoHitProc/size=4096 1.35µs ± 3% 1.07µs ± 0% -20.87% (p=0.100 n=3+3)
CacheNoHitProc/size=4096-4 684ns ± 2% 629ns ± 3% -8.04% (p=0.100 n=3+3)
CacheHitProc/size=0 159ns ± 3% 669ns ± 0% +320.75% (p=0.100 n=3+3)
CacheHitProc/size=0-4 75.1ns ±10% 381.0ns ± 2% +407.10% (p=0.100 n=3+3)
CacheHitProc/size=16 120ns ± 1% 121ns ± 1% ~ (p=0.300 n=3+3)
CacheHitProc/size=16-4 58.1ns ± 2% 65.0ns ± 3% +11.94% (p=0.100 n=3+3)
CacheHitProc/size=128 123ns ± 0% 124ns ± 0% +0.81% (p=0.100 n=3+3)
CacheHitProc/size=128-4 57.6ns ± 0% 74.9ns ± 3% +30.05% (p=0.100 n=3+3)
CacheHitProc/size=512 124ns ± 1% 125ns ± 1% ~ (p=0.300 n=3+3)
CacheHitProc/size=512-4 59.4ns ± 1% 71.5ns ± 2% +20.38% (p=0.100 n=3+3)
CacheHitProc/size=4096 127ns ± 0% 132ns ± 6% +3.94% (p=0.100 n=3+3)
CacheHitProc/size=4096-4 64.2ns ± 1% 80.5ns ± 7% +25.34% (p=0.100 n=3+3)

name old alloc/op new alloc/op delta
NoopStorage 0.00B 0.00B ~ (all equal)
NoopStorage-4 0.00B 0.00B ~ (all equal)
CacheStartup 285B ± 0% 285B ± 0% ~ (all equal)
CacheStartup-4 285B ± 0% 285B ± 0% ~ (all equal)
CacheNoHit/size=0 247B ± 2% 152B ± 0% -38.38% (p=0.100 n=3+3)
CacheNoHit/size=0-4 153B ± 0% 152B ± 0% -0.65% (p=0.100 n=3+3)
CacheNoHit/size=16 247B ± 2% 153B ± 0% -37.97% (p=0.100 n=3+3)
CacheNoHit/size=16-4 153B ± 0% 153B ± 0% ~ (p=1.000 n=3+3)
CacheNoHit/size=128 241B ± 1% 153B ± 0% -36.60% (p=0.100 n=3+3)
CacheNoHit/size=128-4 153B ± 0% 153B ± 0% ~ (p=1.000 n=3+3)
CacheNoHit/size=512 245B ± 1% 153B ± 0% -37.64% (p=0.100 n=3+3)
CacheNoHit/size=512-4 154B ± 0% 153B ± 0% -0.65% (p=0.100 n=3+3)
CacheNoHit/size=4096 244B ± 1% 153B ± 0% -37.21% (p=0.100 n=3+3)
CacheNoHit/size=4096-4 155B ± 0% 152B ± 0% -1.72% (p=0.100 n=3+3)
CacheHit/size=0 5.00B ±100% 152.00B ± 0% +2940.00% (p=0.100 n=3+3)
CacheHit/size=0-4 11.0B ± 9% 152.0B ± 0% +1281.82% (p=0.100 n=3+3)
CacheHit/size=16 0.00B 0.00B ~ (all equal)
CacheHit/size=16-4 0.00B 0.00B ~ (all equal)
CacheHit/size=128 0.00B 0.00B ~ (all equal)
CacheHit/size=128-4 0.00B 0.00B ~ (all equal)
CacheHit/size=512 0.00B 0.00B ~ (all equal)
CacheHit/size=512-4 0.00B 0.00B ~ (all equal)
CacheHit/size=4096 0.00B 0.00B ~ (all equal)
CacheHit/size=4096-4 0.00B 0.00B ~ (all equal)
NoopStoragePar 0.00B 0.00B ~ (all equal)
NoopStoragePar-4 0.00B 0.00B ~ (all equal)
CacheStartupPar 285B ± 0% 285B ± 0% ~ (all equal)
CacheStartupPar-4 282B ± 1% 281B ± 0% ~ (p=0.600 n=3+3)
CacheNoHitPar/size=0 247B ± 2% 152B ± 0% -38.38% (p=0.100 n=3+3)
CacheNoHitPar/size=0-4 161B ± 0% 152B ± 0% -5.59% (p=0.100 n=3+3)
CacheNoHitPar/size=16 245B ± 1% 153B ± 0% -37.55% (p=0.100 n=3+3)
CacheNoHitPar/size=16-4 161B ± 0% 155B ± 0% -3.93% (p=0.100 n=3+3)
CacheNoHitPar/size=128 245B ± 2% 153B ± 0% -37.55% (p=0.100 n=3+3)
CacheNoHitPar/size=128-4 162B ± 0% 153B ± 0% -5.36% (p=0.100 n=3+3)
CacheNoHitPar/size=512 246B ± 3% 153B ± 0% -37.89% (p=0.100 n=3+3)
CacheNoHitPar/size=512-4 161B ± 0% 153B ± 0% -4.97% (p=0.100 n=3+3)
CacheNoHitPar/size=4096 244B ± 3% 153B ± 0% -37.38% (p=0.100 n=3+3)
CacheNoHitPar/size=4096-4 164B ± 0% 153B ± 0% -6.71% (p=0.100 n=3+3)
CacheHitPar/size=0 5.00B ±20% 152.00B ± 0% +2940.00% (p=0.100 n=3+3)
CacheHitPar/size=0-4 14.0B ± 7% 152.0B ± 0% +985.71% (p=0.100 n=3+3)
CacheHitPar/size=16 0.00B 0.00B ~ (all equal)
CacheHitPar/size=16-4 0.00B 0.00B ~ (all equal)
CacheHitPar/size=128 0.00B 0.00B ~ (all equal)
CacheHitPar/size=128-4 0.00B 0.00B ~ (all equal)
CacheHitPar/size=512 0.00B 0.00B ~ (all equal)
CacheHitPar/size=512-4 0.00B 0.00B ~ (all equal)
CacheHitPar/size=4096 0.00B 0.00B ~ (all equal)
CacheHitPar/size=4096-4 0.00B 0.00B ~ (all equal)
NoopStorageProc 0.00B 0.00B ~ (all equal)
NoopStorageProc-4 0.00B 0.00B ~ (all equal)
CacheStartupProc 285B ± 0% 285B ± 0% ~ (all equal)
CacheStartupProc-4 285B ± 0% 285B ± 0% ~ (all equal)
CacheNoHitProc/size=0 243B ± 1% 152B ± 0% -37.53% (p=0.100 n=3+3)
CacheNoHitProc/size=0-4 195B ± 1% 152B ± 0% -22.05% (p=0.100 n=3+3)
CacheNoHitProc/size=16 247B ± 2% 153B ± 0% -37.97% (p=0.100 n=3+3)
CacheNoHitProc/size=16-4 194B ± 0% 153B ± 0% -21.27% (p=0.100 n=3+3)
CacheNoHitProc/size=128 242B ± 4% 153B ± 0% -36.78% (p=0.100 n=3+3)
CacheNoHitProc/size=128-4 193B ± 0% 153B ± 0% -20.86% (p=0.100 n=3+3)
CacheNoHitProc/size=512 240B ± 2% 153B ± 0% -36.48% (p=0.100 n=3+3)
CacheNoHitProc/size=512-4 190B ± 1% 153B ± 0% -19.33% (p=0.100 n=3+3)
CacheNoHitProc/size=4096 245B ± 2% 153B ± 0% -37.55% (p=0.100 n=3+3)
CacheNoHitProc/size=4096-4 181B ± 2% 153B ± 0% -15.47% (p=0.100 n=3+3)
CacheHitProc/size=0 4.33B ±15% 152.00B ± 0% +3407.69% (p=0.100 n=3+3)
CacheHitProc/size=0-4 3.33B ±50% 152.00B ± 0% +4460.00% (p=0.100 n=3+3)
CacheHitProc/size=16 0.00B 0.00B ~ (all equal)
CacheHitProc/size=16-4 0.00B 0.00B ~ (all equal)
CacheHitProc/size=128 0.00B 0.00B ~ (all equal)
CacheHitProc/size=128-4 0.00B 0.00B ~ (all equal)
CacheHitProc/size=512 0.00B 0.00B ~ (all equal)
CacheHitProc/size=512-4 0.00B 0.00B ~ (all equal)
CacheHitProc/size=4096 0.00B 0.00B ~ (all equal)
CacheHitProc/size=4096-4 0.00B 0.00B ~ (all equal)

name old allocs/op new allocs/op delta
NoopStorage 0.00 0.00 ~ (all equal)
NoopStorage-4 0.00 0.00 ~ (all equal)
CacheStartup 5.00 ± 0% 5.00 ± 0% ~ (all equal)
CacheStartup-4 5.00 ± 0% 5.00 ± 0% ~ (all equal)
CacheNoHit/size=0 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHit/size=0-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHit/size=16 3.33 ±20% 3.00 ± 0% ~ (p=1.000 n=3+3)
CacheNoHit/size=16-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHit/size=128 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHit/size=128-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHit/size=512 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHit/size=512-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHit/size=4096 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHit/size=4096-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheHit/size=0 0.00 3.00 ± 0% +Inf% (p=0.100 n=3+3)
CacheHit/size=0-4 0.00 3.00 ± 0% +Inf% (p=0.100 n=3+3)
CacheHit/size=16 0.00 0.00 ~ (all equal)
CacheHit/size=16-4 0.00 0.00 ~ (all equal)
CacheHit/size=128 0.00 0.00 ~ (all equal)
CacheHit/size=128-4 0.00 0.00 ~ (all equal)
CacheHit/size=512 0.00 0.00 ~ (all equal)
CacheHit/size=512-4 0.00 0.00 ~ (all equal)
CacheHit/size=4096 0.00 0.00 ~ (all equal)
CacheHit/size=4096-4 0.00 0.00 ~ (all equal)
NoopStoragePar 0.00 0.00 ~ (all equal)
NoopStoragePar-4 0.00 0.00 ~ (all equal)
CacheStartupPar 5.00 ± 0% 5.00 ± 0% ~ (all equal)
CacheStartupPar-4 4.33 ±15% 4.00 ± 0% ~ (p=1.000 n=3+3)
CacheNoHitPar/size=0 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitPar/size=0-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitPar/size=16 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitPar/size=16-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitPar/size=128 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitPar/size=128-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitPar/size=512 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitPar/size=512-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitPar/size=4096 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitPar/size=4096-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheHitPar/size=0 0.00 3.00 ± 0% +Inf% (p=0.100 n=3+3)
CacheHitPar/size=0-4 0.00 3.00 ± 0% +Inf% (p=0.100 n=3+3)
CacheHitPar/size=16 0.00 0.00 ~ (all equal)
CacheHitPar/size=16-4 0.00 0.00 ~ (all equal)
CacheHitPar/size=128 0.00 0.00 ~ (all equal)
CacheHitPar/size=128-4 0.00 0.00 ~ (all equal)
CacheHitPar/size=512 0.00 0.00 ~ (all equal)
CacheHitPar/size=512-4 0.00 0.00 ~ (all equal)
CacheHitPar/size=4096 0.00 0.00 ~ (all equal)
CacheHitPar/size=4096-4 0.00 0.00 ~ (all equal)
NoopStorageProc 0.00 0.00 ~ (all equal)
NoopStorageProc-4 0.00 0.00 ~ (all equal)
CacheStartupProc 5.00 ± 0% 5.00 ± 0% ~ (all equal)
CacheStartupProc-4 5.00 ± 0% 5.00 ± 0% ~ (all equal)
CacheNoHitProc/size=0 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitProc/size=0-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitProc/size=16 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitProc/size=16-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitProc/size=128 3.33 ±20% 3.00 ± 0% ~ (p=1.000 n=3+3)
CacheNoHitProc/size=128-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitProc/size=512 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitProc/size=512-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitProc/size=4096 3.33 ±20% 3.00 ± 0% ~ (p=1.000 n=3+3)
CacheNoHitProc/size=4096-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheHitProc/size=0 0.00 3.00 ± 0% +Inf% (p=0.100 n=3+3)
CacheHitProc/size=0-4 0.00 3.00 ± 0% +Inf% (p=0.100 n=3+3)
CacheHitProc/size=16 0.00 0.00 ~ (all equal)
CacheHitProc/size=16-4 0.00 0.00 ~ (all equal)
CacheHitProc/size=128 0.00 0.00 ~ (all equal)
CacheHitProc/size=128-4 0.00 0.00 ~ (all equal)
CacheHitProc/size=512 0.00 0.00 ~ (all equal)
CacheHitProc/size=512-4 0.00 0.00 ~ (all equal)
CacheHitProc/size=4096 0.00 0.00 ~ (all equal)
CacheHitProc/size=4096-4 0.00 0.00 ~ (all equal)

0e2be3b3

05 Jan, 2018 1 commit
- debug: add helper to run code outside the signal handler · 875fc1b9
  Julien Muchembled authored Jan 04, 2018
  
  875fc1b9
03 Jan, 2018 3 commits

X zodb/fs1: Don't set .file = nil on Close · a5d0e83f

Kirill Smelkov authored Jan 03, 2018

In case FileStorage will be still used we want to get proper "file is
already closed" error instead of crash.

A particular case of proper usage after Close is to spawn many
prefetches, including ones going after EOF, then after getting some
loads, close the storage as we are done processing.
By definition Prefetch ignores errors, but if FileStorage.file is nil,
e.g. os.File.Name() crashes and so instead of Prefetch ignoring the
error it will crash too.

For example here is how it can happen under neotest:

	Benchmarklink/fs1/zhash.go 1 1.7 µs/object	# null:00  oid=0..2127  nread=8540363  t=3.634083ms	# POLL·0 C1·2 C1E·74 C3·16 C6·0 C7·60
	Benchmarklink/fs1/zhash.go 1 2.2 µs/object	# null:00  oid=0..2127  nread=8540363  t=4.731554ms	# POLL·0 C1·3 C1E·74 C3·18 C6·0 C7·73
	Benchmarklink/fs1/zhash.go 1 1.7 µs/object	# null:00  oid=0..2127  nread=8540363  t=3.689686ms	# POLL·0 C1·17 C1E·70 C3·15 C6·1 C7·88
	Benchmarklink/fs1/zhash.go 1 1.7 µs/object	# null:00  oid=0..2127  nread=8540363  t=3.687432ms	# POLL·1 C1·4 C1E·71 C3·19 C6·0 C7·70
	Benchmarklink/fs1/zhash.go 1 2.3 µs/object	# null:00  oid=0..2127  nread=8540363  t=4.867104ms	# POLL·0 C1·11 C1E·71 C3·22 C6·0 C7·57
	Benchmarklink/fs1/zhash.go+prefetch128 1 6.9 µs/object	# null:00  oid=0..2127  nread=8540363  t=14.655538ms
	panic: runtime error: invalid memory address or nil pointer dereference
	[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x52da01]

	goroutine 2074 [running]:
	os.(*File).Name(...)
		/home/kirr/src/tools/go/go/src/os/file.go:47
	lab.nexedi.com/kirr/neo/go/xcommon/xio.Name(0x5ddb20, 0x0, 0xc420022187, 0x51)
		/home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/xcommon/xio/xio.go:67 +0x381
	lab.nexedi.com/kirr/neo/go/zodb/storage/fs1.(*DataHeader).err(0xc4200221e0, 0x6ddec0, 0x0, 0x5e6509, 0x4, 0x6dd580, 0xc420042130, 0xc420042130, 0x0)
		/home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/storage/fs1/format.go:117 +0x42
	lab.nexedi.com/kirr/neo/go/zodb/storage/fs1.(*DataHeader).Load(0xc4200221e0, 0x6ddec0, 0x0, 0x7fc3b5, 0x0, 0x454530)
		/home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/storage/fs1/format.go:471 +0xf5
	lab.nexedi.com/kirr/neo/go/zodb/storage/fs1.(*DataHeader).loadPrevRev(0xc4200221e0, 0x6ddec0, 0x0, 0x7fc3b5, 0xc4209d8288, 0xc420872d88)
		/home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/storage/fs1/format.go:540 +0x79
	lab.nexedi.com/kirr/neo/go/zodb/storage/fs1.(*DataHeader).LoadPrevRev(0xc4200221e0, 0x6ddec0, 0x0, 0x5d0c60, 0xc4200221e0)
		/home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/storage/fs1/format.go:526 +0x60
	lab.nexedi.com/kirr/neo/go/zodb/storage/fs1.(*FileStorage)._Load(0xc420090360, 0xc4200221e0, 0x3c4918e0f64d888, 0x7f6, 0x0, 0x0, 0x0, 0x0)
		/home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/storage/fs1/filestorage.go:162 +0x48
	lab.nexedi.com/kirr/neo/go/zodb/storage/fs1.(*FileStorage).Load(0xc420090360, 0x6dfa80, 0xc42006a780, 0x3c4918e0f64d888, 0x7f6, 0x0, 0x0, 0x0, 0x0)
		/home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/storage/fs1/filestorage.go:154 +0xb7
	lab.nexedi.com/kirr/neo/go/zodb.(*Cache).loadRCE(0xc4200101c0, 0x6dfa80, 0xc42006a780, 0xc4209e6900)
		/home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/cache.go:313 +0x89
	created by lab.nexedi.com/kirr/neo/go/zodb.(*Cache).Prefetch
		/home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/cache.go:205 +0x9f
	# POLL·0 C1·155 C1E·79 C3·31 C6·0 C7·42
	E: abnormal termination - stopping...

So don't set .file = nil after Close.

Not adding a comment explaining this as leaving things that still might
be used concurrently intact should be common practice.

a5d0e83f

X neotest/info: Handle USB NICs · a971231c

Kirill Smelkov authored Jan 03, 2018

e.g. before:

	# wwan0: lspci: -s: Invalid bus number
	lspci: -s: Invalid bus number
	lspci: -s: Invalid bus number
	  rev

after:

	# wwan0: Novatel Wireless Expedite E362 (usb)

a971231c

X zodb/cache: Also free OCE entries on GC · 521d3ae5

Kirill Smelkov authored Jan 03, 2018

Until now we were only GC'ing RCE entries, but OCE entries (top-level
cache entry for an OID) were never GC'ed thus allowing cache size to
grow infinitely.

Even though the average N(allocations) stays the same this change lowers
pressure on amount of memory allocated and thus helping avoid some GC
speeds things up (see attachment).

Notes:

1. Hit*/size=0 increase is probably due to Cache.entryMap going to
empty/1-element back and forth constantly. size/0 is not going to
happen in practice and so this wat we can accept regression here.

( still NoHit*/size=0 works faster ).

2. HitProc/size=* "regression should be within noise"

name old time/op new time/op delta
NoopStorage-4 56.6ns ± 1% 56.2ns ± 0% ~ (p=0.079 n=5+5)
CacheStartup-4 1.24µs ± 6% 1.28µs ± 9% ~ (p=0.595 n=5+5)
CacheNoHit/size=0-4 1.44µs ± 4% 0.93µs ± 2% -35.26% (p=0.008 n=5+5)
CacheNoHit/size=16-4 1.43µs ± 5% 0.92µs ± 1% -35.19% (p=0.008 n=5+5)
CacheNoHit/size=128-4 1.45µs ± 3% 0.94µs ± 1% -35.03% (p=0.008 n=5+5)
CacheNoHit/size=512-4 1.44µs ± 4% 0.97µs ± 2% -32.64% (p=0.008 n=5+5)
CacheNoHit/size=4096-4 1.45µs ± 2% 1.07µs ± 0% -25.85% (p=0.008 n=5+5)
CacheHit/size=0-4 131ns ± 2% 276ns ±22% +110.99% (p=0.008 n=5+5)
CacheHit/size=16-4 122ns ± 1% 121ns ± 1% ~ (p=0.079 n=5+5)
CacheHit/size=128-4 126ns ± 2% 125ns ± 1% ~ (p=0.563 n=5+5)
CacheHit/size=512-4 127ns ± 1% 126ns ± 0% ~ (p=0.095 n=5+4)
CacheHit/size=4096-4 128ns ± 0% 128ns ± 0% ~ (p=0.556 n=5+4)
NoopStoragePar-4 30.6ns ± 4% 31.2ns ±10% ~ (p=0.690 n=5+5)
CacheStartupPar-4 1.44µs ± 5% 1.43µs ± 3% ~ (p=0.690 n=5+5)
CacheNoHitPar/size=0-4 1.62µs ± 4% 1.04µs ± 1% -35.76% (p=0.008 n=5+5)
CacheNoHitPar/size=16-4 1.65µs ± 4% 1.05µs ± 1% -36.39% (p=0.008 n=5+5)
CacheNoHitPar/size=128-4 1.64µs ± 5% 1.05µs ± 1% -35.84% (p=0.008 n=5+5)
CacheNoHitPar/size=512-4 1.62µs ± 3% 1.08µs ± 1% -33.10% (p=0.008 n=5+5)
CacheNoHitPar/size=4096-4 1.68µs ± 1% 1.18µs ± 0% -29.44% (p=0.008 n=5+5)
CacheHitPar/size=0-4 215ns ± 0% 383ns ± 2% +78.23% (p=0.008 n=5+5)
CacheHitPar/size=16-4 214ns ± 2% 214ns ± 0% ~ (p=0.786 n=5+5)
CacheHitPar/size=128-4 210ns ± 0% 209ns ± 0% ~ (p=0.079 n=5+5)
CacheHitPar/size=512-4 207ns ± 0% 206ns ± 0% -0.48% (p=0.008 n=5+5)
CacheHitPar/size=4096-4 204ns ± 0% 202ns ± 0% -0.98% (p=0.000 n=5+4)
NoopStorageProc-4 31.4ns ± 7% 33.7ns ± 5% ~ (p=0.151 n=5+5)
CacheStartupProc-4 1.13µs ± 5% 1.12µs ± 3% ~ (p=0.690 n=5+5)
CacheNoHitProc/size=0-4 1.12µs ± 5% 0.62µs ± 1% -44.52% (p=0.008 n=5+5)
CacheNoHitProc/size=16-4 1.14µs ± 6% 0.63µs ± 1% -45.14% (p=0.008 n=5+5)
CacheNoHitProc/size=128-4 1.06µs ± 5% 0.64µs ± 2% -40.12% (p=0.008 n=5+5)
CacheNoHitProc/size=512-4 1.14µs ±11% 0.69µs ± 4% -39.87% (p=0.008 n=5+5)
CacheNoHitProc/size=4096-4 1.14µs ± 9% 0.68µs ± 2% -40.21% (p=0.008 n=5+5)
CacheHitProc/size=0-4 56.5ns ± 7% 84.6ns ±14% +49.66% (p=0.008 n=5+5)
CacheHitProc/size=16-4 55.8ns ± 0% 62.0ns ± 6% +11.03% (p=0.008 n=5+5)
CacheHitProc/size=128-4 56.6ns ± 0% 60.9ns ± 4% +7.63% (p=0.008 n=5+5)
CacheHitProc/size=512-4 57.3ns ± 0% 64.1ns ± 7% +11.83% (p=0.016 n=4+5)
CacheHitProc/size=4096-4 61.6ns ± 1% 69.7ns ± 5% +13.29% (p=0.008 n=5+5)

name old alloc/op new alloc/op delta
NoopStorage-4 0.00B 0.00B ~ (all equal)
CacheStartup-4 269B ± 0% 285B ± 0% +5.95% (p=0.008 n=5+5)
CacheNoHit/size=0-4 225B ± 0% 153B ± 0% -32.12% (p=0.008 n=5+5)
CacheNoHit/size=16-4 225B ± 0% 153B ± 0% -32.00% (p=0.029 n=4+4)
CacheNoHit/size=128-4 225B ± 1% 153B ± 0% -31.76% (p=0.008 n=5+5)
CacheNoHit/size=512-4 225B ± 1% 154B ± 0% -31.50% (p=0.008 n=5+5)
CacheNoHit/size=4096-4 224B ± 0% 155B ± 0% -30.80% (p=0.008 n=5+5)
CacheHit/size=0-4 0.00B 13.40B ±42% +Inf% (p=0.008 n=5+5)
CacheHit/size=16-4 0.00B 0.00B ~ (all equal)
CacheHit/size=128-4 0.00B 0.00B ~ (all equal)
CacheHit/size=512-4 0.00B 0.00B ~ (all equal)
CacheHit/size=4096-4 0.00B 0.00B ~ (all equal)
NoopStoragePar-4 0.00B 0.00B ~ (all equal)
CacheStartupPar-4 267B ± 0% 282B ± 1% +5.67% (p=0.016 n=4+5)
CacheNoHitPar/size=0-4 232B ± 1% 162B ± 1% -30.11% (p=0.008 n=5+5)
CacheNoHitPar/size=16-4 228B ± 1% 161B ± 0% -29.21% (p=0.008 n=5+5)
CacheNoHitPar/size=128-4 229B ± 1% 162B ± 0% -29.43% (p=0.008 n=5+5)
CacheNoHitPar/size=512-4 228B ± 1% 162B ± 1% -28.86% (p=0.008 n=5+5)
CacheNoHitPar/size=4096-4 224B ± 0% 166B ± 0% -26.02% (p=0.000 n=5+4)
CacheHitPar/size=0-4 1.00B ± 0% 13.60B ± 4% +1260.00% (p=0.008 n=5+5)
CacheHitPar/size=16-4 0.00B 0.00B ~ (all equal)
CacheHitPar/size=128-4 0.00B 0.00B ~ (all equal)
CacheHitPar/size=512-4 0.00B 0.00B ~ (all equal)
CacheHitPar/size=4096-4 0.00B 0.00B ~ (all equal)
NoopStorageProc-4 0.00B 0.00B ~ (all equal)
CacheStartupProc-4 269B ± 0% 285B ± 0% +5.95% (p=0.008 n=5+5)
CacheNoHitProc/size=0-4 240B ± 0% 194B ± 0% -19.17% (p=0.000 n=5+4)
CacheNoHitProc/size=16-4 240B ± 2% 194B ± 1% -19.38% (p=0.008 n=5+5)
CacheNoHitProc/size=128-4 241B ± 0% 193B ± 1% -20.00% (p=0.016 n=4+5)
CacheNoHitProc/size=512-4 241B ± 1% 188B ± 2% -22.06% (p=0.008 n=5+5)
CacheNoHitProc/size=4096-4 240B ± 1% 179B ± 0% -25.52% (p=0.008 n=5+5)
CacheHitProc/size=0-4 0.00B 3.60B ±17% +Inf% (p=0.008 n=5+5)
CacheHitProc/size=16-4 0.00B 0.00B ~ (all equal)
CacheHitProc/size=128-4 0.00B 0.00B ~ (all equal)
CacheHitProc/size=512-4 0.00B 0.00B ~ (all equal)
CacheHitProc/size=4096-4 0.00B 0.00B ~ (all equal)

name old allocs/op new allocs/op delta
NoopStorage-4 0.00 0.00 ~ (all equal)
CacheStartup-4 5.00 ± 0% 5.00 ± 0% ~ (all equal)
CacheNoHit/size=0-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHit/size=16-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHit/size=128-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHit/size=512-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHit/size=4096-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheHit/size=0-4 0.00 0.00 ~ (all equal)
CacheHit/size=16-4 0.00 0.00 ~ (all equal)
CacheHit/size=128-4 0.00 0.00 ~ (all equal)
CacheHit/size=512-4 0.00 0.00 ~ (all equal)
CacheHit/size=4096-4 0.00 0.00 ~ (all equal)
NoopStoragePar-4 0.00 0.00 ~ (all equal)
CacheStartupPar-4 4.00 ± 0% 4.00 ± 0% ~ (all equal)
CacheNoHitPar/size=0-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitPar/size=16-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitPar/size=128-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitPar/size=512-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitPar/size=4096-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheHitPar/size=0-4 0.00 0.00 ~ (all equal)
CacheHitPar/size=16-4 0.00 0.00 ~ (all equal)
CacheHitPar/size=128-4 0.00 0.00 ~ (all equal)
CacheHitPar/size=512-4 0.00 0.00 ~ (all equal)
CacheHitPar/size=4096-4 0.00 0.00 ~ (all equal)
NoopStorageProc-4 0.00 0.00 ~ (all equal)
CacheStartupProc-4 5.00 ± 0% 5.00 ± 0% ~ (all equal)
CacheNoHitProc/size=0-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitProc/size=16-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitProc/size=128-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitProc/size=512-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheNoHitProc/size=4096-4 3.00 ± 0% 3.00 ± 0% ~ (all equal)
CacheHitProc/size=0-4 0.00 0.00 ~ (all equal)
CacheHitProc/size=16-4 0.00 0.00 ~ (all equal)
CacheHitProc/size=128-4 0.00 0.00 ~ (all equal)
CacheHitProc/size=512-4 0.00 0.00 ~ (all equal)
CacheHitProc/size=4096-4 0.00 0.00 ~ (all equal)

521d3ae5

31 Dec, 2017 2 commits

X zodb/cache: Switch RCE.ready from chan to sync.WaitGroup · 1f07e51a

Kirill Smelkov authored Dec 31, 2017

Currently RCE.ready is chan(struct{}) and is closed to indicate 1->N
that loading of an RCE has finished. There is a drawback however with
using channel for this function:

making RCE.ready allocates and thus adds pressure on GC.

We can use sync.WaitGroup functionality for this purpose of notifying
that something is ready. Usually sync.WaitGroup is used in N->1 way, but
as it also correctly works in N->M mode we can use in in our scenario
where 1 loading goroutine notifies N RCE waiters.

Checking already closed channel was also found to checking already done
sync.WaitGroup. Reason is that sync.WaitGroup is only a light wrapper
around runtime.sema, but channel is much more heavyweight.

Speedup with this patch:

name old time/op new time/op delta
NoopStorage-4 56.2ns ± 0% 57.1ns ± 2% ~ (p=0.079 n=5+5)
CacheStartup-4 1.34µs ± 7% 1.22µs ± 3% -8.68% (p=0.008 n=5+5)
CacheNoHit/size=0-4 1.67µs ± 4% 1.42µs ± 4% -15.08% (p=0.008 n=5+5)
CacheNoHit/size=16-4 1.73µs ± 7% 1.42µs ± 4% -17.83% (p=0.008 n=5+5)
CacheNoHit/size=128-4 1.68µs ± 5% 1.42µs ± 5% -15.65% (p=0.008 n=5+5)
CacheNoHit/size=512-4 1.62µs ± 4% 1.43µs ± 5% -12.18% (p=0.008 n=5+5)
CacheNoHit/size=4096-4 1.69µs ± 2% 1.44µs ± 0% -15.03% (p=0.008 n=5+5)
CacheHit/size=0-4 158ns ± 1% 130ns ± 2% -17.47% (p=0.008 n=5+5)
CacheHit/size=16-4 147ns ± 2% 124ns ± 7% -16.01% (p=0.008 n=5+5)
CacheHit/size=128-4 149ns ± 0% 126ns ± 5% -15.30% (p=0.016 n=4+5)
CacheHit/size=512-4 151ns ± 0% 126ns ± 1% -16.56% (p=0.000 n=4+5)
CacheHit/size=4096-4 154ns ± 0% 129ns ± 2% -16.49% (p=0.008 n=5+5)
NoopStoragePar-4 32.2ns ± 9% 30.4ns ± 5% ~ (p=0.175 n=5+5)
CacheStartupPar-4 1.64µs ± 2% 1.42µs ± 4% -13.31% (p=0.008 n=5+5)
CacheNoHitPar/size=0-4 1.88µs ± 2% 1.63µs ± 3% -13.33% (p=0.008 n=5+5)
CacheNoHitPar/size=16-4 1.87µs ± 1% 1.62µs ± 2% -13.33% (p=0.008 n=5+5)
CacheNoHitPar/size=128-4 1.90µs ± 3% 1.64µs ± 2% -13.68% (p=0.008 n=5+5)
CacheNoHitPar/size=512-4 1.86µs ± 3% 1.62µs ± 1% -12.91% (p=0.008 n=5+5)
CacheNoHitPar/size=4096-4 1.87µs ± 3% 1.70µs ± 3% -9.21% (p=0.008 n=5+5)
CacheHitPar/size=0-4 233ns ± 0% 217ns ± 3% -6.87% (p=0.016 n=4+5)
CacheHitPar/size=16-4 228ns ± 2% 225ns ± 2% ~ (p=0.119 n=5+5)
CacheHitPar/size=128-4 232ns ± 4% 214ns ± 1% -7.92% (p=0.008 n=5+5)
CacheHitPar/size=512-4 228ns ± 1% 210ns ± 1% -7.82% (p=0.008 n=5+5)
CacheHitPar/size=4096-4 226ns ± 2% 209ns ± 2% -7.54% (p=0.008 n=5+5)
NoopStorageProc-4 34.1ns ± 6% 34.9ns ±18% ~ (p=0.690 n=5+5)
CacheStartupProc-4 1.14µs ± 8% 1.12µs ± 4% ~ (p=0.802 n=5+5)
CacheNoHitProc/size=0-4 1.32µs ± 4% 1.10µs ± 6% -16.92% (p=0.008 n=5+5)
CacheNoHitProc/size=16-4 1.32µs ± 2% 1.14µs ± 7% -13.54% (p=0.008 n=5+5)
CacheNoHitProc/size=128-4 1.30µs ± 6% 1.07µs ±10% -17.99% (p=0.008 n=5+5)
CacheNoHitProc/size=512-4 1.26µs ± 5% 1.09µs ± 5% -13.47% (p=0.008 n=5+5)
CacheNoHitProc/size=4096-4 1.27µs ± 3% 1.09µs ± 7% -14.55% (p=0.008 n=5+5)
CacheHitProc/size=0-4 69.5ns ± 6% 56.4ns ±10% -18.88% (p=0.008 n=5+5)
CacheHitProc/size=16-4 75.1ns ± 6% 55.8ns ± 1% -25.65% (p=0.008 n=5+5)
CacheHitProc/size=128-4 74.5ns ± 4% 57.1ns ± 1% -23.31% (p=0.008 n=5+5)
CacheHitProc/size=512-4 69.4ns ± 1% 58.1ns ± 2% -16.27% (p=0.008 n=5+5)
CacheHitProc/size=4096-4 93.3ns ± 5% 63.2ns ± 4% -32.25% (p=0.008 n=5+5)

name old allocs/op new allocs/op delta
NoopStorage-4 0.00 0.00 ~ (all equal)
CacheStartup-4 6.00 ± 0% 5.00 ± 0% -16.67% (p=0.008 n=5+5)
CacheNoHit/size=0-4 4.00 ± 0% 3.00 ± 0% -25.00% (p=0.008 n=5+5)
CacheNoHit/size=16-4 4.00 ± 0% 3.00 ± 0% -25.00% (p=0.008 n=5+5)
CacheNoHit/size=128-4 4.00 ± 0% 3.00 ± 0% -25.00% (p=0.008 n=5+5)
CacheNoHit/size=512-4 4.00 ± 0% 3.00 ± 0% -25.00% (p=0.008 n=5+5)
CacheNoHit/size=4096-4 4.00 ± 0% 3.00 ± 0% -25.00% (p=0.008 n=5+5)
CacheHit/size=0-4 0.00 0.00 ~ (all equal)
CacheHit/size=16-4 0.00 0.00 ~ (all equal)
CacheHit/size=128-4 0.00 0.00 ~ (all equal)
CacheHit/size=512-4 0.00 0.00 ~ (all equal)
CacheHit/size=4096-4 0.00 0.00 ~ (all equal)
NoopStoragePar-4 0.00 0.00 ~ (all equal)
CacheStartupPar-4 5.00 ± 0% 4.00 ± 0% -20.00% (p=0.008 n=5+5)
CacheNoHitPar/size=0-4 4.00 ± 0% 3.00 ± 0% -25.00% (p=0.008 n=5+5)
CacheNoHitPar/size=16-4 4.00 ± 0% 3.00 ± 0% -25.00% (p=0.008 n=5+5)
CacheNoHitPar/size=128-4 4.00 ± 0% 3.00 ± 0% -25.00% (p=0.008 n=5+5)
CacheNoHitPar/size=512-4 4.00 ± 0% 3.00 ± 0% -25.00% (p=0.008 n=5+5)
CacheNoHitPar/size=4096-4 4.00 ± 0% 3.00 ± 0% -25.00% (p=0.008 n=5+5)
CacheHitPar/size=0-4 0.00 0.00 ~ (all equal)
CacheHitPar/size=16-4 0.00 0.00 ~ (all equal)
CacheHitPar/size=128-4 0.00 0.00 ~ (all equal)
CacheHitPar/size=512-4 0.00 0.00 ~ (all equal)
CacheHitPar/size=4096-4 0.00 0.00 ~ (all equal)
NoopStorageProc-4 0.00 0.00 ~ (all equal)
CacheStartupProc-4 6.00 ± 0% 5.00 ± 0% -16.67% (p=0.008 n=5+5)
CacheNoHitProc/size=0-4 4.00 ± 0% 3.00 ± 0% -25.00% (p=0.008 n=5+5)
CacheNoHitProc/size=16-4 4.00 ± 0% 3.00 ± 0% -25.00% (p=0.008 n=5+5)
CacheNoHitProc/size=128-4 4.00 ± 0% 3.00 ± 0% -25.00% (p=0.008 n=5+5)
CacheNoHitProc/size=512-4 4.00 ± 0% 3.00 ± 0% -25.00% (p=0.008 n=5+5)
CacheNoHitProc/size=4096-4 4.00 ± 0% 3.00 ± 0% -25.00% (p=0.008 n=5+5)
CacheHitProc/size=0-4 0.00 0.00 ~ (all equal)
CacheHitProc/size=16-4 0.00 0.00 ~ (all equal)
CacheHitProc/size=128-4 0.00 0.00 ~ (all equal)
CacheHitProc/size=512-4 0.00 0.00 ~ (all equal)
CacheHitProc/size=4096-4 0.00 0.00 ~ (all equal)

1f07e51a

X zodb/cache: Benchmarks · 0d377587

Kirill Smelkov authored Dec 31, 2017

So that we can measure how every change affects cache performance.

Added Cache.Close() along the way, since if without it, there was no way
to release gcmain goroutine stack and with many benchmarks run this was
causing out of memory.

0d377587

29 Dec, 2017 1 commit
- . · b47715f9
  Kirill Smelkov authored Dec 29, 2017
  
  b47715f9
26 Dec, 2017 1 commit

X zodb/cache: Fix concurrency bug () · e80dcbde

Kirill Smelkov authored Dec 26, 2017

By extending loadRCE to accept how much the caller wants returned
rce.buf to be xincref'ed we can teach it to do the incref consistently
under rce.parent lock either itself, or schedule the incref to loadRCE
to be done after rce is loaded right before it is exposed to outside
world (rce waiters + gc).

e80dcbde

21 Dec, 2017 3 commits

X *: Fix vet errors automatically found by Go1.10 · 148222a1
Kirill Smelkov authored Dec 21, 2017

148222a1

X zodb/cache: A concurency bug was found · 42687746

Kirill Smelkov authored Dec 21, 2017

which is showing itself as e.g.

---- 8< ----
panic: Buf: refcnt < 0

goroutine 7 [running]:
lab.nexedi.com/kirr/neo/go/zodb.(*Buf).Release(0xc42000db40)
        /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/buffer.go:107 +0x116
lab.nexedi.com/kirr/neo/go/zodb.(*Buf).XRelease(0xc42000db40)
        /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/buffer.go:136 +0x3a
lab.nexedi.com/kirr/neo/go/zodb.(*Cache).gc(0xc4200101c0)
        /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/cache.go:488 +0x22f
lab.nexedi.com/kirr/neo/go/zodb.(*Cache).gcmain(0xc4200101c0)
        /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/cache.go:451 +0x3f
created by lab.nexedi.com/kirr/neo/go/zodb.NewCache
        /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/cache.go:123 +0x126
---- 8< ----

during zhash.go -prefetch run.

This patch adds the test for this bug and explains the problem in detail
there. The test currently fails:

--- FAIL: TestCache (0.01s)
panic: Buf.Incref: refcnt was < 1 [recovered]
        panic: Buf.Incref: refcnt was < 1

goroutine 18 [running]:
testing.tRunner.func1(0xc4240ce000)
        /home/kirr/src/tools/go/go/src/testing/testing.go:711 +0x2d2
panic(0x588a20, 0x5ebe70)
        /home/kirr/src/tools/go/go/src/runtime/panic.go:491 +0x283
lab.nexedi.com/kirr/neo/go/zodb.(*Buf).Incref(0xc4200c2460)
        /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/buffer.go:134 +0x58
lab.nexedi.com/kirr/neo/go/zodb.(*Buf).XIncref(0xc4200c2460)
        /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/buffer.go:148 +0x3a
lab.nexedi.com/kirr/neo/go/zodb.(*Cache).Load(0xc4200ca000, 0x6ab1a0, 0xc42001a148, 0x4, 0x1, 0x10, 0xc4200bf2e0, 0x10, 0x10)
        /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/cache.go:168 +0x1c7
lab.nexedi.com/kirr/neo/go/zodb.TestCache.func2(0x4, 0x1, 0xc4200c2440, 0x4, 0x0, 0x0)
        /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/cache_test.go:155 +0xcc
lab.nexedi.com/kirr/neo/go/zodb.TestCache(0xc4240ce000)
        /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/cache_test.go:579 +0x4eb5
testing.tRunner(0xc4240ce000, 0x5d4728)
        /home/kirr/src/tools/go/go/src/testing/testing.go:746 +0xd0
created by testing.(*T).Run
        /home/kirr/src/tools/go/go/src/testing/testing.go:789 +0x2de
exit status 2

42687746

Preserve 'packed' flag on import/iteration · a414f91f
Julien Muchembled authored Dec 21, 2017

a414f91f

20 Dec, 2017 1 commit

X Split IStorage -> IStorage, IStorageDriver · 0abecd63

Kirill Smelkov authored Dec 20, 2017

- IStorageDriver implements only raw access to a particular storage
- Prefetching logic + other common bits are implemented byt zodb package
  infrastructure (e.g. Prefetch() and URL()) and access to them is
  provided by IStorage.

It currently regresses plain load speed:

name                           old time/object  new time/object  delta
dataset:wczblk1-8
deco/fs1/zhash.py                  15.4µs ± 4%      15.2µs ± 2%      ~     (p=0.159 n=4+5)
deco/fs1/zhash.py-P16               116µs ±17%       121µs ±21%      ~     (p=0.407 n=16+16)
deco/fs1/zhash.go                  1.50µs ± 0%      5.30µs ± 0%  +253.33%  (p=0.016 n=5+4)
deco/fs1/zhash.go+prefetch128      4.08µs ± 5%      4.20µs ± 2%      ~     (p=0.143 n=5+5)
deco/fs1/zhash.go-P16             4.77µs ±179%     33.85µs ±54%  +610.14%  (p=0.000 n=15+16)
dataset:prod1-1024
deco/fs1/zhash.py                  12.2µs ± 1%      12.4µs ± 4%      ~     (p=0.540 n=4+5)
deco/fs1/zhash.py-P16               102µs ±12%       101µs ±16%      ~     (p=0.802 n=16+16)
deco/fs1/zhash.go                  1.10µs ± 0%      2.66µs ± 2%  +141.82%  (p=0.008 n=5+5)
deco/fs1/zhash.go+prefetch128      2.70µs ± 0%      2.67µs ± 3%      ~     (p=1.000 n=4+4)
deco/fs1/zhash.go-P16             3.20µs ±138%     17.25µs ±42%  +439.06%  (p=0.000 n=16+16)

will try to investigate what is going on inside.

0abecd63

18 Dec, 2017 2 commits
- X zodb: Clarify load semantic: for deleted data err="no data" and buf, serial = nil, 0 · 6ae2604b
  Kirill Smelkov authored Dec 18, 2017
  
  6ae2604b
- X zodb: Goodby XTid; Load always loads `At`; loadSerial is actually not needed · 75dc3060
  Kirill Smelkov authored Dec 14, 2017
```
also:

- DataTid -> DataTidHint + 0 if there is no such hint.
```
  75dc3060
15 Dec, 2017 3 commits
- fixup! storage: speed up replication by not getting object next_serial for nothing · 5abfa5fd
  Julien Muchembled authored Dec 15, 2017
  
  5abfa5fd
- Merge "client: fix accounting of cache size" · 121b3882
  Julien Muchembled authored Dec 15, 2017
  
  121b3882
- client: fix accounting of cache size · 5b02f44b
  Julien Muchembled authored Dec 13, 2017
  
  5b02f44b
13 Dec, 2017 4 commits
- . · ba61dad6
  Kirill Smelkov authored Dec 13, 2017
  
  ba61dad6
- X neotest/bench-cpu: Also benchmark sha1 for 2M; report size units as e.g. 4K not 4096B · 9a266d11
  Kirill Smelkov authored Dec 13, 2017
  
  9a266d11
- X neotest/bench-disk: Deduplicate code; change 1M -> 2M · 44529dbf
  Kirill Smelkov authored Dec 13, 2017
```
So now we are benchmarking disk for sizes 4K and 2M which are the usual
sizes popping up with e.g. wendelin.core.
```
  44529dbf
- doc: comments, fixups · f2070ca4
  Julien Muchembled authored Dec 13, 2017
  
  f2070ca4
11 Dec, 2017 4 commits

Merge remote-tracking branch 'origin/master' into t · f6816a7c

Kirill Smelkov authored Dec 11, 2017

* origin/master:
  client: account for cache hit/miss statistics
  client: remove redundant information from cache's __repr__
  cache: fix possible endless loop in __repr__/_iterQueue
  storage: speed up replication by not getting object next_serial for nothing
  storage: speed up replication by sending bigger network packets
  neoctl: remove ignored option
  client: bug found, add log to collect more information
  client: new 'cache-size' Storage option
  doc: mention HTTPS URLs when possible
  doc: update comment in neolog about Python issue 13773
  neolog: add support for xz-compressed logs, using external xzcat commands
  neolog: --from option now also tries to parse with dateutil
  importer: do not crash if a backup cluster tries to replicate
  storage: disable data deduplication by default
  Release version 1.8.1

f6816a7c

client: account for cache hit/miss statistics · c76b3a0a

Kirill Smelkov authored Jul 22, 2016

This information is handy to see how well cache performs.

Amended by Julien Muchembled:
- do not abbreviate some existing field names in repr result (asking the
  user to look at the source code in order to decipher logs is not nice)
- hit: change from %.1f to %.3g
- hit: hide it completely if nload is 0
- use __future__.division instead of adding more casts to float

c76b3a0a

client: remove redundant information from cache's __repr__ · d1f52422
Julien Muchembled authored Dec 11, 2017

d1f52422
cache: fix possible endless loop in __repr__/_iterQueue · d83cb872
Julien Muchembled authored Dec 09, 2017

d83cb872

08 Dec, 2017 1 commit

X neotest/bench-disk: Also benchmark randomly reading 1M blocks · 8bac3dba

Kirill Smelkov authored Dec 08, 2017

On my disk it gives:

name                                 time/op
deco/disk/randread/direct/4K-min     98.0µs ± 1%
deco/disk/randread/direct/4K-avg      104µs ± 0%
deco/disk/randread/direct/1M-min     2.90ms ±17%
deco/disk/randread/direct/1M-avg     3.55ms ± 0%
deco/disk/randread/pagecache/4K-min   227ns ± 1%
deco/disk/randread/pagecache/4K-avg   629ns ± 0%
deco/disk/randread/pagecache/1M-min  70.8µs ± 7%
deco/disk/randread/pagecache/1M-avg  99.4µs ± 1%

8bac3dba

05 Dec, 2017 2 commits
- storage: speed up replication by not getting object next_serial for nothing · be839e92
  Julien Muchembled authored Dec 05, 2017
  
  be839e92
- storage: speed up replication by sending bigger network packets · c25e68bc
  Julien Muchembled authored Dec 01, 2017
  
  c25e68bc
04 Dec, 2017 1 commit
- neoctl: remove ignored option · 96aeb716
  Julien Muchembled authored Dec 01, 2017
  
  96aeb716
22 Nov, 2017 1 commit
- . · 3e0610ce
  Kirill Smelkov authored Nov 22, 2017
  
  3e0610ce
21 Nov, 2017 1 commit

client: bug found, add log to collect more information · a1082cbc

Julien Muchembled authored Nov 21, 2017

INFO Z2 Log files reopened successfully
INFO SignalHandler Caught signal SIGTERM
INFO Z2 Shutting down fast
INFO ZServer closing HTTP to new connections
ERROR ZODB.Connection Couldn't load state for BTrees.LOBTree.LOBucket 0xc12e29
Traceback (most recent call last):
  File "ZODB/Connection.py", line 909, in setstate
    self._setstate(obj, oid)
  File "ZODB/Connection.py", line 953, in _setstate
    p, serial = self._storage.load(oid, '')
  File "neo/client/Storage.py", line 81, in load
    return self.app.load(oid)[:2]
  File "neo/client/app.py", line 355, in load
    data, tid, next_tid, _ = self._loadFromStorage(oid, tid, before_tid)
  File "neo/client/app.py", line 387, in _loadFromStorage
    askStorage)
  File "neo/client/app.py", line 297, in _askStorageForRead
    self.sync()
  File "neo/client/app.py", line 898, in sync
    self._askPrimary(Packets.Ping())
  File "neo/client/app.py", line 163, in _askPrimary
    return self._ask(self._getMasterConnection(), packet,
  File "neo/client/app.py", line 177, in _getMasterConnection
    result = self.master_conn = self._connectToPrimaryNode()
  File "neo/client/app.py", line 202, in _connectToPrimaryNode
    index = (index + 1) % len(master_list)
ZeroDivisionError: integer division or modulo by zero

a1082cbc

20 Nov, 2017 1 commit
- . · 428eb133
  Kirill Smelkov authored Nov 20, 2017
  
  428eb133
19 Nov, 2017 1 commit
- client: new 'cache-size' Storage option · acef3571
  Julien Muchembled authored Nov 19, 2017
  
  acef3571
17 Nov, 2017 1 commit
- doc: mention HTTPS URLs when possible · 9c56e9cd
  Julien Muchembled authored Nov 17, 2017
  
  9c56e9cd