Problem in AOF rewrite

[antirez]

An user reported the following problem:

The symptom: redis-server was still running but was not accepting any new connections.

Logs at the time the issue started manifesting:

[25201] 07 May 13:32:54 * Asynchronous AOF fsync is taking too long (disk is busy?). Writing the AOF buffer without waiting for fsync to complete, this may slow down Redis.
[32264] 07 May 13:32:59 * SYNC append only file rewrite performed
[25201] 07 May 13:32:59 * Background AOF rewrite terminated with success
[25201] 07 May 13:32:59 * Parent diff successfully flushed to the rewritten AOF (445290 bytes)
[25201] 07 May 13:32:59 * Background AOF rewrite successful
[2985] 07 May 16:20:13 * SYNC append only file rewrite performed
[2986] 07 May 16:20:21 * SYNC append only file rewrite performed
[2987] 07 May 16:20:29 * SYNC append only file rewrite performed
[2988] 07 May 16:20:37 * SYNC append only file rewrite performed
[2991] 07 May 16:20:44 * SYNC append only file rewrite performed
[2992] 07 May 16:20:52 * SYNC append only file rewrite performed
[2993] 07 May 16:21:00 * SYNC append only file rewrite performed
[2994] 07 May 16:21:08 * SYNC append only file rewrite performed
[2995] 07 May 16:21:16 * SYNC append only file rewrite performed
[2996] 07 May 16:21:24 * SYNC append only file rewrite performed
[2997] 07 May 16:21:32 * SYNC append only file rewrite performed
[2998] 07 May 16:21:39 * SYNC append only file rewrite performed
[2999] 07 May 16:21:47 * SYNC append only file rewrite performed
[3000] 07 May 16:21:55 * SYNC append only file rewrite performed
[3003] 07 May 16:22:03 * SYNC append only file rewrite performed
[3004] 07 May 16:22:11 * SYNC append only file rewrite performed
[3005] 07 May 16:22:19 * SYNC append only file rewrite performed

.... this continued for ~20hrs until we restarted it here....

[1418] 08 May 13:45:53 * SYNC append only file rewrite performed
[1421] 08 May 13:46:01 * SYNC append only file rewrite performed
[1423] 08 May 13:46:09 * SYNC append only file rewrite performed
[25201] 08 May 13:46:16 # Redis is now ready to exit, bye bye...
[1430] 08 May 13:46:20 # Deprecated configuration directive: "glueoutputbuf"
[1431] 08 May 13:46:20 * Server started, Redis version 2.4.10
[1431] 08 May 13:46:20 # WARNING overcommit_memory is set to 0! Background save may fail under low memory condition. To fix this issue add 'vm.overcommit_memory = 1' to /etc/sysctl.conf and then reboot or run the command 'sysctl vm.overcommit_memory=1' for this to take effect.
[1431] 08 May 13:46:59 * DB loaded from append only file: 39 seconds
[1431] 08 May 13:46:59 * The server is now ready to accept connections on port 6380
[1431] 08 May 13:47:00 * Connecting to MASTER...
[1431] 08 May 13:47:00 * MASTER <-> SLAVE sync started
[1431] 08 May 13:47:00 * Non blocking connect for SYNC fired the event.
[1431] 08 May 13:47:00 # I/O error writing to MASTER: Connection refused
[1431] 08 May 13:47:00 * MASTER MODE enabled (user request)
[1431] 08 May 13:47:01 * Slave ask for synchronization

INFO output ofthe instance (probably after restart, see short uptime):

redis 127.0.0.1:6380> info
redis_version:2.4.10
redis_git_sha1:00000000
redis_git_dirty:0
arch_bits:64
multiplexing_api:epoll
gcc_version:4.1.2
process_id:1431
uptime_in_seconds:27249
uptime_in_days:0
lru_clock:1530626
used_cpu_sys:190.68
used_cpu_user:132.01
used_cpu_sys_children:0.77
used_cpu_user_children:0.03
connected_clients:73
connected_slaves:1
client_longest_output_list:0
client_biggest_input_buf:0
blocked_clients:0
used_memory:605376680
used_memory_human:577.33M
used_memory_rss:627777536
used_memory_peak:633387016
used_memory_peak_human:604.04M
mem_fragmentation_ratio:1.04
mem_allocator:jemalloc-2.2.5
loading:0
aof_enabled:1
changes_since_last_save:10364382
bgsave_in_progress:0
last_save_time:1336484829
bgrewriteaof_in_progress:0
total_connections_received:1400
total_commands_processed:10424169
expired_keys:7038
evicted_keys:0
keyspace_hits:6429
keyspace_misses:4949
pubsub_channels:1
pubsub_patterns:0
latest_fork_usec:18786
vm_enabled:0
role:master
aof_current_size:4420043114
aof_base_size:2962762693
aof_pending_rewrite:0
aof_buffer_length:0
aof_pending_bio_fsync:0
slave0:10.7.2.31,47349,online
db1:keys=3386,expires=3292
db2:keys=375,expires=357
db37:keys=53,expires=48

[nikegp]

looks like I'm having the same issue
what I can tell so far is that we have quite large dataset on ec2 34g instance with about 850 req/sec
aof mode enabled, rdb snapshotting disabled
after bgsave was issued the instance stopped responding however its process was running

[zou]

I'm seeing the similar problem, clients can't even connect to the server

[antirez]

I think actually the above problem was fixed in the 2.6 branch, and you are reporting a different issue unless you see repeated lines like this:

[2985] 07 May 16:20:13 * SYNC append only file rewrite performed
[2986] 07 May 16:20:21 * SYNC append only file rewrite performed

That is, if you see multiple lines like the above without any different log line in between. Is that the case? Otherwise I think we can close this issue as solved. Thanks!

[antirez]

Closing for lack of news... we never saw this again, probably gone away with recent changes in AOF code.