evinet
April 8, 2015, 12:14pm
1
Hy,
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
wchu
April 10, 2015, 6:51am
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)
evinet
April 10, 2015, 2:44pm
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
wchu
April 15, 2015, 11:32pm
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?
dkoch
April 21, 2015, 2:49pm
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
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
1 Like