Hello,
We see increased latency of read during a heavy write load. High write load does java async client through lua. Please help to resolve a problem. What we are doing wrong, or that we should tuning?
Cluster: 8 servers xeon e5 2620, asd 3.7.3. Regular good load per the cluster: 120k reads (get), 6k writes (set), periodically another operations (very low load).
asd config example:
service {
user aerospike
group aerospike
paxos-single-replica-limit 1
pidfile /var/run/aerospike/asd.pid
service-threads 12
transaction-queues 12
transaction-threads-per-queue 4
proto-fd-max 65535
}
logging {
file /var/log/aerospike/aerospike.log {
context any info
}
}
network {
service {
address any
port 3000
access-address 10.0.0.20
reuse-address
}
heartbeat {
mode multicast
address 239.6.103.77
port 9918
interface-address 10.0.0.20
interval 150
timeout 10
}
fabric {
port 3001
}
info {
port 3003
}
}
namespace audience {
replication-factor 1
memory-size 64G
default-ttl 0
storage-engine device {
file /opt/aerospike/data/audience.data
file /opt/aerospike/data2/audience.data
filesize 70G
data-in-memory true
}
}
trans_in_progress when good:
Feb 21 2017 06:19:10 GMT: INFO (info): (thr_info.c::5009) trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (13086, 14495717, 14482631) : hb (0, 0, 0) : fab (114, 114, 0)
Feb 21 2017 06:19:20 GMT: INFO (info): (thr_info.c::5009) trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (13085, 14495735, 14482650) : hb (0, 0, 0) : fab (114, 114, 0)
Feb 21 2017 06:19:30 GMT: INFO (info): (thr_info.c::5009) trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (13089, 14495793, 14482704) : hb (0, 0, 0) : fab (114, 114, 0)
Feb 21 2017 06:19:40 GMT: INFO (info): (thr_info.c::5009) trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (13090, 14495951, 14482861) : hb (0, 0, 0) : fab (114, 114, 0)
Feb 21 2017 06:19:50 GMT: INFO (info): (thr_info.c::5009) trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (13097, 14496016, 14482919) : hb (0, 0, 0) : fab (114, 114, 0)
Feb 21 2017 06:20:00 GMT: INFO (info): (thr_info.c::5009) trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (13103, 14496046, 14482943) : hb (0, 0, 0) : fab (114, 114, 0)
Feb 21 2017 06:20:10 GMT: INFO (info): (thr_info.c::5009) trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (13144, 14496119, 14482975) : hb (0, 0, 0) : fab (114, 114, 0)
Feb 21 2017 06:20:20 GMT: INFO (info): (thr_info.c::5009) trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (13094, 14496138, 14483044) : hb (0, 0, 0) : fab (114, 114, 0)
Feb 21 2017 06:20:31 GMT: INFO (info): (thr_info.c::5009) trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (13062, 14496179, 14483117) : hb (0, 0, 0) : fab (114, 114, 0)
Feb 21 2017 06:20:41 GMT: INFO (info): (thr_info.c::5009) trans_in_progress: wr 1 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (13036, 14496324, 14483288) : hb (0, 0, 0) : fab (114, 114, 0)
trans_in_progress when bad:
Feb 21 2017 06:29:51 GMT: INFO (info): (thr_info.c::5009) trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (13024, 14498657, 14485633) : hb (0, 0, 0) : fab (114, 114, 0)
Feb 21 2017 06:30:01 GMT: INFO (info): (thr_info.c::5009) trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (13035, 14498685, 14485650) : hb (0, 0, 0) : fab (114, 114, 0)
Feb 21 2017 06:30:11 GMT: INFO (info): (thr_info.c::5009) trans_in_progress: wr 3 prox 50 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (13746, 14499451, 14485705) : hb (0, 0, 0) : fab (114, 114, 0)
Feb 21 2017 06:30:21 GMT: INFO (info): (thr_info.c::5009) trans_in_progress: wr 3 prox 27 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (13762, 14499496, 14485734) : hb (0, 0, 0) : fab (114, 114, 0)
Feb 21 2017 06:30:31 GMT: INFO (info): (thr_info.c::5009) trans_in_progress: wr 5 prox 1 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (13694, 14499516, 14485822) : hb (0, 0, 0) : fab (114, 114, 0)
Feb 21 2017 06:30:41 GMT: INFO (info): (thr_info.c::5009) trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (13692, 14499545, 14485853) : hb (0, 0, 0) : fab (114, 114, 0)
Feb 21 2017 06:30:51 GMT: INFO (info): (thr_info.c::5009) trans_in_progress: wr 6 prox 1 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (13714, 14499691, 14485977) : hb (0, 0, 0) : fab (114, 114, 0)
Feb 21 2017 06:31:01 GMT: INFO (info): (thr_info.c::5009) trans_in_progress: wr 10 prox 1 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (13694, 14499759, 14486065) : hb (0, 0, 0) : fab (114, 114, 0)
Feb 21 2017 06:31:11 GMT: INFO (info): (thr_info.c::5009) trans_in_progress: wr 4 prox 58 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (13811, 14500033, 14486222) : hb (0, 0, 0) : fab (114, 114, 0)
Feb 21 2017 06:31:21 GMT: INFO (info): (thr_info.c::5009) trans_in_progress: wr 1 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (13801, 14500083, 14486282) : hb (0, 0, 0) : fab (114, 114, 0)
asmonitor latency when good:
====writes_master====
timespan ops/sec >1ms >8ms >64ms
10.0.0.12:3000 06:17:56-GMT->06:18:06 688.8 0.00 0.00 0.00
10.0.0.130:3000 06:17:54-GMT->06:18:04 994.3 0.98 0.00 0.00
10.0.0.13:3000 06:17:49-GMT->06:17:59 890.9 0.02 0.01 0.00
10.0.0.197:3000 06:17:52-GMT->06:18:02 812.9 0.00 0.00 0.00
10.0.0.20:3000 06:17:50-GMT->06:18:00 710.4 0.20 0.00 0.00
10.0.0.25:3000 06:17:47-GMT->06:17:57 785.3 0.01 0.00 0.00
10.0.0.8:3000 06:17:56-GMT->06:18:06 1153.3 0.01 0.00 0.00
10.0.0.98:3000 06:17:49-GMT->06:17:59 772.7 0.01 0.00 0.00
====reads====
timespan ops/sec >1ms >8ms >64ms
10.0.0.12:3000 06:17:56-GMT->06:18:06 13719.9 0.00 0.00 0.00
10.0.0.130:3000 06:17:54-GMT->06:18:04 14075.0 0.32 0.00 0.00
10.0.0.13:3000 06:17:49-GMT->06:17:59 14435.4 0.00 0.00 0.00
10.0.0.197:3000 06:17:52-GMT->06:18:02 14832.0 0.00 0.00 0.00
10.0.0.20:3000 06:17:50-GMT->06:18:00 14100.7 0.12 0.00 0.00
10.0.0.25:3000 06:17:47-GMT->06:17:57 14315.3 0.00 0.00 0.00
10.0.0.8:3000 06:17:56-GMT->06:18:06 15246.8 0.01 0.00 0.00
10.0.0.98:3000 06:17:49-GMT->06:17:59 15301.0 0.01 0.00 0.00
====udf====
timespan ops/sec >1ms >8ms >64ms
10.0.0.12:3000 06:17:56-GMT->06:18:06 562.2 0.14 0.00 0.00
10.0.0.130:3000 06:17:54-GMT->06:18:04 602.9 0.90 0.00 0.00
10.0.0.13:3000 06:17:49-GMT->06:17:59 438.8 0.25 0.00 0.00
10.0.0.197:3000 06:17:52-GMT->06:18:02 596.4 0.18 0.00 0.00
10.0.0.20:3000 06:17:50-GMT->06:18:00 515.8 0.37 0.04 0.02
10.0.0.25:3000 06:17:47-GMT->06:17:57 450.3 0.18 0.00 0.00
10.0.0.8:3000 06:17:56-GMT->06:18:06 479.3 0.13 0.00 0.00
10.0.0.98:3000 06:17:49-GMT->06:17:59 459.0 0.41 0.00 0.00
====proxy====
timespan ops/sec >1ms >8ms >64ms
10.0.0.12:3000 06:17:56-GMT->06:18:06 0.0 0.00 0.00 0.00
10.0.0.130:3000 06:17:54-GMT->06:18:04 0.0 0.00 0.00 0.00
10.0.0.13:3000 06:17:49-GMT->06:17:59 0.0 0.00 0.00 0.00
10.0.0.197:3000 06:17:52-GMT->06:18:02 0.0 0.00 0.00 0.00
10.0.0.20:3000 06:17:50-GMT->06:18:00 0.0 0.00 0.00 0.00
10.0.0.25:3000 06:17:47-GMT->06:17:57 0.0 0.00 0.00 0.00
10.0.0.8:3000 06:17:56-GMT->06:18:06 0.0 0.00 0.00 0.00
10.0.0.98:3000 06:17:49-GMT->06:17:59 0.0 0.00 0.00 0.00
====query====
timespan ops/sec >1ms >8ms >64ms
10.0.0.12:3000 06:17:56-GMT->06:18:06 222.4 0.04 0.00 0.00
10.0.0.130:3000 06:17:54-GMT->06:18:04 220.1 0.64 0.00 0.00
10.0.0.13:3000 06:17:49-GMT->06:17:59 222.3 0.00 0.00 0.00
10.0.0.197:3000 06:17:52-GMT->06:18:02 221.2 0.05 0.00 0.00
10.0.0.20:3000 06:17:50-GMT->06:18:00 223.5 0.22 0.00 0.00
10.0.0.25:3000 06:17:47-GMT->06:17:57 220.5 0.00 0.00 0.00
10.0.0.8:3000 06:17:56-GMT->06:18:06 221.9 0.00 0.00 0.00
10.0.0.98:3000 06:17:49-GMT->06:17:59 221.6 0.05 0.00 0.00
asmonitor latency when bad:
====writes_master====
timespan ops/sec >1ms >8ms >64ms
10.0.0.12:3000 06:30:56-GMT->06:31:06 614.7 17.72 4.57 0.03
10.0.0.13:3000 06:30:59-GMT->06:31:09 513.6 16.55 4.15 0.04
10.0.0.197:3000 06:31:03-GMT->06:31:13 481.2 9.16 1.37 0.00
10.0.0.20:3000 06:31:01-GMT->06:31:11 420.8 20.18 10.50 0.71
10.0.0.25:3000 06:30:58-GMT->06:31:08 529.7 16.99 4.64 0.00
10.0.0.8:3000 06:30:57-GMT->06:31:07 771.1 55.71 39.24 10.61
10.0.0.98:3000 06:30:59-GMT->06:31:09 483.3 41.71 31.18 10.45
====reads====
timespan ops/sec >1ms >8ms >64ms
10.0.0.12:3000 06:30:56-GMT->06:31:06 6041.6 23.42 6.62 0.06
10.0.0.13:3000 06:30:59-GMT->06:31:09 4274.0 23.08 6.61 0.06
10.0.0.197:3000 06:31:03-GMT->06:31:13 4101.0 14.26 2.57 0.00
10.0.0.20:3000 06:31:01-GMT->06:31:11 2960.8 38.66 22.22 1.36
10.0.0.25:3000 06:30:58-GMT->06:31:08 5310.6 23.82 6.78 0.00
10.0.0.8:3000 06:30:57-GMT->06:31:07 6466.2 68.78 50.92 14.08
10.0.0.98:3000 06:30:59-GMT->06:31:09 4638.6 70.56 58.30 19.93
====udf====
timespan ops/sec >1ms >8ms >64ms
10.0.0.12:3000 06:30:56-GMT->06:31:06 3741.2 29.86 2.05 0.00
10.0.0.13:3000 06:30:59-GMT->06:31:09 3317.2 27.71 1.98 0.00
10.0.0.197:3000 06:31:03-GMT->06:31:13 3011.9 21.65 1.91 0.00
10.0.0.20:3000 06:31:01-GMT->06:31:11 3138.9 26.13 1.91 0.00
10.0.0.25:3000 06:30:58-GMT->06:31:08 3517.2 29.95 1.97 0.00
10.0.0.8:3000 06:30:57-GMT->06:31:07 4066.9 39.23 2.13 0.00
10.0.0.98:3000 06:30:59-GMT->06:31:09 3622.0 33.96 2.09 0.00
====proxy====
timespan ops/sec >1ms >8ms >64ms
10.0.0.12:3000 06:30:56-GMT->06:31:06 364.3 82.73 41.39 25.09
10.0.0.13:3000 06:30:59-GMT->06:31:09 376.5 90.12 64.91 42.68
10.0.0.197:3000 06:31:03-GMT->06:31:13 393.8 96.34 82.22 55.00
10.0.0.20:3000 06:31:01-GMT->06:31:11 387.9 96.00 79.99 51.38
10.0.0.25:3000 06:30:58-GMT->06:31:08 364.8 86.49 53.45 33.53
10.0.0.8:3000 06:30:57-GMT->06:31:07 371.0 94.42 74.53 40.43
10.0.0.98:3000 06:30:59-GMT->06:31:09 381.5 97.22 84.95 51.45
====query====
timespan ops/sec >1ms >8ms >64ms
10.0.0.12:3000 06:30:56-GMT->06:31:06 14.4 0.00 0.00 0.00
10.0.0.13:3000 06:30:59-GMT->06:31:09 9.2 0.00 0.00 0.00
10.0.0.197:3000 06:31:03-GMT->06:31:13 5.3 1.89 0.00 0.00
10.0.0.20:3000 06:31:01-GMT->06:31:11 6.1 3.28 0.00 0.00
10.0.0.25:3000 06:30:58-GMT->06:31:08 11.8 0.00 0.00 0.00
10.0.0.8:3000 06:30:57-GMT->06:31:07 13.7 0.00 0.00 0.00
10.0.0.98:3000 06:30:59-GMT->06:31:09 9.3 1.08 0.00 0.00
What else to provide data?
