(error) MISCONF Redis is configured to save RDB snapshots, but is currently not able to persist on disk. Commands that may modify the data set are disabled. Please check Redis logs for details about the error.

[Giovanni Trovato]

Hello to all,

my problem is this: (error) MISCONF Redis is configured to save RDB snapshots, but is currently not able to persist on disk. Commands that may modify the data set are disabled. Please check Redis logs for details about the error.

The problem occurs when the dump file reaches about 20GB

----------------------------

config get *

----------------------------

"dbfilename" "dump.rdb"

"requirepass" "xxxx"

"masterauth" ""

"bind" ""

"unixsocket" ""

"logfile" "/var/log/redis_6379.log"

"pidfile" "/var/run/redis_6379.pid"

"maxmemory" "0"

"maxmemory-samples" "3"

"timeout" "0"

"tcp-keepalive" "0"

"auto-aof-rewrite-percentage" "100"

"auto-aof-rewrite-min-size" "67108864"

"hash-max-ziplist-entries" "512"

"hash-max-ziplist-value" "64"

"list-max-ziplist-entries" "512"

"list-max-ziplist-value" "64"

"set-max-intset-entries" "512"

"zset-max-ziplist-entries" "128"

"zset-max-ziplist-value" "64"

"lua-time-limit" "5000"

"slowlog-log-slower-than" "10000"

"slowlog-max-len" "128"

"port" "6379"

"databases" "16"

"repl-ping-slave-period" "10"

"repl-timeout" "60"

"maxclients" "10000"

"watchdog-period" "0"

"slave-priority" "100"

"hz" "10"

"no-appendfsync-on-rewrite" "no"

"slave-serve-stale-data" "yes"

"slave-read-only" "yes"

"stop-writes-on-bgsave-error" "yes"

"daemonize" "yes"

"rdbcompression" "yes"

"rdbchecksum" "yes"

"activerehashing" "yes"

"repl-disable-tcp-nodelay" "no"

"aof-rewrite-incremental-fsync" "yes"

"appendonly" "no"

"dir" "/xxx/redis"

"maxmemory-policy" "volatile-lru"

"appendfsync" "everysec"

"save" "900 1 300 10 60 10000"

"loglevel" "verbose"

"client-output-buffer-limit" "normal 0 0 0 slave 268435456 67108864 60 pubsub 33554432 8388608 60"

"unixsocketperm" "0"

"slaveof" ""

------------------------------------

Log file ("loglevel" "verbose"):

tail -f log file es: set A B

----------------------------

[29029] 18 Jun 12:31:12.182 - DB 0: 1410155 keys (1332111 volatile) in 4194304 slots HT.

[29029] 18 Jun 12:31:12.182 - DB 1: 23751249 keys (22672533 volatile) in 67108864 slots HT.

[29029] 18 Jun 12:31:12.182 - 15 clients connected (0 slaves), 42818063112 bytes in use

[29029] 18 Jun 12:31:15.353 - Client closed connection

----------------------------

File Dump:

-----------------------------

-rw-r--r-- 1 root root  21G Jun 18 11:07 dump.rdb

----------------------------------------

---------------------

Redis INFO

---------------------

Server

hz 10

gcc_version 4.4.7

run_id e1d711351801adbf3ea5778ece07c69157f7e134

tcp_port 6379

redis_version 2.6.13

process_id 29029

uptime_in_seconds 446160

uptime_in_days 5

lru_clock 841290

multiplexing_api epoll

redis_git_dirty 0

redis_mode standalone

os Linux 2.6.32-358.6.2.el6.x86_64 x86_64

arch_bits 64

redis_git_sha1 0

Clients

client_biggest_input_buf 0

blocked_clients 0

client_longest_output_list 0

connected_clients 26

Memory

used_memory 46355357280

mem_allocator jemalloc-3.2.0

used_memory_human 43.17G

used_memory_peak 46355070816

used_memory_rss 40159465472

used_memory_peak_human 43.17G

mem_fragmentation_ratio 0.87

used_memory_lua 31744

Persistence

aof_enabled 0

aof_rewrite_in_progress 0

loading 0

rdb_last_bgsave_status err

aof_rewrite_scheduled 0

rdb_bgsave_in_progress 1

aof_last_bgrewrite_status ok

aof_last_rewrite_time_sec -1

rdb_current_bgsave_time_sec 0

rdb_last_save_time 1371546436

rdb_changes_since_last_save 42156093

aof_current_rewrite_time_sec -1

rdb_last_bgsave_time_sec 59

Stats

total_connections_received 1030

pubsub_patterns 0

evicted_keys 0

keyspace_misses 54191056

rejected_connections 0

pubsub_channels 0

instantaneous_ops_per_sec 3513

total_commands_processed 732464571

latest_fork_usec 1568360

expired_keys 946306

keyspace_hits 218386184

Replication

connected_slaves 0

role master

CPU

used_cpu_sys_children 3370.33

used_cpu_user 7030.46

used_cpu_user_children 32239.49

used_cpu_sys 11944.66

Keyspace

db1 {'keys': 25454943, 'expires': 24334235}

db0 {'keys': 1643814, 'expires': 1559551}

---------------------------------------------

I accept suggestions,

thank you all

[Salvatore Sanfilippo]

Hello Giovanni,

you should try to see what happens in the log file when you try to
persist, there is surely more interesting information earlier in the
log file.

Cheers,
Salvatore

> --
> You received this message because you are subscribed to the Google Groups
> "Redis DB" group.
> To unsubscribe from this group and stop receiving emails from it, send an
> email to redis-db+u...@googlegroups.com.
> To post to this group, send email to redi...@googlegroups.com.
> Visit this group at http://groups.google.com/group/redis-db.
> For more options, visit https://groups.google.com/groups/opt_out.
>
>



--
Salvatore 'antirez' Sanfilippo
open source developer - GoPivotal
http://invece.org

Beauty is more important in computing than anywhere else in technology
because software is so complicated. Beauty is the ultimate defence
against complexity.
— David Gelernter

[Giovanni Trovato]

Hi Salvatore,

I do not know if it can be useful

-------------------

strace -fF redis-cli -a xxx SET A B

-----------------

execve("/usr/local/bin/redis-cli", ["redis-cli", "-a", "xxx", "SET", "A", "B"], [/* 26 vars */]) = 0

brk(0)                                  = 0x156a000

mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f2acc031000

access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)

open("/etc/ld.so.cache", O_RDONLY)      = 3

fstat(3, {st_mode=S_IFREG|0644, st_size=52072, ...}) = 0

mmap(NULL, 52072, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f2acc024000

close(3)                                = 0

open("/lib64/libm.so.6", O_RDONLY)      = 3

read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0p>\300\256?\0\0\0"..., 832) = 832

fstat(3, {st_mode=S_IFREG|0755, st_size=598680, ...}) = 0

mmap(0x3faec00000, 2633912, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3faec00000

mprotect(0x3faec83000, 2093056, PROT_NONE) = 0

mmap(0x3faee82000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x82000) = 0x3faee82000

close(3)                                = 0

open("/lib64/libdl.so.2", O_RDONLY)     = 3

read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\340\r\0\256?\0\0\0"..., 832) = 832

fstat(3, {st_mode=S_IFREG|0755, st_size=22536, ...}) = 0

mmap(0x3fae000000, 2109696, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3fae000000

mprotect(0x3fae002000, 2097152, PROT_NONE) = 0

mmap(0x3fae202000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) = 0x3fae202000

close(3)                                = 0

open("/lib64/libpthread.so.0", O_RDONLY) = 3

read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0`\\\200\256?\0\0\0"..., 832) = 832

fstat(3, {st_mode=S_IFREG|0755, st_size=145720, ...}) = 0

mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f2acc023000

mmap(0x3fae800000, 2212768, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3fae800000

mprotect(0x3fae817000, 2097152, PROT_NONE) = 0

mmap(0x3faea17000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x17000) = 0x3faea17000

mmap(0x3faea19000, 13216, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x3faea19000

close(3)                                = 0

open("/lib64/libc.so.6", O_RDONLY)      = 3

read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\360\355A\256?\0\0\0"..., 832) = 832

fstat(3, {st_mode=S_IFREG|0755, st_size=1922152, ...}) = 0

mmap(0x3fae400000, 3745960, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3fae400000

mprotect(0x3fae58a000, 2093056, PROT_NONE) = 0

mmap(0x3fae789000, 20480, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x189000) = 0x3fae789000

mmap(0x3fae78e000, 18600, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x3fae78e000

close(3)                                = 0

mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f2acc022000

mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f2acc020000

arch_prctl(ARCH_SET_FS, 0x7f2acc020720) = 0

mprotect(0x3fae789000, 16384, PROT_READ) = 0

mprotect(0x3faea17000, 4096, PROT_READ) = 0

mprotect(0x3fae202000, 4096, PROT_READ) = 0

mprotect(0x3faee82000, 4096, PROT_READ) = 0

mprotect(0x3fade1f000, 4096, PROT_READ) = 0

munmap(0x7f2acc024000, 52072)           = 0

set_tid_address(0x7f2acc0209f0)         = 6183

set_robust_list(0x7f2acc020a00, 0x18)   = 0

futex(0x7fffbe183dcc, FUTEX_WAKE_PRIVATE, 1) = 0

futex(0x7fffbe183dcc, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 1, NULL, 7f2acc020720) = -1 EAGAIN (Resource temporarily unavailable)

rt_sigaction(SIGRTMIN, {0x3fae805ae0, [], SA_RESTORER|SA_SIGINFO, 0x3fae80f500}, NULL, 8) = 0

rt_sigaction(SIGRT_1, {0x3fae805b70, [], SA_RESTORER|SA_RESTART|SA_SIGINFO, 0x3fae80f500}, NULL, 8) = 0

rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0

getrlimit(RLIMIT_STACK, {rlim_cur=10240*1024, rlim_max=RLIM_INFINITY}) = 0

readlink("/etc/je_malloc.conf", 0x7fffbe182cb0, 4096) = -1 ENOENT (No such file or directory)

mmap(NULL, 4194304, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f2acbc20000

munmap(0x7f2acbc20000, 4194304)         = 0

mmap(NULL, 8384512, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f2acb821000

munmap(0x7f2acb821000, 4059136)         = 0

munmap(0x7f2acc000000, 131072)          = 0

open("/proc/stat", O_RDONLY|O_CLOEXEC)  = 3

read(3, "cpu  106777884 34408 115112220 2"..., 8192) = 3837

close(3)                                = 0

mmap(NULL, 4194304, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f2acb800000

ioctl(1, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo ...}) = 0

brk(0)                                  = 0x156a000

brk(0x158c000)                          = 0x158c000

socket(PF_NETLINK, SOCK_RAW, 0)         = 3

bind(3, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 0

getsockname(3, {sa_family=AF_NETLINK, pid=6183, groups=00000000}, [12]) = 0

sendto(3, "\24\0\0\0\26\0\1\3\26c\300Q\0\0\0\0\0\0\0\0", 20, 0, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 20

recvmsg(3, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"0\0\0\0\24\0\2\0\26c\300Q'\30\0\0\2\10\200\376\1\0\0\0\10\0\1\0\177\0\0\1"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 216

recvmsg(3, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"@\0\0\0\24\0\2\0\26c\300Q'\30\0\0\n\200\200\376\1\0\0\0\24\0\1\0\0\0\0\0"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 256

recvmsg(3, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"\24\0\0\0\3\0\2\0\26c\300Q'\30\0\0\0\0\0\0\1\0\0\0\24\0\1\0\0\0\0\0"..., 4096}], msg_controllen=0, msg_flags=0}, 0) = 20

close(3)                                = 0

socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 3

fcntl(3, F_GETFL)                       = 0x2 (flags O_RDWR)

fcntl(3, F_SETFL, O_RDWR|O_NONBLOCK)    = 0

connect(3, {sa_family=AF_INET, sin_port=htons(6379), sin_addr=inet_addr("127.0.0.1")}, 16) = -1 EINPROGRESS (Operation now in progress)

poll([{fd=3, events=POLLOUT}], 1, -1)   = 1 ([{fd=3, revents=POLLOUT}])

getsockopt(3, SOL_SOCKET, SO_ERROR, [12884901888], [4]) = 0

fcntl(3, F_GETFL)                       = 0x802 (flags O_RDWR|O_NONBLOCK)

fcntl(3, F_SETFL, O_RDWR)               = 0

setsockopt(3, SOL_TCP, TCP_NODELAY, [1], 4) = 0

setsockopt(3, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0

setsockopt(3, SOL_TCP, TCP_KEEPIDLE, [15], 4) = 0

setsockopt(3, SOL_TCP, TCP_KEEPINTVL, [5], 4) = 0

setsockopt(3, SOL_TCP, TCP_KEEPCNT, [3], 4) = 0

write(3, "*2\r\n$4\r\nAUTH\r\n$10\r\nGs5s9SfSD8\r\n", 31) = 31

read(3, "+OK\r\n", 16384)               = 5

write(3, "*3\r\n$3\r\nSET\r\n$1\r\nA\r\n$1\r\nB\r\n", 27) = 27

read(3, "-MISCONF Redis is configured to "..., 16384) = 204

fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 1), ...}) = 0

mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f2acc030000

write(1, "(error) MISCONF Redis is configu"..., 210(error) MISCONF Redis is configured to save RDB snapshots, but is currently not able to persist on disk. Commands that may modify the data set are disabled. Please check Redis logs for details about the error.

) = 210

exit_group(0)                           = ?

-----------------------------------------------------------------

[Salvatore Sanfilippo]

Unfortunately not, I need the part of the log where Redis tells you
why it is not able to persist.

tail -f <your log file>
redis-cli BGSAVE

Read the log output and report back.

Thanks,
Salvatore

[Giovanni Trovato]

I do not see information :(

----------

<CONFIG set loglevel verbose>

redis-cli BGSAVE

tail -f <log file>

--------------

[29029] 18 Jun 15:53:56.927 - Accepted 127.0.0.1:57978

[29029] 18 Jun 15:53:56.965 - Client closed connection

[29029] 18 Jun 15:53:59.421 - DB 0: 1644727 keys (1560426 volatile) in 4194304 slots HT.

[29029] 18 Jun 15:53:59.421 - DB 1: 25599767 keys (24475158 volatile) in 67108864 slots HT.

[29029] 18 Jun 15:53:59.421 - 18 clients connected (0 slaves), 46622650368 bytes in use

[29029] 18 Jun 15:54:04.533 - DB 0: 1644723 keys (1560422 volatile) in 4194304 slots HT.

[29029] 18 Jun 15:54:04.533 - DB 1: 25599764 keys (24475155 volatile) in 67108864 slots HT.

[29029] 18 Jun 15:54:04.533 - 18 clients connected (0 slaves), 46622647936 bytes in use

----------------------

[Giovanni Trovato]

After you have killed the redis

---------------------------------------------------

# redis-cli BGSAVE 

Background saving started

(0.96s)

#  tail -f /var/log/redis_6379.log 

[29285] 18 Jun 17:14:32.957 - DB 1: 22809441 keys (21746435 volatile) in 33554432 slots HT.

[29285] 18 Jun 17:14:32.957 - 1 clients connected (0 slaves), 40966948536 bytes in use

# ll -ltr

total 24359964

-rw-r--r-- 1 root root 22379389983 Jun 18 11:07 dump.rdb

-rw-r--r-- 1 root root  1491468288 Jun 18 16:46 temp-20044.rdb

-rw-r--r-- 1 root root   715063296 Jun 18 17:24 temp-1300.rdb

---------------------------------------------------

after 2 minutes

# redis-cli BGSAVE 

(error) ERR Background save already in progress

---------------------------------------------------

> write(1, "(error) MISCONF Redis is configu"..., 210(error) MISCONF Redis is

> configured to save RDB snapshots, but is currently not able to persist on
> disk. Commands that may modify the data set are disabled. Please check Redis
> logs for details about the error.

> ) = 210
> exit_group(0)                           = ?
> -----------------------------------------------------------------
>
>
> Il giorno martedì 18 giugno 2013 15:28:37 UTC+2, Giovanni Trovato ha
> scritto:
>>

[Salvatore Sanfilippo]

Giovanni as I said you *first* start tail -f, and in another terminal
call BGSAVE, otherwise you'll never be able to see the error.

[Giovanni Trovato]

Hello Salvatore, I've done it this way.

* I commented on the following parameters:

  # save 900 1

  # save 300 10

  # save 60 10000

* I ran the command BGSAVE

* I waited that ended writing file "temp-xxx.rdb" (operation time 40 min)

* The write was successful and I have not received any error message, but did not create a new file dump.rdb

The problem occurs when I active:

save 900 1

save 300 10

save 60 10000

[Salvatore Sanfilippo]

The BGSAVE still failed since you said the dump.rdb was not created,
just Redis does not reply with an error since from its point of view
persistency is disabled.

Since you are still not telling us what happens in the log file when
save fails, there is no way to help you, and posting the latest few
lines of log does not help, you should report the portion of the log
with the save error.

Salvatore

[Giovanni Trovato]

---------------------------

(TTY: pts/1) # redis-cli CONFIG GET save 

"save" "900 1 300 10 60 10000"

(TTY: pts/1) # redis-cli BGSAVE

Background saving started

(TTY: pts/2) # tail -f /var/log/redis_6379.log 

no error

(TTY: pts/1) # ls -la

-rw-r--r-- 1 root root 22372335231 Jun 19 14:51 dump.rdb

the problem has not occurred

---------------------------

The only problem I noticed during the activity is:

 * Max number of open files set to 10032

could this be the problem?

I increased this:

---

# cat /proc/sys/fs/file-max           

4000000

# cat /proc/sys/fs/file-nr 

2592    0       4000000

---

Il giorno martedì 18 giugno 2013 15:28:37 UTC+2, Giovanni Trovato ha scritto:

[Giovanni]

Other tests carried out:

(TTY: pts/1) #  tail -f /var/log/redis_6379.log

[23867] 20 Jun 11:16:56.679 * Background saving started by pid 20593

[23867] 20 Jun 11:23:11.588 # Background saving terminated by signal 9

[23867] 20 Jun 11:23:11.637 * 10000 changes in 60 seconds. Saving...

[23867] 20 Jun 11:23:12.837 * Background saving started by pid 1039

----------

(TTY: pts/2) # strace -fF -p 20593

..., 196608) = 196608

+++ killed by SIGKILL +++

---------

the file dump.rdb is not being overwritten.

writes up to 20 gb

-------

# ll

-rw-r--r-- 1 root root 21435680113 Jun 20 08:16 dump.rdb

----------

[Giovanni]

Here is what the problem is

cat /var/log/messages

------------

Jun 20 11:23:09 xx kernel: Out of memory: Kill process 23867 (redis-server) score 721 or sacrifice child

Jun 20 11:23:09 xx kernel: Killed process 20593, UID 0, (redis-server) total-vm:43122808kB, anon-rss:37390084kB, file-rss:40kB

Jun 20 11:23:13 xx smbd[1040]: [2013/06/20 11:23:13.074398,  0] param/loadparm.c:6146(lp_int)

Jun 20 11:23:13 xxs mbd[1040]:   lp_int(): value is NULL or empty!

---------------

[Salvatore Sanfilippo]

Ok, that's useful :-)

The OOM killer is killing your Redis child, as you ran out of memory.
In the Redis log if you examine carefully you'll see this incident
reported (Redis child killed by signal).

For this to happen you probably have no or little configured swap. If
you enable Linux swapping, you'll see performances degradations
instead of OOM killer.
Having more RAM or a schema design reducing the amount of RAM needed
seems like the way to go.

Cheers,
Salvatore

[Giovanni]

thanks Salvatore,

I'm using redis with these settings:

vm.overcommit_memory = 1

---------------------------

# free -m

              total       used       free     shared    buffers     cached

Mem:     48251      47791    460          0          0           71

# vmstat -S M 

procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----

 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st

 0  2   8026    230      1    734    0    0   170   694    0    0  4  5 85  5  0

------------------------

[Giovanni]

Is there a way to have a bigger dataset?

for example greater than 200GB?

[AcidZombie24]

I'll give you two tips

The +/- line in free -m is very useful because it list required memory while the above list required memory + memory used by caching files.

If you use hashs to decrease amount of keys (hset mykey123 45 myval) is more efficient then set mykey12345 myval. BUT from my test depending on the myval size it is typically efficient with <=100 fields.

Maybe this is a 3rd tip but I thought its obvious that you should use have 50% of extra memory to save. If you have redis configured to 5gb you'll need 7.5 of memory. Mostly because the fork will require some memory and the contents will change while the dump is happening thus ram for those pages are required.