How To Use "show latencies" asadm command?

Audience: DBAs and SREs investigating server-side latency.
Applies to: Aerospike Database Enterprise 5.7.0.0 and later, with asadm.

Context

asadm -e "show latencies" shows, for each node, how many transactions per second each latency histogram recorded and what share of them were slow. With the default settings it gives a quick health check. With extra columns and the optional microbenchmark histograms, it shows which stage of a transaction the time is spent in.

This article explains:

• what the columns mean
• how to show more columns
• how to use microbenchmarks to find where the latency comes from

Reading show latencies

asadm -e "show latencies"

Namespace|Histogram|Node             |ops/sec|>1ms|>8ms|>64ms
test     |read     |10.0.0.11:3000   |  502.1| 0.0| 0.0|  0.0
test     |read     |10.0.0.12:3000   |  498.8| 0.0| 0.0|  0.0
         |         |                 | 1000.9| 0.0| 0.0|  0.0
test     |write    |10.0.0.11:3000   |  500.5|0.64|0.04|  0.0
test     |write    |10.0.0.12:3000   |  499.9|0.92|0.04|  0.0
         |         |                 | 1000.4|0.78|0.04|  0.0

Things to know when reading it

• The percentages are cumulative, so they do not add up. Each column includes the slower columns to its right. In the example, 0.92% of writes on the second node took 1 ms or more, and 0.04% took 8 ms or more. The 0.04% is part of the 0.92%.
• **Values cover the last ticker-interval only.** Each node recalculates them every ticker-interval (default 10 seconds) from the transactions in that interval. Running the command twice within the same interval gives the same numbers. These are not totals since startup.
• The total row is weighted. ops/sec is summed across nodes. The percentages are averaged, weighted by each node's ops/sec.
• **Check ops/sec before reacting to a percentage.** At low throughput, one slow transaction can be a large percentage. For example, 1 slow transaction out of 3 shows as 33%.
• Latency is timed inside the server. Each transaction is timed from when the node has read the request until it sends the response. Time on the client and on the network to the client is not included. If the application sees high latency but show latencies does not, look at the client, its connection pool and the network.
• A default histogram is shown only after it has recorded traffic. For example, udf does not appear on a node that has never run a UDF. Microbenchmark histograms that are turned on are shown even when they record nothing, with 0.0 throughput.

Filtering

asadm -e "show latencies for test"          # namespaces whose name contains "test"
asadm -e "show latencies like write"        # histograms whose name contains "write"
asadm -e "show latencies with 10.0.0.11"    # one node only

Showing more columns

Each node keeps 17 thresholds, at every power of two from 1 ms to 65536 ms. By default asadm shows every third one (>1ms, >8ms, >64ms). Two options control which ones you see:

All 17 thresholds:

asadm -e "show latencies -e 1 -b 17"

Namespace|Histogram|Node          |ops/sec|>1ms|>2ms|>4ms|>8ms|>16ms|>32ms|>64ms|>128ms|...|>65536ms
test     |write    |10.0.0.11:3000|  500.5|0.64|0.18|0.08|0.04|  0.0|  0.0|  0.0|   0.0|...|     0.0

Every power of two up to 128 ms, which is enough for most investigations:

asadm -e "show latencies -e 1 -b 8"

A wider range in fewer columns (>1ms, >4ms, >16ms, ... >65536ms):

asadm -e "show latencies -e 2 -b 9"

To print every node's raw values, use asinfo:

asadm --enable -e "asinfo -v 'latencies:'"

Each histogram is returned as its name, the units (msec), ops/sec, and then the 17 percentages from >1 to >65536, for example {test}-write:msec,500.5,0.64,0.18,0.08,0.04,0.00,....

Investigating latency with microbenchmarks

The default histograms show how long a whole transaction took. Microbenchmarks split each transaction into stages and record a histogram for each stage, so you can see which stage the time goes to. They are off by default and can be turned on and off while the node is running.

1. Find the slow histogram and node

asadm -e "show latencies -e 1 -b 8"

Note which histogram (read, write, batch-sub-read, and so on) has the higher percentages, and whether it affects every node or only one. If only one node is slow, look at that node's host, devices and network first.

2. Turn on the matching microbenchmark on every node

For example, for writes in namespace test:

asadm -e "enable; manage config namespace test param enable-benchmarks-write to true"

manage config applies the change to every node. It needs a user whose role includes sys-admin. The change lasts until the node restarts.

3. Wait about 20 seconds, then show the stages

The stage histograms appear after two ticker intervals (about 20 seconds with the default ticker-interval). Until then, -v shows only the default histograms.

asadm -e "show latencies -v -e 1 -b 8 like write"

-v adds the microbenchmark histograms to the output.

Namespace|Histogram       |Node          |ops/sec|>1ms|>2ms|>4ms|>8ms|...
test     |write           |10.0.0.11:3000|  499.4| 0.4|0.12|0.06|0.04|...
test     |write-dup-res   |10.0.0.11:3000|    0.0| 0.0| 0.0| 0.0| 0.0|...
test     |write-master    |10.0.0.11:3000|  499.3| 0.0| 0.0| 0.0| 0.0|...
test     |write-repl-write|10.0.0.11:3000|  499.4|0.34|0.10|0.06|0.04|...
test     |write-response  |10.0.0.11:3000|  499.4| 0.0| 0.0| 0.0| 0.0|...
test     |write-restart   |10.0.0.11:3000|    0.1| 0.0| 0.0| 0.0| 0.0|...
test     |write-start     |10.0.0.11:3000|  499.3| 0.0| 0.0| 0.0| 0.0|...

Each stage histogram times only its own stage: from the end of the previous stage to the end of this one. The stage whose percentages match the write row is where the time goes. In the example, write-repl-write accounts for almost all of the writes that took 1 ms or more, so the time is spent waiting for the replica.

A stage that does not apply to a transaction is not recorded, so its ops/sec is lower than the total or 0. For example, write-dup-res records only during migrations or in strong-consistency namespaces.

4. Find the stage that matches, then check the likely cause

5. Go further for storage or fabric

Storage. Turn on the per-device histograms with:

asadm -e "enable; manage config namespace test param enable-benchmarks-storage to true"

These histograms are written only to the server log, every ticker-interval. show latencies does not show them. Each one is named after the device or file, for example {test}-/dev/nvme0n1-read and {test}-/dev/nvme0n1-write. There are also size histograms ({test}-device-read-size, {test}-device-write-size) in bytes. The counts in the log are cumulative from when the histogram was turned on.

grep -A3 'histogram dump: {test}-/dev/' /var/log/aerospike/aerospike.log | tail -20

Use -A3, because one histogram's buckets can span several log lines. Bucket (NN: count) holds the transactions that took from 2^(NN-1) to 2^NN milliseconds, and bucket 00 holds those under 1 ms.

Fabric. If repl-write or dup-res is slow, turn on the inter-node histograms:

asadm -e "enable; manage config service param enable-benchmarks-fabric to true"

They appear under show latencies -v with no namespace, as fabric-<channel>-send-init, -send-fragment, -recv-fragment and -recv-cb. The channels are rw (replica writes and duplicate resolution), bulk (migrations), ctrl and meta.

Server 8.2.0.0 and later also have enable-benchmarks-repl (one {ns}-repl-write histogram per replica confirmation) and enable-benchmarks-migrate ({ns}-migrate-emigrate, the time for a migrated record to be confirmed). show latencies -v does not show them, so read them with asinfo:

asadm --enable -e "asinfo -v 'latencies:hist={test}-benchmarks-repl'"

6. Turn the microbenchmarks off

Microbenchmarks add a small cost to every transaction. Turn them off when you are finished:

asadm -e "enable; manage config namespace test param enable-benchmarks-write to false"

To keep one on after a restart, also set it in aerospike.conf.

Notes

• Microsecond histograms. With microsecond-histograms true, the histograms are recorded in microseconds and the columns become >1us, >2us, and so on. When it is set in aerospike.conf, every histogram uses microseconds. It can only be changed at runtime when every microbenchmark is off, and then only the microbenchmarks switch to microseconds. The default histograms stay in milliseconds, and asadm labels every column ms. In that case, read the units from asinfo -v 'latencies:hist={test}-benchmarks-write', where each histogram starts with msec or usec.
• Proxy histogram. enable-hist-proxy (namespace) adds a proxy histogram for transactions this node forwarded to another node. It appears under show latencies -v.
• Collectinfo. show latencies also works in collectinfo mode (asadm -cf <collectinfo>). It shows the values captured when the collectinfo was taken, and accepts only for and like.
• For a full list of histograms, see Latency monitoring.

Applies To Earliest Version

5.7.0.0

Applies To Latest Version

Current Version