Commit 8d708026 authored by Kirill Smelkov's avatar Kirill Smelkov

X z6001 localhost time with C-states >C1 disabled

It improves a lot:

ZEO:             ~660μs ->  ~490μs
NEO/pylite:      ~750μs ->  ~470μs      (Cpy)
NEO/pylite:      ~500μs ->  ~370μs      (Cgo)
NEO/pysql:      ~1450μs ->  ~780μs      (Cpy)
NEO/pysql:      ~1000μs ->  ~670μs      (Cgo)
NEO/go:          ~450μs ->  ~280μs      (Cpy)
NEO/go:           ~90μs ->   ~80μs      (Cgo)
NEO/go-nosha1:    ~60μs ->   ~55μs
parent 42abaf7a
(with: cpupower idle-set --disable-by-latency 5)
>>> bench-local
# Thu, 05 Oct 2017 17:21:04 +0300
# neotest@z6001.ivan.nexedi.com (2401:5180:0:6f::1)
# Linux COMP-2784-z6001 4.10.0-35-generic #39~16.04.1-Ubuntu SMP Wed Sep 13 09:02:42 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux
# cpu: Intel(R) Xeon(R) CPU X5650 @ 2.67GHz
# cpu[0-23]: freq: acpi-cpufreq/performance [1.59GHz - 2.66GHz]
# cpu[0-23]: idle: intel_idle/menu: POLL(0μs) C1-NHM(3μs) !C1E-NHM(10μs) !C3-NHM(20μs) !C6-NHM(200μs)
# cpu: WARNING: frequency not fixed - benchmark timings won't be stable
# sda: ADATA SU800 rev 8BS 119,2G
# enp1s0: Broadcom Corporation NetXtreme BCM5764M Gigabit Ethernet PCIe rev 10 (rxc: 20μs/5f/0μs-irq/5f-irq txc: 72μs/53f/0μs-irq/5f-irq)
# enp1s0: WARNING: RX coalesce latency is max 20μs - that will add to networked request-reply latency
# Python 2.7.12
# go version go1.9 linux/amd64
# sqlite 3.11.0 (py mod 2.6.0)
# mysqld Ver 10.1.25-MariaDB-1 for debian-linux-gnu on x86_64 (Ubuntu 17.10)
# neo : v1.8-1256-g42abaf7
# zodb : 5.3.0
# zeo : 5.1.0
# mysqlclient : 1.3.12
# wendelin.core : 0.11
*** random direct (no kernel cache) 4K-read disk latency
--- . (ext4 /dev/sda1) ioping statistics ---
18.1 k requests completed in 2.97 s, 70.7 MiB read, 6.10 k iops, 23.8 MiB/s
generated 18.1 k requests in 3.00 s, 70.7 MiB, 6.03 k iops, 23.6 MiB/s
min/avg/max/mdev = 118.9 us / 163.9 us / 2.82 ms / 45.5 us
< 124.3 us 654 | *
< 129.0 us 5671 | ***************
< 133.6 us 12 |
< 138.3 us 10 |
< 142.9 us 6 |
< 147.6 us 0 |
< 152.3 us 1 |
< 156.9 us 220 |
< 161.6 us 5789 | ***************
< 166.2 us 11 |
< 170.9 us 9 |
< 175.5 us 2 |
< 180.2 us 0 |
< 184.8 us 0 |
< 189.5 us 0 |
< 194.2 us 0 |
< 198.8 us 1 |
< 203.5 us 0 |
< 208.1 us 110 |
< 212.8 us 4713 | *************
< 217.4 us 738 | **
< +∞ 46 |
# POLL·3 C1-NHM·19735 C1E-NHM·0 C3-NHM·0 C6-NHM·0
--- . (ext4 /dev/sda1) ioping statistics ---
18.2 k requests completed in 2.97 s, 71.0 MiB read, 6.13 k iops, 24.0 MiB/s
generated 18.2 k requests in 3.00 s, 71.0 MiB, 6.06 k iops, 23.7 MiB/s
min/avg/max/mdev = 119.1 us / 163.1 us / 226.3 us / 35.0 us
< 119.1 us 0 |
< 123.7 us 122 |
< 128.3 us 6339 | *****************
< 132.9 us 19 |
< 137.5 us 7 |
< 142.1 us 0 |
< 146.8 us 0 |
< 151.4 us 0 |
< 156.0 us 89 |
< 160.6 us 5816 | ***************
< 165.2 us 45 |
< 169.8 us 9 |
< 174.5 us 2 |
< 179.1 us 0 |
< 183.7 us 0 |
< 188.3 us 0 |
< 192.9 us 0 |
< 197.5 us 0 |
< 202.1 us 0 |
< 206.8 us 44 |
< 211.4 us 3920 | **********
< +∞ 1675 | ****
# POLL·0 C1-NHM·19258 C1E-NHM·0 C3-NHM·0 C6-NHM·0
--- . (ext4 /dev/sda1) ioping statistics ---
18.0 k requests completed in 2.97 s, 70.4 MiB read, 6.07 k iops, 23.7 MiB/s
generated 18.0 k requests in 3.00 s, 70.4 MiB, 6.01 k iops, 23.5 MiB/s
min/avg/max/mdev = 123.6 us / 164.6 us / 225.4 us / 34.9 us
< 124.8 us 62 |
< 129.7 us 6236 | *****************
< 134.6 us 19 |
< 139.5 us 14 |
< 144.4 us 0 |
< 149.3 us 0 |
< 154.3 us 0 |
< 159.2 us 3390 | *********
< 164.1 us 2610 | *******
< 169.0 us 3 |
< 173.9 us 3 |
< 178.8 us 0 |
< 183.7 us 0 |
< 188.7 us 0 |
< 193.6 us 0 |
< 198.5 us 0 |
< 203.4 us 0 |
< 208.3 us 0 |
< 213.2 us 4139 | ***********
< 218.1 us 1443 | ****
< 223.1 us 6 |
< +∞ 3 |
# POLL·10 C1-NHM·37070 C1E-NHM·0 C3-NHM·0 C6-NHM·0
--- . (ext4 /dev/sda1) ioping statistics ---
18.0 k requests completed in 2.97 s, 70.3 MiB read, 6.06 k iops, 23.7 MiB/s
generated 18.0 k requests in 3.00 s, 70.3 MiB, 6.00 k iops, 23.4 MiB/s
min/avg/max/mdev = 123.9 us / 164.9 us / 2.82 ms / 44.8 us
< 124.1 us 2 |
< 128.6 us 6173 | *****************
< 133.1 us 220 |
< 137.6 us 4 |
< 142.1 us 10 |
< 146.6 us 0 |
< 151.2 us 0 |
< 155.7 us 0 |
< 160.2 us 4245 | ***********
< 164.7 us 1679 | ****
< 169.2 us 12 |
< 173.7 us 3 |
< 178.2 us 1 |
< 182.7 us 0 |
< 187.2 us 0 |
< 191.8 us 0 |
< 196.3 us 0 |
< 200.8 us 0 |
< 205.3 us 0 |
< 209.8 us 1 |
< 214.3 us 5088 | **************
< +∞ 460 | *
# POLL·4 C1-NHM·36813 C1E-NHM·0 C3-NHM·0 C6-NHM·0
*** random cached 4K-read disk latency
--- . (ext4 /dev/sda1) ioping statistics ---
2.40 M requests completed in 2.82 s, 9.14 GiB read, 849.1 k iops, 3.24 GiB/s
generated 2.40 M requests in 3.00 s, 9.14 GiB, 798.6 k iops, 3.05 GiB/s
min/avg/max/mdev = 418 ns / 1.18 us / 46.0 us / 342 ns
< 952 ns 272224 | *****
< 996 ns 109878 | **
< 1.04 us 123688 | **
< 1.09 us 163621 | ***
< 1.13 us 224189 | ****
< 1.18 us 239329 | ****
< 1.22 us 295933 | ******
< 1.26 us 268068 | *****
< 1.31 us 229241 | ****
< 1.35 us 161689 | ***
< 1.40 us 119279 | **
< 1.44 us 89775 | *
< 1.49 us 49800 | *
< 1.53 us 25231 |
< 1.58 us 11115 |
< 1.62 us 4977 |
< 1.67 us 2589 |
< 1.71 us 1301 |
< 1.76 us 694 |
< 1.80 us 411 |
< 1.85 us 306 |
< +∞ 2341 |
# POLL·1 C1-NHM·1578 C1E-NHM·0 C3-NHM·0 C6-NHM·0
--- . (ext4 /dev/sda1) ioping statistics ---
2.72 M requests completed in 2.80 s, 10.4 GiB read, 972.8 k iops, 3.71 GiB/s
generated 2.72 M requests in 3.00 s, 10.4 GiB, 907.7 k iops, 3.46 GiB/s
min/avg/max/mdev = 405 ns / 1.03 us / 38.2 us / 279 ns
< 933 ns 910310 | ****************
< 974 ns 424205 | *******
< 1.01 us 290946 | *****
< 1.06 us 195291 | ***
< 1.10 us 156093 | **
< 1.14 us 140421 | **
< 1.18 us 127746 | **
< 1.22 us 110023 | **
< 1.26 us 95822 | *
< 1.30 us 81144 | *
< 1.35 us 60962 | *
< 1.39 us 42640 |
< 1.43 us 31746 |
< 1.47 us 21260 |
< 1.51 us 13305 |
< 1.55 us 8024 |
< 1.59 us 4088 |
< 1.64 us 2293 |
< 1.68 us 1552 |
< 1.72 us 983 |
< 1.76 us 657 |
< +∞ 3456 |
# POLL·1 C1-NHM·1595 C1E-NHM·0 C3-NHM·0 C6-NHM·0
--- . (ext4 /dev/sda1) ioping statistics ---
2.73 M requests completed in 2.80 s, 10.4 GiB read, 978.0 k iops, 3.73 GiB/s
generated 2.73 M requests in 3.00 s, 10.4 GiB, 911.4 k iops, 3.48 GiB/s
min/avg/max/mdev = 410 ns / 1.02 us / 35.4 us / 274 ns
< 635 ns 17959 |
< 690 ns 3728 |
< 745 ns 2578 |
< 800 ns 19964 |
< 855 ns 200005 | ***
< 910 ns 471941 | ********
< 965 ns 575731 | **********
< 1.02 us 393987 | *******
< 1.08 us 238873 | ****
< 1.13 us 195915 | ***
< 1.19 us 166010 | ***
< 1.24 us 142489 | **
< 1.30 us 111267 | **
< 1.35 us 79476 | *
< 1.41 us 51303 |
< 1.46 us 31703 |
< 1.52 us 16302 |
< 1.57 us 7647 |
< 1.63 us 3182 |
< 1.68 us 1355 |
< 1.74 us 673 |
< +∞ 1882 |
# POLL·0 C1-NHM·1114 C1E-NHM·0 C3-NHM·0 C6-NHM·0
--- . (ext4 /dev/sda1) ioping statistics ---
2.77 M requests completed in 2.79 s, 10.6 GiB read, 992.6 k iops, 3.79 GiB/s
generated 2.77 M requests in 3.00 s, 10.6 GiB, 922.8 k iops, 3.52 GiB/s
min/avg/max/mdev = 412 ns / 1.01 us / 54.4 us / 274 ns
< 827 ns 165074 | **
< 858 ns 215243 | ***
< 890 ns 287003 | *****
< 922 ns 344330 | ******
< 954 ns 329465 | *****
< 986 ns 248974 | ****
< 1.02 us 173729 | ***
< 1.05 us 141418 | **
< 1.08 us 125147 | **
< 1.11 us 113582 | **
< 1.15 us 102731 | *
< 1.18 us 94032 | *
< 1.21 us 83042 | *
< 1.24 us 75922 | *
< 1.27 us 62464 | *
< 1.30 us 52934 |
< 1.34 us 41030 |
< 1.37 us 31955 |
< 1.40 us 24179 |
< 1.43 us 18485 |
< 1.47 us 13342 |
< +∞ 24210 |
# POLL·0 C1-NHM·973 C1E-NHM·0 C3-NHM·0 C6-NHM·0
*** FileStorage
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=0.309s (36.3μs / object) x=zhash.py # POLL·0 C1-NHM·700 C1E-NHM·0 C3-NHM·0 C6-NHM·0
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=0.305s (35.8μs / object) x=zhash.py # POLL·0 C1-NHM·542 C1E-NHM·0 C3-NHM·0 C6-NHM·0
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=0.311s (36.5μs / object) x=zhash.py # POLL·1 C1-NHM·641 C1E-NHM·0 C3-NHM·0 C6-NHM·0
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=0.303s (35.6μs / object) x=zhash.py # POLL·3 C1-NHM·613 C1E-NHM·0 C3-NHM·0 C6-NHM·0
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=29.992173ms (3.528µs / object) x=zhash.go # POLL·4 C1-NHM·520 C1E-NHM·0 C3-NHM·0 C6-NHM·0
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=29.867467ms (3.513µs / object) x=zhash.go # POLL·2 C1-NHM·485 C1E-NHM·0 C3-NHM·0 C6-NHM·0
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=31.876544ms (3.75µs / object) x=zhash.go # POLL·1 C1-NHM·537 C1E-NHM·0 C3-NHM·0 C6-NHM·0
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=31.940049ms (3.757µs / object) x=zhash.go # POLL·1 C1-NHM·544 C1E-NHM·0 C3-NHM·0 C6-NHM·0
*** ZEO
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=4.294s (505.2μs / object) x=zhash.py # POLL·3 C1-NHM·126061 C1E-NHM·0 C3-NHM·0 C6-NHM·0
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=4.141s (487.2μs / object) x=zhash.py # POLL·7 C1-NHM·140622 C1E-NHM·0 C3-NHM·0 C6-NHM·0
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=4.163s (489.7μs / object) x=zhash.py # POLL·6 C1-NHM·152169 C1E-NHM·0 C3-NHM·0 C6-NHM·0
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=4.187s (492.6μs / object) x=zhash.py # POLL·18 C1-NHM·138080 C1E-NHM·0 C3-NHM·0 C6-NHM·0
(skipping zhash.go on ZEO -- Cgo does not support zeo:// protocol)
*** NEO/py sqlite
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=4.125s (485.3μs / object) x=zhash.py # POLL·6 C1-NHM·81900 C1E-NHM·0 C3-NHM·0 C6-NHM·0
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=4.021s (473.1μs / object) x=zhash.py # POLL·8 C1-NHM·88974 C1E-NHM·0 C3-NHM·0 C6-NHM·0
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=4.030s (474.1μs / object) x=zhash.py # POLL·4 C1-NHM·89442 C1E-NHM·0 C3-NHM·0 C6-NHM·0
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=4.227s (497.3μs / object) x=zhash.py # POLL·2 C1-NHM·86842 C1E-NHM·0 C3-NHM·0 C6-NHM·0
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=3.150344169s (370.628µs / object) x=zhash.go # POLL·23 C1-NHM·85931 C1E-NHM·0 C3-NHM·0 C6-NHM·0
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=3.156508991s (371.353µs / object) x=zhash.go # POLL·44 C1-NHM·85815 C1E-NHM·0 C3-NHM·0 C6-NHM·0
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=3.157598232s (371.482µs / object) x=zhash.go # POLL·30 C1-NHM·85845 C1E-NHM·0 C3-NHM·0 C6-NHM·0
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=3.126495706s (367.823µs / object) x=zhash.go # POLL·42 C1-NHM·85510 C1E-NHM·0 C3-NHM·0 C6-NHM·0
2017-10-05 17:22:25.3812 ERROR NEO [ app: 91] primary master is down
Cluster state changed
*** NEO/py sql
2017-10-05 17:22:25 140072741472512 [Note] mysqld (mysqld 10.1.25-MariaDB-1) starting as process 22806 ...
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=6.667s (784.4μs / object) x=zhash.py # POLL·4 C1-NHM·123426 C1E-NHM·0 C3-NHM·0 C6-NHM·0
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=6.543s (769.7μs / object) x=zhash.py # POLL·20 C1-NHM·125341 C1E-NHM·0 C3-NHM·0 C6-NHM·0
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=6.662s (783.8μs / object) x=zhash.py # POLL·9 C1-NHM·122428 C1E-NHM·0 C3-NHM·0 C6-NHM·0
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=6.533s (768.5μs / object) x=zhash.py # POLL·2 C1-NHM·120735 C1E-NHM·0 C3-NHM·0 C6-NHM·0
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=5.670660571s (667.136µs / object) x=zhash.go # POLL·30 C1-NHM·119570 C1E-NHM·0 C3-NHM·0 C6-NHM·0
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=5.681001248s (668.353µs / object) x=zhash.go # POLL·46 C1-NHM·120748 C1E-NHM·0 C3-NHM·0 C6-NHM·0
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=5.660336118s (665.921µs / object) x=zhash.go # POLL·49 C1-NHM·120544 C1E-NHM·0 C3-NHM·0 C6-NHM·0
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=5.668879132s (666.926µs / object) x=zhash.go # POLL·57 C1-NHM·119752 C1E-NHM·0 C3-NHM·0 C6-NHM·0
2017-10-05 17:23:17.2962 ERROR NEO [ app: 91] primary master is down
Cluster state changed
*** NEO/go
2017-10-05 17:23:19.8402 ERROR NEO [ handler: 59] unexpected packet: Retry Later in PrimaryBootstrapHandler
2017-10-05 17:23:19.8406 ERROR NEO [ app:233] Connection to None lost
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=2.385s (280.6μs / object) x=zhash.py
# POLL·9 C1-NHM·127109 C1E-NHM·0 C3-NHM·0 C6-NHM·0
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=2.468s (290.3μs / object) x=zhash.py # POLL·8 C1-NHM·127383 C1E-NHM·0 C3-NHM·0 C6-NHM·0
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=2.371s (278.9μs / object) x=zhash.py # POLL·9 C1-NHM·125148 C1E-NHM·0 C3-NHM·0 C6-NHM·0
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=2.375s (279.4μs / object) x=zhash.py # POLL·2 C1-NHM·126397 C1E-NHM·0 C3-NHM·0 C6-NHM·0
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=699.179263ms (82.256µs / object) x=zhash.go # POLL·24 C1-NHM·68794 C1E-NHM·0 C3-NHM·0 C6-NHM·0
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=709.117853ms (83.425µs / object) x=zhash.go # POLL·24 C1-NHM·74652 C1E-NHM·0 C3-NHM·0 C6-NHM·0
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=683.703002ms (80.435µs / object) x=zhash.go # POLL·21 C1-NHM·61659 C1E-NHM·0 C3-NHM·0 C6-NHM·0
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=672.47012ms (79.114µs / object) x=zhash.go # POLL·21 C1-NHM·68183 C1E-NHM·0 C3-NHM·0 C6-NHM·0
2017/10/05 17:23:34 talk master([2401:5180:0:6f::1]:5552): context canceled
2017-10-05 17:23:34.6563 ERROR NEO [ app: 91] primary master is down
Cluster state changed
*** NEO/go (sha1 disabled)
# NEO/go/storage: skipping SHA1 computations
# NEO/go/client: skipping SHA1 checks
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=477.947274ms (56.229µs / object) x=zhash.go
# POLL·6 C1-NHM·59252 C1E-NHM·0 C3-NHM·0 C6-NHM·0
# NEO/go/client: skipping SHA1 checks
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=479.279429ms (56.385µs / object) x=zhash.go
# POLL·14 C1-NHM·58647 C1E-NHM·0 C3-NHM·0 C6-NHM·0
# NEO/go/client: skipping SHA1 checks
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=467.723795ms (55.026µs / object) x=zhash.go
# POLL·23 C1-NHM·57850 C1E-NHM·0 C3-NHM·0 C6-NHM·0
# NEO/go/client: skipping SHA1 checks
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=465.597699ms (54.776µs / object) x=zhash.go
# POLL·12 C1-NHM·58058 C1E-NHM·0 C3-NHM·0 C6-NHM·0
2017/10/05 17:23:37 talk master([2401:5180:0:6f::1]:5552): context canceled
2017-10-05 17:23:37.8425 ERROR NEO [ app: 91] primary master is down
Cluster state changed
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment