One node showing inexplicably high read latency/CPU load

Operations Tuning
,
1

Hello,

We are trying to debug a node that shows high read latency and CPU load in an aerospike cluster with size 4. This is a somewhat similar issue we were seeing and we posted a couple of months ago, however this is for a different cluster:

Again, here’s the asmonitor read latency:

Aerospike Interactive Shell, version 3.3.23
Monitor> latency
	====reads====
                                   timespan   ops/sec    >1ms    >8ms   >64ms
10.1.111.104:3000    00:11:28-GMT->00:11:38    2167.9   19.30   11.97    1.85
10.1.111.105:3000    00:11:22-GMT->00:11:32    2581.1    0.07    0.00    0.00
10.1.111.106:3000    00:11:27-GMT->00:11:37    2831.5    0.19    0.00    0.00
10.1.96.252:3000     00:11:26-GMT->00:11:36    2746.6    0.19    0.07    0.00

One of the nodes is behaving poorly, it also shows higher CPU load than the rest, in a somewhat consistent manner (over time).

I did run the iostat -x 2 command as mentioned in the linked topic, however, the results seemed very similar between this node and another node, that doesn’t show the high latency/CPU problem.

I gathered some statistics about the issue using the asadmin tool and the two metrics that were exceptionally higher for the misbehaving node are the following two:

rw_err_dup_cluster_key                      :   118716            83                0                 3992
err_tsvc_requests                           :   5504727           994               1033907           1103650

The first column is the node with high latency/CPU load. I checked what those mean here Metrics Reference | Aerospike Documentation but I couldn’t explain 100% why we are seeing this issue. Also, from my limited understanding of what those metrics might mean, I can’t explain why this issue would be still happening on the node.

Any other steps we can take in finding the root cause of this issue? Also, is there any other Docs that provides less terse explanations of the metrics than the ones found here Metrics Reference | Aerospike Documentation ?

Any help or insight on how to proceed debugging and resolving this issue is much appreciated.

Thanks

2

This could be a hot key, could you provide the err_rx_pending_limit stats and your transaction-pending-limit configuration?

We could also enable micro and storage benchmarks. Let them run for about an hour and grep the logs for hist.c. You will notice after enabling the benchmarks there will be more histograms printed than normal. These histograms are printed every 10 seconds by default, I would be interested in seeing the last group printed after running for an hour.

3

A hot key is unlikely, because we would see the exception from the client (we are monitoring closely for that particular issue). The metric you specified isn’t showing anything useful:

err_rw_pending_limit                        :   0                 0                 0                 0

We haven’t touched the transaction-pending-limit config, so it’s set at the default (20).

I did enable microbenchmarks and storage benchmarks and here are the first histograms (hist.c) after ~ 1hour of running:

Oct 07 2015 20:18:48 GMT: INFO (info): (hist.c::137) histogram dump: info_fulfill (90791 total) msec
Oct 07 2015 20:18:48 GMT: INFO (info): (hist.c::163)  (00: 0000090791)
Oct 07 2015 20:18:48 GMT: INFO (info): (hist.c::137) histogram dump: write_storage_close (0 total) msec
Oct 07 2015 20:18:48 GMT: INFO (info): (hist.c::137) histogram dump: write_sindex (0 total) msec
Oct 07 2015 20:18:48 GMT: INFO (info): (hist.c::137) histogram dump: defrag_storage_close (0 total) msec
Oct 07 2015 20:18:48 GMT: INFO (info): (hist.c::137) histogram dump: prole_fabric_send (0 total) msec
Oct 07 2015 20:18:48 GMT: INFO (info): (hist.c::137) histogram dump: SSD_READ_0 /dev/sdb (4780173 total) msec
Oct 07 2015 20:18:48 GMT: INFO (info): (hist.c::154)  (00: 0004765875) (01: 0000006935) (02: 0000004140) (03: 0000001610)
Oct 07 2015 20:18:48 GMT: INFO (info): (hist.c::163)  (04: 0000001355) (05: 0000000258)
Oct 07 2015 20:18:48 GMT: INFO (info): (hist.c::137) histogram dump: SSD_LARGE_BLOCK_READ_0 /dev/sdb (0 total) msec
Oct 07 2015 20:18:48 GMT: INFO (info): (hist.c::137) histogram dump: SSD_WRITE_0 /dev/sdb (0 total) msec
Oct 07 2015 20:18:48 GMT: INFO (info): (hist.c::137) histogram dump: SSD_FSYNC_0 /dev/sdb (0 total) msec

We have more clusters configured in the same way as the cluster that has the misbehaving node, but none of them are experiencing the same issue, at the moment.

All our aerospike clusters are deployed on AWS.

Any other pointers on where to look next (other metrics maybe…) that we could look to figure this out?

4

This isn’t the full micro/storage benchmark output so there may be another benchmark that may provide better insight.

That said, from this output you can see that some (258) of the SSD_READ from /dev/sdb take up 2^5 (32) msecs. The amount of transactions experiencing these latencies is much less than what was reported by the macro benchmarks (0.2% vs 19.3% > 1ms). So if during this hour your latencies were consistently as you originally reported then this isn’t going to be the problem, however if the latencies you reported earlier are not consistent and come in spikes then the characteristics of the SSD_READ latencies could explain that, but I wouldn’t be able to observe that from a single snapshot. We could see if this is the case by using the asloglatency tool.

asloglatency -n8 -e1 -f -1:00:00 -t 300 -h "SSD_READ_0 /dev/sdb"
5

The issue happened again 3 hours ago and I ran the storage benchmark again and here is the result of running the loglatency tool for the period that we saw that slower latency in one node:

           % > (ms)

slice-to (sec)      1      2      4      8     16     32     64    128  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ --------
19:51:24   300   1.65   1.34   1.04   0.74   0.30   0.07   0.01   0.00    583.6
19:56:24   300   1.77   1.42   1.07   0.79   0.42   0.20   0.12   0.01    633.1
20:01:24   300   1.28   0.84   0.53   0.37   0.17   0.04   0.02   0.00    644.3
20:06:24   300   2.24   1.81   1.37   0.99   0.39   0.11   0.07   0.00    595.3
20:11:24   300   1.11   0.67   0.42   0.33   0.25   0.14   0.06   0.00    574.7
20:16:24   300   1.11   0.85   0.61   0.41   0.23   0.11   0.06   0.00    539.3
20:21:24   300   2.10   1.63   1.18   0.84   0.35   0.13   0.05   0.00    639.0
20:26:24   300   0.69   0.47   0.31   0.23   0.14   0.09   0.04   0.00    669.9
20:31:24   300   0.40   0.29   0.20   0.14   0.09   0.03   0.01   0.00    664.9
20:36:24   300   0.48   0.30   0.20   0.13   0.08   0.02   0.00   0.00    739.6
20:41:25   301   0.48   0.29   0.17   0.12   0.06   0.02   0.01   0.00    670.9
20:46:25   300   0.46   0.35   0.25   0.18   0.11   0.05   0.01   0.00    635.8
20:51:25   300   0.28   0.19   0.13   0.09   0.03   0.01   0.00   0.00    733.3
20:56:25   300   0.51   0.31   0.19   0.14   0.08   0.03   0.02   0.00    746.4
21:01:25   300   0.57   0.38   0.25   0.19   0.13   0.04   0.01   0.00    730.2
21:06:25   300   0.46   0.27   0.17   0.12   0.06   0.01   0.01   0.00    652.8
21:11:25   300   0.49   0.32   0.20   0.14   0.10   0.04   0.01   0.00    664.4
21:16:25   300   0.67   0.47   0.31   0.23   0.15   0.07   0.02   0.00    688.8
21:21:25   300   0.66   0.46   0.33   0.25   0.16   0.05   0.00   0.00    736.8
21:26:25   300   0.47   0.28   0.17   0.11   0.07   0.03   0.02   0.00    725.8
21:31:25   300   0.27   0.20   0.14   0.10   0.06   0.02   0.01   0.00    732.9
21:36:25   300   0.48   0.29   0.16   0.11   0.06   0.02   0.01   0.00    716.7
21:41:25   300   0.51   0.31   0.17   0.12   0.08   0.02   0.00   0.00    781.4
21:46:25   300   0.51   0.34   0.25   0.18   0.13   0.07   0.04   0.00    754.2
21:51:25   300   0.30   0.23   0.17   0.13   0.08   0.02   0.01   0.00    735.5
21:56:25   300   0.38   0.20   0.09   0.06   0.03   0.00   0.00   0.00    801.5
22:01:25   300   0.54   0.35   0.24   0.18   0.12   0.05   0.02   0.00    795.4
22:06:25   300   0.48   0.31   0.20   0.16   0.10   0.02   0.00   0.00    722.9
22:11:25   300   0.23   0.19   0.15   0.11   0.07   0.03   0.01   0.00    763.8
-------------- ------ ------ ------ ------ ------ ------ ------ ------ --------
 avg         0.74   0.53   0.37   0.27   0.14   0.05   0.02   0.00    692.0
 max         2.24   1.81   1.37   0.99   0.42   0.20   0.12   0.01    801.5

It is evident that the spikes in read latency are correlated to the read behaviour of the SSD drive. The drives are ephemeral disks in AWS instances.

Why does this problem come and go? It happened 2 weeks ago and today for about half an hour (till 20:30 UTC) and then stopped happening. I guess that is a question to ask to AWS too, but since we only see this behaviour on instances that run aerospike, I am wondering if anyone else has seen the same issue and if there are any ways to prevent/mitigate it.

6

Before you had ~12% exceeding 8ms. This shows a worst case max of ~1% exceeding 8ms. Could you also supply the read latencies?

asloglatency -l /path/to/aerospike.log -n8 -e1 -f -1:00:00 -t 300 -h "reads"
7

Yes, so I am seeing this issue happening right now, so here’s the SSD_READ_0 and reads histograms for a period of 2.5 hours while this issue is happening:

SSD_READ_0:

                   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ --------
17:03:46   300   3.41   2.56   1.93   1.52   1.11   0.67   0.29   0.06    328.2
17:08:46   300   1.05   0.63   0.39   0.27   0.13   0.02   0.01   0.00    484.8
17:13:46   300   2.67   1.92   1.41   1.10   0.79   0.48   0.25   0.01    487.3
17:18:46   300   1.90   1.32   0.93   0.77   0.56   0.33   0.16   0.02    492.8
17:23:46   300   1.01   0.59   0.34   0.22   0.11   0.05   0.02   0.00    490.1
17:28:46   300   0.79   0.42   0.19   0.15   0.09   0.02   0.01   0.00    472.4
17:33:46   300   2.28   1.71   1.26   0.99   0.68   0.35   0.14   0.01    461.3
17:38:46   300   0.96   0.52   0.28   0.19   0.10   0.03   0.01   0.00    486.0
17:43:46   300   1.21   0.70   0.39   0.30   0.20   0.10   0.05   0.00    493.9
17:48:46   300   1.17   0.48   0.15   0.10   0.05   0.02   0.00   0.00    468.5
17:53:46   300   1.86   1.33   0.97   0.77   0.57   0.34   0.13   0.02    469.3
17:58:46   300   1.33   0.73   0.35   0.24   0.14   0.04   0.02   0.00    486.3
18:03:46   300   1.22   0.72   0.42   0.34   0.25   0.12   0.04   0.00    485.0
18:08:46   300   1.75   1.24   0.86   0.62   0.38   0.20   0.11   0.01    559.0
18:13:47   301   1.19   0.58   0.28   0.22   0.16   0.11   0.05   0.00    599.8
18:18:47   300   0.96   0.50   0.24   0.18   0.12   0.04   0.00   0.00    577.6
18:23:47   300   0.79   0.42   0.21   0.14   0.08   0.03   0.03   0.00    568.7
18:28:47   300   0.59   0.35   0.19   0.13   0.09   0.05   0.01   0.00    556.9
18:33:47   300   1.14   0.86   0.63   0.46   0.33   0.23   0.15   0.07    497.3
18:38:47   300   0.80   0.58   0.41   0.29   0.17   0.05   0.02   0.00    477.8
-------------- ------ ------ ------ ------ ------ ------ ------ ------ --------
     avg         1.40   0.91   0.59   0.45   0.31   0.16   0.08   0.01    497.0
     max         3.41   2.56   1.93   1.52   1.11   0.67   0.29   0.07    599.8

And the reads:

                   % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ --------
16:18:35   300   0.62   0.36   0.21   0.16   0.11   0.03   0.01   0.00   1220.0
16:23:35   300   0.61   0.34   0.19   0.14   0.09   0.03   0.01   0.00   1229.8
16:28:35   300   0.71   0.41   0.23   0.16   0.10   0.03   0.01   0.00   1267.9
16:33:35   300   0.98   0.43   0.22   0.18   0.13   0.05   0.02   0.00   1227.1
16:38:35   300   0.57   0.27   0.12   0.09   0.06   0.01   0.00   0.00   1266.5
16:43:36   301   3.02   2.33   1.83   1.51   1.06   0.51   0.19   0.04   1245.4
16:48:36   300   4.64   3.22   2.26   1.78   1.26   0.65   0.30   0.01   1276.2
16:53:36   300  13.44  11.86   9.75   7.49   4.48   1.34   0.61   0.11   1270.3
16:58:36   300  14.56  11.29   7.73   5.39   3.02   0.88   0.28   0.03   1309.8
17:03:36   300  12.64  10.27   7.86   6.15   4.30   2.20   1.22   0.07   1264.3
17:08:36   300   7.00   3.89   1.19   0.46   0.27   0.10   0.05   0.00   1309.0
17:13:36   300   6.58   4.82   3.24   2.47   1.81   1.01   0.56   0.02   1301.9
17:18:36   300   1.84   1.40   1.05   0.85   0.58   0.26   0.12   0.02   1316.4
17:23:36   300  10.12   6.33   2.89   1.74   1.23   0.66   0.42   0.02   1313.0
17:28:36   300   0.73   0.38   0.18   0.13   0.08   0.02   0.01   0.00   1264.2
17:33:36   300  10.34   8.54   6.54   4.99   3.22   1.27   0.62   0.03   1242.9
17:38:36   300   6.78   3.84   1.20   0.42   0.26   0.12   0.06   0.01   1311.3
17:43:36   300   0.90   0.56   0.34   0.27   0.18   0.07   0.03   0.00   1331.7
17:48:36   300   0.87   0.36   0.12   0.08   0.04   0.01   0.00   0.00   1255.5
17:53:36   300   6.30   4.69   3.28   2.48   1.76   0.98   0.53   0.02   1252.1
17:58:36   300   6.39   3.44   0.95   0.31   0.17   0.06   0.03   0.01   1288.6
18:03:36   300   2.55   2.07   1.69   1.42   1.09   0.66   0.40   0.02   1281.6
18:08:36   300  11.77   8.01   4.67   3.37   2.53   1.40   0.88   0.03   1449.7
18:13:37   301   1.18   0.70   0.43   0.32   0.19   0.09   0.04   0.00   1562.5
18:18:37   300   0.80   0.43   0.21   0.16   0.10   0.02   0.00   0.00   1506.9
18:23:37   300   0.65   0.34   0.17   0.12   0.07   0.02   0.01   0.00   1489.8
18:28:37   300   0.51   0.32   0.20   0.15   0.09   0.03   0.01   0.00   1464.6
18:33:37   300   9.32   6.75   4.33   3.27   2.52   1.47   0.92   0.06   1313.6
18:38:37   300   3.29   1.93   0.72   0.33   0.18   0.05   0.02   0.00   1254.4
-------------- ------ ------ ------ ------ ------ ------ ------ ------ --------
     avg         4.82   3.43   2.20   1.60   1.07   0.48   0.25   0.02   1313.0
     max        14.56  11.86   9.75   7.49   4.48   2.20   1.22   0.11   1562.5

That being said, another question I have is, out of the vast number of metrics available for Aerospike, which ones are key to monitor for performance, especially wrt reads and read latency?

8

For performance you would need to monitor the histograms. We have curated a few key metrics to determine cluster stability. For performance you would probably want to use the latency info command. You may also find our collectd plugin helpful.

As you can see, the SSD_READ_0 histogram accounts for a small percentage of the overall latency issue. There are other histograms being printed to the logs that would shed more light onto where the latency is going. My best guess from what I do see is that the latency could probably be improved by increasing the number of transaction threads. I’m not sure what you currently have configured but a common SSD configuration is 8 queues and 8 threads per queue. The SSD_READ_0 latency should be the dominant source of server side latency.

9

Ok, we will try to bump up the transaction threads per queue to 8 from 4. See if that helps. Thanks for your assistance.

10

After reading Reading Microbenchmarks and since the issue was happening again on a different aerospike cluster we have in production, I gathered the benchmarks mentioned in the article.

The following benchmarks seem to be the ones showing higher latency:

q_wait:

q_wait
Oct 27 2015 18:49:58
               % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ --------
18:54:58   300   2.93   2.77   2.45   1.93   1.25   0.66   0.26   0.07   1483.8
18:59:58   300   3.13   2.99   2.75   2.32   1.72   1.04   0.35   0.06   1543.0
19:04:58   300   2.48   2.40   2.25   2.00   1.59   1.02   0.37   0.03   1453.5
19:09:58   300   0.73   0.67   0.55   0.35   0.11   0.01   0.00   0.00   1590.4
19:14:58   300   0.59   0.57   0.52   0.44   0.33   0.21   0.09   0.02   1603.3
19:19:58   300   4.86   4.58   4.05   3.15   1.91   0.95   0.37   0.04   1674.5
19:24:58   300   2.08   2.01   1.87   1.63   1.25   0.77   0.28   0.03   1658.4
19:29:58   300   2.04   2.00   1.94   1.80   1.54   1.03   0.39   0.02   1624.7
19:34:59   301   0.08   0.08   0.08   0.07   0.06   0.04   0.02   0.00   1635.9
19:39:59   300   4.89   4.56   3.96   2.92   1.50   0.56   0.23   0.01   1657.3
19:44:59   300   1.86   1.76   1.57   1.25   0.79   0.42   0.14   0.00   1624.3
19:49:59   300   1.36   1.26   1.08   0.76   0.35   0.09   0.03   0.00   1664.5
19:54:59   300   0.98   0.91   0.79   0.58   0.29   0.07   0.01   0.00   1692.6
19:59:59   300   0.43   0.39   0.34   0.22   0.07   0.00   0.00   0.00   1694.0
20:04:59   300   4.06   3.95   3.73   3.35   2.70   1.77   0.62   0.03   1545.8
20:09:59   300   1.26   1.22   1.15   1.03   0.81   0.51   0.19   0.02   1603.4
20:14:59   300   1.07   1.03   0.93   0.77   0.54   0.33   0.14   0.01   1675.9
20:19:59   300   6.41   5.94   5.01   3.43   1.33   0.12   0.01   0.00   1670.2
20:24:59   300   0.36   0.34   0.29   0.21   0.09   0.01   0.00   0.00   1716.1
20:29:59   300   4.82   4.65   4.35   3.79   2.88   1.80   0.84   0.20   1732.8
20:34:59   300   4.53   4.35   4.02   3.39   2.38   1.37   0.61   0.14   1726.8
20:39:59   300   7.99   7.74   7.28   6.45   5.00   3.12   1.37   0.27   1777.0
20:44:59   300   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   1757.2
20:49:59   300   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   1738.3
20:54:59   300   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   1773.1
20:59:59   300   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   1755.7
21:04:59   300   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   1604.0
21:09:59   300   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   1656.3
21:14:59   300   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   1676.6
21:19:59   300   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   1680.3
-------------- ------ ------ ------ ------ ------ ------ ------ ------ --------
     avg         1.96   1.87   1.70   1.39   0.95   0.53   0.21   0.03   1656.0
     max         7.99   7.74   7.28   6.45   5.00   3.12   1.37   0.27   1777.0

reads_tree:

Oct 27 2015 18:49:58
               % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ --------
18:54:58   300   0.68   0.63   0.56   0.47   0.36   0.17   0.03   0.00   1473.4
18:59:58   300   0.47   0.43   0.38   0.32   0.25   0.12   0.04   0.00   1526.1
19:04:58   300   0.37   0.33   0.29   0.25   0.20   0.11   0.05   0.00   1437.9
19:09:58   300   0.27   0.25   0.23   0.19   0.14   0.06   0.00   0.00   1590.3
19:14:58   300   0.11   0.10   0.09   0.07   0.05   0.03   0.01   0.00   1599.8
19:19:58   300   1.07   1.00   0.91   0.76   0.59   0.26   0.04   0.00   1657.5
19:24:58   300   0.25   0.22   0.19   0.15   0.12   0.07   0.02   0.00   1645.0
19:29:58   300   0.10   0.08   0.07   0.06   0.05   0.04   0.03   0.00   1607.0
19:34:59   301   0.01   0.01   0.01   0.00   0.00   0.00   0.00   0.00   1635.2
19:39:59   300   1.03   0.94   0.83   0.68   0.53   0.23   0.02   0.00   1647.4
19:44:59   300   0.29   0.26   0.23   0.19   0.15   0.08   0.02   0.00   1616.9
19:49:59   300   0.27   0.24   0.21   0.18   0.13   0.06   0.01   0.00   1662.8
19:54:59   300   0.17   0.16   0.14   0.12   0.09   0.04   0.00   0.00   1691.2
19:59:59   300   0.11   0.10   0.09   0.08   0.06   0.02   0.00   0.00   1694.0
20:04:59   300   0.44   0.40   0.35   0.29   0.24   0.15   0.08   0.01   1516.8
20:09:59   300   0.13   0.12   0.10   0.08   0.07   0.04   0.01   0.00   1594.7
20:14:59   300   0.14   0.13   0.11   0.09   0.07   0.04   0.01   0.00   1670.0
20:19:59   300   1.27   1.18   1.07   0.88   0.66   0.29   0.01   0.00   1667.6
20:24:59   300   0.06   0.06   0.05   0.04   0.03   0.01   0.00   0.00   1715.9
20:29:59   300   0.45   0.40   0.35   0.29   0.23   0.13   0.04   0.01   1700.0
20:34:59   300   0.44   0.39   0.34   0.28   0.22   0.12   0.03   0.01   1701.8
20:39:59   300   0.61   0.54   0.47   0.39   0.31   0.19   0.08   0.01   1718.5
20:44:59   300   0.01   0.01   0.00   0.00   0.00   0.00   0.00   0.00   1757.2
20:49:59   300   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   1738.3
20:54:59   300   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   1773.1
20:59:59   300   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   1755.7
21:04:59   300   0.01   0.01   0.00   0.00   0.00   0.00   0.00   0.00   1604.0
21:09:59   300   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   1656.3
21:14:59   300   0.01   0.01   0.00   0.00   0.00   0.00   0.00   0.00   1676.6
21:19:59   300   0.01   0.00   0.00   0.00   0.00   0.00   0.00   0.00   1680.3
-------------- ------ ------ ------ ------ ------ ------ ------ ------ --------
     avg         0.29   0.27   0.24   0.20   0.15   0.08   0.02   0.00   1647.0
     max         1.27   1.18   1.07   0.88   0.66   0.29   0.08   0.01   1773.1

reads_storage_read:

Oct 27 2015 18:49:58
               % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ --------
18:54:58   300   8.71   7.95   6.82   5.23   4.05   1.83   0.36   0.05   1018.5
18:59:58   300   6.35   5.75   4.92   3.85   2.98   1.53   0.56   0.04   1054.6
19:04:58   300   4.49   4.04   3.42   2.71   2.15   1.22   0.62   0.05    979.0
19:09:58   300   2.99   2.74   2.40   1.81   1.36   0.56   0.00   0.00   1086.9
19:14:58   300   1.30   1.13   0.92   0.68   0.49   0.26   0.08   0.02   1094.9
19:19:58   300  11.91  10.99   9.69   7.52   5.79   2.75   0.42   0.05   1136.4
19:24:58   300   3.19   2.82   2.33   1.80   1.43   0.81   0.31   0.03   1141.6
19:29:58   300   1.52   1.25   0.99   0.86   0.75   0.64   0.51   0.02   1119.4
19:34:59   301   0.19   0.13   0.09   0.06   0.03   0.02   0.02   0.00   1127.5
19:39:59   300  15.54  14.02  11.97   9.07   6.77   3.07   0.24   0.04   1135.3
19:44:59   300   4.34   3.93   3.43   2.67   2.03   1.01   0.22   0.00   1118.7
19:49:59   300   4.09   3.73   3.23   2.48   1.82   0.82   0.05   0.00   1150.4
19:54:59   300   2.66   2.43   2.12   1.59   1.20   0.56   0.03   0.00   1161.9
19:59:59   300   1.62   1.45   1.26   0.93   0.67   0.29   0.00   0.00   1174.9
20:04:59   300   6.30   5.51   4.51   3.63   2.96   1.92   1.02   0.05   1042.3
20:09:59   300   1.91   1.64   1.36   1.09   0.85   0.55   0.25   0.02   1112.1
20:14:59   300   2.21   1.98   1.67   1.28   0.97   0.49   0.14   0.01   1165.2
20:19:59   300  19.50  18.06  16.01  12.27   9.20   4.17   0.05   0.00   1159.0
20:24:59   300   1.09   0.97   0.83   0.61   0.45   0.20   0.00   0.00   1195.6
20:29:59   300   7.31   6.53   5.53   4.34   3.35   1.95   0.64   0.12   1194.5
20:34:59   300   7.02   6.30   5.34   4.15   3.25   1.85   0.50   0.09   1195.9
20:39:59   300  10.33   9.14   7.56   5.96   4.65   2.94   1.22   0.17   1208.9
20:44:59   300   0.16   0.11   0.05   0.03   0.00   0.00   0.00   0.00   1239.0
20:49:59   300   0.14   0.09   0.04   0.02   0.00   0.00   0.00   0.00   1221.6
20:54:59   300   0.11   0.07   0.03   0.01   0.00   0.00   0.00   0.00   1243.4
20:59:59   300   0.15   0.10   0.06   0.03   0.01   0.00   0.00   0.00   1239.8
21:04:59   300   0.14   0.08   0.04   0.02   0.01   0.00   0.00   0.00   1117.4
21:09:59   300   0.13   0.08   0.04   0.02   0.00   0.00   0.00   0.00   1155.8
21:14:59   300   0.15   0.09   0.05   0.03   0.01   0.00   0.00   0.00   1173.8
21:19:59   300   0.13   0.08   0.04   0.02   0.01   0.00   0.00   0.00   1197.4
-------------- ------ ------ ------ ------ ------ ------ ------ ------ --------
     avg         4.19   3.77   3.23   2.49   1.91   0.98   0.24   0.03   1145.0
     max        19.50  18.06  16.01  12.27   9.20   4.17   1.22   0.17   1243.4

SSD_READ_0 /dev/sdb

Oct 27 2015 18:49:58
               % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ --------
18:54:58   300   8.99   8.20   6.99   5.33   4.14   1.99   0.46   0.08    507.9
18:59:58   300   6.53   5.91   5.03   3.91   2.99   1.57   0.56   0.03    521.7
19:04:58   300   4.56   4.08   3.45   2.76   2.14   1.22   0.66   0.05    486.0
19:09:58   300   2.99   2.73   2.40   1.83   1.37   0.57   0.00   0.00    541.3
19:14:58   300   1.31   1.15   0.92   0.69   0.51   0.28   0.10   0.01    546.2
19:19:58   300  11.82  10.87   9.56   7.45   5.77   2.73   0.48   0.06    569.4
19:24:58   300   3.21   2.80   2.27   1.75   1.34   0.73   0.31   0.01    577.0
19:29:58   300   1.45   1.18   0.93   0.81   0.74   0.59   0.47   0.02    565.8
19:34:59   301   0.18   0.13   0.08   0.05   0.03   0.02   0.02   0.00    562.3
19:39:59   300  14.65  12.90  10.57   7.61   5.38   2.19   0.16   0.02    566.0
19:44:59   300   4.16   3.72   3.21   2.46   1.86   0.88   0.27   0.00    556.9
19:49:59   300   3.85   3.45   2.92   2.21   1.58   0.65   0.05   0.00    574.1
19:54:59   300   2.57   2.32   2.00   1.45   1.08   0.44   0.04   0.00    581.7
19:59:59   300   1.53   1.36   1.17   0.85   0.61   0.22   0.00   0.00    590.4
20:04:59   300   5.69   4.73   3.61   2.75   2.15   1.29   0.73   0.01    521.4
20:09:59   300   1.78   1.50   1.23   0.99   0.77   0.49   0.28   0.02    560.0
20:14:59   300   2.12   1.86   1.55   1.17   0.88   0.43   0.14   0.01    581.4
20:19:59   300  19.08  17.53  15.33  11.52   8.48   3.56   0.06   0.00    583.2
20:24:59   300   1.09   0.97   0.82   0.61   0.45   0.19   0.01   0.00    603.0
20:29:59   300   7.49   6.66   5.61   4.32   3.25   1.84   0.65   0.18    595.1
20:34:59   300   7.45   6.68   5.62   4.34   3.39   1.98   0.49   0.12    600.8
20:39:59   300  10.89   9.76   8.11   6.47   5.07   3.22   1.36   0.25    604.2
20:44:59   300   0.16   0.10   0.05   0.03   0.01   0.00   0.00   0.00    623.5
20:49:59   300   0.12   0.08   0.04   0.01   0.00   0.00   0.00   0.00    616.1
20:54:59   300   0.14   0.09   0.04   0.02   0.00   0.00   0.00   0.00    624.1
20:59:59   300   0.17   0.12   0.07   0.04   0.00   0.00   0.00   0.00    617.5
21:04:59   300   0.15   0.09   0.05   0.03   0.01   0.00   0.00   0.00    562.9
21:09:59   300   0.13   0.09   0.05   0.02   0.00   0.00   0.00   0.00    581.0
21:14:59   300   0.15   0.09   0.05   0.03   0.01   0.00   0.00   0.00    592.7
21:19:59   300   0.13   0.07   0.03   0.02   0.01   0.00   0.00   0.00    602.7
-------------- ------ ------ ------ ------ ------ ------ ------ ------ --------
     avg         4.15   3.71   3.13   2.38   1.80   0.90   0.24   0.03    573.0
     max        19.08  17.53  15.33  11.52   8.48   3.56   1.36   0.25    624.1

And SSD_READ_1 /dev/sdc

Oct 27 2015 18:49:58
               % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128  ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ --------
18:54:58   300   8.43   7.70   6.65   5.13   3.96   1.67   0.26   0.02    510.2
18:59:58   300   6.16   5.59   4.82   3.80   2.96   1.50   0.55   0.06    532.5
19:04:58   300   4.43   4.00   3.40   2.67   2.16   1.22   0.58   0.05    492.5
19:09:58   300   3.00   2.75   2.41   1.80   1.36   0.56   0.00   0.00    544.4
19:14:58   300   1.28   1.12   0.91   0.67   0.48   0.25   0.07   0.03    548.1
19:19:58   300  12.01  11.12   9.84   7.60   5.83   2.77   0.37   0.03    566.0
19:24:58   300   3.17   2.84   2.40   1.86   1.52   0.89   0.31   0.06    563.7
19:29:58   300   1.59   1.32   1.06   0.90   0.77   0.69   0.55   0.03    553.1
19:34:59   301   0.19   0.13   0.09   0.07   0.03   0.03   0.02   0.00    564.4
19:39:59   300  16.43  15.14  13.37  10.52   8.16   3.95   0.31   0.06    568.6
19:44:59   300   4.52   4.15   3.66   2.88   2.19   1.15   0.18   0.00    560.9
19:49:59   300   4.33   4.01   3.55   2.74   2.07   0.99   0.04   0.00    575.8
19:54:59   300   2.76   2.53   2.25   1.74   1.32   0.68   0.02   0.00    579.7
19:59:59   300   1.71   1.54   1.34   1.01   0.74   0.36   0.00   0.00    584.0
20:04:59   300   6.92   6.29   5.41   4.52   3.77   2.54   1.31   0.09    519.8
20:09:59   300   2.04   1.78   1.49   1.19   0.95   0.61   0.23   0.02    551.1
20:14:59   300   2.30   2.09   1.78   1.38   1.06   0.56   0.14   0.01    582.8
20:19:59   300  19.94  18.61  16.71  13.04   9.94   4.79   0.04   0.00    574.9
20:24:59   300   1.08   0.96   0.84   0.61   0.44   0.21   0.00   0.00    592.0
20:29:59   300   7.13   6.40   5.46   4.37   3.45   2.05   0.63   0.07    598.7
20:34:59   300   6.61   5.92   5.06   3.96   3.12   1.73   0.51   0.07    594.3
20:39:59   300   9.77   8.53   7.02   5.46   4.23   2.66   1.07   0.10    603.6
20:44:59   300   0.17   0.11   0.05   0.02   0.00   0.00   0.00   0.00    614.8
20:49:59   300   0.15   0.10   0.05   0.02   0.00   0.00   0.00   0.00    604.7
20:54:59   300   0.08   0.05   0.02   0.01   0.00   0.00   0.00   0.00    618.6
20:59:59   300   0.13   0.08   0.05   0.03   0.01   0.00   0.00   0.00    621.7
21:04:59   300   0.12   0.07   0.04   0.02   0.00   0.00   0.00   0.00    553.8
21:09:59   300   0.13   0.07   0.04   0.02   0.00   0.00   0.00   0.00    574.2
21:14:59   300   0.14   0.09   0.05   0.02   0.00   0.00   0.00   0.00    580.4
21:19:59   300   0.13   0.09   0.05   0.02   0.01   0.00   0.00   0.00    593.9
-------------- ------ ------ ------ ------ ------ ------ ------ ------ --------
     avg         4.23   3.84   3.33   2.60   2.02   1.06   0.24   0.02    570.0
     max        19.94  18.61  16.71  13.04   9.94   4.79   1.31   0.10    621.7

I guess what the above information tells us is that the latency is attributed to the two SSD drives of that instance being slower than normal, which I guess is a question to AWS.

During the time that the latency is high, we also notice a high CPU load on that aerospike node and higher number of client connections to it. I don’t know if that can tell us why the reads are slow or explain why the SSDs might show slower reads (node gets overloaded).

Are there any other histograms I can gather to see if higher CPU load or higher number of connections can result to a degradation in read performance?

Apart from a bad AWS EC2 instance ephemeral drive, are there any cluster or node level operations (re-balancing of the keys, defrag of SSD volumes) that could explain a higher CPU load? What metrics/histograms I should be looking at, to catch issues during those operations? The problem seems to be happening at random times for about 1-2 hours each time and then disappear, that’s why I am asking for any cluster/node level operations that could be happening at specific intervals.

Note: We haven’t transitioned to 8 transaction queues per thread, yet.

Thank you again for your assistance with these issues, and sorry for the lengthy post.

11

Just curious, did you pre-warm these drives?

Migrations have high potential to add latency to reads for two reasons. Migrations increase the load on the network and drives (even more so for non data-in-memory namespaces). If there are multiple version of a given partition write transactions will need to read all versions before applying a write.

Defrag is a continuous background threads per drive. As blocks on the drive fall below the defrag-lwm-pct that block will be defragged. It isn’t normal that defrag would spike, but we do log for each drive the rate at which defrag is going.

There are also expiration and eviction which are handled by nsup, which in older version had an increased effect on latency but no longer.

I suspect the q_wait is a result of the drive’s performance dips. Each thread only services a single transaction at a time and with slow disks it is easy for all threads to be servicing other requests.

The increased cpu load and client connections may be partially explained by clients is timing out transactions which cause the client to open new sockets requiring increased processing on the server to open the sockets.