What does client_write_timeout stands for?

Hi All,

I am using replication on 2 node setup with client write policy set to AS_POLICY_COMMIT_LEVEL_ALL.
Total timeout on client is set to 0 so I guess transaction-max-ns (which defaults to 1 sec) would be honored on server side. On client side I see timeout errors.

E1122 11:15:34.175964    61 AeroOps.cpp:203] WriteListener::error msg:AEROSPIKE_ERR_TIMEOUT, err code:9



Tried to get sense of context in which timeout could be happening.

Admin> show statistics like timeout
~~~~~~~~~Service Statistics (2019-11-22 16:18:50 UTC)~~~~~~~~
NODE               :   192.168.4.227:3000   192.168.4.27:3000   
batch_index_timeout:   0                    0                   
batch_timeout      :   0                    0                   

~~~~~~~CLEAN Namespace Statistics (2019-11-22 16:18:50 UTC)~~~~~~
NODE                   :   192.168.4.227:3000   192.168.4.27:3000   
batch_sub_proxy_timeout:   0                    0                   
batch_sub_read_timeout :   0                    0                   
batch_sub_tsvc_timeout :   0                    0                   
client_delete_timeout  :   0                    0                   
client_proxy_timeout   :   0                    0                   
client_read_timeout    :   0                    0                   
client_tsvc_timeout    :   0                    0                   
client_udf_timeout     :   0                    0                   
client_write_timeout   :   797                  0                   
re_repl_timeout        :   0                    0                   
udf_sub_tsvc_timeout   :   0                    0                   
udf_sub_udf_timeout    :   0                    0                   
xdr_delete_timeout     :   0                    0                   
xdr_write_timeout      :   0                    0                   

~~~~~~~DIRTY Namespace Statistics (2019-11-22 16:18:50 UTC)~~~~~~
NODE                   :   192.168.4.227:3000   192.168.4.27:3000   
batch_sub_proxy_timeout:   0                    0                   
batch_sub_read_timeout :   0                    0                   
batch_sub_tsvc_timeout :   0                    0                   
client_delete_timeout  :   0                    0                   
client_proxy_timeout   :   0                    0                   
client_read_timeout    :   0                    0                   
client_tsvc_timeout    :   0                    0                   
client_udf_timeout     :   0                    0                   
client_write_timeout   :   599                  37                  
re_repl_timeout        :   0                    0                   
udf_sub_tsvc_timeout   :   0                    0                   
udf_sub_udf_timeout    :   0                    0                   
xdr_delete_timeout     :   0                    0                   
xdr_write_timeout      :   0                    0                   

Admin> 

I see some writes got succeeded though.

~~~~~~~~~~~~~DIRTY Namespace Statistics (2019-11-22 14:57:19 UTC)~~~~~~~~~~~~
NODE                               :   192.168.4.227:3000   192.168.4.27:3000   
allow-nonxdr-writes                :   true                 true                
allow-xdr-writes                   :   true                 true                
client_lang_write_success          :   0                    0                   
client_write_error                 :   0                    0                   
client_write_success               :   2292                 73                  
client_write_timeout               :   530                  12    
  1. Whats does client_write_timeout stands for?

  2. Any configuration option to handle it?

  3. Why writes are not distributed evenly across 2 nodes?

I enabled debug logs for fabric but couldn’t confirm if these are replica write failures.

Thanks,
Mahaveer

My (wild) guess would be for issues / latency between the 2 nodes and maybe connectivity issues between the client and one of the node. Looking at the logs and the configuration should provide more insight.

These are writes (puts) from the client that resulted in a timeout.

Writes for a particular record are always sent to the node acting as master for a the partition that record belongs to. Likely the client_write_success imbalance is due to a hot record.

Hi Meher & Kevin,
Thanks for prompt response.

Admin> show statistics like fd
~~~~Service Statistics (2019-11-23 01:47:17 UTC)~~~~
NODE      :   192.168.4.227:3000   192.168.4.27:3000   
reaped_fds:   10337                504                 

Admin> root@photon-machine:/# asloglatency  -f head -t 600 -n 10 -e 1 -N DIRTY  -h write  
Histogram : {DIRTY}-write
Log       : /var/log/aerospike/aerospike.log
From      : 2019-11-22 11:04:14

Nov 22 2019 11:16:55
               % > (ms)
slice-to (sec)      1      2      4      8     16     32     64    128    256    512    ops/sec
-------------- ------ ------ ------ ------ ------ ------ ------ ------ ------ ------ ----------
11:26:55   600  99.77  34.41   4.85   2.31   1.39   0.46   0.00   0.00   0.00   0.00        0.7
11:36:56   601  98.75  37.50  16.25   8.13   4.38   2.08   0.42   0.00   0.00   0.00        0.8
11:46:56   600   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00        0.0
11:56:56   600   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00        0.0
12:06:56   600   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00   0.00        0.0
12:16:56   600 100.00  48.83  16.63   7.89   4.48   2.13   0.85   0.00   0.00   0.00        0.8
12:26:57   601  99.13  44.47  12.15   3.47   1.08   0.65   0.00   0.00   0.00   0.00        0.8
12:36:57   600  98.36  36.44  11.51   4.93   1.64   1.64   1.37   0.00   0.00   0.00        0.6


In non-cluster mode, I don’t see timeouts.

  1. Which logs should be looked into?
  2. Any config option changes which can be tried out?
  3. In case of replication, which CONTEXT to enable debug logs for? So far I’ve tried socket, rw, fabric.

Thanks.

You might want to enable write microbenchmakrs and look for write-repl-write in aerospike.log in the clustered mode:

asinfo -v 'set-config:context=namespace;id=DIRTY;enable-benchmarks-write=true'

Log-analyzer> histogram -h write-repl-write -N DIRTY -b 8 -d 900 -f -14500 -p 100
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~DIRTY - write-repl-write Latency (Page-1)~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
NODE                :   bcc6e4f99565000    .        .         .          .           .            .         |   
.                   :   % >1ms             % >8ms   % >64ms   % >512ms   % >4096ms   % >32768ms   ops/sec   |   
Nov 23 2019 03:04:40:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:50:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:05:00:   90.00              0.00     0.00      0.00       0.00        0.00         3.0       |   
Nov 23 2019 03:05:10:   96.03              5.56     0.00      0.00       0.00        0.00         12.6      |   
Nov 23 2019 03:05:20:   98.82              5.88     0.00      0.00       0.00        0.00         8.5       |   
Nov 23 2019 03:05:30:   100.00             10.53    5.26      0.00       0.00        0.00         3.8       |   
Nov 23 2019 03:05:40:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:05:50:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:06:00:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
  1. Does it mean NW between cluster nodes is slow?
  2. Any configuration option to increase efficiency?

Here is the write path pre ver 4.7. Mostly still the same. Look at all other microbenchmarks and identify the source of the latency. They are all captured once you turn the write microbenchmark on. Confirm - write-repl-write is dominant source.

Thanks for help.
Still I’ve few queries.

  1. How to get fabric network connection performance numbers?
  2. Parameters to look into NIC configuration from aerospike point of view?

Here is the log of all the micro-bench-marking for write.

Log-analyzer> histogram -h write-start -N DIRTY -b 8 -d 250 -f -14300 -p 100
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~DIRTY - write-start Latency (Page-1)~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
NODE                :   bcc6e4f99565000    .        .         .          .           .            .         |   
.                   :   % >1ms             % >8ms   % >64ms   % >512ms   % >4096ms   % >32768ms   ops/sec   |   
Nov 23 2019 03:02:30:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:02:40:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:02:50:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:00:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:10:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:20:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:30:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:40:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:50:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:00:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:10:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:20:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:30:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:40:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:50:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:05:00:   0.00               0.00     0.00      0.00       0.00        0.00         3.8       |   
Nov 23 2019 03:05:10:   2.58               0.65     0.00      0.00       0.00        0.00         15.5      |   
Nov 23 2019 03:05:20:   1.92               0.00     0.00      0.00       0.00        0.00         10.4      |   
Nov 23 2019 03:05:30:   0.00               0.00     0.00      0.00       0.00        0.00         4.5       |   
Nov 23 2019 03:05:40:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:05:50:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:06:00:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:06:10:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:06:20:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
avg                 :   0.19               0.03     0.00      0.00       0.00        0.00         1.0       |   
max                 :   2.58               0.65     0.00      0.00       0.00        0.00         15.5      |   

Log-analyzer> histogram -h write-repl-write -N DIRTY -b 8 -d 250 -f -14300 -p 100
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~DIRTY - write-repl-write Latency (Page-1)~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
NODE                :   bcc6e4f99565000    .        .         .          .           .            .         |   
.                   :   % >1ms             % >8ms   % >64ms   % >512ms   % >4096ms   % >32768ms   ops/sec   |   
Nov 23 2019 03:02:30:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:02:40:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:02:50:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:00:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:10:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:20:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:30:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:40:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:50:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:00:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:10:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:20:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:30:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:40:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:50:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:05:00:   90.00              0.00     0.00      0.00       0.00        0.00         3.0       |   
Nov 23 2019 03:05:10:   96.03              5.56     0.00      0.00       0.00        0.00         12.6      |   
Nov 23 2019 03:05:20:   98.82              5.88     0.00      0.00       0.00        0.00         8.5       |   
Nov 23 2019 03:05:30:   100.00             10.53    5.26      0.00       0.00        0.00         3.8       |   
Nov 23 2019 03:05:40:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:05:50:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:06:00:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:06:10:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:06:20:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
avg                 :   16.04              0.92     0.22      0.00       0.00        0.00         1.0       |   
max                 :   100.00             10.53    5.26      0.00       0.00        0.00         12.6      |   

Log-analyzer> histogram -h write-dup-res -N DIRTY -b 8 -d 250 -f -14300 -p 100
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~DIRTY - write-dup-res Latency (Page-1)~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
NODE                :   bcc6e4f99565000    .        .         .          .           .            .         |   
.                   :   % >1ms             % >8ms   % >64ms   % >512ms   % >4096ms   % >32768ms   ops/sec   |   
Nov 23 2019 03:02:30:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:02:40:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:02:50:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:00:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:10:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:20:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:30:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:40:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:50:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:00:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:10:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:20:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:30:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:40:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:50:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:05:00:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:05:10:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:05:20:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:05:30:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:05:40:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:05:50:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:06:00:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:06:10:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:06:20:   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.0       |   
max                 :   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   

Log-analyzer> histogram -h write-master -N DIRTY -b 8 -d 250 -f -14300 -p 100
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~DIRTY - write-master Latency (Page-1)~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
NODE                :   bcc6e4f99565000    .        .         .          .           .            .         |   
.                   :   % >1ms             % >8ms   % >64ms   % >512ms   % >4096ms   % >32768ms   ops/sec   |   
Nov 23 2019 03:02:30:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:02:40:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:02:50:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:00:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:10:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:20:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:30:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:40:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:50:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:00:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:10:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:20:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:30:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:40:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:50:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:05:00:   5.26               5.26     0.00      0.00       0.00        0.00         3.8       |   
Nov 23 2019 03:05:10:   2.58               1.94     0.00      0.00       0.00        0.00         15.5      |   
Nov 23 2019 03:05:20:   0.00               0.00     0.00      0.00       0.00        0.00         10.4      |   
Nov 23 2019 03:05:30:   0.00               0.00     0.00      0.00       0.00        0.00         4.5       |   
Nov 23 2019 03:05:40:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:05:50:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:06:00:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:06:10:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:06:20:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
avg                 :   0.33               0.30     0.00      0.00       0.00        0.00         1.0       |   
max                 :   5.26               5.26     0.00      0.00       0.00        0.00         15.5      |   

Log-analyzer> histogram -h write-restart -N DIRTY -b 8 -d 250 -f -14300 -p 100
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~DIRTY - write-restart Latency (Page-1)~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
NODE                :   bcc6e4f99565000    .        .         .          .           .            .         |   
.                   :   % >1ms             % >8ms   % >64ms   % >512ms   % >4096ms   % >32768ms   ops/sec   |   
Nov 23 2019 03:02:30:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:02:40:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:02:50:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:00:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:10:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:20:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:30:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:40:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:50:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:00:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:10:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:20:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:30:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:40:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:50:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:05:00:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:05:10:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:05:20:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:05:30:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:05:40:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:05:50:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:06:00:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:06:10:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:06:20:   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.0       |   
max                 :   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   

Log-analyzer> histogram -h write-response -N DIRTY -b 8 -d 250 -f -14300 -p 100
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~DIRTY - write-response Latency (Page-1)~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
NODE                :   bcc6e4f99565000    .        .         .          .           .            .         |   
.                   :   % >1ms             % >8ms   % >64ms   % >512ms   % >4096ms   % >32768ms   ops/sec   |   
Nov 23 2019 03:02:30:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:02:40:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:02:50:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:00:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:10:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:20:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:30:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:40:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:03:50:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:00:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:10:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:20:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:30:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:40:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:04:50:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:05:00:   0.00               0.00     0.00      0.00       0.00        0.00         3.0       |   
Nov 23 2019 03:05:10:   0.00               0.00     0.00      0.00       0.00        0.00         12.6      |   
Nov 23 2019 03:05:20:   1.18               0.00     0.00      0.00       0.00        0.00         8.5       |   
Nov 23 2019 03:05:30:   0.00               0.00     0.00      0.00       0.00        0.00         3.8       |   
Nov 23 2019 03:05:40:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:05:50:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:06:00:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:06:10:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
Nov 23 2019 03:06:20:   0.00               0.00     0.00      0.00       0.00        0.00         0.0       |   
avg                 :   0.05               0.00     0.00      0.00       0.00        0.00         1.0       |   
max                 :   1.18               0.00     0.00      0.00       0.00        0.00         12.6      |   

Log-analyzer> 

Fabric has its own microbenchmarks that you can turn on. Read more here - in fabric transaction analysis: https://www.aerospike.com/docs/operations/monitor/latency/index.html

If you had hot-key writes, you will see high write-restart total count in the logs, grep for write-restart and it will show you total count - and latency data. The histograms are computed from those raw counts.

What’s interesting is that you have a few high write-master also. What is your configuration for this namespace in the aeropsike.conf file? What is your server version?

I see some high write-response numbers too. That means the socket send buffer is getting full because of a slow network connection to the client. Looks like you definitely have some network issues.

© 2015 Copyright Aerospike, Inc. | All rights reserved. Creators of the Aerospike Database.