Large read latency during a heavy write load


#1

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?


#2

I’m curious why your proxy ops are going up. AFAIK you shouldn’t be proxying unless you have migrations going. Was the cluster stable the entire time?

http://www.aerospike.com/docs/architecture Proxy: In rare cases during cluster re-configurations when the Client Layer may be briefly out of date, the Transaction Processing module transparently proxys the request to another node.

Can you ‘egrep -i “cluster.?size|fault|dead|timeout|connect” /var/log/aerospike/aerospike.log’ to confirm if we have nodes coming/going?


#3

Cluster was stable.

egrep returns the big result, each line like:

Feb 21 2017 02:38:18 GMT: INFO (info): (thr_info.c::4985)  ClusterSize 8 ::: objects 319632822 ::: sub_objects 0

#4

Right - just curious if your clustersize changed at all during the issue? or if there were any integrity faults You could pipe it into grep -v “Clustersize 8”


#6

I have not seen changes in the size of the cluster.

or if there were any integrity faults

Sorry, what do you mean?

No result for the last grep.


#7

Well, its unlikely since you are saying the cluster size never went down - but may still be worth a look at this article Monitoring Cluster integrity

Since aerospike histograms are accurately capturing the slowness, I’d recommend you turn on microbenchmarking and look at the breakdown there. Reading Microbenchmarks You should be able to pinpoint the source of the problem, whether it be storage related, network, or otherwise

Do you know if the object size changes at all during your reads, or is it pretty consistent? I’m wondering if the high level of operations is for low object sizes, and then for some reason you are getting large requests. Just a shot in the dark… Microbenchmarks should be your best shot.


#8

I find it difficult to answer the last question of the size of the object…

It would be better if we will do bench and come back. Thank you for the recommendation.


#9

Proxies also appear when a client is just starting up and hasn’t received the partition map yet.

There is a steady churn on proto sockets, sockets originating from clients. This could mean that new clients are being started or existing clients are periodically restarted.


#10

Hello,

We got the following results:

read: reads, demarshal_hist write: writes_master, writes_internal, writes_net

These metrics have increased values during high write load, like:

# asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 22 2017 08:30:00' -d 0:10:00 -n 10 -e 1 -h reads
reads
Feb 22 2017 08:30:03
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
08:31:03    60   0.08   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  15088.0
08:32:03    60   4.88   2.61   0.98   0.34   0.15   0.01   0.00   0.00   0.00   0.00  11944.2
08:33:03    60   7.73   4.54   2.17   0.93   0.37   0.04   0.00   0.00   0.00   0.00  11380.7
08:34:03    60   7.51   4.79   2.71   1.63   1.04   0.52   0.04   0.00   0.00   0.00  12907.5
08:35:07    64  15.53  12.30   9.66   7.63   5.92   3.94   1.58   0.85   0.85   0.84   3697.7
08:36:07    60  10.15   6.68   4.01   2.35   1.40   0.68   0.46   0.18   0.00   0.00    594.9
08:37:07    60  10.64   7.16   4.00   1.84   0.76   0.12   0.01   0.00   0.00   0.00    755.5
08:38:07    60   0.19   0.13   0.08   0.05   0.02   0.01   0.00   0.00   0.00   0.00   3546.1
08:39:07    60   0.03   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   7350.1
08:40:07    60   0.19   0.11   0.03   0.01   0.01   0.01   0.01   0.00   0.00   0.00  15136.0
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg         5.69   3.83   2.36   1.48   0.97   0.53   0.21   0.10   0.08   0.08   8209.0
	 max        15.53  12.30   9.66   7.63   5.92   3.94   1.58   0.85   0.85   0.84  15136.0

Additionaly as for hardware, during high write load we see a slight increase of CPU user time and the disk utilization up to 100 percent on one server of the cluster (utilization)…

Cluster was stable.


#11

Additionally, I see a strange zabbix trigger (that checks tcp port 3000): one server the same server becomes unavailable. Maybe it indirectly shows cluster integrity problem…?


#12

Could you share the microbenchmark as well?


#13

Do you want to see all metrics results? I have given one example because the results are very bulky, but essentially they are the same for these metrics…


#14

Too much data is better than not enough, I always say :slight_smile:


#15

Increases are write moments.

$ asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 27 2017 07:25:00' -d 0:10:00 -n 10 -e 1 -h reads
reads
Feb 27 2017 07:25:00
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
07:26:00    60   0.29   0.05   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00  13805.8
07:27:00    60   0.35   0.07   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00  13816.4
07:28:00    60   5.60   3.25   1.51   0.55   0.21   0.01   0.00   0.00   0.00   0.00  12811.6
07:29:00    60  11.32   7.87   4.95   3.08   2.05   1.24   0.63   0.10   0.01   0.01  10105.0
07:30:00    60  11.14   7.26   3.85   1.74   0.73   0.11   0.01   0.00   0.00   0.00  11765.3
07:31:00    60  11.22   8.45   6.21   4.75   3.79   2.93   2.01   0.95   0.08   0.00  11918.7
07:32:00    60   0.24   0.03   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  14218.8
07:33:00    60   0.81   0.55   0.46   0.37   0.20   0.00   0.00   0.00   0.00   0.00  13454.6
07:34:00    60   0.35   0.12   0.06   0.02   0.00   0.00   0.00   0.00   0.00   0.00  13581.0
07:35:00    60   0.25   0.04   0.01   0.01   0.00   0.00   0.00   0.00   0.00   0.00  13766.7
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg         4.16   2.77   1.71   1.05   0.70   0.43   0.27   0.11   0.01   0.00  12924.0
	 max        11.32   8.45   6.21   4.75   3.79   2.93   2.01   0.95   0.08   0.01  14218.8

$ asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 27 2017 07:25:00' -d 0:10:00 -n 10 -e 1 -h demarshal_hist
demarshal_hist
Feb 27 2017 07:25:00
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
07:26:00    60   0.15   0.03   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00  17052.7
07:27:00    60   0.18   0.04   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00  16927.1
07:28:00    60   5.52   3.27   1.52   0.55   0.20   0.01   0.00   0.00   0.00   0.00  16857.8
07:29:00    60  10.82   7.51   4.65   2.83   1.84   1.06   0.52   0.08   0.01   0.01  13866.1
07:30:00    60  11.07   7.30   3.89   1.77   0.74   0.12   0.01   0.00   0.00   0.00  15558.6
07:31:00    60  11.22   8.50   6.28   4.82   3.85   2.96   2.04   0.99   0.11   0.00  16179.8
07:32:00    60   0.13   0.02   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  17890.3
07:33:00    60   0.70   0.57   0.50   0.41   0.26   0.00   0.00   0.00   0.00   0.00  16388.0
07:34:00    60   0.23   0.10   0.05   0.02   0.00   0.00   0.00   0.00   0.00   0.00  16596.7
07:35:00    60   0.13   0.03   0.01   0.01   0.00   0.00   0.00   0.00   0.00   0.00  16730.4
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg         4.02   2.74   1.69   1.04   0.69   0.42   0.26   0.11   0.01   0.00  16404.0
	 max        11.22   8.50   6.28   4.82   3.85   2.96   2.04   0.99   0.11   0.01  17890.3

$ asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 27 2017 07:25:00' -d 0:10:00 -n 10 -e 1 -h q_wait
q_wait
Feb 27 2017 07:25:00
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
07:26:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  15319.3
07:27:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  15035.8
07:28:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  15264.1
07:29:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  12547.9
07:30:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  14609.1
07:31:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  14942.4
07:32:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  16320.1
07:33:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  14614.0
07:34:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  15066.0
07:35:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  14848.7
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg         0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  14856.0
	 max         0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  16320.1

$ asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 27 2017 07:25:00' -d 0:10:00 -n 10 -e 1 -h reads_q_process
reads_q_process
Feb 27 2017 07:25:00
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
07:26:00    60   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  13805.8
07:27:00    60   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  13816.4
07:28:00    60   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  12811.7
07:29:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  10105.0
07:30:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  11765.2
07:31:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  11918.8
07:32:00    60   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  14218.8
07:33:00    60   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  13454.6
07:34:00    60   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  13581.0
07:35:00    60   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  13766.8
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg         0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  12924.0
	 max         0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  14218.8

$ asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 27 2017 07:25:00' -d 0:10:00 -n 10 -e 1 -h reads_start
reads_start
Feb 27 2017 07:25:00
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
07:26:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
07:27:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
07:28:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
07:29:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
07:30:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
07:31:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
07:32:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
07:33:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
07:34:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
07:35:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg         0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
	 max         0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0

$ asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 27 2017 07:25:00' -d 0:10:00 -n 10 -e 1 -h reads_internal
reads_internal
Feb 27 2017 07:25:00
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
07:26:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
07:27:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
07:28:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
07:29:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
07:30:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
07:31:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
07:32:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
07:33:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
07:34:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
07:35:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg         0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
	 max         0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0

$ asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 27 2017 07:25:00' -d 0:10:00 -n 10 -e 1 -h reads_tree
reads_tree
Feb 27 2017 07:25:00
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
07:26:00    60   0.02   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  13805.8
07:27:00    60   0.03   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  13816.4
07:28:00    60   0.02   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  12811.7
07:29:00    60   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  10105.1
07:30:00    60   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  11765.1
07:31:00    60   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  11918.8
07:32:00    60   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  14218.8
07:33:00    60   0.02   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  13454.6
07:34:00    60   0.02   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  13581.0
07:35:00    60   0.02   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  13766.8
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg         0.02   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  12924.0
	 max         0.03   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  14218.8

$ asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 27 2017 07:25:00' -d 0:10:00 -n 10 -e 1 -h reads_storage_open
reads_storage_open
Feb 27 2017 07:25:00
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
07:26:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   6077.2
07:27:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   6076.7
07:28:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   5649.7
07:29:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   4446.7
07:30:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   5194.0
07:31:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   5275.8
07:32:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   6331.9
07:33:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   5955.4
07:34:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   6019.2
07:35:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   6069.4
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg         0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   5709.0
	 max         0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   6331.9

$ asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 27 2017 07:25:00' -d 0:10:00 -n 10 -e 1 -h reads_storage_read
reads_storage_read
Feb 27 2017 07:25:00
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
07:26:00    60   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   6075.5
07:27:00    60   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   6075.1
07:28:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   5648.5
07:29:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   4445.6
07:30:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   5192.5
07:31:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   5273.7
07:32:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   6327.9
07:33:00    60   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   5953.2
07:34:00    60   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   6016.4
07:35:00    60   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   6065.8
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg         0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   5707.0
	 max         0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   6327.9

$ asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 27 2017 07:25:00' -d 0:10:00 -n 10 -e 1 -h reads_net
reads_net
Feb 27 2017 07:25:00
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
07:26:00    60   0.07   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  13805.8
07:27:00    60   0.08   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  13816.3
07:28:00    60   0.05   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  12811.7
07:29:00    60   0.03   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  10105.0
07:30:00    60   0.03   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  11765.1
07:31:00    60   0.02   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  11918.8
07:32:00    60   0.04   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  14218.8
07:33:00    60   0.06   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  13454.6
07:34:00    60   0.06   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  13581.0
07:35:00    60   0.06   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  13766.8
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg         0.05   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  12924.0
	 max         0.08   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  14218.8

$ asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 27 2017 07:25:00' -d 0:10:00 -n 10 -e 1 -h reads_cleanup
reads_cleanup
Feb 27 2017 07:25:00
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
07:26:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  13805.8
07:27:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  13816.3
07:28:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  12811.7
07:29:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  10105.0
07:30:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  11765.2
07:31:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  11918.8
07:32:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  14218.8
07:33:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  13454.6
07:34:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  13581.0
07:35:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  13766.8
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg         0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  12924.0
	 max         0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  14218.8

$ asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 27 2017 07:25:00' -d 0:10:00 -n 10 -e 1 -h writes_master
writes_master
Feb 27 2017 07:25:00
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
07:26:00    60   1.61   0.87   0.75   0.72   0.67   0.64   0.47   0.11   0.03   0.00    777.7
07:27:00    60   1.60   0.84   0.71   0.69   0.66   0.54   0.30   0.01   0.00   0.00    605.5
07:28:00    60   6.81   3.85   1.85   0.91   0.48   0.23   0.07   0.00   0.00   0.00    644.5
07:29:00    60  13.55   9.75   6.77   4.75   3.36   1.90   0.87   0.14   0.05   0.04    565.6
07:30:00    60  12.16   7.88   4.28   2.17   0.98   0.30   0.12   0.00   0.00   0.00    609.7
07:31:00    60   7.72   5.39   3.83   3.01   2.35   1.80   1.22   0.53   0.10   0.02    972.5
07:32:00    60   1.11   0.48   0.28   0.18   0.10   0.04   0.01   0.00   0.00   0.00    703.5
07:33:00    60   2.16   1.35   1.17   1.08   0.94   0.72   0.42   0.17   0.09   0.06    615.7
07:34:00    60   1.41   0.75   0.62   0.55   0.46   0.34   0.10   0.01   0.00   0.00    620.1
07:35:00    60   1.80   1.14   1.04   1.01   0.89   0.63   0.31   0.06   0.02   0.01    631.5
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg         4.99   3.23   2.13   1.51   1.09   0.71   0.39   0.10   0.03   0.01    674.0
	 max        13.55   9.75   6.77   4.75   3.36   1.90   1.22   0.53   0.10   0.06    972.5

$ asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 27 2017 07:25:00' -d 0:10:00 -n 10 -e 1 -h q_wait
q_wait
Feb 27 2017 07:25:00
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
07:26:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  15319.3
07:27:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  15035.8
07:28:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  15264.1
07:29:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  12547.9
07:30:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  14609.1
07:31:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  14942.4
07:32:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  16320.1
07:33:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  14614.0
07:34:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  15066.0
07:35:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  14848.7
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg         0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  14856.0
	 max         0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  16320.1

$ asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 27 2017 07:25:00' -d 0:10:00 -n 10 -e 1 -h writes_internal
writes_internal
Feb 27 2017 07:25:00
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
07:26:00    60   0.53   0.11   0.02   0.01   0.00   0.00   0.00   0.00   0.00   0.00    953.1
07:27:00    60   0.56   0.09   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00    818.6
07:28:00    60  26.57   7.54   2.98   1.82   0.63   0.02   0.00   0.00   0.00   0.00   1971.7
07:29:00    60  34.67   9.68   3.40   2.16   0.96   0.04   0.01   0.01   0.01   0.01   2247.6
07:30:00    60  40.34  10.92   3.32   2.27   1.21   0.05   0.00   0.00   0.00   0.00   2561.2
07:31:00    60  30.71   7.14   2.03   1.74   0.83   0.08   0.02   0.01   0.01   0.01   2687.0
07:32:00    60   0.36   0.04   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   1421.1
07:33:00    60   0.54   0.11   0.03   0.03   0.02   0.02   0.02   0.02   0.02   0.01    736.6
07:34:00    60   0.38   0.07   0.02   0.01   0.00   0.00   0.00   0.00   0.00   0.00    772.4
07:35:00    60   0.43   0.07   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00    686.8
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg        13.51   3.58   1.18   0.80   0.36   0.02   0.01   0.00   0.00   0.00   1485.0
	 max        40.34  10.92   3.40   2.27   1.21   0.08   0.02   0.02   0.02   0.01   2687.0

$ asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 27 2017 07:25:00' -d 0:10:00 -n 10 -e 1 -h write_storage_close
write_storage_close
Feb 27 2017 07:25:00
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
07:26:00    60   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00    777.7
07:27:00    60   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00    605.6
07:28:00    60   0.02   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00    644.5
07:29:00    60   0.04   0.04   0.04   0.04   0.04   0.04   0.04   0.04   0.04   0.04    565.6
07:30:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00    609.7
07:31:00    60   0.06   0.06   0.06   0.06   0.06   0.05   0.05   0.03   0.03   0.02    972.5
07:32:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00    703.5
07:33:00    60   0.02   0.02   0.02   0.02   0.02   0.02   0.02   0.02   0.02   0.01    615.7
07:34:00    60   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00    620.1
07:35:00    60   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00    631.5
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg         0.02   0.01   0.01   0.01   0.01   0.01   0.01   0.01   0.01   0.01    674.0
	 max         0.06   0.06   0.06   0.06   0.06   0.05   0.05   0.04   0.04   0.04    972.5

$ asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 27 2017 07:25:00' -d 0:10:00 -n 10 -e 1 -h wt_master_wait_prole
wt_master_wait_prole
Feb 27 2017 07:25:00
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
07:26:00    60  97.77  97.33  96.88  91.31  83.74  77.95  51.89   0.00   0.00   0.00      7.5
07:27:00    60  96.68  96.68  96.40  93.07  88.09  73.41  37.67   0.00   0.00   0.00      6.0
07:28:00    60  96.70  96.70  94.51  89.56  77.47  59.89  20.88   0.55   0.00   0.00      3.0
07:29:00    60  95.99  95.99  94.31  91.30  82.61  51.51  29.10   0.00   0.00   0.00      5.0
07:30:00    60  67.73  64.54  59.11  50.48  36.10  17.25  10.54   0.00   0.00   0.00      5.2
07:31:00    60  18.99  14.73  10.47   6.20   1.55   0.39   0.00   0.00   0.00   0.00      4.3
07:32:00    60  48.76  43.81  29.14  18.29   9.90   3.62   0.76   0.00   0.00   0.00      8.8
07:33:00    60  97.04  97.04  96.05  93.58  85.93  69.38  27.90   1.73   0.00   0.00      6.8
07:34:00    60  73.18  71.97  63.55  54.09  39.68  27.16   2.83   0.06   0.00   0.00     28.9
07:35:00    60  96.81  96.81  95.40  91.33  79.12  48.67  14.87   0.00   0.00   0.00      9.4
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg        78.96  77.56  73.58  67.92  58.42  42.92  19.64   0.23   0.00   0.00      8.0
	 max        97.77  97.33  96.88  93.58  88.09  77.95  51.89   1.73   0.00   0.00     28.9

$ asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 27 2017 07:25:00' -d 0:10:00 -n 10 -e 1 -h writes_net
writes_net
Feb 27 2017 07:25:00
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
07:26:00    60   0.55   0.10   0.02   0.01   0.00   0.00   0.00   0.00   0.00   0.00   1198.6
07:27:00    60   0.64   0.10   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00    912.7
07:28:00    60  24.89   6.93   2.75   1.65   0.57   0.01   0.00   0.00   0.00   0.00   2184.8
07:29:00    60  35.61   9.80   3.43   2.14   0.95   0.04   0.01   0.01   0.01   0.01   2263.3
07:30:00    60  40.49  10.94   3.29   2.21   1.19   0.05   0.00   0.00   0.00   0.00   2627.7
07:31:00    60  30.88   7.16   1.99   1.69   0.81   0.08   0.02   0.01   0.01   0.01   2761.0
07:32:00    60   0.38   0.03   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   1795.6
07:33:00    60   0.61   0.11   0.03   0.02   0.02   0.02   0.02   0.02   0.02   0.01    866.4
07:34:00    60   0.35   0.06   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   1027.7
07:35:00    60   0.49   0.08   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00    767.3
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg        13.49   3.53   1.15   0.77   0.35   0.02   0.01   0.00   0.00   0.00   1640.0
	 max        40.49  10.94   3.43   2.21   1.19   0.08   0.02   0.02   0.02   0.01   2761.0

$ asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 27 2017 07:25:00' -d 0:10:00 -n 10 -e 1 -h writes_prole
writes_prole
Feb 27 2017 07:25:00
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
07:26:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00     10.3
07:27:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      8.1
07:28:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      5.4
07:29:00    60   1.41   1.41   1.41   1.41   1.41   1.41   1.41   1.41   1.41   1.13      5.9
07:30:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      7.9
07:31:00    60   0.19   0.19   0.19   0.19   0.19   0.19   0.19   0.19   0.00   0.00      8.7
07:32:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00     14.5
07:33:00    60   0.31   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00     10.9
07:34:00    60   0.08   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00     20.5
07:35:00    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00     12.1
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg         0.20   0.16   0.16   0.16   0.16   0.16   0.16   0.16   0.14   0.11     10.0

#16

Very quickly looking at this, it seems the bottleneck is at the network level (demarshal_hist / writes_net / wt_master_wait_prole). writes_internal also has an impact likely due to reads required for ‘updates’.


#17

Agreed… Check ethtool and sar -n DEV to see if you can find any clues. Aside from that, make sure you aren’t saturating your link. Maybe check interrupts are distributed http://www.aerospike.com/docs/operations/plan/network/


#18

Some tuning has improved the problem, but it seems the two server are pulled down cluster… because not good network hardware. We will investigate the issue more. Thank you very much for your help.


#19

Now:

# asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 28 2017 08:23:00' -d 0:10:00 -n 10 -e 1 -h reads
reads
Feb 28 2017 08:23:01
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
08:24:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  20424.4
08:25:01    60   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  19711.9
08:26:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  19457.9
08:27:01    60   0.97   0.46   0.19   0.08   0.01   0.00   0.00   0.00   0.00   0.00  15902.7
08:28:01    60   0.91   0.37   0.13   0.06   0.00   0.00   0.00   0.00   0.00   0.00   3312.0
08:29:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   2789.6
08:30:01    60   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   2783.6
08:31:01    60   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   3046.5
08:32:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  10887.1
08:33:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  20330.0
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg         0.19   0.08   0.03   0.01   0.00   0.00   0.00   0.00   0.00   0.00  11864.0
	 max         0.97   0.46   0.19   0.08   0.01   0.00   0.00   0.00   0.00   0.00  20424.4
#
# asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 28 2017 08:23:00' -d 0:10:00 -n 10 -e 1 -h demarshal_hist
demarshal_hist
Feb 28 2017 08:23:01
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
08:24:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  19730.7
08:25:01    60   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  19167.4
08:26:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  19597.1
08:27:01    60   1.35   0.64   0.26   0.11   0.02   0.00   0.00   0.00   0.00   0.00  16616.0
08:28:01    60   1.40   0.65   0.29   0.11   0.00   0.00   0.00   0.00   0.00   0.00   6905.3
08:29:01    60   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   5487.2
08:30:01    60   0.06   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   5719.4
08:31:01    60   0.02   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   6925.3
08:32:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  12701.6
08:33:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  20161.9
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg         0.28   0.13   0.06   0.02   0.00   0.00   0.00   0.00   0.00   0.00  13301.0
	 max         1.40   0.65   0.29   0.11   0.02   0.00   0.00   0.00   0.00   0.00  20161.9
#
# asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 28 2017 08:23:00' -d 0:10:00 -n 10 -e 1 -h q_wait
q_wait
Feb 28 2017 08:23:01
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
08:24:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  17542.9
08:25:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  17056.4
08:26:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  17431.0
08:27:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  14637.8
08:28:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   5352.3
08:29:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   3513.8
08:30:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   4126.7
08:31:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   4901.5
08:32:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  10669.7
08:33:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  18329.9
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg         0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  11356.0
	 max         0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  18329.9
#
# asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 28 2017 08:23:00' -d 0:10:00 -n 10 -e 1 -h reads_q_process
reads_q_process
Feb 28 2017 08:23:01
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
08:24:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  20424.5
08:25:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  19711.8
08:26:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  19457.9
08:27:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  15902.7
08:28:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   3312.0
08:29:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   2789.6
08:30:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   2783.6
08:31:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   3046.5
08:32:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  10887.2
08:33:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  20330.4
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg         0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  11864.0
	 max         0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  20424.5
#
# asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 28 2017 08:23:00' -d 0:10:00 -n 10 -e 1 -h reads_start
reads_start
Feb 28 2017 08:23:01
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
08:24:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
08:25:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
08:26:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
08:27:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
08:28:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
08:29:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
08:30:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
08:31:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
08:32:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
08:33:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg         0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
	 max         0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
#
# asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 28 2017 08:23:00' -d 0:10:00 -n 10 -e 1 -h reads_internal
reads_internal
Feb 28 2017 08:23:01
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
08:24:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
08:25:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
08:26:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
08:27:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
08:28:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
08:29:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
08:30:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
08:31:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
08:32:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
08:33:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg         0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
	 max         0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.0
#
# asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 28 2017 08:23:00' -d 0:10:00 -n 10 -e 1 -h reads_tree
reads_tree
Feb 28 2017 08:23:01
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
08:24:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  20424.5
08:25:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  19711.8
08:26:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  19457.9
08:27:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  15902.7
08:28:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   3312.0
08:29:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   2789.6
08:30:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   2783.6
08:31:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   3046.5
08:32:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  10887.2
08:33:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  20330.4
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg         0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  11864.0
	 max         0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  20424.5
#
# asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 28 2017 08:23:00' -d 0:10:00 -n 10 -e 1 -h reads_storage_open
reads_storage_open
Feb 28 2017 08:23:01
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
08:24:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   9037.1
08:25:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   8725.1
08:26:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   8640.8
08:27:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   6978.7
08:28:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   1539.4
08:29:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   1335.3
08:30:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   1341.7
08:31:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   1519.8
08:32:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   4861.2
08:33:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   8945.5
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg         0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   5292.0
	 max         0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   9037.1
#
# asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 28 2017 08:23:00' -d 0:10:00 -n 10 -e 1 -h reads_storage_read
reads_storage_read
Feb 28 2017 08:23:01
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
08:24:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   9028.3
08:25:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   8716.2
08:26:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   8631.6
08:27:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   6971.7
08:28:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   1539.0
08:29:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   1335.3
08:30:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   1341.7
08:31:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   1519.7
08:32:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   4851.3
08:33:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   8936.3
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg         0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   5287.0
	 max         0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   9028.3
#
# asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 28 2017 08:23:00' -d 0:10:00 -n 10 -e 1 -h reads_net
reads_net
Feb 28 2017 08:23:01
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
08:24:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  20424.5
08:25:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  19711.8
08:26:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  19458.0
08:27:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  15902.7
08:28:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   3312.0
08:29:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   2789.6
08:30:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   2783.6
08:31:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   3046.5
08:32:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  10887.2
08:33:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  20330.4
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg         0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  11864.0
	 max         0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  20424.5
#
# asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 28 2017 08:23:00' -d 0:10:00 -n 10 -e 1 -h reads_cleanup
reads_cleanup
Feb 28 2017 08:23:01
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
08:24:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  20424.5
08:25:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  19711.8
08:26:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  19458.0
08:27:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  15902.7
08:28:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   3312.0
08:29:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   2789.6
08:30:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   2783.6
08:31:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   3046.5
08:32:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  10887.2
08:33:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  20330.4
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg         0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  11864.0
	 max         0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  20424.5
#
# asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 28 2017 08:23:00' -d 0:10:00 -n 10 -e 1 -h writes_master
writes_master
Feb 28 2017 08:23:01
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
08:24:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00    919.4
08:25:01    60   0.03   0.02   0.02   0.01   0.01   0.01   0.00   0.00   0.00   0.00    910.4
08:26:01    60   0.01   0.01   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00    805.1
08:27:01    60   1.33   0.65   0.21   0.08   0.02   0.00   0.00   0.00   0.00   0.00    668.0
08:28:01    60   0.99   0.39   0.14   0.08   0.05   0.05   0.05   0.05   0.04   0.04    414.4
08:29:01    60   0.01   0.01   0.01   0.01   0.01   0.00   0.00   0.00   0.00   0.00    411.2
08:30:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00    422.1
08:31:01    60   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00    951.4
08:32:01    60   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00    843.9
08:33:01    60   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00    967.8
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg         0.24   0.11   0.04   0.02   0.01   0.01   0.01   0.01   0.00   0.00    731.0
	 max         1.33   0.65   0.21   0.08   0.05   0.05   0.05   0.05   0.04   0.04    967.8
#
# asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 28 2017 08:23:00' -d 0:10:00 -n 10 -e 1 -h q_wait
q_wait
Feb 28 2017 08:23:01
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
08:24:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  17542.9
08:25:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  17056.4
08:26:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  17431.0
08:27:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  14637.8
08:28:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   5352.3
08:29:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   3513.8
08:30:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   4126.7
08:31:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   4901.5
08:32:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  10669.7
08:33:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  18329.9
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg         0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  11356.0
	 max         0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00  18329.9
#
# asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 28 2017 08:23:00' -d 0:10:00 -n 10 -e 1 -h writes_internal
writes_internal
Feb 28 2017 08:23:01
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
08:24:01    60   0.02   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   1222.0
08:25:01    60   0.05   0.03   0.01   0.01   0.01   0.01   0.00   0.00   0.00   0.00   1046.5
08:26:01    60   0.07   0.01   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   1243.3
08:27:01    60  11.01   2.05   1.61   1.35   0.10   0.00   0.00   0.00   0.00   0.00   2221.1
08:28:01    60   6.84   1.47   1.32   0.96   0.02   0.01   0.01   0.01   0.01   0.01   1649.6
08:29:01    60   0.06   0.03   0.01   0.01   0.01   0.00   0.00   0.00   0.00   0.00    437.1
08:30:01    60   0.04   0.01   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00    663.3
08:31:01    60   0.72   0.24   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   1596.1
08:32:01    60   0.07   0.03   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   1094.4
08:33:01    60   0.03   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   1018.2
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg         1.89   0.39   0.30   0.23   0.01   0.00   0.00   0.00   0.00   0.00   1219.0
	 max        11.01   2.05   1.61   1.35   0.10   0.01   0.01   0.01   0.01   0.01   2221.1
#
# asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 28 2017 08:23:00' -d 0:10:00 -n 10 -e 1 -h write_storage_close
write_storage_close
Feb 28 2017 08:23:01
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
08:24:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00    919.4
08:25:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00    910.5
08:26:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00    805.1
08:27:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00    668.0
08:28:01    60   0.05   0.05   0.05   0.05   0.05   0.05   0.05   0.05   0.04   0.04    414.5
08:29:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00    411.1
08:30:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00    422.1
08:31:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00    951.4
08:32:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00    843.9
08:33:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00    967.8
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg         0.01   0.01   0.01   0.01   0.01   0.01   0.01   0.01   0.00   0.00    731.0
	 max         0.05   0.05   0.05   0.05   0.05   0.05   0.05   0.05   0.04   0.04    967.8
You have new mail in /var/spool/mail/root
#
# asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 28 2017 08:23:00' -d 0:10:00 -n 10 -e 1 -h wt_master_wait_prole
wt_master_wait_prole
Feb 28 2017 08:23:01
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
08:24:01    60   0.05   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00     30.6
08:25:01    60   0.17   0.17   0.11   0.11   0.11   0.11   0.06   0.06   0.06   0.00     29.0
08:26:01    60   0.14   0.14   0.14   0.14   0.14   0.14   0.14   0.07   0.07   0.07     23.0
08:27:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00     10.0
08:28:01    60   1.64   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      1.0
08:29:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.2
08:30:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.2
08:31:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.4
08:32:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00     26.5
08:33:01    60   0.10   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00     16.9
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg         0.21   0.03   0.03   0.03   0.03   0.03   0.02   0.01   0.01   0.01     13.0
	 max         1.64   0.17   0.14   0.14   0.14   0.14   0.14   0.07   0.07   0.07     30.6
#
# asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 28 2017 08:23:00' -d 0:10:00 -n 10 -e 1 -h writes_net
writes_net
Feb 28 2017 08:23:01
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
08:24:01    60   0.02   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   1270.5
08:25:01    60   0.05   0.02   0.01   0.01   0.01   0.01   0.00   0.00   0.00   0.00   1146.1
08:26:01    60   0.07   0.01   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   1290.4
08:27:01    60  11.02   1.99   1.55   1.30   0.10   0.00   0.00   0.00   0.00   0.00   2311.3
08:28:01    60   5.84   1.19   1.06   0.78   0.02   0.01   0.01   0.01   0.01   0.01   2043.9
08:29:01    60   0.05   0.03   0.01   0.01   0.01   0.00   0.00   0.00   0.00   0.00    506.9
08:30:01    60   0.02   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   1127.5
08:31:01    60   0.71   0.24   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   1629.4
08:32:01    60   0.07   0.03   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   1200.2
08:33:01    60   0.02   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   1405.1
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg         1.79   0.35   0.26   0.21   0.01   0.00   0.00   0.00   0.00   0.00   1393.0
	 max        11.02   1.99   1.55   1.30   0.10   0.01   0.01   0.01   0.01   0.01   2311.3
#
# asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'FEB 28 2017 08:23:00' -d 0:10:00 -n 10 -e 1 -h writes_prole
writes_prole
Feb 28 2017 08:23:01
			   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
08:24:01    60   0.09   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00     17.7
08:25:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00     16.5
08:26:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00     31.5
08:27:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00     14.1
08:28:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      1.1
08:29:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.3
08:30:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      0.9
08:31:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00      3.4
08:32:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00     36.2
08:33:01    60   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00     32.6
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
	 avg         0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00     15.0
	 max         0.09   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00     36.2

Overall performance is now better than it was. We will upgrade some hardware (planned, so has coincided), will see what will change.


#20

Also please make sure all of your nodes are configured the same with regard to replication-factor. I wouldn’t expect writes_net and wt_master_wait_prole to report anything with replication-factor 1. However, the microbenchmarks were reworked in 3.9.x to increase granularity and address some misreporting – maybe this is an instance of misreporting.


#21

Ok, we will update asd soon. replication is 1.