Commits · 0e2be3b3b890b25eb66683d137a0e10ca97285c5 · Kirill Smelkov / neo

08 Jan, 2018 1 commit

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

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 2 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

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
13 Dec, 2017 3 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
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 4 commits
- doc: mention HTTPS URLs when possible · 9c56e9cd
  Julien Muchembled authored Nov 17, 2017
  
  9c56e9cd
- doc: update comment in neolog about Python issue 13773 · e2e2d895
  Julien Muchembled authored Nov 17, 2017
  
  e2e2d895
- neolog: add support for xz-compressed logs, using external xzcat commands · 188c55f9
  Julien Muchembled authored Nov 17, 2017
  
  188c55f9
- neolog: --from option now also tries to parse with dateutil · 9ee4e04d
  Julien Muchembled authored Nov 17, 2017
  
  9ee4e04d
15 Nov, 2017 1 commit
- importer: do not crash if a backup cluster tries to replicate · d6f61422
  Julien Muchembled authored Nov 15, 2017
```
It's not possible yet to replicate a node that is importing data.
One must wait that the migration is finished.
```
  d6f61422
09 Nov, 2017 6 commits
- X fs1: Load of deleted oid should return "no data" · 467c573c
  Kirill Smelkov authored Nov 09, 2017
  
  467c573c
- . · 35eb77b2
  Kirill Smelkov authored Nov 09, 2017
  
  35eb77b2
- X fs1: test for empty-file case · 4c621541
  Kirill Smelkov authored Nov 09, 2017
  
  4c621541
- X fs1: Fix empty file iteration · 98fa98ce
  Kirill Smelkov authored Nov 09, 2017
  
  98fa98ce
- X fs1: switch error/EOF from (0, -1) -> (-1, 0) · cd186bf8
  Kirill Smelkov authored Nov 09, 2017
  
  cd186bf8
- . · 23870baf
  Kirill Smelkov authored Nov 09, 2017
  
  23870baf
08 Nov, 2017 1 commit
- . · fe8d33cd
  Kirill Smelkov authored Nov 08, 2017
  
  fe8d33cd