Skip to content

N
neo
Commit 4b5db5b0 authored by Kirill Smelkov's avatar Kirill Smelkov
Browse files
Options

X time on z6001 (localhost) 

~ the same as on oct04 only we add C-states profiling. C-states are not yet disabled.
parent b1f98a52
Hide whitespace changes
Inline Side-by-side
Showing with 323 additions and 0 deletions
go/time-soct05-z6001.txt 0 → 100644
View file @ 4b5db5b0
>>> bench-local
# Thu, 05 Oct 2017 16:04:33 +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
# cpu: WARNING: C-state exit-latency is max 200μs - that can add to networked(?) and IPC(?) request-reply latency
# 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-1253-gb1f98a5
# 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 ---
15.6 k requests completed in 2.95 s, 61.1 MiB read, 5.31 k iops, 20.7 MiB/s
generated 15.6 k requests in 3.00 s, 61.1 MiB, 5.22 k iops, 20.4 MiB/s
min/avg/max/mdev = 49.2 us / 188.4 us / 563.1 us / 39.6 us
< 125.7 us 24 |
< 132.7 us 573 | *
< 139.7 us 1797 | *****
< 146.7 us 202 |
< 153.7 us 557 | *
< 160.8 us 1247 | ***
< 167.8 us 887 | **
< 174.8 us 1631 | *****
< 181.8 us 621 | *
< 188.8 us 1568 | *****
< 195.8 us 269 |
< 202.9 us 376 | *
< 209.9 us 346 | *
< 216.9 us 990 | ***
< 223.9 us 1612 | *****
< 230.9 us 207 |
< 237.9 us 488 | *
< 245.0 us 758 | **
< 252.0 us 355 | *
< 259 us 302 |
< 266.0 us 307 |
< +∞ 431 | *
# POLL·4 C1-NHM·1957 C1E-NHM·9486 C3-NHM·7008 C6-NHM·3309
--- . (ext4 /dev/sda1) ioping statistics ---
15.9 k requests completed in 2.95 s, 62.0 MiB read, 5.39 k iops, 21.0 MiB/s
generated 15.9 k requests in 3.00 s, 62.0 MiB, 5.29 k iops, 20.7 MiB/s
min/avg/max/mdev = 123.7 us / 185.6 us / 317.3 us / 41.2 us
< 123.7 us 0 |
< 131.0 us 985 | ***
< 138.3 us 2321 | *******
< 145.6 us 353 | *
< 153.0 us 158 |
< 160.3 us 477 | *
< 167.6 us 1951 | ******
< 174.9 us 1607 | *****
< 182.2 us 1108 | ***
< 189.5 us 188 |
< 196.8 us 49 |
< 204.1 us 297 |
< 211.4 us 455 | *
< 218.7 us 1941 | ******
< 226.0 us 2007 | ******
< 233.3 us 266 |
< 240.6 us 12 |
< 247.9 us 15 |
< 255.2 us 79 |
< 262.5 us 329 | *
< 269.8 us 1078 | ***
< +∞ 102 |
# POLL·1 C1-NHM·3602 C1E-NHM·7215 C3-NHM·3621 C6-NHM·2454
--- . (ext4 /dev/sda1) ioping statistics ---
15.7 k requests completed in 2.95 s, 61.1 MiB read, 5.31 k iops, 20.8 MiB/s
generated 15.7 k requests in 3.00 s, 61.2 MiB, 5.22 k iops, 20.4 MiB/s
min/avg/max/mdev = 124.4 us / 188.2 us / 862.9 us / 41.9 us
< 125.7 us 54 |
< 135.0 us 1215 | ***
< 144.3 us 1946 | ******
< 153.6 us 304 |
< 162.8 us 685 | **
< 172.1 us 2765 | ********
< 181.4 us 1240 | ***
< 190.7 us 630 | **
< 200.0 us 104 |
< 209.3 us 474 | *
< 218.6 us 2078 | ******
< 227.9 us 2008 | ******
< 237.2 us 298 |
< 246.4 us 5 |
< 255.7 us 100 |
< 265.0 us 515 | *
< 274.3 us 1112 | ***
< 283.6 us 12 |
< 292.9 us 0 |
< 302.2 us 4 |
< 311.5 us 0 |
< +∞ 5 |
# POLL·0 C1-NHM·2670 C1E-NHM·7414 C3-NHM·4882 C6-NHM·1595
--- . (ext4 /dev/sda1) ioping statistics ---
15.6 k requests completed in 2.95 s, 61.1 MiB read, 5.31 k iops, 20.7 MiB/s
generated 15.6 k requests in 3.00 s, 61.1 MiB, 5.21 k iops, 20.4 MiB/s
min/avg/max/mdev = 123.5 us / 188.3 us / 332.3 us / 41.7 us
< 124.1 us 4 |
< 131.8 us 1087 | ***
< 139.5 us 1823 | *****
< 147.3 us 493 | *
< 155.0 us 14 |
< 162.7 us 850 | **
< 170.4 us 2249 | *******
< 178.2 us 1150 | ***
< 185.9 us 945 | ***
< 193.6 us 43 |
< 201.3 us 297 |
< 209.1 us 529 | *
< 216.8 us 1984 | ******
< 224.5 us 1655 | *****
< 232.3 us 475 | *
< 240.0 us 33 |
< 247.7 us 20 |
< 255.4 us 124 |
< 263.2 us 557 | *
< 270.9 us 1186 | ***
< 278.6 us 16 |
< +∞ 12 |
# POLL·2 C1-NHM·3835 C1E-NHM·5794 C3-NHM·3770 C6-NHM·2903
*** random cached 4K-read disk latency
--- . (ext4 /dev/sda1) ioping statistics ---
2.59 M requests completed in 2.80 s, 9.88 GiB read, 925.7 k iops, 3.53 GiB/s
generated 2.59 M requests in 3.00 s, 9.88 GiB, 863.4 k iops, 3.29 GiB/s
min/avg/max/mdev = 401 ns / 1.08 us / 99.2 us / 354 ns
< 936 ns 550354 | **********
< 1.15 us 1138976 | *********************
< 1.35 us 793764 | ***************
< 1.56 us 100488 | *
< 1.77 us 4320 |
< 1.98 us 1025 |
< 2.19 us 346 |
< 2.40 us 34 |
< 2.61 us 11 |
< 2.82 us 7 |
< 3.03 us 5 |
< 3.23 us 7 |
< 3.44 us 2 |
< 3.65 us 2 |
< 3.86 us 1 |
< 4.07 us 2 |
< 4.28 us 0 |
< 4.49 us 1 |
< 4.70 us 1 |
< 4.91 us 2 |
< 5.12 us 0 |
< +∞ 703 |
# POLL·0 C1-NHM·78 C1E-NHM·2 C3-NHM·23 C6-NHM·981
--- . (ext4 /dev/sda1) ioping statistics ---
2.59 M requests completed in 2.80 s, 9.88 GiB read, 925.5 k iops, 3.53 GiB/s
generated 2.59 M requests in 3.00 s, 9.88 GiB, 863.0 k iops, 3.29 GiB/s
min/avg/max/mdev = 400 ns / 1.08 us / 92.1 us / 356 ns
< 901 ns 401102 | *******
< 944 ns 191200 | ***
< 987 ns 211161 | ****
< 1.03 us 231923 | ****
< 1.07 us 226094 | ****
< 1.12 us 257292 | ****
< 1.16 us 247490 | ****
< 1.20 us 261994 | *****
< 1.25 us 185971 | ***
< 1.29 us 137271 | **
< 1.33 us 95889 | *
< 1.38 us 65088 | *
< 1.42 us 37224 |
< 1.46 us 18463 |
< 1.50 us 8893 |
< 1.55 us 4340 |
< 1.59 us 2330 |
< 1.64 us 1334 |
< 1.68 us 794 |
< 1.72 us 517 |
< 1.76 us 366 |
< +∞ 2244 |
# POLL·6 C1-NHM·63 C1E-NHM·0 C3-NHM·12 C6-NHM·802
--- . (ext4 /dev/sda1) ioping statistics ---
2.59 M requests completed in 2.80 s, 9.88 GiB read, 925.6 k iops, 3.53 GiB/s
generated 2.59 M requests in 3.00 s, 9.88 GiB, 863.1 k iops, 3.29 GiB/s
min/avg/max/mdev = 396 ns / 1.08 us / 89.6 us / 355 ns
< 874 ns 306522 | *****
< 913 ns 149310 | **
< 953 ns 184539 | ***
< 993 ns 193811 | ***
< 1.03 us 208048 | ****
< 1.07 us 213827 | ****
< 1.11 us 233283 | ****
< 1.15 us 236388 | ****
< 1.19 us 227699 | ****
< 1.23 us 206368 | ***
< 1.27 us 138855 | **
< 1.31 us 105631 | **
< 1.35 us 73025 | *
< 1.39 us 48666 |
< 1.43 us 29941 |
< 1.47 us 14415 |
< 1.51 us 7278 |
< 1.55 us 3956 |
< 1.59 us 2227 |
< 1.63 us 1309 |
< 1.67 us 809 |
< +∞ 3344 |
# POLL·0 C1-NHM·83 C1E-NHM·0 C3-NHM·26 C6-NHM·1301
--- . (ext4 /dev/sda1) ioping statistics ---
2.57 M requests completed in 2.80 s, 9.81 GiB read, 918.8 k iops, 3.51 GiB/s
generated 2.57 M requests in 3.00 s, 9.81 GiB, 857.2 k iops, 3.27 GiB/s
min/avg/max/mdev = 395 ns / 1.09 us / 106.0 us / 403 ns
< 883 ns 316701 | ******
< 923 ns 149055 | **
< 964 ns 200771 | ***
< 1.00 us 195291 | ***
< 1.04 us 213743 | ****
< 1.09 us 214945 | ****
< 1.13 us 238683 | ****
< 1.17 us 231984 | ****
< 1.21 us 233982 | ****
< 1.25 us 172208 | ***
< 1.29 us 128989 | **
< 1.33 us 98091 | *
< 1.37 us 68398 | *
< 1.41 us 43557 |
< 1.45 us 26396 |
< 1.49 us 14407 |
< 1.53 us 8524 |
< 1.57 us 5047 |
< 1.61 us 3041 |
< 1.65 us 1966 |
< 1.70 us 1321 |
< +∞ 4291 |
# POLL·0 C1-NHM·128 C1E-NHM·4 C3-NHM·71 C6-NHM·3517
*** FileStorage
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=0.327s (38.4μs / object) x=zhash.py # POLL·0 C1-NHM·86 C1E-NHM·2 C3-NHM·20 C6-NHM·675
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=0.332s (39.1μs / object) x=zhash.py # POLL·0 C1-NHM·61 C1E-NHM·0 C3-NHM·17 C6-NHM·704
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=0.328s (38.6μs / object) x=zhash.py # POLL·0 C1-NHM·73 C1E-NHM·2 C3-NHM·21 C6-NHM·649
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=0.328s (38.6μs / object) x=zhash.py # POLL·0 C1-NHM·88 C1E-NHM·3 C3-NHM·26 C6-NHM·763
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=34.023355ms (4.002µs / object) x=zhash.go # POLL·1 C1-NHM·109 C1E-NHM·81 C3-NHM·31 C6-NHM·360
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=33.881917ms (3.986µs / object) x=zhash.go # POLL·3 C1-NHM·106 C1E-NHM·68 C3-NHM·23 C6-NHM·374
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=33.949263ms (3.994µs / object) x=zhash.go # POLL·2 C1-NHM·87 C1E-NHM·65 C3-NHM·30 C6-NHM·344
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=33.893226ms (3.987µs / object) x=zhash.go # POLL·1 C1-NHM·92 C1E-NHM·72 C3-NHM·30 C6-NHM·340
*** ZEO
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=5.551s (653.0μs / object) x=zhash.py # POLL·1 C1-NHM·85437 C1E-NHM·12302 C3-NHM·15123 C6-NHM·9403
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=4.824s (567.6μs / object) x=zhash.py # POLL·8 C1-NHM·115083 C1E-NHM·12192 C3-NHM·10557 C6-NHM·2337
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=5.640s (663.5μs / object) x=zhash.py # POLL·5 C1-NHM·61062 C1E-NHM·12452 C3-NHM·15452 C6-NHM·12123
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=5.747s (676.1μs / object) x=zhash.py # POLL·2 C1-NHM·70394 C1E-NHM·9996 C3-NHM·16575 C6-NHM·13035
(skipping zhash.go on ZEO -- Cgo does not support zeo:// protocol)
*** NEO/py sqlite
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=6.969s (819.9μs / object) x=zhash.py # POLL·9 C1-NHM·156 C1E-NHM·26 C3-NHM·32602 C6-NHM·3814
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=6.399s (752.9μs / object) x=zhash.py # POLL·1 C1-NHM·5677 C1E-NHM·820 C3-NHM·30688 C6-NHM·5030
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=6.403s (753.3μs / object) x=zhash.py # POLL·3 C1-NHM·5278 C1E-NHM·1181 C3-NHM·29293 C6-NHM·5561
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=6.573s (773.3μs / object) x=zhash.py # POLL·5 C1-NHM·248 C1E-NHM·43 C3-NHM·33051 C6-NHM·4434
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=4.350029325s (511.768µs / object) x=zhash.go # POLL·35 C1-NHM·1230 C1E-NHM·45038 C3-NHM·23470 C6-NHM·21380
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=4.260295555s (501.211µs / object) x=zhash.go # POLL·33 C1-NHM·1610 C1E-NHM·44524 C3-NHM·24013 C6-NHM·18913
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=4.231757617s (497.853µs / object) x=zhash.go # POLL·23 C1-NHM·1428 C1E-NHM·44468 C3-NHM·23539 C6-NHM·20199
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=4.28639353s (504.281µs / object) x=zhash.go # POLL·44 C1-NHM·1471 C1E-NHM·44500 C3-NHM·23863 C6-NHM·18967
2017-10-05 16:06:15.0127 ERROR NEO [ app: 91] primary master is down
Cluster state changed
*** NEO/py sql
2017-10-05 16:06:15 140570542455040 [Note] mysqld (mysqld 10.1.25-MariaDB-1) starting as process 1681 ...
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=12.130s (1427.0μs / object) x=zhash.py # POLL·2 C1-NHM·1392 C1E-NHM·97 C3-NHM·52015 C6-NHM·32037
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=12.344s (1452.2μs / object) x=zhash.py # POLL·1 C1-NHM·95 C1E-NHM·30 C3-NHM·48326 C6-NHM·30220
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=11.705s (1377.1μs / object) x=zhash.py # POLL·2 C1-NHM·5025 C1E-NHM·267 C3-NHM·53488 C6-NHM·29232
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=12.288s (1445.7μs / object) x=zhash.py # POLL·2 C1-NHM·299 C1E-NHM·36 C3-NHM·50270 C6-NHM·30874
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=7.99381064s (940.448µs / object) x=zhash.go # POLL·61 C1-NHM·1713 C1E-NHM·46012 C3-NHM·51258 C6-NHM·26201
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=8.84641095s (1.040754ms / object) x=zhash.go # POLL·51 C1-NHM·1900 C1E-NHM·44684 C3-NHM·43376 C6-NHM·39600
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=8.944908356s (1.052342ms / object) x=zhash.go # POLL·50 C1-NHM·1855 C1E-NHM·45202 C3-NHM·40353 C6-NHM·41918
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=8.290325208s (975.332µs / object) x=zhash.go # POLL·47 C1-NHM·1920 C1E-NHM·45078 C3-NHM·48121 C6-NHM·30789
2017-10-05 16:07:40.6204 ERROR NEO [ app: 91] primary master is down
Cluster state changed
*** NEO/go
2017-10-05 16:07:43.5086 ERROR NEO [ app:233] Connection to None lost
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=4.646s (546.6μs / object) x=zhash.py # POLL·0 C1-NHM·2340 C1E-NHM·22320 C3-NHM·34965 C6-NHM·13608
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=4.136s (486.6μs / object) x=zhash.py # POLL·7 C1-NHM·1470 C1E-NHM·29500 C3-NHM·35636 C6-NHM·11185
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=3.534s (415.7μs / object) x=zhash.py # POLL·4 C1-NHM·39349 C1E-NHM·19890 C3-NHM·32059 C6-NHM·8243
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=3.121s (367.2μs / object) x=zhash.py # POLL·3 C1-NHM·46090 C1E-NHM·28201 C3-NHM·21200 C6-NHM·7140
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=795.027664ms (93.532µs / object) x=zhash.go # POLL·17 C1-NHM·5284 C1E-NHM·64227 C3-NHM·634 C6-NHM·3777
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=779.003228ms (91.647µs / object) x=zhash.go # POLL·3 C1-NHM·4391 C1E-NHM·61792 C3-NHM·310 C6-NHM·4121
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=733.441049ms (86.287µs / object) x=zhash.go # POLL·16 C1-NHM·3994 C1E-NHM·58749 C3-NHM·1806 C6-NHM·1494
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=754.088669ms (88.716µs / object) x=zhash.go # POLL·24 C1-NHM·5615 C1E-NHM·59930 C3-NHM·2637 C6-NHM·1099
2017/10/05 16:08:04 talk master([2401:5180:0:6f::1]:5552): context canceled
2017-10-05 16:08:04.6005 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=488.196464ms (57.434µs / object) x=zhash.go # POLL·1 C1-NHM·19284 C1E-NHM·37967 C3-NHM·1252 C6-NHM·2828
# NEO/go/client: skipping SHA1 checks
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=521.781008ms (61.386µs / object) x=zhash.go # POLL·10 C1-NHM·16624 C1E-NHM·39296 C3-NHM·682 C6-NHM·3210
# NEO/go/client: skipping SHA1 checks
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=548.99473ms (64.587µs / object) x=zhash.go # POLL·20 C1-NHM·14312 C1E-NHM·44682 C3-NHM·793 C6-NHM·3452
# NEO/go/client: skipping SHA1 checks
crc32:83514ce0 ; oid=0..8499 nread=34159871 t=520.70824ms (61.259µs / object) x=zhash.go # POLL·19 C1-NHM·15976 C1E-NHM·39292 C3-NHM·2901 C6-NHM·724
2017/10/05 16:08:08 talk master([2401:5180:0:6f::1]:5552): context canceled
2017-10-05 16:08:08.0123 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
GitLab Nexedi Edition | About GitLab | About Nexedi | 沪ICP备2021021310号-2 | 沪ICP备2021021310号-7