Memory errors

[matijav]

Hi guys,

I ran into a server memory errors problem today on 1 of our clusters. I was getting Server memory errors on writes although the cluster didn’t reach the high watermarks.

The cluster is made of 3 nodes, high-water-disk-pct was 65% and the nodes were 61%, 60% and 63% full. Memory was only 30% full so not an issue here, cpu load wasn’t high. All other parameters were on default values. Aerospike version is 3.12.1.1.

Storage is on raw devices:

storage-engine device {
    device /dev/sdc
    device /dev/sdd
    write-block-size 128K
}

The issue was that although the cluster didn’t reach the watermark it was returning errors on writes. Shouldn’t the watermark be the threshold when aerospike just forcibly evicts old data and not stops new writes? I don’t understand why this happened.

Here is also a full namespace config:

namespace realtime {
        replication-factor 2
        memory-size 96G
        default-ttl 0

        high-water-memory-pct 70
        high-water-disk-pct 65
        stop-writes-pct 90

        storage-engine device {
                device /dev/sdc
                device /dev/sdd
                write-block-size 128K
        }

        set winnotice {
                set-disable-eviction true
        }
}

Thanks, Matija

[kporter]

@matijav

I was getting Server memory errors on writes although the cluster didn’t reach the high watermarks.

1. What were the errors?

2. Were there any warnings in Aerospike’s log?

@matijav

Shouldn’t the watermark be the threshold when aerospike just forcibly evicts old data and not stops new writes?

There are two reasons writes may be stopped:

1. Aerospike has breached stop-writes-pct for either memory or storage.
2. The storage layer’s avail-pct has fallen below the min-avail-pct configuration. This can happen when either the underlying storage is unable to keep up with the load and has fallen behind in defrag or there are no write blocks are eligible for defrag as determined by defrag-lwm-pct.

3. What was the “avail-pct” of your storage at this time?

grep "avail-pct" /var/log/aerospike/aerospike.log

[matijav]

I’m using a go client so I just got ‘Server memory error’. (SERVER_MEM_ERROR ResultCode = 8)

No, no warnings in logs, only this kind of logs:

Jun 29 2017 09:14:06 GMT: INFO (info): (ticker.c:170) NODE-ID bb932cae42aa83c CLUSTER-SIZE 3
Jun 29 2017 09:14:06 GMT: INFO (info): (ticker.c:253)    system-memory: free-kbytes 90290280 free-pct 68 heap-kbytes (30985519,31036508,31385600) heap-efficiency-pct 98.7
Jun 29 2017 09:14:06 GMT: INFO (info): (ticker.c:267)    in-progress: tsvc-q 0 info-q 0 nsup-delete-q 0 rw-hash 0 proxy-hash 0 tree-gc-q 0
Jun 29 2017 09:14:06 GMT: INFO (info): (ticker.c:289)    fds: proto (34,1253146,1253112) heartbeat (2,3,1) fabric (48,48,0)
Jun 29 2017 09:14:06 GMT: INFO (info): (ticker.c:298)    heartbeat-received: self 0 foreign 10793517
Jun 29 2017 09:14:06 GMT: INFO (info): (ticker.c:328)    fabric-bytes-per-second: bulk (0,0) ctrl (0,0) meta (0,0) rw (31179,18744)
Jun 29 2017 09:14:06 GMT: INFO (info): (ticker.c:382) {realtime} objects: all 455112909 master 226475731 prole 228637178
Jun 29 2017 09:14:06 GMT: INFO (info): (ticker.c:443) {realtime} migrations: complete
Jun 29 2017 09:14:06 GMT: INFO (info): (ticker.c:471) {realtime} memory-usage: total-bytes 29127226176 index-bytes 29127226176 sindex-bytes 0 used-pct 28.26
Jun 29 2017 09:14:06 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290275534080 avail-pct 8 cache-read-pct 29.70
Jun 29 2017 09:14:06 GMT: INFO (info): (ticker.c:585) {realtime} client: tsvc (0,177) proxy (94164,0,0) read (1370008718,0,0,5204896007) write (1295302574,41305483,0) delete (0,0,0,0) udf (0,0,0) lang (0,0,0,0)
Jun 29 2017 09:14:06 GMT: INFO (info): (hist.c:145) histogram dump: {realtime}-read (6574904725 total) msec
Jun 29 2017 09:14:06 GMT: INFO (info): (hist.c:162)  (00: 6551040119) (01: 0020736680) (02: 0002484990) (03: 0000591141)
Jun 29 2017 09:14:06 GMT: INFO (info): (hist.c:162)  (04: 0000037664) (05: 0000012990) (06: 0000000983) (07: 0000000149)
Jun 29 2017 09:14:06 GMT: INFO (info): (hist.c:171)  (08: 0000000009)
Jun 29 2017 09:14:06 GMT: INFO (info): (hist.c:145) histogram dump: {realtime}-write (1336608057 total) msec
Jun 29 2017 09:14:06 GMT: INFO (info): (hist.c:162)  (00: 1303918273) (01: 0028329902) (02: 0003588241) (03: 0000713670)
Jun 29 2017 09:14:06 GMT: INFO (info): (hist.c:162)  (04: 0000054865) (05: 0000002754) (06: 0000000339) (07: 0000000013)
Jun 29 2017 09:14:06 GMT: INFO (info): (ticker.c:382) {distlock} objects: all 0 master 0 prole 0
Jun 29 2017 09:14:06 GMT: INFO (info): (ticker.c:443) {distlock} migrations: complete
Jun 29 2017 09:14:06 GMT: INFO (info): (ticker.c:462) {distlock} memory-usage: total-bytes 0 index-bytes 0 sindex-bytes 0 data-bytes 0 used-pct 0.00
Jun 29 2017 09:14:06 GMT: INFO (info): (ticker.c:585) {distlock} client: tsvc (0,0) proxy (0,0,0) read (0,0,0,0) write (237831,2505,0) delete (1857,0,0,0) udf (0,0,0) lang (0,0,0,0)
Jun 29 2017 09:14:06 GMT: INFO (info): (hist.c:145) histogram dump: {distlock}-write (240336 total) msec
Jun 29 2017 09:14:06 GMT: INFO (info): (hist.c:162)  (00: 0000237332) (01: 0000001284) (02: 0000001417) (03: 0000000201)
Jun 29 2017 09:14:06 GMT: INFO (info): (hist.c:171)  (04: 0000000032) (05: 0000000061) (06: 0000000009)
Jun 29 2017 09:14:37 GMT: INFO (drv_ssd): (drv_ssd.c:2118) {realtime} /dev/sdd: used-bytes 145150033408 free-wblocks 157520 write-q 0 write (25288648,0.0) defrag-q 0 defrag-read (24980403,0.0) defrag-write (12250503,0.0)
Jun 29 2017 09:14:37 GMT: INFO (drv_ssd): (drv_ssd.c:2118) {realtime} /dev/sdc: used-bytes 145125398912 free-wblocks 158002 write-q 0 write (25257368,0.0) defrag-q 0 defrag-read (24949853,0.0) defrag-write (12235755,0.0)

Jun 29 2017 09:16:17 GMT: INFO (nsup): (thr_nsup.c:1109) {realtime} Records: 226473469, 0 0-vt, 2443(196832403) expired, 0(0) evicted, 0(0) set deletes. Evict ttl: 0. Waits: 0,0,0. Total time: 33675 ms
Jun 29 2017 09:16:17 GMT: INFO (nsup): (thr_nsup.c:1181) {distlock} nsup start
Jun 29 2017 09:16:17 GMT: INFO (nsup): (thr_nsup.c:1109) {distlock} Records: 0, 0 0-vt, 0(15) expired, 0(0) evicted, 0(0) set deletes. Evict ttl: 0. Waits: 0,0,0. Total time: 3 ms

This is the avail-pct when errors started (8:55):

Jun 29 2017 08:55:04 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290279977600 avail-pct 8 cache-read-pct 18.35
Jun 29 2017 08:55:14 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290282199552 avail-pct 8 cache-read-pct 17.58
Jun 29 2017 08:55:25 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290282453632 avail-pct 8 cache-read-pct 16.33
Jun 29 2017 08:55:35 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290282281728 avail-pct 8 cache-read-pct 6.62
Jun 29 2017 08:55:45 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290282174208 avail-pct 8 cache-read-pct 8.95
Jun 29 2017 08:55:55 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290282144256 avail-pct 8 cache-read-pct 11.26
Jun 29 2017 08:56:05 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290282124800 avail-pct 8 cache-read-pct 13.05
Jun 29 2017 08:56:15 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290282555136 avail-pct 8 cache-read-pct 17.54

At 10:25 errors stopped but just before the cache-read-pct fell to zero.

Jun 29 2017 10:19:37 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290254875904 avail-pct 8 cache-read-pct 20.28
Jun 29 2017 10:19:47 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290254807552 avail-pct 8 cache-read-pct 31.47
Jun 29 2017 10:19:57 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290254706432 avail-pct 8 cache-read-pct 28.06
Jun 29 2017 10:20:07 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290254598400 avail-pct 8 cache-read-pct 27.70
Jun 29 2017 10:20:17 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290254489600 avail-pct 8 cache-read-pct 24.90
Jun 29 2017 10:20:27 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290254518656 avail-pct 8 cache-read-pct 30.27
Jun 29 2017 10:20:37 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290254518656 avail-pct 8 cache-read-pct 0.00
Jun 29 2017 10:20:47 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290254518656 avail-pct 8 cache-read-pct 0.00
Jun 29 2017 10:20:57 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290254518656 avail-pct 8 cache-read-pct 0.00
Jun 29 2017 10:21:07 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290254494464 avail-pct 8 cache-read-pct 0.00
Jun 29 2017 10:21:17 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290254367616 avail-pct 8 cache-read-pct 0.00
Jun 29 2017 10:21:27 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290254257664 avail-pct 8 cache-read-pct 0.00
Jun 29 2017 10:21:37 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290254114048 avail-pct 8 cache-read-pct 0.00
Jun 29 2017 10:21:47 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290254039552 avail-pct 8 cache-read-pct 0.00
Jun 29 2017 10:21:57 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290253908480 avail-pct 8 cache-read-pct 0.00
Jun 29 2017 10:22:07 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290253799168 avail-pct 8 cache-read-pct 0.00
Jun 29 2017 10:22:17 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290253682944 avail-pct 8 cache-read-pct 0.00
Jun 29 2017 10:22:27 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290253689216 avail-pct 8 cache-read-pct 0.00
Jun 29 2017 10:22:37 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290253716608 avail-pct 8 cache-read-pct 0.00
Jun 29 2017 10:22:47 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290253737344 avail-pct 8 cache-read-pct 0.00
Jun 29 2017 10:22:57 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290253763968 avail-pct 8 cache-read-pct 0.00
Jun 29 2017 10:23:07 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290253761536 avail-pct 8 cache-read-pct 0.00
Jun 29 2017 10:23:17 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290253643648 avail-pct 8 cache-read-pct 0.00
Jun 29 2017 10:23:27 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290253542656 avail-pct 8 cache-read-pct 0.00
Jun 29 2017 10:23:37 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290253450752 avail-pct 8 cache-read-pct 0.00
Jun 29 2017 10:23:47 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290253399296 avail-pct 8 cache-read-pct 0.00
Jun 29 2017 10:23:57 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290253294336 avail-pct 8 cache-read-pct 100.00
Jun 29 2017 10:24:07 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290253186048 avail-pct 8 cache-read-pct 0.00
Jun 29 2017 10:24:17 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290253080576 avail-pct 8 cache-read-pct 0.00
Jun 29 2017 10:24:27 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290253079040 avail-pct 8 cache-read-pct 0.00
Jun 29 2017 10:24:37 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290253106432 avail-pct 8 cache-read-pct 0.00
Jun 29 2017 10:24:47 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290253133568 avail-pct 8 cache-read-pct 0.00
Jun 29 2017 10:24:57 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290253161984 avail-pct 8 cache-read-pct 0.00
Jun 29 2017 10:25:07 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290253159296 avail-pct 8 cache-read-pct 0.00
Jun 29 2017 10:25:17 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290253063808 avail-pct 8 cache-read-pct 0.00
Jun 29 2017 10:25:27 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290252969472 avail-pct 8 cache-read-pct 0.00
Jun 29 2017 10:25:37 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290252881152 avail-pct 8 cache-read-pct 0.00
Jun 29 2017 10:25:47 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290252842880 avail-pct 8 cache-read-pct 0.00
Jun 29 2017 10:25:57 GMT: INFO (info): (ticker.c:510) {realtime} device-usage: used-bytes 290252732928 avail-pct 8 cache-read-pct 0.00

[kporter]

@matijav

Jun 29 2017 09:14:37 GMT: INFO (drv_ssd): (drv_ssd.c:2118) {realtime} /dev/sdd: used-bytes 145150033408 free-wblocks 157520 write-q 0 write (25288648,0.0) defrag-q 0 defrag-read (24980403,0.0) defrag-write (12250503,0.0) Jun 29 2017 09:14:37 GMT: INFO (drv_ssd): (drv_ssd.c:2118) {realtime} /dev/sdc: used-bytes 145125398912 free-wblocks 158002 write-q 0 write (25257368,0.0) defrag-q 0 defrag-read (24949853,0.0) defrag-write (12235755,0.0)

You are running very close to stop-writes-pct:

bytes_used / ((free_wblocks * wblock_size * 1kb) + bytes_used) = fraction_used
145150033408 / ((157520 * 128 * 1024) + 145150033408) = ~0.875

I suspect that it must have breached during this event.

BTW you are also really close to min-avail-pct as well.

@matijav

Jun 29 2017 09:14:37 GMT: INFO (drv_ssd): (drv_ssd.c:2118) {realtime} /dev/sdc: used-bytes 145125398912 free-wblocks 158002 write-q 0 write (25257368,0.0) defrag-q 0 defrag-read (24949853,0.0) defrag-write (12235755,0.0)

Defrag isn’t doing anything in this snapshot for a 10 second window, but this isn’t unexpected since the write rate is also 0. If your write rate is generally low then you may want to increase defrag-lwm-pct to 65 (be aware that this will result in write amplification which increases non-linearly to value of defrag-lwm-pct).

[matijav]

Hi Kevin,

How was the cluster running close to stop-writes-pct is the memory was 30% used or so? So this was a memory issue, not a disk issue?

Yeah, the writes stopped and it started throwing errors, so this probably why the writes were 0.

So min-avail-pct is high watermark minus the consumed space? This means that the actual high watermark is the setting value minus the min-avail-pct?

The write rate is usually high, around 2k writes per second when no jobs are running and up to 30k wps when jobs are inserting data into as.

[kporter]

@matijav

How was the cluster running close to stop-writes-pct is the memory was 30% used or so? So this was a memory issue, not a disk issue?

You are correct, at one time stop_writes applied to either memory or disk but hasn’t been that way for a very long time .

When the system enters stop_wrtes a warning will be logged containing the phrase “stop_writes”. This warning includes the reason it entered stop_writes. This is the only path where stop_writes can be triggered and every other way for the server to respond with error code 8 will log individual warnings. Likely the server dipped below the min-avail-pct though I would need to see the warning to be sure.

@matijav

So min-avail-pct is high watermark minus the consumed space? This means that the actual high watermark is the setting value minus the min-avail-pct?

No, min-avail-pct is the minimum amount of disk space that is available for writes required to allow a client write. This is needed to ensure defrag has space to write in order to recover more “avail-pct”.

Here is a detailed kb article that describes these situations:

Understanding when server no longer accepts writes

The Aerospike Knowledge Base has moved to https://support.aerospike.com. Content on https://discuss.aerospike.com is being migrated to either https://support.aerospike.com or https://docs.aerospike.com. Maintenance on articles stored in this repository ceased on December 31st 2022 and this article may be stale. If you have any questions, please do not hesitate to raise a case via https://support.aerospike.com. Summary This article explains scenarios which would lead to an Aerospike cluster no…

[matijav]

Oh, now I get it. I read the articles in your links and now I understand what is min-avail-pct and how is connected to defrag and why the stop writes happened.

Thanks for the help Kevin