Expiration falling behind

@kporter, i been also facing the same issues at my setup, as i use single AS community server, we have high volumes of data and it is stored with 300seconds on ttl on each record, but it never expires any, here is a snapshot of some metrics which might help you.

[ec2-user@ip-172-30-1-180 ~]$ cat /etc/aerospike/aerospike.conf
# Aerospike database configuration file.

service {
	user root
	group root
	paxos-single-replica-limit 1 # Number of nodes where the replica count is automatically reduced to 1.
	pidfile /newvolume/var/run/aerospike/asd.pid
	service-threads 16
	transaction-queues 16
	transaction-threads-per-queue 4
	proto-fd-max 99999
	proto-fd-idle-ms 10000
	nsup-period 10
}

logging {
	# Log file must be an absolute path.
	file /newvolume/var/log/aerospike/aerospike.log {
		context any info
	}
}

network {
	service {
		address any
		port 3000
		reuse-address
		access-address 172.30.1.180 virtual
	}

	heartbeat {
		mode multicast
		address 239.1.99.222
		port 9918

		# To use unicast-mesh heartbeats, remove the 3 lines above, and see
		# aerospike_mesh.conf for alternative.

		interval 150
		timeout 10
	}

	fabric {
		port 3001
	}

	info {
		port 3003
	}
}

namespace centralns {
        replication-factor 1
        memory-size 108G
        default-ttl 0

        storage-engine device {
                file /newvolume/opt/aerospike/data/centralns.dat
                filesize 1000G
		write-block-size 128K
        }
}
[ec2-user@ip-172-30-1-180 ~]$ asmonitor

Enter help for commands

1 hosts in cluster: 172.30.1.180:3000
Aerospike Interactive Shell, version 3.7.5
Monitor> info
===NODES===
2017-05-19 12:49:01.669654
Sorting by IP, in Ascending order: 
ip:port               Build   Cluster      Cluster   Free   Free   Migrates              Node         Principal   Replicated    Sys
                          .      Size   Visibility   Disk    Mem          .                ID                ID      Objects   Free
                          .         .            .    pct    pct          .                 .                 .            .    Mem
172.30.1.180:3000    3.7.5.1         1         true     93     94      (0,0)   BB9B6941919D10A   BB9B6941919D10A   99,237,126     94
Number of nodes displayed: 1


 ===NAMESPACE===
Total (unique) objects in cluster for centralns : 99,237,140
Note: Total (unique) objects is an under estimate if migrations are in progress.


ip/namespace              Avail   Evicted       Master     Repl     Stop      Used   Used     Used   Used    hwm   hwm
                            Pct   Objects      Objects   Factor   Writes      Disk   Disk      Mem    Mem   Disk   Mem
                              .         .            .        .        .         .      %        .      %      .     .
172.30.1.180/centralns       92         0   99,237,140        1    false   64.28 G      7   5.91 G      6     50    60
Number of rows displayed: 1
Monitor> exit

Config files location : /home/ec2-user/.asmonitor/asmonitor.conf
Folder used by asmonitor for files : /home/ec2-user/.asmonitor/
[ec2-user@ip-172-30-1-180 ~]$ asinfo -l -v 'statistics'
cluster_size=1
cluster_key=F98896FAC496E218
cluster_integrity=true
objects=99270160
sub-records=0
total-bytes-disk=1073741824000
used-bytes-disk=69042935296
free-pct-disk=93
total-bytes-memory=115964116992
used-bytes-memory=6353290240
data-used-bytes-memory=0
index-used-bytes-memory=6353290240
sindex-used-bytes-memory=0
free-pct-memory=94
stat_read_reqs=6085393098
stat_read_reqs_xdr=0
stat_read_success=2121457454
stat_read_errs_notfound=3963935641
stat_read_errs_other=0
stat_write_reqs=322758276
stat_write_reqs_xdr=0
stat_write_success=322758276
stat_write_errs=0
stat_xdr_pipe_writes=0
stat_xdr_pipe_miss=0
stat_delete_success=223057803
stat_rw_timeout=0
udf_read_reqs=0
udf_read_success=0
udf_read_errs_other=0
udf_write_reqs=0
udf_write_success=0
udf_write_err_others=0
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=0
stat_proxy_reqs_xdr=0
stat_proxy_success=0
stat_proxy_errs=0
stat_ldt_proxy=0
stat_cluster_key_err_ack_dup_trans_reenqueue=0
stat_expired_objects=114504343
stat_evicted_objects=0
stat_deleted_set_objects=0
stat_evicted_objects_time=0
stat_zero_bin_records=0
stat_nsup_deletes_not_shipped=162294291
stat_compressed_pkts_received=0
err_tsvc_requests=21554
err_tsvc_requests_timeout=0
err_out_of_space=0
err_duplicate_proxy_request=0
err_rw_request_not_found=13
err_rw_pending_limit=0
err_rw_cant_put_unique=0
geo_region_query_count=0
geo_region_query_cells=0
geo_region_query_points=0
geo_region_query_falsepos=0
fabric_msgs_sent=0
fabric_msgs_rcvd=0
paxos_principal=BB9B6941919D10A
migrate_msgs_sent=0
migrate_msgs_recv=0
migrate_progress_send=0
migrate_progress_recv=0
migrate_num_incoming_accepted=0
migrate_num_incoming_refused=0
queue=4
transactions=4040145455
reaped_fds=261460
scans_active=0
basic_scans_succeeded=0
basic_scans_failed=1
aggr_scans_succeeded=0
aggr_scans_failed=0
udf_bg_scans_succeeded=0
udf_bg_scans_failed=0
batch_index_initiate=3508538128
batch_index_queue=1:0,1:0,1:0,3:0
batch_index_complete=3508538122
batch_index_timeout=0
batch_index_errors=0
batch_index_unused_buffers=250
batch_index_huge_buffers=0
batch_index_created_buffers=29081
batch_index_destroyed_buffers=28825
batch_initiate=0
batch_queue=0
batch_tree_count=0
batch_timeout=0
batch_errors=0
info_queue=0
delete_queue=16812
proxy_in_progress=0
proxy_initiate=0
proxy_action=0
proxy_retry=0
proxy_retry_q_full=0
proxy_unproxy=0
proxy_retry_same_dest=0
proxy_retry_new_dest=0
write_master=322758278
write_prole=0
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=0
rw_err_ack_badnode=0
client_connections=2667
waiting_transactions=0
tree_count=0
record_refs=99270178
record_locks=1
migrate_tx_objs=0
migrate_rx_objs=0
ongoing_write_reqs=0
err_storage_queue_full=0
partition_actual=4096
partition_replica=0
partition_desync=0
partition_absent=0
partition_zombie=0
partition_object_count=99270161
partition_ref_count=4118
system_free_mem_pct=94
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_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=38517
stat_write_errs_notfound=0
stat_write_errs_other=0
heartbeat_received_self=255951
heartbeat_received_foreign=0
query_reqs=0
query_success=0
query_fail=0
query_abort=0
query_avg_rec_count=0
query_short_running=0
query_long_running=0
query_short_queue_full=0
query_long_queue_full=0
query_short_reqs=0
query_long_reqs=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
[ec2-user@ip-172-30-1-180 ~]$ asinfo -v 'get-config:' -l
transaction-queues=16
transaction-threads-per-queue=4
transaction-duplicate-threads=0
transaction-pending-limit=20
migrate-threads=1
migrate-max-num-incoming=256
migrate-rx-lifetime-ms=60000
proto-fd-max=99999
proto-fd-idle-ms=10000
proto-slow-netio-sleep-ms=1
transaction-retry-ms=1000
transaction-max-ms=1000
transaction-repeatable-read=false
ticker-interval=10
log-local-time=false
microbenchmarks=false
storage-benchmarks=false
ldt-benchmarks=false
scan-max-active=100
scan-max-done=100
scan-max-udf-transactions=32
scan-threads=4
batch-index-threads=4
batch-threads=4
batch-max-requests=5000
batch-max-buffers-per-queue=255
batch-max-unused-buffers=256
batch-priority=200
nsup-delete-sleep=100
nsup-period=10
nsup-startup-evict=true
paxos-retransmit-period=5
paxos-single-replica-limit=1
paxos-max-cluster-size=32
paxos-protocol=v3
paxos-recovery-policy=manual
write-duplicate-resolution-disable=false
respond-client-on-master-completion=false
replication-fire-and-forget=false
info-threads=16
allow-inline-transactions=true
use-queue-per-device=false
snub-nodes=false
prole-extra-ttl=0
max-msgs-per-type=-1
service-threads=16
fabric-workers=16
pidfile=/newvolume/var/run/aerospike/asd.pid
memory-accounting=false
udf-runtime-gmax-memory=18446744073709551615
udf-runtime-max-memory=18446744073709551615
sindex-builder-threads=4
sindex-data-max-memory=ULONG_MAX
query-threads=6
query-worker-threads=15
query-priority=10
query-in-transaction-thread=0
query-req-in-query-thread=0
query-req-max-inflight=100
query-bufpool-size=256
query-batch-size=100
query-priority-sleep-us=1
query-short-q-max-size=500
query-long-q-max-size=500
query-rec-count-bound=18446744073709551615
query-threshold=10
query-untracked-time-ms=1000
query-pre-reserve-partitions=false
service-address=0.0.0.0
service-port=3000
access-address=172.30.1.180
reuse-address=true
fabric-port=3001
fabric-keepalive-enabled=true
fabric-keepalive-time=1
fabric-keepalive-intvl=1
fabric-keepalive-probes=10
network-info-port=3003
heartbeat-mode=multicast
heartbeat-protocol=v2
heartbeat-address=239.1.99.222
heartbeat-port=9918
heartbeat-interval=150
heartbeat-timeout=10
enable-security=false
privilege-refresh-period=300
report-authentication-sinks=0
report-data-op-sinks=0
report-sys-admin-sinks=0
report-user-admin-sinks=0
report-violation-sinks=0
syslog-local=-1
enable-xdr=false
xdr-namedpipe-path=NULL
forward-xdr-writes=false
xdr-delete-shipping-enabled=true
xdr-nsup-deletes-enabled=false
stop-writes-noxdr=false
reads-hist-track-back=1800
reads-hist-track-slice=10
reads-hist-track-thresholds=1,8,64
writes_master-hist-track-back=1800
writes_master-hist-track-slice=10
writes_master-hist-track-thresholds=1,8,64
proxy-hist-track-back=1800
proxy-hist-track-slice=10
proxy-hist-track-thresholds=1,8,64
udf-hist-track-back=1800
udf-hist-track-slice=10
udf-hist-track-thresholds=1,8,64
query-hist-track-back=1800
query-hist-track-slice=10
query-hist-track-thresholds=1,8,64
query_rec_count-hist-track-back=1800
query_rec_count-hist-track-slice=10
query_rec_count-hist-track-thresholds=1,8,64
[ec2-user@ip-172-30-1-180 ~]$ asinfo -v 'hist-dump:ns=centralns;hist=ttl'
centralns:ttl=100,864,5060364,4443960,3856727,3406033,3064149,2753621,2608490,2229002,2031532,1684548,1373003,1065835,770459,466249,165430,328,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,306361,198587,171518,156951,126786,117620,110467,98720,80378,78223,69918,69741,57858,55356,59457,53118,542274;
[ec2-user@ip-172-30-1-180 ~]$ asinfo -v 'get-config:context=namespace;id=centralns' -l
memory-size=115964116992
high-water-disk-pct=50
high-water-memory-pct=60
evict-tenths-pct=5
stop-writes-pct=90
cold-start-evict-ttl=4294967295
repl-factor=1
default-ttl=0
max-ttl=0
conflict-resolution-policy=generation
single-bin=false
ldt-enabled=false
ldt-page-size=8192
enable-xdr=false
sets-enable-xdr=true
ns-forward-xdr-writes=false
allow-nonxdr-writes=true
allow-xdr-writes=true
disallow-null-setname=false
total-bytes-memory=115964116992
read-consistency-level-override=off
write-commit-level-override=off
migrate-order=5
migrate-sleep=1
migrate-tx-partitions-initial=0
migrate-tx-partitions-remaining=0
migrate-rx-partitions-initial=0
migrate-rx-partitions-remaining=0
migrate-tx-partitions-imbalance=0
total-bytes-disk=1073741824000
defrag-lwm-pct=50
defrag-queue-min=0
defrag-sleep=1000
defrag-startup-minimum=10
flush-max-ms=1000
fsync-max-sec=0
max-write-cache=67108864
min-avail-pct=5
post-write-queue=256
data-in-memory=false
file=/newvolume/opt/aerospike/data/centralns.dat
filesize=1073741824000
writethreads=1
writecache=67108864
obj-size-hist-max=100

and most of the time i see in logs is this, i hope nsup is not running or something.

May 19 2017 07:23:13 GMT: INFO (info): (thr_info.c::4996)    tree_counts: nsup 0 scan 0 dup 0 wprocess 0 migrx 0 migtx 0 ssdr 0 ssdw 0 rw 4

Could you run:

asadm -e "show stat like expir"

From the output provided, you aren’t evicting, but that is different from expiration. It is a common error, eviction is basically early expiration when resources are constrained.

BTW, asmonitor has been replaced with asadm. I believe running “info” in asadm will show expiration as well as eviction.

As we are observing, an increased growth in keys, as all records are stored with ttl of 300 seconds, it should expire, but number of records keeps on growing, this is the output of what you asked.

[ec2-user@ip-172-30-1-180 ~]$ asadm -e "show stat like expir"
~~~~~~~~~~~Service Statistics~~~~~~~~~~~
NODE                :   172.30.1.180:3000   
stat_expired_objects:   180542789          

~~~~~centralns Namespace Statistics~~~~~
NODE                 :   172.30.1.180:3000   
expired-objects      :   180542789          
non-expirable-objects:   14        
Admin> info
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~Network Information~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
            Node               Node                 Ip     Build   Enterprise   Cluster            Cluster     Cluster         Principal   Client     Uptime   
               .                 Id                  .         .            .      Size                Key   Integrity                 .    Conns          .   
172.30.1.180:3000   *BB9B6941919D10A   172.30.1.180:3000   3.7.5.1   False              1   F98896FAC496E218   True        BB9B6941919D10A     2635   14:42:51   
Number of rows: 1

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~Namespace Information~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
 Namespace               Node   Avail%   Evictions      Master   Replica     Repl     Stop     Pending         Disk    Disk     HWM        Mem     Mem    HWM      Stop   
         .                  .        .           .     Objects   Objects   Factor   Writes    Migrates         Used   Used%   Disk%       Used   Used%   Mem%   Writes%   
         .                  .        .           .           .         .        .        .   (tx%,rx%)            .       .       .          .       .      .         .   
centralns   172.30.1.180:3000   86               0   160.695 M   0.000     1        false    (0,0)       102.317 GB   11      50      9.578 GB   9       60     90        
centralns                                       0   160.695 M   0.000                       (0,0)       102.317 GB                   9.578 GB                            
Number of rows: 2


All of your keys are not stored with a ttl of 300 as you can see from the ttl histogram you have provided. Appears you have two different classes of ttls being stored, one around 864 * 15 = 12960 and the other at above 864 * 100 = 86400. Half of your records have a ttl above or equal to 864 * 5 = 4320.

You also have 14 objects that never expire.

:slight_smile: Let me give you the pin point picture.

var asKey = {
        ns:"centralns",
        set:"tempdata",
        key:"C_"+reqkey
};
var rec = {
        data:maindata
};
var meta = { ttl: 300 };
var policy = { key: aerospike.policy.key.SEND };
aerospikeclient.put(asKey,rec,meta,policy, function(err, key) {
[ec2-user@ip-172-30-1-180 ~]$ asadm -e "show stat like expir"
~~~~~~~~~~~Service Statistics~~~~~~~~~~~
NODE                :   172.30.1.180:3000   
stat_expired_objects:   290059669          

~~~~~centralns Namespace Statistics~~~~~
NODE                 :   172.30.1.180:3000   
expired-objects      :   290059669          
non-expirable-objects:   15                 
[ec2-user@ip-172-30-1-180 ~]$ aql
Aerospike Query
Copyright 2013-2015 Aerospike. All rights reserved.

aql> show sets
+-----------+------------------+----------------+-------------------+----------------+--------------+----------------+------------+
| n_objects | disable-eviction | set-enable-xdr | stop-writes-count | n-bytes-memory | ns_name      | set_name       | set-delete |
+-----------+------------------+----------------+-------------------+----------------+--------------+----------------+------------+
| 7860533   | "false"          | "use-default"  | 0                 | 0              | "centralns"  | "countset"     | "false"    |
| 1         | "false"          | "use-default"  | 0                 | 0              | "centralns"  | "idset"        | "false"    |
| 222365861 | "false"          | "use-default"  | 0                 | 0              | "centralns"  | "tempdata"     | "false"    |
| 17        | "false"          | "use-default"  | 0                 | 0              | "centralns"  | "flags"        | "false"    |
+-----------+------------------+----------------+-------------------+----------------+--------------+----------------+------------+
4 rows in set (0.000 secs)
OK

As you can see in above, for countset set we use 86400 secs as expiry, for other two sets (idset and flags) we don’t impose any expiry, but our biggest worry is tempdata set, where we only store keys with ttl of 300 seconds, i even verified it in code also, gave you sample of our above. It just keeps on growing.

[ec2-user@ip-172-30-1-180 ~]$ asmonitor

Enter help for commands

1 hosts in cluster: 172.30.1.180:3000
Aerospike Interactive Shell, version 3.7.5
Monitor> latency
	====writes_master====
                                  timespan   ops/sec   >1ms   >8ms   >64ms
172.30.1.180:3000    01:30:40-GMT->01:30:50    8223.4   0.00   0.00    0.00
 
 
	====reads====
                                  timespan    ops/sec   >1ms   >8ms   >64ms
172.30.1.180:3000    01:30:40-GMT->01:30:50   160952.3   0.01   0.00    0.00
 
	====udf====
                                  timespan   ops/sec   >1ms   >8ms   >64ms
172.30.1.180:3000    01:30:40-GMT->01:30:50       0.0   0.00   0.00    0.00
 
	====proxy====
                                  timespan   ops/sec   >1ms   >8ms   >64ms
172.30.1.180:3000    01:30:40-GMT->01:30:50       0.0   0.00   0.00    0.00
 
	====query====
                                  timespan   ops/sec   >1ms   >8ms   >64ms
172.30.1.180:3000    01:30:40-GMT->01:30:50       0.0   0.00   0.00    0.00
 
Monitor>

As i can evaluate based on above numbers, even with around 8000 writes per second and considering all keys with ttl of 300, this tempdata should not go above 2.4mn objects, but its at 221mn+ as of now.

Gotcha.

Try reducing:[quote=“u999, post:6, topic:4080”] nsup-delete-sleep=100 [/quote]

At one time the default was ‘0’, didn’t cause any issue for for most users. Since you have many pending expirations, setting it to ‘0’ could overwhelm your transaction queues so I would try lowering it incrementally and monitoring the effect on latency.

There are other useful nsup log lines, though better logs appeared in 3.9.x.

nsup clear waits: 1441

Appears when an NSUP round completes and indicates how much time was spent waiting (nsup-delete-sleeps).

@kporter, thanks for info, after setting to following, i observed some downtime in responses (best guess is AS might be cleaning the stuff so latency induced in responding to reads), after all got stabilized, we got the system back and running smoothly with normal key counts.

asinfo -v 'set-config:context=service;nsup-period=5'
asinfo -v 'set-config:context=service;nsup-delete-sleep=0'
1 Like

@kporter, I am facing a similar issue where my expiration rate is lagging behind the write rate. I am using a in memory cache (AS version : 3.16.0.6) , with a key TTL of 3 mins. The application use case is multi gets(batch size of 80-90 keys) and writes on cache misses.

I tried setting the nsup-delete-sleep to 0 and reducing the nsup-period, but the mget response time increases significantly because there is heavy increase in CPU utilisation. Putting in more capacity in terms of CPU is not feasible. Are there any other configs that I can tune, which might help here.

Also, I have enough memory at hand, so I can afford the expirations to be a bit slow, but when the stop_write state is reached (within couple of hours), cluster can never recover back automatically, as writes again continue to happen at the same rate after some memory is freed up by expirations. Are there some configs that I can tune, to speed up expirations at the stop_write/high-water-memory-pct stage, and let the writes be stopped until some percentage of memory is available again?

Please let me know, if you need some more data/numbers on this.

I would suggest upgrading to a more recent version. As of version 4.5.1, expirations are handled much more efficiently and will stress the system less. Having said that, if the bottleneck is the time it takes for nsup to complete a cycle (rather than the time it takes to process the deletion) you can also look at increasing the number of nsup-threads.

1 Like