False histogram dump reads in logs build 3.5.4


#1

Hy,
“Histogram dump: reads” in aerospike.log file are false.
My configuration : 3 servers with Aerospike Community Edition build 3.5.4, replication factor of 2 with local SSD on GCE.
We have actually a little read activity on the cluster : about 600-800 reads per seconds on each node.
When looking in AMC, we can see the read activity at this rate, but analyzing the log file, there is a big problem, values are really out

node 1 : 
Apr 08 2015 12:11:25 GMT: INFO (info): (hist.c::137) histogram dump: reads (11 total) msec
Apr 08 2015 12:11:25 GMT: INFO (info): (hist.c::163)  (00: 0000000011)

node 2 : 
Apr 08 2015 12:11:43 GMT: INFO (info): (hist.c::137) histogram dump: reads (0 total) msec<br>
Apr 08 2015 12:11:43 GMT: INFO (info): (hist.c::137) histogram dump: writes_master (0 total) msec

node 3 : 
Apr 08 2015 12:11:52 GMT: INFO (info): (hist.c::137) histogram dump: reads (3 total) msec
Apr 08 2015 12:11:52 GMT: INFO (info): (hist.c::163)  (00: 0000000003) 

Seem's like there is a log bug no ? I should have about 600 to 800 reads as shown by AMC.

Best regards.

Emmanuel


#2

are there any proxy happening in the cluster? are there any errors reported in stats? (try doing an asinfo -v “statistics” -l, and see if there is any err_xxx counts)


#3

Hy,

No I can’t see any errors. No proxy either, we are using GCE and nodes are all in the same zone, using local SSDs.

Stats : asinfo -v "statistics" -l
cluster_size=3
cluster_key=1E9C2CE97A912A9B
cluster_integrity=true
objects=225083283
sub-records=0
total-bytes-disk=402653184000
used-bytes-disk=176786812544
free-pct-disk=56
total-bytes-memory=26843545600
used-bytes-memory=14405330112
data-used-bytes-memory=0
index-used-bytes-memory=14405330112
sindex-used-bytes-memory=0
free-pct-memory=46
stat_read_reqs=381260667
stat_read_reqs_xdr=0
stat_read_success=381260667
stat_read_errs_notfound=0
stat_read_errs_other=0
stat_write_reqs=279814360
stat_write_reqs_xdr=0
stat_write_success=279813299
stat_write_errs=0
stat_xdr_pipe_writes=0
stat_xdr_pipe_miss=0
stat_delete_success=1543
stat_rw_timeout=1068
udf_read_reqs=381260656
udf_read_success=381260654
udf_read_errs_other=2
udf_write_reqs=279813589
udf_write_success=279813588
udf_write_err_others=1
udf_delete_reqs=0
udf_delete_success=0
udf_delete_err_others=0
udf_lua_errs=0
udf_scan_rec_reqs=0
udf_query_rec_reqs=0
udf_replica_writes=0
stat_proxy_reqs=2
stat_proxy_reqs_xdr=0
stat_proxy_success=2
stat_proxy_errs=0
stat_ldt_proxy=0
stat_cluster_key_trans_to_proxy_retry=0
stat_cluster_key_transaction_reenqueue=0
stat_slow_trans_queue_push=0
stat_slow_trans_queue_pop=0
stat_slow_trans_queue_batch_pop=0
stat_cluster_key_regular_processed=0
stat_cluster_key_prole_retry=0
stat_cluster_key_err_ack_dup_trans_reenqueue=0
stat_cluster_key_partition_transaction_queue_count=0
stat_cluster_key_err_ack_rw_trans_reenqueue=0
stat_expired_objects=0
stat_evicted_objects=0
stat_deleted_set_objects=0
stat_evicted_set_objects=0
stat_evicted_objects_time=0
stat_zero_bin_records=0
stat_nsup_deletes_not_shipped=0
err_tsvc_requests=0
err_out_of_space=0
err_duplicate_proxy_request=0
err_rw_request_not_found=312
err_rw_pending_limit=0
err_rw_cant_put_unique=0
fabric_msgs_sent=562176214
fabric_msgs_rcvd=562176198
paxos_principal=BB92370F00A0142
migrate_msgs_sent=31117
migrate_msgs_recv=52478
migrate_progress_send=0
migrate_progress_recv=0
migrate_num_incoming_accepted=8250
migrate_num_incoming_refused=0
queue=0
transactions=816302713
reaped_fds=1500663
tscan_initiate=57
tscan_pending=0
tscan_succeeded=57
tscan_aborted=0
batch_initiate=0
batch_queue=0
batch_tree_count=0
batch_timeout=0
batch_errors=0
info_queue=0
delete_queue=0
proxy_in_progress=0
proxy_initiate=2
proxy_action=24
proxy_retry=0
proxy_retry_q_full=0
proxy_unproxy=0
proxy_retry_same_dest=0
proxy_retry_new_dest=0
write_master=279814360
write_prole=282309292
read_dup_prole=0
rw_err_dup_internal=0
rw_err_dup_cluster_key=0
rw_err_dup_send=0
rw_err_write_internal=0
rw_err_write_cluster_key=0
rw_err_write_send=0
rw_err_ack_internal=0
rw_err_ack_nomatch=1061
rw_err_ack_badnode=0
client_connections=421
waiting_transactions=0
tree_count=0
record_refs=225138436
record_locks=0
migrate_tx_objs=0
migrate_rx_objs=0
ongoing_write_reqs=0
err_storage_queue_full=0
partition_actual=1369
partition_replica=1381
partition_desync=0
partition_absent=1346
partition_object_count=225083283
partition_ref_count=4097
system_free_mem_pct=52
sindex_ucgarbage_found=0
sindex_gc_locktimedout=0
sindex_gc_inactivity_dur=0
sindex_gc_activity_dur=0
sindex_gc_list_creation_time=0
sindex_gc_list_deletion_time=0
sindex_gc_objects_validated=0
sindex_gc_garbage_found=0
sindex_gc_garbage_cleaned=0
system_swapping=false
err_replica_null_node=0
err_replica_non_null_node=0
err_sync_copy_null_node=0
err_sync_copy_null_master=0
storage_defrag_corrupt_record=0
err_write_fail_prole_unknown=0
err_write_fail_prole_generation=0
err_write_fail_unknown=0
err_write_fail_key_exists=0
err_write_fail_generation=0
err_write_fail_generation_xdr=0
err_write_fail_bin_exists=0
err_write_fail_parameter=0
err_write_fail_incompatible_type=0
err_write_fail_noxdr=0
err_write_fail_prole_delete=0
err_write_fail_not_found=0
err_write_fail_key_mismatch=0
err_write_fail_record_too_big=0
err_write_fail_bin_name=0
err_write_fail_bin_not_found=0
err_write_fail_forbidden=0
stat_duplicate_operation=0
uptime=1214671
stat_write_errs_notfound=0
stat_write_errs_other=0
heartbeat_received_self=0
heartbeat_received_foreign=23180608
query_reqs=0
query_success=0
query_fail=0
query_abort=0
query_avg_rec_count=0
query_short_queue_full=0
query_long_queue_full=0
query_short_running=0
query_long_running=0
query_tracked=0
query_agg=0
query_agg_success=0
query_agg_err=0
query_agg_abort=0
query_agg_avg_rec_count=0
query_lookups=0
query_lookup_success=0
query_lookup_err=0
query_lookup_abort=0
query_lookup_avg_rec_count=0

Result of writes :

 # asloglatency -l /var/log/aerospike/aerospike.log -h writes_master
writes_master
Apr 10 2015 14:39:37
               % > (ms)
slice-to (sec)      1      8     64  ops/sec
-------------- ------ ------ ------ --------
14:39:47    10   0.00   0.00   0.00      0.0
14:39:57    10   0.00   0.00   0.00      0.0
14:40:07    10   0.00   0.00   0.00      0.0
14:40:17    10   0.00   0.00   0.00      0.0
14:40:27    10   0.00   0.00   0.00      0.0
14:40:37    10   0.00   0.00   0.00      0.0
14:40:47    10   0.00   0.00   0.00      0.0
14:40:57    10   0.00   0.00   0.00      0.0
-------------- ------ ------ ------ --------
     avg         0.00   0.00   0.00      0.0
     max         0.00   0.00   0.00      0.0

#4

If you can, can we have both an asloglatency dump for the 3 nodes for a few 10-second time-slices, as well as the AMC screen shot at the same time?


#5

Hello,

Jumping in for my colleague Emmanuel here. Please find below the information you asked for:

-001:~ $ sudo asloglatency -l /var/log/aerospike/aerospike.log -h writes_master -t 10
writes_master
Apr 21 2015 13:58:56
               % > (ms)
slice-to (sec)      1      8     64  ops/sec
-------------- ------ ------ ------ --------
13:59:06    10   0.00   0.00   0.00      0.0
13:59:16    10   0.00   0.00   0.00      0.0
13:59:26    10   0.00   0.00   0.00      0.0
13:59:36    10   0.00   0.00   0.00      0.0
13:59:46    10   0.00   0.00   0.00      0.0
13:59:56    10   0.00   0.00   0.00      0.0
14:00:06    10   0.00   0.00   0.00      0.0
14:00:16    10   0.00   0.00   0.00      0.0
14:00:26    10   0.00   0.00   0.00      0.0
14:00:36    10   0.00   0.00   0.00      0.0
14:00:46    10   0.00   0.00   0.00      0.0
14:00:56    10   0.00   0.00   0.00      0.0
14:01:06    10   0.00   0.00   0.00      0.0
14:01:16    10   0.00   0.00   0.00      0.0
14:01:26    10   0.00   0.00   0.00      0.0
14:01:36    10   0.00   0.00   0.00      0.0
14:01:46    10   0.00   0.00   0.00      0.0
14:01:56    10   0.00   0.00   0.00      0.0
14:02:06    10   0.00   0.00   0.00      0.0
14:02:16    10   0.00   0.00   0.00      0.0
14:02:26    10   0.00   0.00   0.00      0.0
14:02:36    10   0.00   0.00   0.00      0.0
14:02:46    10   0.00   0.00   0.00      0.0
14:02:56    10   0.00   0.00   0.00      0.0
14:03:06    10   0.00   0.00   0.00      0.0
14:03:16    10   0.00   0.00   0.00      0.0
14:03:26    10   0.00   0.00   0.00      0.0
14:03:36    10   0.00   0.00   0.00      0.0
14:03:46    10   0.00   0.00   0.00      0.0
14:03:56    10   0.00   0.00   0.00      0.0
14:04:06    10   0.00   0.00   0.00      0.0
14:04:16    10   0.00   0.00   0.00      0.0
14:04:26    10   0.00   0.00   0.00      0.0
14:04:36    10   0.00   0.00   0.00      0.0
14:04:46    10   0.00   0.00   0.00      0.0
14:04:56    10   0.00   0.00   0.00      0.0
14:05:06    10   0.00   0.00   0.00      0.0
14:05:16    10   0.00   0.00   0.00      0.0
14:05:26    10   0.00   0.00   0.00      0.0
14:05:36    10   0.00   0.00   0.00      0.0
14:05:46    10   0.00   0.00   0.00      0.0
14:05:56    10   0.00   0.00   0.00      0.0
14:06:06    10   0.00   0.00   0.00      0.0
-------------- ------ ------ ------ --------
     avg         0.00   0.00   0.00      0.0
     max         0.00   0.00   0.00      0.0

*************

002:~ $ sudo asloglatency -l /var/log/aerospike/aerospike.log -h writes_master -t 10
writes_master
Apr 21 2015 13:59:54
               % > (ms)
slice-to (sec)      1      8     64  ops/sec
-------------- ------ ------ ------ --------
14:00:04    10   0.00   0.00   0.00      0.0
14:00:14    10   0.00   0.00   0.00      0.0
14:00:24    10   0.00   0.00   0.00      0.0
14:00:34    10   0.00   0.00   0.00      0.0
14:00:44    10   0.00   0.00   0.00      0.0
14:00:54    10   0.00   0.00   0.00      0.0
14:01:04    10   0.00   0.00   0.00      0.0
14:01:14    10   0.00   0.00   0.00      0.0
14:01:24    10   0.00   0.00   0.00      0.0
14:01:34    10   0.00   0.00   0.00      0.0
14:01:44    10   0.00   0.00   0.00      0.0
14:01:54    10   0.00   0.00   0.00      0.0
14:02:04    10   0.00   0.00   0.00      0.0
14:02:14    10   0.00   0.00   0.00      0.0
14:02:24    10   0.00   0.00   0.00      0.0
14:02:34    10   0.00   0.00   0.00      0.0
14:02:44    10   0.00   0.00   0.00      0.0
14:02:54    10   0.00   0.00   0.00      0.0
14:03:04    10   0.00   0.00   0.00      0.0
14:03:14    10   0.00   0.00   0.00      0.0
14:03:24    10   0.00   0.00   0.00      0.0
14:03:34    10   0.00   0.00   0.00      0.0
14:03:44    10   0.00   0.00   0.00      0.0
14:03:54    10   0.00   0.00   0.00      0.0
14:04:04    10   0.00   0.00   0.00      0.0
14:04:14    10   0.00   0.00   0.00      0.0
14:04:24    10   0.00   0.00   0.00      0.0
14:04:34    10   0.00   0.00   0.00      0.0
14:04:44    10   0.00   0.00   0.00      0.0
14:04:54    10   0.00   0.00   0.00      0.0
14:05:04    10   0.00   0.00   0.00      0.0
14:05:14    10   0.00   0.00   0.00      0.0
14:05:24    10   0.00   0.00   0.00      0.0
14:05:34    10   0.00   0.00   0.00      0.0
14:05:44    10   0.00   0.00   0.00      0.0
14:05:54    10   0.00   0.00   0.00      0.0
14:06:04    10   0.00   0.00   0.00      0.0
14:06:14    10   0.00   0.00   0.00      0.0
-------------- ------ ------ ------ --------
     avg         0.00   0.00   0.00      0.0
     max         0.00   0.00   0.00      0.0

**********

003:~ $ sudo asloglatency -l /var/log/aerospike/aerospike.log -h writes_master -t 10
writes_master
Apr 21 2015 14:00:03
               % > (ms)
slice-to (sec)      1      8     64  ops/sec
-------------- ------ ------ ------ --------
14:00:13    10   0.00   0.00   0.00      0.0
14:00:23    10   0.00   0.00   0.00      0.0
14:00:33    10   0.00   0.00   0.00      0.0
14:00:43    10   0.00   0.00   0.00      0.0
14:00:53    10   0.00   0.00   0.00      0.0
14:01:03    10   0.00   0.00   0.00      0.0
14:01:13    10   0.00   0.00   0.00      0.0
14:01:23    10   0.00   0.00   0.00      0.0
14:01:33    10   0.00   0.00   0.00      0.0
14:01:43    10   0.00   0.00   0.00      0.0
14:01:53    10   0.00   0.00   0.00      0.0
14:02:03    10   0.00   0.00   0.00      0.0
14:02:13    10   0.00   0.00   0.00      0.0
14:02:23    10   0.00   0.00   0.00      0.0
14:02:33    10   0.00   0.00   0.00      0.0
14:02:43    10   0.00   0.00   0.00      0.0
14:02:53    10   0.00   0.00   0.00      0.0
14:03:03    10   0.00   0.00   0.00      0.0
14:03:13    10   0.00   0.00   0.00      0.0
14:03:23    10   0.00   0.00   0.00      0.0
14:03:33    10   0.00   0.00   0.00      0.0
14:03:43    10   0.00   0.00   0.00      0.0
14:03:53    10   0.00   0.00   0.00      0.0
14:04:03    10   0.00   0.00   0.00      0.0
14:04:13    10   0.00   0.00   0.00      0.0
14:04:23    10   0.00   0.00   0.00      0.0
14:04:33    10   0.00   0.00   0.00      0.0
14:04:43    10   0.00   0.00   0.00      0.0
14:04:53    10   0.00   0.00   0.00      0.0
14:05:04    11   0.00   0.00   0.00      0.0
14:05:14    10   0.00   0.00   0.00      0.0
14:05:24    10   0.00   0.00   0.00      0.0
14:05:34    10   0.00   0.00   0.00      0.0
14:05:44    10   0.00   0.00   0.00      0.0
14:05:54    10   0.00   0.00   0.00      0.0
14:06:04    10   0.00   0.00   0.00      0.0
14:06:14    10   0.00   0.00   0.00      0.0
-------------- ------ ------ ------ --------
     avg         0.00   0.00   0.00      0.0
     max         0.00   0.00   0.00      0.0

----

Screenshot of the AMC: https://lh3.googleusercontent.com/aOymmTUXgxaYiNKG-r2avJvWKvo7sPFy8094tFbgXmxRasi80-eLK4R45XxO2N5JKOieEB4QMN_awYw=w1256-h539


#6

Hy,

Finally we found the solution. We are updating data in a map in a single bin using udf functions. The histogram to be analyse is udf and not writes_master. $ asloglatency -l /var/log/aerospike/aerospike.log -h udf

# asloglatency -l /var/log/aerospike/aerospike.log -h udf
udf
May 01 2015 15:26:06
           % > (ms)
slice-to (sec)      1      8     64  ops/sec
-------------- ------ ------ ------ --------
15:26:16    10   1.45   0.06   0.00    179.5
15:26:26    10   0.47   0.00   0.00    170.8
15:26:36    10   1.02   0.00   0.00    196.3
-------------- ------ ------ ------ --------
 avg         0.98   0.02   0.00    182.0
 max         1.45   0.06   0.00    196.3