• Kirill Smelkov's avatar
    X zodb/cache: Speedup checkpoint · 64ede21c
    Kirill Smelkov authored
    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
20180109-time-deco-Cenabled-goclientcache=off.txt 123 KB