Skip to main content

Log Latency Tool (asloglatency)

The Aerospike Log Latency tool (asloglatency) analyzes Aerospike log files and returns the latency measurements. It returns latency analysis for a given time period in a tabular, easy to read form. The utility analyzes a histogram by parsing latency log lines during successive time slices, and calculating the percentage of operations in each time slice that exceeded various latency thresholds.

Usage

You run the tool at the command line, and provide option parameters. Use the --help option to display the list of options.

asloglatency OPTIONS

Options

OptionDefaultDescription
-l/var/log/aerospike/aerospike.logPath to Aerospike's log file.
-h <\HISTOGRAM>(required) Name of the histogram to query.
-N <\NAMESPACE>Name of the namespace to examine latency. This works for logs of server version 3.9 and above.
-t <\TIME>10Analysis slice interval in seconds or time format.
Time Format: 1:00:00
-f <\TIME>tailLog time from which to analyze. May use the following formats: head, 'Sep 22 2011 22:40:14', -3600, or -1:00:00.
-d <\TIME>Maximum time period to analyze. May use the following formats: 3600 or 1:00:00.
-n <\N>3Number of buckets to display.
-e <\N>3Show the 0-th and then every n-th bucket.
-rDisabledRun until user presses return key or ctrl-c. Auto enabled if -f tail.

Examples

The most common use case for this utility is monitoring a live server in real-time. The default parameters support this common pattern.

info

Starting with Aerospike server version 3.9, the histograms are now at a per-namespace level and the naming and terminology is updated. See the Monitoring latencies page for details on monitoring latencies prior to version 3.9.

For each set of histogram data, the following intervals are tracked:

IntervalTime required to complete
00 to 20 ms ( 0 ms to < 1 ms )
120 to 21 ms ( 1 ms to < 2 ms )
221 to 22 ms ( 2 ms to < 4 ms )
322 to 23 ms ( 4 ms to < 8 ms )
etc.

These can be configured using asinfo command. See Configuration Reference.

$ asloglatency -h {test}-write

It returns the following histogram for writes for namespace test:

{test}-write
Jul 06 2016 20:15:45
% > (ms)
slice-to (sec) 1 8 64 ops/sec
-------------- ------ ------ ------ --------
20:15:55 10 1.40 1.19 0.00 35535.6
20:16:05 10 1.46 1.21 0.00 35143.0
20:16:15 10 1.48 1.25 0.00 35235.0
20:16:25 10 1.49 1.27 0.00 34741.3
20:16:35 10 1.40 1.19 0.00 35243.0
20:16:45 10 1.42 1.23 0.00 35202.1
20:16:55 10 1.44 1.22 0.00 35047.6
20:17:05 10 1.56 1.33 0.00 34085.9
-------------- ------ ------ ------ --------
avg 1.46 1.24 0.00 35029.0
max 1.56 1.33 0.00 35535.6

Press Enter or CTRL+C to stop the script and display averages & maximums.

Histogram buckets illustrate a distribution of events. Column 1 contains the % of write operations that were not completed within 1 ms. The second column contains counts of writes that were not completed within 8 ms.

asloglatency does not calculate in increments between 0 and 1. If you need to measure sub-millisecond latencies, you can measure them and calculate averages on the client.

The following example is another way to write same query as above.

$ asloglatency -N test -h write

Another common use case is to examine a time period in the past. The following example analyzes reads for the test namespace:

$ asloglatency -h {test}-read -f -100 -d 0:02:00

The analysis starts 100 seconds before the end of the log file. It reviews two minutes of records, and analyzes data in 10 second increments.

{test}-read
Jul 06 2016 20:31:06
% > (ms)
slice-to (sec) 1 8 64 ops/sec
-------------- ------ ------ ------ --------
20:31:16 10 1.33 1.12 0.00 8616.8
20:31:26 10 1.38 1.18 0.00 8745.4
20:31:36 10 1.49 1.24 0.00 8565.5
20:31:46 10 1.52 1.29 0.00 8488.6
20:31:56 10 1.36 1.14 0.00 8620.2
20:32:06 10 1.50 1.28 0.00 8358.7
20:32:16 10 1.42 1.22 0.00 8675.5
20:32:26 10 1.42 1.20 0.00 8416.8
20:32:36 10 1.57 1.34 0.00 8539.2
20:32:46 10 1.46 1.23 0.00 8555.7
-------------- ------ ------ ------ --------
avg 1.45 1.22 0.00 8558.0
max 1.57 1.34 0.00 8745.4
info

Analyzing a time period that bridges a server restart distorts results of time slices and average/maximum calculations.

Another common use case is to examine aggregate latency for all namespaces.

$ asloglatency -h query

It returns the following histogram for queries for all namespaces:

query
Jul 10 2016 11:06:27
% > (ms)
slice-to (sec) 1 8 64 ops/sec
-------------- ------ ------ ------ --------
11:06:37 10 4.24 0.26 0.00 4507.4
11:06:47 10 4.55 0.19 0.00 4484.7
11:06:57 10 4.87 0.31 0.00 4478.2
11:07:07 10 6.35 0.68 0.00 4288.6
11:07:17 10 2.93 0.02 0.00 3247.9
11:07:27 10 1.31 0.02 0.00 3493.6
11:07:37 10 0.49 0.00 0.00 3394.5
11:07:47 10 0.30 0.00 0.00 2666.3
11:07:57 10 0.57 0.00 0.00 3094.7
11:08:07 10 0.25 0.00 0.00 2184.1
-------------- ------ ------ ------ --------
avg 2.59 0.15 0.00 3584.0
max 6.35 0.68 0.00 4507.4

Histograms

See the Monitoring latencies page for monitoring latencies and details about the histograms.

For server versions prior to 3.9, see Histograms for server version before 3.9