The Aerospike Knowledge Base has moved to https://support.aerospike.com. Content on https://discuss.aerospike.com is being migrated to either https://support.aerospike.com or https://docs.aerospike.com. Maintenance on articles stored in this repository ceased on December 31st 2022 and this article may be stale. If you have any questions, please do not hesitate to raise a case via https://support.aerospike.com.
Synopsis
The following article explains understanding Aerospike read performance and troubleshooting through microbenchmarks analysis. This article is for server versions prior to 3.9.
For versions 3.9 and above, microbenchmarks can be enabled at the namespace level. Refer to the Monitor Latency page for details.
Details
Aerospike server installation distribution includes various tools including asloglatency that analyzes Aerospike log files and provides histograms for various crucial Aerospike performance parameters.
sudo asloglatency -l /var/log/aerospike/aerospike.log -f head -e 1 -n 10 -h reads
By default, a few meta parameter histograms are enabled such as writes(writes_master), reads, query and more. Additional histograms could be enabled by turning on micro benchmark settings
Turn on microbenchmarks:
asinfo -h [host ip] -v "set-config:context=service;microbenchmarks=true"
Note: Make sure to turn off microbenchmark after the investigation is done, as the extra logging could affect the performance.
Lets get our the first histogram reads using asloglatency tool. Reads histogram provides Aerospike read operation timeline on the server from the point the request is received by Aerospike Server to the time the response is sent back over wire back to the requesting client, without including the time spent over wire for client communication. This histogram represents the complete read operation for Aerospike server and we will further drill down in to smaller operations in the read path further in this article.
Here the histogram is modified as followed. Timeslice is set to 300 second (5 mins), number of buckets to display is set to 10 and also the log file is being read from its head (beginning).
[root@localhost vagrant]# asloglatency -l /var/log/aerospike/aerospike.log -t 300 -f head -n 10 -e 1 -h reads
Apr 13 2015 06:17:08
% > (ms)
slice-to (sec) 1 2 4 8 16 32 64 128 256 512 ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
06:22:08 300 12.80 6.31 2.83 0.83 0.07 0.00 0.00 0.00 0.00 0.00 3171.3
06:27:09 301 15.60 7.93 3.75 1.14 0.09 0.00 0.00 0.00 0.00 0.00 3026.9
06:32:09 300 16.31 8.37 4.00 1.26 0.09 0.00 0.00 0.00 0.00 0.00 2940.0
06:37:09 300 16.01 8.05 3.97 1.33 0.13 0.00 0.00 0.00 0.00 0.00 166.4
06:42:09 300 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0
06:47:09 300 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0
06:52:09 300 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0
06:57:09 300 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0
07:02:09 300 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0
07:07:09 300 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0
07:12:09 300 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0
07:17:09 300 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0
07:22:09 300 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0
07:27:10 301 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0
07:32:10 300 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
avg 4.05 2.04 0.97 0.30 0.03 0.00 0.00 0.00 0.00 0.00 620.0
max 16.31 8.37 4.00 1.33 0.13 0.00 0.00 0.00 0.00 0.00 3171.3
How one should be reading these histograms? First column timestamp from log file, second column shows time slice the row is analysed for, last column shows operations per second in absolute number for this specific time interval. The columns 3 and higher show % number of operations taking more than 1 millisecond, 2 milliseconds, 4 milliseconds and so on. Lets look at first row above, with time stamp 06:22:08, this row shows 12.8% of transactions took more than 1 millisecond, 6.31% transactions took more than 2 milliseconds until 0.07% transactions took more than 16 milliseconds. Please note, these numbers are % of all transactions those took more than 1ms, 2ms … 512ms, which means number of transactions that took more than 2ms are always includes in number of transactions that took more than 1ms. It is not number of transactions between 1ms and 2ms.
Looking at the histogram, most of the read transactions are reported in 06:22:08GMT to 06:37:09GMT. Lets focus on the results only for this time duration. This could be done as follows. Please note -f value has changed and -d parameters has been added to the asloglatency command line options. Also, modified -t (time slice) to show more granular data points.
[root@localhost vagrant]# asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'APR 13 2015 06:22:08' -d 0:11:00 -n 10 -e 1 -h reads
Apr 13 2015 06:22:08
% > (ms)
slice-to (sec) 1 2 4 8 16 32 64 128 256 512 ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
06:23:08 60 15.65 8.01 3.72 1.16 0.10 0.01 0.00 0.00 0.00 0.00 3049.3
06:24:08 60 15.40 7.83 3.70 1.12 0.10 0.00 0.00 0.00 0.00 0.00 2965.6
06:25:08 60 15.85 8.00 3.83 1.22 0.10 0.01 0.00 0.00 0.00 0.00 2991.8
06:26:09 61 15.50 7.89 3.79 1.14 0.08 0.00 0.00 0.00 0.00 0.00 3048.3
06:27:09 60 15.58 7.91 3.73 1.04 0.07 0.00 0.00 0.00 0.00 0.00 3079.4
06:28:09 60 16.00 8.06 3.76 1.06 0.07 0.00 0.00 0.00 0.00 0.00 3038.4
06:29:09 60 16.10 8.25 3.97 1.27 0.07 0.00 0.00 0.00 0.00 0.00 3003.7
06:30:09 60 16.14 8.29 3.97 1.23 0.09 0.00 0.00 0.00 0.00 0.00 2928.5
06:31:09 60 16.61 8.67 4.24 1.42 0.13 0.00 0.00 0.00 0.00 0.00 2834.9
06:32:09 60 16.73 8.62 4.08 1.35 0.10 0.00 0.00 0.00 0.00 0.00 2894.3
06:33:09 60 16.01 8.05 3.97 1.33 0.13 0.00 0.00 0.00 0.00 0.00 832.1
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
avg 15.96 8.14 3.89 1.21 0.09 0.00 0.00 0.00 0.00 0.00 2788.0
max 16.73 8.67 4.24 1.42 0.13 0.01 0.00 0.00 0.00 0.00 3079.4
We see almost uniform latencies in this histogram, ~15% read operations taking more than 1ms time for ~3K reads per second throughput. This test is configured for multiple nodes and performance benchmark test to run on local laptop, hence the throughput is lower. But, lets focus on the analysis of reads operation and histograms.
In the next steps we will be executing the micro-benchmark histograms to analyse the read latencies in more depth.
First lets understand how read operation path and related histograms structure for these micro-benchmark histogram to make more sense.
Server side read operation is considered as an operation starting from the point where a Aerospike server node receives read request from client application to the point the response is packed and ready to be sent back over wire to the client application. The micro-benchmarks provide the following steps in the read code path for deeper analysis.
How to decipher read transaction related micro-benchmarks
- T0: Start of the read transaction on the Aerospike server. The transaction request notification received from client application over wire
- T1: demarshal_hist: Time spent from receiving network notification to the time the data is read over wire and put in to the transaction queue, Delta between T0 and T1. Note, demarshal_hist is not specific to only read operations, but includes all the transaction requests coming in from client application
- T2: q_wait : Time spent waiting in the transaction request, Delta between T1 and T2. Note, q_wait is not specific to only read operations, but includes all the transaction requests being queued
- T3: reads_q_process : Time spent between transaction pulled from transaction queue to start processing the transaction. Delta between T2 and T3
- T3(a): reads_start : Time spent in duplicate resolution, Delta between T3 and T3(a). Optional step needed only for duplicate resolution, probably when cluster state has changed and data migration could be happening
- T3(b): reads_internal : Time spent in acquiring primary index lock during duplicate resolution. Delta between T3(a) and T3(b). Optional step needed only for duplicate resolution, probably when cluster state has changed and data migration could be happening
- T4: reads_tree : Time spent in getting the primary index from the primary index tree. Delta between T3 (optionally T3(b)) and T4
- T5: reads_storage_open : Time spent in opening the data storage. Delta between T4 and T5
- T6: reads_storage_read : Time spent in reading the record from data storage. Delta between T5 and T6
- T7: reads_net : Time spent in packaging the record to be sent over wire to the client application, and sending to the client. Delta between T6 and T7
- T8: reads_cleanup : Time spent in freeing up resources allocated for reads transaction processing. Delta between T7 and T8
- T9: reads : Overall read transaction processing time, summing up all the above steps. Delta between T0 and T9
demarshal_hist
[root@localhost vagrant]# asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'APR 13 2015 06:22:08' -d 0:11:00 -n 10 -e 1 -h demarshal_hist
Apr 13 2015 06:22:08
% > (ms)
slice-to (sec) 1 2 4 8 16 32 64 128 256 512 ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
06:23:08 60 8.53 4.31 1.96 0.58 0.05 0.00 0.00 0.00 0.00 0.00 3811.0
06:24:08 60 8.34 4.14 1.93 0.54 0.05 0.00 0.00 0.00 0.00 0.00 3704.1
06:25:08 60 8.55 4.27 2.02 0.59 0.05 0.00 0.00 0.00 0.00 0.00 3737.0
06:26:09 61 8.40 4.18 1.98 0.57 0.04 0.00 0.00 0.00 0.00 0.00 3818.9
06:27:09 60 8.51 4.21 1.91 0.49 0.03 0.00 0.00 0.00 0.00 0.00 3846.9
06:28:09 60 8.71 4.31 1.97 0.52 0.04 0.00 0.00 0.00 0.00 0.00 3796.8
06:29:09 60 8.77 4.33 2.01 0.58 0.02 0.00 0.00 0.00 0.00 0.00 3759.8
06:30:09 60 8.68 4.40 2.08 0.59 0.04 0.00 0.00 0.00 0.00 0.00 3662.4
06:31:09 60 9.14 4.70 2.26 0.73 0.06 0.00 0.00 0.00 0.00 0.00 3543.6
06:32:09 60 9.12 4.56 2.13 0.65 0.04 0.00 0.00 0.00 0.00 0.00 3618.3
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
avg 8.68 4.34 2.02 0.58 0.04 0.00 0.00 0.00 0.00 0.00 3730.0
max 9.14 4.70 2.26 0.73 0.06 0.00 0.00 0.00 0.00 0.00 3846.9
demarshal_hist seems to be the significant contributor for the overall reads latency. But, this histogram also include other transaction requests. In this case, read transactions are ~3K per second, but this histogram shows ~3.7K transactions per second, the other transactions are write operations in this specific example.
q_wait
[root@localhost vagrant]# asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'APR 13 2015 06:22:08' -d 0:11:00 -n 10 -e 1 -h q_wait
Apr 13 2015 06:22:08
% > (ms)
slice-to (sec) 1 2 4 8 16 32 64 128 256 512 ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
06:23:08 60 0.12 0.07 0.03 0.01 0.00 0.00 0.00 0.00 0.00 0.00 3808.4
06:24:08 60 0.12 0.07 0.03 0.01 0.00 0.00 0.00 0.00 0.00 0.00 3701.5
06:25:08 60 0.11 0.07 0.03 0.01 0.00 0.00 0.00 0.00 0.00 0.00 3734.4
06:26:09 61 0.12 0.07 0.03 0.01 0.00 0.00 0.00 0.00 0.00 0.00 3816.4
06:27:09 60 0.11 0.06 0.03 0.01 0.00 0.00 0.00 0.00 0.00 0.00 3844.3
06:28:09 60 0.10 0.06 0.03 0.01 0.00 0.00 0.00 0.00 0.00 0.00 3794.2
06:29:09 60 0.13 0.07 0.04 0.01 0.00 0.00 0.00 0.00 0.00 0.00 3757.2
06:30:09 60 0.14 0.07 0.03 0.01 0.00 0.00 0.00 0.00 0.00 0.00 3659.8
06:31:09 60 0.12 0.07 0.04 0.01 0.00 0.00 0.00 0.00 0.00 0.00 3541.1
06:32:09 60 0.12 0.07 0.03 0.01 0.00 0.00 0.00 0.00 0.00 0.00 3615.7
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
avg 0.12 0.07 0.03 0.01 0.00 0.00 0.00 0.00 0.00 0.00 3727.0
max 0.14 0.07 0.04 0.01 0.00 0.00 0.00 0.00 0.00 0.00 3844.3
q_wait histogram also include other transaction requests. In this case, read transactions are ~3K per second, but this histogram shows ~3.7K transactions per second, the other transactions are write operations in this specific example.
reads_q_process
[root@localhost vagrant]# asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'APR 13 2015 06:22:08' -d 0:11:00 -n 10 -e 1 -h reads_q_process
Apr 13 2015 06:22:08
% > (ms)
slice-to (sec) 1 2 4 8 16 32 64 128 256 512 ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
06:23:08 60 0.20 0.12 0.06 0.01 0.00 0.00 0.00 0.00 0.00 0.00 3049.2
06:24:08 60 0.18 0.11 0.04 0.01 0.00 0.00 0.00 0.00 0.00 0.00 2965.6
06:25:08 60 0.21 0.11 0.05 0.01 0.00 0.00 0.00 0.00 0.00 0.00 2991.9
06:26:09 61 0.18 0.11 0.05 0.01 0.00 0.00 0.00 0.00 0.00 0.00 3048.3
06:27:09 60 0.17 0.10 0.04 0.01 0.00 0.00 0.00 0.00 0.00 0.00 3079.3
06:28:09 60 0.20 0.11 0.05 0.01 0.00 0.00 0.00 0.00 0.00 0.00 3038.5
06:29:09 60 0.19 0.12 0.06 0.02 0.00 0.00 0.00 0.00 0.00 0.00 3003.8
06:30:09 60 0.21 0.12 0.05 0.01 0.00 0.00 0.00 0.00 0.00 0.00 2928.4
06:31:09 60 0.22 0.14 0.07 0.01 0.00 0.00 0.00 0.00 0.00 0.00 2835.4
06:32:09 60 0.21 0.12 0.06 0.01 0.00 0.00 0.00 0.00 0.00 0.00 2893.9
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
avg 0.20 0.12 0.05 0.01 0.00 0.00 0.00 0.00 0.00 0.00 2983.0
max 0.22 0.14 0.07 0.02 0.00 0.00 0.00 0.00 0.00 0.00 3079.3
reads_start
[root@localhost vagrant]# asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'APR 13 2015 06:22:08' -d 0:11:00 -n 10 -e 1 -h reads_start
Apr 13 2015 06:22:08
% > (ms)
slice-to (sec) 1 2 4 8 16 32 64 128 256 512 ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
06:23:08 60 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0
06:24:08 60 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0
06:25:08 60 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0
06:26:09 61 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0
06:27:09 60 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0
06:28:09 60 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0
06:29:09 60 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0
06:30:09 60 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0
06:31:09 60 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0
06:32:09 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
reads_internal
[root@localhost vagrant]# asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'APR 13 2015 06:22:08' -d 0:11:00 -n 10 -e 1 -h reads_internal
Apr 13 2015 06:22:08
% > (ms)
slice-to (sec) 1 2 4 8 16 32 64 128 256 512 ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
06:23:08 60 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0
06:24:08 60 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0
06:25:08 60 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0
06:26:09 61 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0
06:27:09 60 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0
06:28:09 60 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0
06:29:09 60 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0
06:30:09 60 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0
06:31:09 60 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0
06:32:09 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
reads_tree
[root@localhost vagrant]# asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'APR 13 2015 06:22:08' -d 0:11:00 -n 10 -e 1 -h reads_tree
Apr 13 2015 06:22:08
% > (ms)
slice-to (sec) 1 2 4 8 16 32 64 128 256 512 ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
06:23:08 60 0.20 0.12 0.05 0.01 0.00 0.00 0.00 0.00 0.00 0.00 3049.3
06:24:08 60 0.19 0.11 0.04 0.01 0.00 0.00 0.00 0.00 0.00 0.00 2965.6
06:25:08 60 0.18 0.09 0.04 0.01 0.00 0.00 0.00 0.00 0.00 0.00 2991.9
06:26:09 61 0.19 0.12 0.06 0.01 0.00 0.00 0.00 0.00 0.00 0.00 3048.3
06:27:09 60 0.18 0.10 0.05 0.01 0.00 0.00 0.00 0.00 0.00 0.00 3079.3
06:28:09 60 0.19 0.11 0.05 0.01 0.00 0.00 0.00 0.00 0.00 0.00 3038.5
06:29:09 60 0.18 0.11 0.04 0.01 0.00 0.00 0.00 0.00 0.00 0.00 3003.8
06:30:09 60 0.20 0.11 0.06 0.01 0.00 0.00 0.00 0.00 0.00 0.00 2928.4
06:31:09 60 0.19 0.12 0.05 0.01 0.00 0.00 0.00 0.00 0.00 0.00 2835.0
06:32:09 60 0.20 0.12 0.05 0.01 0.00 0.00 0.00 0.00 0.00 0.00 2894.3
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
avg 0.19 0.11 0.05 0.01 0.00 0.00 0.00 0.00 0.00 0.00 2983.0
max 0.20 0.12 0.06 0.01 0.00 0.00 0.00 0.00 0.00 0.00 3079.3
reads_storage_open
[root@localhost vagrant]# asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'APR 13 2015 06:22:08' -d 0:11:00 -n 10 -e 1 -h reads_storage_open
Apr 13 2015 06:22:08
% > (ms)
slice-to (sec) 1 2 4 8 16 32 64 128 256 512 ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
06:23:08 60 0.12 0.06 0.03 0.01 0.00 0.00 0.00 0.00 0.00 0.00 3049.3
06:24:08 60 0.11 0.06 0.03 0.01 0.00 0.00 0.00 0.00 0.00 0.00 2965.6
06:25:08 60 0.13 0.08 0.03 0.01 0.00 0.00 0.00 0.00 0.00 0.00 2991.9
06:26:09 61 0.11 0.06 0.02 0.00 0.00 0.00 0.00 0.00 0.00 0.00 3048.3
06:27:09 60 0.12 0.06 0.03 0.00 0.00 0.00 0.00 0.00 0.00 0.00 3079.3
06:28:09 60 0.11 0.06 0.02 0.00 0.00 0.00 0.00 0.00 0.00 0.00 3038.4
06:29:09 60 0.11 0.07 0.03 0.01 0.00 0.00 0.00 0.00 0.00 0.00 3003.8
06:30:09 60 0.13 0.07 0.03 0.01 0.00 0.00 0.00 0.00 0.00 0.00 2928.5
06:31:09 60 0.13 0.08 0.04 0.01 0.00 0.00 0.00 0.00 0.00 0.00 2835.0
06:32:09 60 0.13 0.07 0.03 0.01 0.00 0.00 0.00 0.00 0.00 0.00 2894.3
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
avg 0.12 0.07 0.03 0.01 0.00 0.00 0.00 0.00 0.00 0.00 2983.0
max 0.13 0.08 0.04 0.01 0.00 0.00 0.00 0.00 0.00 0.00 3079.3
reads_storage_read
[root@localhost vagrant]# asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'APR 13 2015 06:22:08' -d 0:11:00 -n 10 -e 1 -h reads_storage_read
Apr 13 2015 06:22:08
% > (ms)
slice-to (sec) 1 2 4 8 16 32 64 128 256 512 ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
06:23:08 60 0.26 0.15 0.06 0.01 0.00 0.00 0.00 0.00 0.00 0.00 3049.3
06:24:08 60 0.23 0.12 0.05 0.01 0.00 0.00 0.00 0.00 0.00 0.00 2965.6
06:25:08 60 0.28 0.15 0.07 0.01 0.00 0.00 0.00 0.00 0.00 0.00 2991.9
06:26:09 61 0.24 0.14 0.07 0.01 0.00 0.00 0.00 0.00 0.00 0.00 3048.3
06:27:09 60 0.27 0.16 0.07 0.02 0.00 0.00 0.00 0.00 0.00 0.00 3079.3
06:28:09 60 0.25 0.14 0.07 0.01 0.00 0.00 0.00 0.00 0.00 0.00 3038.4
06:29:09 60 0.23 0.14 0.05 0.01 0.00 0.00 0.00 0.00 0.00 0.00 3003.8
06:30:09 60 0.26 0.15 0.07 0.02 0.00 0.00 0.00 0.00 0.00 0.00 2928.5
06:31:09 60 0.25 0.15 0.07 0.02 0.00 0.00 0.00 0.00 0.00 0.00 2835.0
06:32:09 60 0.28 0.15 0.07 0.01 0.00 0.00 0.00 0.00 0.00 0.00 2894.3
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
avg 0.26 0.14 0.07 0.01 0.00 0.00 0.00 0.00 0.00 0.00 2983.0
max 0.28 0.16 0.07 0.02 0.00 0.00 0.00 0.00 0.00 0.00 3079.3
reads_net
[root@localhost vagrant]# asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'APR 13 2015 06:22:08' -d 0:11:00 -n 10 -e 1 -h reads_net
Apr 13 2015 06:22:08
% > (ms)
slice-to (sec) 1 2 4 8 16 32 64 128 256 512 ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
06:23:08 60 2.17 1.18 0.52 0.14 0.01 0.00 0.00 0.00 0.00 0.00 3049.3
06:24:08 60 2.21 1.18 0.54 0.13 0.01 0.00 0.00 0.00 0.00 0.00 2965.6
06:25:08 60 2.22 1.21 0.56 0.15 0.00 0.00 0.00 0.00 0.00 0.00 2991.9
06:26:09 61 2.18 1.20 0.55 0.12 0.00 0.00 0.00 0.00 0.00 0.00 3048.2
06:27:09 60 2.11 1.17 0.51 0.12 0.01 0.00 0.00 0.00 0.00 0.00 3079.4
06:28:09 60 2.18 1.17 0.53 0.11 0.01 0.00 0.00 0.00 0.00 0.00 3038.5
06:29:09 60 2.23 1.23 0.59 0.15 0.00 0.00 0.00 0.00 0.00 0.00 3003.7
06:30:09 60 2.30 1.22 0.57 0.14 0.01 0.00 0.00 0.00 0.00 0.00 2928.5
06:31:09 60 2.34 1.28 0.63 0.16 0.00 0.00 0.00 0.00 0.00 0.00 2834.9
06:32:09 60 2.37 1.30 0.61 0.15 0.00 0.00 0.00 0.00 0.00 0.00 2894.3
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
avg 2.23 1.21 0.56 0.14 0.01 0.00 0.00 0.00 0.00 0.00 2983.0
max 2.37 1.30 0.63 0.16 0.01 0.00 0.00 0.00 0.00 0.00 3079.4
reads_cleanup
[root@localhost vagrant]# asloglatency -l /var/log/aerospike/aerospike.log -t 60 -f 'APR 13 2015 06:22:08' -d 0:11:00 -n 10 -e 1 -h reads_cleanup
Apr 13 2015 06:22:08
% > (ms)
slice-to (sec) 1 2 4 8 16 32 64 128 256 512 ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
06:23:08 60 0.18 0.11 0.05 0.01 0.00 0.00 0.00 0.00 0.00 0.00 3049.3
06:24:08 60 0.17 0.11 0.05 0.01 0.00 0.00 0.00 0.00 0.00 0.00 2965.6
06:25:08 60 0.18 0.11 0.05 0.01 0.00 0.00 0.00 0.00 0.00 0.00 2991.9
06:26:09 61 0.16 0.10 0.05 0.01 0.00 0.00 0.00 0.00 0.00 0.00 3048.3
06:27:09 60 0.18 0.11 0.05 0.01 0.00 0.00 0.00 0.00 0.00 0.00 3079.4
06:28:09 60 0.19 0.12 0.06 0.01 0.00 0.00 0.00 0.00 0.00 0.00 3038.5
06:29:09 60 0.19 0.11 0.05 0.01 0.00 0.00 0.00 0.00 0.00 0.00 3003.7
06:30:09 60 0.18 0.11 0.05 0.01 0.00 0.00 0.00 0.00 0.00 0.00 2928.5
06:31:09 60 0.17 0.09 0.04 0.01 0.00 0.00 0.00 0.00 0.00 0.00 2834.9
06:32:09 60 0.20 0.12 0.06 0.01 0.00 0.00 0.00 0.00 0.00 0.00 2894.3
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ --------
avg 0.18 0.11 0.05 0.01 0.00 0.00 0.00 0.00 0.00 0.00 2983.0
max 0.20 0.12 0.06 0.01 0.00 0.00 0.00 0.00 0.00 0.00 3079.4
Summary
Read transaction processing has a number of sub tasks that Aerospike performs. In this specific example, demarshal_hist seems to be the major contributor in the read latency. demarshal_hist is histogram of time spent in receiving the request from client application over TCP connection, deserialize the data, put this request in appropriate data structure and getting it in to the transaction. Hence, probable causes could be the network IO latency between client and server, higher memory/cpu utilization of the Aerospike server.
It’s worthwhile noting that the numbers represented in the histograms are latencies for the specific sub-task within a read transaction. Assume, if every sub-task is taking < 1ms, but such 10 subtasks when combined together would go beyond 1ms. Hence, you could as well have a case where none of the subtasks show anything more than 1ms, but overall read transaction latencies are higher. Usually, a couple of subtasks should show up as significant contributors in latencies, providing vital pointers on tuning Aerospike better.
Getting to know which sub task could be the bottleneck helps in fine tuning the system perform better.
Do check out Analyzing Write Operations for similar information on write transaction request microbenchmark analysis