1. 03 Jan, 2018 3 commits
    • Kirill Smelkov's avatar
      X zodb/fs1: Don't set .file = nil on Close · a5d0e83f
      Kirill Smelkov authored
      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
    • Kirill Smelkov's avatar
      X neotest/info: Handle USB NICs · a971231c
      Kirill Smelkov authored
      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
    • Kirill Smelkov's avatar
      X zodb/cache: Also free OCE entries on GC · 521d3ae5
      Kirill Smelkov authored
      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
  2. 31 Dec, 2017 2 commits
    • Kirill Smelkov's avatar
      X zodb/cache: Switch RCE.ready from chan to sync.WaitGroup · 1f07e51a
      Kirill Smelkov authored
      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
    • Kirill Smelkov's avatar
      X zodb/cache: Benchmarks · 0d377587
      Kirill Smelkov authored
      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
  3. 29 Dec, 2017 1 commit
  4. 26 Dec, 2017 1 commit
    • Kirill Smelkov's avatar
      X zodb/cache: Fix concurrency bug (42687746) · e80dcbde
      Kirill Smelkov authored
      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
  5. 21 Dec, 2017 2 commits
    • Kirill Smelkov's avatar
      148222a1
    • Kirill Smelkov's avatar
      X zodb/cache: A concurency bug was found · 42687746
      Kirill Smelkov authored
      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
  6. 20 Dec, 2017 1 commit
    • Kirill Smelkov's avatar
      X Split IStorage -> IStorage, IStorageDriver · 0abecd63
      Kirill Smelkov authored
      - 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
  7. 18 Dec, 2017 2 commits
  8. 13 Dec, 2017 3 commits
  9. 11 Dec, 2017 4 commits
    • Kirill Smelkov's avatar
      Merge remote-tracking branch 'origin/master' into t · f6816a7c
      Kirill Smelkov authored
      * 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
    • Kirill Smelkov's avatar
      client: account for cache hit/miss statistics · c76b3a0a
      Kirill Smelkov authored
      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
    • Julien Muchembled's avatar
    • Julien Muchembled's avatar
  10. 08 Dec, 2017 1 commit
    • Kirill Smelkov's avatar
      X neotest/bench-disk: Also benchmark randomly reading 1M blocks · 8bac3dba
      Kirill Smelkov authored
      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
  11. 05 Dec, 2017 2 commits
  12. 04 Dec, 2017 1 commit
  13. 22 Nov, 2017 1 commit
  14. 21 Nov, 2017 1 commit
    • Julien Muchembled's avatar
      client: bug found, add log to collect more information · a1082cbc
      Julien Muchembled authored
      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
  15. 20 Nov, 2017 1 commit
  16. 19 Nov, 2017 1 commit
  17. 17 Nov, 2017 4 commits
  18. 15 Nov, 2017 1 commit
  19. 09 Nov, 2017 6 commits
  20. 08 Nov, 2017 2 commits