1. 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
  2. 29 Dec, 2017 1 commit
  3. 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
  4. 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
  5. 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
  6. 18 Dec, 2017 2 commits
  7. 13 Dec, 2017 3 commits
  8. 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
  9. 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
  10. 05 Dec, 2017 2 commits
  11. 04 Dec, 2017 1 commit
  12. 22 Nov, 2017 1 commit
  13. 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
  14. 20 Nov, 2017 1 commit
  15. 19 Nov, 2017 1 commit
  16. 17 Nov, 2017 4 commits
  17. 15 Nov, 2017 1 commit
  18. 09 Nov, 2017 6 commits
  19. 08 Nov, 2017 5 commits