Software watchdog crashes redis during rdb save point #1771

Closed
andygrunwald opened this Issue May 22, 2014 · 28 comments

Comments

Projects
None yet
3 participants
@andygrunwald
Contributor

andygrunwald commented May 22, 2014

We got some trouble with our redis server regarding timeouts and high latencies. Regarding the latency documentation (http://redis.io/topics/latency) we tried to activate the software watchdog.

Our save points are "standard" (rdb):

save 900 1
save 300 10
save 60 10000

We got 16 databases and a maxmemory of 48GB.

We enabled the software watchdog first with 500 ms via

CONFIG SET watchdog-period 500

A save point was triggered (with watchdog enabled) and the redis server crashed immediately.

Redis-Version: 2.8.9
Operating System:

$ uname -a
FreeBSD redis1.trivago.com 9.2-RELEASE-p6 FreeBSD 9.2-RELEASE-p6 #0: Tue May 13 08:21:53 UTC 2014     root@amd64-builder.daemonology.net:/usr/obj/usr/src/sys/GENERIC  amd64

Here are the logs of crash + restart:

1571] 21 May 18:06:26.550 * Background saving started by pid 20267
[20267] 21 May 18:08:25.195 * DB saved on disk
[1571 | signal handler] (1400688506) 
--- WATCHDOG TIMER EXPIRED ---
[1571] 21 May 18:08:26.331 # 

=== REDIS BUG REPORT START: Cut & paste starting from here ===
[1571] 21 May 18:08:26.331 #     Redis 2.8.9 crashed by signal: 11
[1571] 21 May 18:08:26.331 #     Failed assertion: <no assertion failed> (<no file>:0)
[1571] 21 May 18:08:26.331 # --- STACK TRACE


                _._                                                  
           _.-``__ ''-._                                             
      _.-``    `.  `_.  ''-._           Redis 2.8.9 (00000000/0) 64 bit
  .-`` .-```.  ```\/    _.,_ ''-._                                   
 (    '      ,       .-`  | `,    )     Running in stand alone mode
 |`-._`-...-` __...-.``-._|'` _.-'|     Port: 6380
 |    `-._   `._    /     _.-'    |     PID: 20398
  `-._    `-._  `-./  _.-'    _.-'                                   
 |`-._`-._    `-.__.-'    _.-'_.-'|                                  
 |    `-._`-._        _.-'_.-'    |           http://redis.io        
  `-._    `-._`-.__.-'_.-'    _.-'                                   
 |`-._`-._    `-.__.-'    _.-'_.-'|                                  
 |    `-._`-._        _.-'_.-'    |                                  
  `-._    `-._`-.__.-'_.-'    _.-'                                   
      `-._    `-.__.-'    _.-'                                       
          `-._        _.-'                                           
              `-.__.-'                                               

[20398] 21 May 18:10:50.836 # Server started, Redis version 2.8.9

[20398] 21 May 18:11:22.261 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:11:27.002 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:11:29.387 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:11:29.554 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:11:31.085 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:11:33.549 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:11:35.760 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:11:36.069 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:11:46.132 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:11:46.252 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:11:46.327 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:11:47.929 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:11:48.443 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:11:48.536 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:11:48.571 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:11:50.789 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:11:50.916 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:11:50.946 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:11:53.787 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:11:53.846 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:11:53.876 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:11:56.293 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:11:56.327 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:11:56.666 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:11:58.220 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:11:59.813 # Accepting client connection: accept: Software caused connection abort

[20398] 21 May 18:12:05.743 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:12:08.500 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:12:10.321 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:12:12.297 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:12:12.329 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:12:14.149 # Accepting client connection: accept: Software caused connection abort
^C
[root@redis1 /appdata/redis/logs_6380]# tail -f redis_6380.log 
[20398] 21 May 18:11:56.327 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:11:56.666 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:11:58.220 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:11:59.813 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:12:05.743 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:12:08.500 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:12:10.321 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:12:12.297 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:12:12.329 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:12:14.149 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:12:15.858 # Accepting client connection: accept: Software caused connection abort


[20398] 21 May 18:12:32.725 * DB loaded from disk: 101.888 seconds
[20398] 21 May 18:12:32.725 * The server is now ready to accept connections on port 6380
[20398] 21 May 18:12:32.735 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:12:32.744 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:12:32.745 # Accepting client connection: accept: Software caused connection abort
[20398] 21 May 18:12:32.746 * Slave asks for synchronization
[20398] 21 May 18:12:32.746 * Partial resynchronization not accepted: Runid mismatch (Client asked for 'bcf3f55502af2484af6fa5140f8fbb611ab9321e', I'm 'bf911f6d8e6e488c8c809864aa8486eba887feef')
[20398] 21 May 18:12:32.746 * Starting BGSAVE for SYNC
[20398] 21 May 18:12:33.162 * Background saving started by pid 20418
[20418] 21 May 18:14:12.573 * DB saved on disk
[20398] 21 May 18:14:13.450 * Background saving terminated with success
[20398] 21 May 18:15:14.073 * 10000 changes in 60 seconds. Saving...
[20398] 21 May 18:15:14.274 * Background saving started by pid 20508
[20508] 21 May 18:16:44.886 * DB saved on disk
[20398] 21 May 18:16:45.519 * Background saving terminated with success
[20398] 21 May 18:16:58.104 * Synchronization with slave succeeded
[20398] 21 May 18:17:46.004 * 10000 changes in 60 seconds. Saving...
[20398] 21 May 18:17:46.261 * Background saving started by pid 20510
[20510] 21 May 18:19:18.171 * DB saved on disk
[20398] 21 May 18:19:18.797 * Background saving terminated with success
[20398] 21 May 18:20:19.028 * 10000 changes in 60 seconds. Saving...
[20398] 21 May 18:20:19.312 * Background saving started by pid 20594

Here is a redis info (with modified slave ip address):

redis-cli -p 6380 INFO
# Server
redis_version:2.8.9
redis_git_sha1:00000000
redis_git_dirty:0
redis_build_id:53bb8484a594dab0
redis_mode:standalone
os:FreeBSD 9.2-RELEASE-p6 amd64
arch_bits:64
multiplexing_api:kqueue
gcc_version:4.2.1
process_id:20398
run_id:bf911f6d8e6e488c8c809864aa8486eba887feef
tcp_port:6380
uptime_in_seconds:53709
uptime_in_days:0
hz:10
lru_clock:8233431
config_file:/usr/local/etc/redis_6380.conf

# Clients
connected_clients:65
client_longest_output_list:0
client_biggest_input_buf:0
blocked_clients:0

# Memory
used_memory:11231875376
used_memory_human:10.46G
used_memory_rss:11231923968
used_memory_peak:12198858520
used_memory_peak_human:11.36G
used_memory_lua:33792
mem_fragmentation_ratio:1.00
mem_allocator:libc

# Persistence
loading:0
rdb_changes_since_last_save:7875
rdb_bgsave_in_progress:0
rdb_last_save_time:1400742246
rdb_last_bgsave_status:ok
rdb_last_bgsave_time_sec:128
rdb_current_bgsave_time_sec:-1
aof_enabled:0
aof_rewrite_in_progress:0
aof_rewrite_scheduled:0
aof_last_rewrite_time_sec:-1
aof_current_rewrite_time_sec:-1
aof_last_bgrewrite_status:ok
aof_last_write_status:ok

# Stats
total_connections_received:20883238
total_commands_processed:1464561492
instantaneous_ops_per_sec:771
rejected_connections:0
sync_full:1
sync_partial_ok:0
sync_partial_err:1
expired_keys:622997
evicted_keys:0
keyspace_hits:480478421
keyspace_misses:17653570
pubsub_channels:0
pubsub_patterns:0
latest_fork_usec:450797

# Replication
role:master
connected_slaves:1
slave0:ip=111.222.333.4444,port=6380,state=online,offset=45484974777,lag=1
master_repl_offset:45484995315
repl_backlog_active:1
repl_backlog_size:1048576
repl_backlog_first_byte_offset:45483946740
repl_backlog_histlen:1048576

# CPU
used_cpu_sys:2052.40
used_cpu_user:5284.90
used_cpu_sys_children:912.71
used_cpu_user_children:27393.28

# Keyspace
db0:keys=39355280,expires=838513,avg_ttl=249056694
db4:keys=62,expires=62,avg_ttl=73770671
db5:keys=844,expires=0,avg_ttl=0
db8:keys=154,expires=154,avg_ttl=403093829
db9:keys=1108,expires=0,avg_ttl=0
db11:keys=4026987,expires=4026986,avg_ttl=1608844295

The crash was yesterday evening (2014-05-21 ~6pm).
The info is from a few minutes ago (2014-05-22 ~9am).

If you need more information please let me know.

@mattsta

This comment has been minimized.

Show comment
Hide comment
@mattsta

mattsta May 22, 2014

Contributor

I can't seem to reproduce the crash on a FreeBSD 9.2 system. The error report shows a segfault, which wouldn't be triggered by the watchdog alarm.

Can you reproduce the crash?

timeouts and high latencies.

It looks like you're running FreeBSD on EC2, so some timeouts and latency could just be intrinsic to your deployment. You can run redis-cli --intrinsic-latency 30 (runs for 30 seconds) to get a sense of what the OS is doing to processes on your system. You can also test network latency to your server with redis-cli --latency. It's best to run --latency from your client machines and not the redis-server server (though, you can run it on your server too and compare the latency introduced by your network).

Contributor

mattsta commented May 22, 2014

I can't seem to reproduce the crash on a FreeBSD 9.2 system. The error report shows a segfault, which wouldn't be triggered by the watchdog alarm.

Can you reproduce the crash?

timeouts and high latencies.

It looks like you're running FreeBSD on EC2, so some timeouts and latency could just be intrinsic to your deployment. You can run redis-cli --intrinsic-latency 30 (runs for 30 seconds) to get a sense of what the OS is doing to processes on your system. You can also test network latency to your server with redis-cli --latency. It's best to run --latency from your client machines and not the redis-server server (though, you can run it on your server too and compare the latency introduced by your network).

@andygrunwald

This comment has been minimized.

Show comment
Hide comment
@andygrunwald

andygrunwald May 22, 2014

Contributor

We didn`t try to reproduce the crash, because it was on a production environment. So we did not tried again. We want to start a new try with save points disabled in the next days (maybe tomorrow).

From the crash we got a 13 GB big core file. But this redis wasn`t compiled with debug symbols so afaik this core file is useless, right?

We are running this server not on EC2. We are running it on our own physical hardware. No vm.

We did a latency check today (2014-05-22 ~9am). Here are the results:

Intrinsic-latency on the redis server machine:

$ redis-cli -p 6380 --intrinsic-latency 60
Max latency so far: 5 microseconds.
Max latency so far: 9 microseconds.
Max latency so far: 121 microseconds.
Max latency so far: 122 microseconds.

24586821 total runs (avg 2 microseconds per run).
Worst run took 61.00x times the avarege.09:29

Latency from a client machine:

$ redis-cli --latency -p 6380 -h 111.222.333.4444
min: 0, max: 463, avg: 2.03 (19443 samples)

During watchdog execution the server was in production and under load (~ 140 connected clients).
Maybe this can be the issue?

Contributor

andygrunwald commented May 22, 2014

We didn`t try to reproduce the crash, because it was on a production environment. So we did not tried again. We want to start a new try with save points disabled in the next days (maybe tomorrow).

From the crash we got a 13 GB big core file. But this redis wasn`t compiled with debug symbols so afaik this core file is useless, right?

We are running this server not on EC2. We are running it on our own physical hardware. No vm.

We did a latency check today (2014-05-22 ~9am). Here are the results:

Intrinsic-latency on the redis server machine:

$ redis-cli -p 6380 --intrinsic-latency 60
Max latency so far: 5 microseconds.
Max latency so far: 9 microseconds.
Max latency so far: 121 microseconds.
Max latency so far: 122 microseconds.

24586821 total runs (avg 2 microseconds per run).
Worst run took 61.00x times the avarege.09:29

Latency from a client machine:

$ redis-cli --latency -p 6380 -h 111.222.333.4444
min: 0, max: 463, avg: 2.03 (19443 samples)

During watchdog execution the server was in production and under load (~ 140 connected clients).
Maybe this can be the issue?

@mattsta

This comment has been minimized.

Show comment
Hide comment
@mattsta

mattsta May 22, 2014

Contributor

Oh, that does help. Now it crashes for me too. I'll reproduce it under a debugger and let you know what I find.

Contributor

mattsta commented May 22, 2014

Oh, that does help. Now it crashes for me too. I'll reproduce it under a debugger and let you know what I find.

@andygrunwald

This comment has been minimized.

Show comment
Hide comment
@andygrunwald

andygrunwald May 22, 2014

Contributor

I tried to reproduce this with a MacOSX notebook (no load, no big database) and was not successful.
What does the trick to make it crash?

If i can help to try to reproduce (on a freebsd vm and not in production) just ping me :)

Contributor

andygrunwald commented May 22, 2014

I tried to reproduce this with a MacOSX notebook (no load, no big database) and was not successful.
What does the trick to make it crash?

If i can help to try to reproduce (on a freebsd vm and not in production) just ping me :)

mattsta added a commit to mattsta/redis that referenced this issue May 22, 2014

Disable recursive watchdog signal handler
If we are in the signal handler, we don't want to handle
the signal again.  In extreme cases, this can cause a stack overflow
and segfault Redis.

Fixes #1771
@mattsta

This comment has been minimized.

Show comment
Hide comment
@mattsta

mattsta May 22, 2014

Contributor

So, the behavior is somewhat random, but reproducible given enough tries.

I first reproduced it (on FreeBSD only) with redis-server in one terminal (all default options), then setting CONFIG SET watchdog-period 3, then running redis-benchmark -r 1200000000 -t set -n 99999999. The server died with a segfault within two minutes (sometimes it doesn't fail though, or it takes much longer).

The segfault could also be triggered (sometimes) by manually running SAVE and/or BGSAVE against the server while the long redis-benchmark runs (still with the watchdog timer enabled).

Looking closer, all the watchdog does is deliver a SIGALRM when a timeout happens. So, we can set watchdog-period then send a SIGALRM ourselves to print the watchdog timer output with kill -SIGALRM [redis-server pid]. That works great. We can even loop it: while true; do kill -SIGALRM [redis-server pid]; done. When we do that, redis-server dies pretty quickly. A backtrace shows we blow out our stack with thousands of watchdogSignalHandler. This happens on FreeBSD, OS X, and Linux.

So! At this point, we see, sometimes, SIGALRM is being delivered while we are already in the signal handler. That's bad.

The signal handler is being initialized with SA_NODEFER | SA_ONSTACK | SA_SIGINFO. The SA_NODEFER option lets the signal handler be interrupted by the same signal currently being handled, letting us end up with an infinite stack of signal handlers until the kernel segfaults us.

Removing SA_NODEFER from the watchdog options makes redis-server not die when confronted with a while true; SIGALRM loop.

Since testing for the original situation isn't entirely reliable, I haven't been able to compare many "this crashes" vs "this fixes it" runs. Feel free to try some different configurations on your own systems and report back.

Contributor

mattsta commented May 22, 2014

So, the behavior is somewhat random, but reproducible given enough tries.

I first reproduced it (on FreeBSD only) with redis-server in one terminal (all default options), then setting CONFIG SET watchdog-period 3, then running redis-benchmark -r 1200000000 -t set -n 99999999. The server died with a segfault within two minutes (sometimes it doesn't fail though, or it takes much longer).

The segfault could also be triggered (sometimes) by manually running SAVE and/or BGSAVE against the server while the long redis-benchmark runs (still with the watchdog timer enabled).

Looking closer, all the watchdog does is deliver a SIGALRM when a timeout happens. So, we can set watchdog-period then send a SIGALRM ourselves to print the watchdog timer output with kill -SIGALRM [redis-server pid]. That works great. We can even loop it: while true; do kill -SIGALRM [redis-server pid]; done. When we do that, redis-server dies pretty quickly. A backtrace shows we blow out our stack with thousands of watchdogSignalHandler. This happens on FreeBSD, OS X, and Linux.

So! At this point, we see, sometimes, SIGALRM is being delivered while we are already in the signal handler. That's bad.

The signal handler is being initialized with SA_NODEFER | SA_ONSTACK | SA_SIGINFO. The SA_NODEFER option lets the signal handler be interrupted by the same signal currently being handled, letting us end up with an infinite stack of signal handlers until the kernel segfaults us.

Removing SA_NODEFER from the watchdog options makes redis-server not die when confronted with a while true; SIGALRM loop.

Since testing for the original situation isn't entirely reliable, I haven't been able to compare many "this crashes" vs "this fixes it" runs. Feel free to try some different configurations on your own systems and report back.

@andygrunwald

This comment has been minimized.

Show comment
Hide comment
@andygrunwald

andygrunwald May 22, 2014

Contributor

Thanks for your work @mattsta!
I will try to setup your fork and reproduce this on a macbook or a freebsd system.

Contributor

andygrunwald commented May 22, 2014

Thanks for your work @mattsta!
I will try to setup your fork and reproduce this on a macbook or a freebsd system.

@antirez

This comment has been minimized.

Show comment
Hide comment
@antirez

antirez May 22, 2014

Owner

Excellent investigation, thanks. This is not the first crash report using the software watchdog, but it was never with enough context to reproduce like this one. It's great that we are going to have a more solid software watchdog implementation...

Owner

antirez commented May 22, 2014

Excellent investigation, thanks. This is not the first crash report using the software watchdog, but it was never with enough context to reproduce like this one. It's great that we are going to have a more solid software watchdog implementation...

@andygrunwald

This comment has been minimized.

Show comment
Hide comment
@andygrunwald

andygrunwald May 26, 2014

Contributor

Thanks for everyone.
Sadly i can`t reproduce this behaviour on my local mac book (after 10 tries) and i do not want to test it in production :(

Can anyone else reproduce it?
And will be this change merged in 2.8.10 ? Or in 3.0?

@mattsta: Will you take care of merging?

Contributor

andygrunwald commented May 26, 2014

Thanks for everyone.
Sadly i can`t reproduce this behaviour on my local mac book (after 10 tries) and i do not want to test it in production :(

Can anyone else reproduce it?
And will be this change merged in 2.8.10 ? Or in 3.0?

@mattsta: Will you take care of merging?

@antirez

This comment has been minimized.

Show comment
Hide comment
@antirez

antirez May 26, 2014

Owner

Hello, Sure I'll merge the fix. I'll try to reproduce it on my local systems btw.

Owner

antirez commented May 26, 2014

Hello, Sure I'll merge the fix. I'll try to reproduce it on my local systems btw.

@antirez

This comment has been minimized.

Show comment
Hide comment
@antirez

antirez May 26, 2014

Owner

p.s. it will be merged both into 2.8.10 and 3.0 of course.

Owner

antirez commented May 26, 2014

p.s. it will be merged both into 2.8.10 and 3.0 of course.

@mattsta

This comment has been minimized.

Show comment
Hide comment
@mattsta

mattsta May 26, 2014

Contributor

It's possible the case of crashing with watchdog+saving only happens on FreeBSD due to how different kernels handle signals. Linux and OS X could be handling signals in a less error-prone way to avoid the problem completely. Each OS still fails the 'while true send SIGALRM' trick though.

Contributor

mattsta commented May 26, 2014

It's possible the case of crashing with watchdog+saving only happens on FreeBSD due to how different kernels handle signals. Linux and OS X could be handling signals in a less error-prone way to avoid the problem completely. Each OS still fails the 'while true send SIGALRM' trick though.

@antirez

This comment has been minimized.

Show comment
Hide comment
@antirez

antirez May 26, 2014

Owner

@mattsta we definitely saw this happening on Linux multiple times, it is just hard to trigger...

Owner

antirez commented May 26, 2014

@mattsta we definitely saw this happening on Linux multiple times, it is just hard to trigger...

@antirez

This comment has been minimized.

Show comment
Hide comment
@antirez

antirez May 26, 2014

Owner

Btw, focusing on this issue to try to understand better what happens and what you did. When I've some news I'll write it down, anyway your fix seems the right thing to do regardless of the findings. I'm just curious if this fix is related to the previous crashes we saw.

Owner

antirez commented May 26, 2014

Btw, focusing on this issue to try to understand better what happens and what you did. When I've some news I'll write it down, anyway your fix seems the right thing to do regardless of the findings. I'm just curious if this fix is related to the previous crashes we saw.

@antirez

This comment has been minimized.

Show comment
Hide comment
@antirez

antirez May 26, 2014

Owner

Ok, @mattsta I see that you actually reproduced the problem without using the SIGALRM flood, so... you did your tests on FreeBSD directly?

Owner

antirez commented May 26, 2014

Ok, @mattsta I see that you actually reproduced the problem without using the SIGALRM flood, so... you did your tests on FreeBSD directly?

@antirez

This comment has been minimized.

Show comment
Hide comment
@antirez

antirez May 26, 2014

Owner

@mattsta btw your SIGALRM loop brings back very old memories... http://seclists.org/bugtraq/1998/May/139

Owner

antirez commented May 26, 2014

@mattsta btw your SIGALRM loop brings back very old memories... http://seclists.org/bugtraq/1998/May/139

@mattsta

This comment has been minimized.

Show comment
Hide comment
@mattsta

mattsta May 26, 2014

Contributor

I tested on the "FreeBSD 9.2 i386" image from http://www.vagrantbox.es/ by first updating ports then installing redis from ports (which includes their FreeBSD specific patches allowing backtraces and, optionally, automatically replacing Lua with LuaJIT!).

Nice 16 year old similar issue too!

Contributor

mattsta commented May 26, 2014

I tested on the "FreeBSD 9.2 i386" image from http://www.vagrantbox.es/ by first updating ports then installing redis from ports (which includes their FreeBSD specific patches allowing backtraces and, optionally, automatically replacing Lua with LuaJIT!).

Nice 16 year old similar issue too!

@antirez

This comment has been minimized.

Show comment
Hide comment
@antirez

antirez May 26, 2014

Owner

@mattsta I'm stressing the hell out of my Linux box with HZ=1000 and a watchdog timer of 4 ms, benchmark active, plus a redis-cli -r -1 BGSAVE. No way to trigger a crash. Btw this could be explained by the following Linux kernel characteristic (from setitimer man page):

       The  generation  and  delivery  of  a signal are distinct, and only one
       instance of each of the signals listed  above  may  be  pending  for  a
       process.   Under  very  heavy  loading, an ITIMER_REAL timer may expire
       before the signal from a previous expiration has been  delivered.   The
       second signal in such an event will be lost.

Probably it is actually hard on Linux to get two signals delivered at the same time by only using the setitimer() interface.

However, if after the fix you can no longer trigger the issue on FreeBSD, this is a big hint about likely the bug being now fixed.

I can see only another more general cause here, but this would be not hard to spot, while we can't see the problem actually... which is, a bad interaction with an interrupted syscall not handled in the Redis code.

So I'm quite confident you found the real issue. Now grepping for the past related issues.

Owner

antirez commented May 26, 2014

@mattsta I'm stressing the hell out of my Linux box with HZ=1000 and a watchdog timer of 4 ms, benchmark active, plus a redis-cli -r -1 BGSAVE. No way to trigger a crash. Btw this could be explained by the following Linux kernel characteristic (from setitimer man page):

       The  generation  and  delivery  of  a signal are distinct, and only one
       instance of each of the signals listed  above  may  be  pending  for  a
       process.   Under  very  heavy  loading, an ITIMER_REAL timer may expire
       before the signal from a previous expiration has been  delivered.   The
       second signal in such an event will be lost.

Probably it is actually hard on Linux to get two signals delivered at the same time by only using the setitimer() interface.

However, if after the fix you can no longer trigger the issue on FreeBSD, this is a big hint about likely the bug being now fixed.

I can see only another more general cause here, but this would be not hard to spot, while we can't see the problem actually... which is, a bad interaction with an interrupted syscall not handled in the Redis code.

So I'm quite confident you found the real issue. Now grepping for the past related issues.

@antirez antirez referenced this issue May 26, 2014

Closed

Redis crash #1023

@antirez

This comment has been minimized.

Show comment
Hide comment
@antirez

antirez May 26, 2014

Owner

Ok an interesting fact. If you look at #1023, the bug output is exactly the same (the watchdog timer fires, it tries to generate the backtrace, fails probably because of the nested call, segfaults, tries again to generate the trace, and dies silently). Another hint about this being the same issue that @mattsta discovered.

Owner

antirez commented May 26, 2014

Ok an interesting fact. If you look at #1023, the bug output is exactly the same (the watchdog timer fires, it tries to generate the backtrace, fails probably because of the nested call, segfaults, tries again to generate the trace, and dies silently). Another hint about this being the same issue that @mattsta discovered.

@mattsta mattsta closed this in 7a0c5fd May 26, 2014

mattsta added a commit that referenced this issue May 26, 2014

Disable recursive watchdog signal handler
If we are in the signal handler, we don't want to handle
the signal again.  In extreme cases, this can cause a stack overflow
and segfault Redis.

Fixes #1771

mattsta added a commit that referenced this issue May 26, 2014

Disable recursive watchdog signal handler
If we are in the signal handler, we don't want to handle
the signal again.  In extreme cases, this can cause a stack overflow
and segfault Redis.

Fixes #1771
@antirez

This comment has been minimized.

Show comment
Hide comment
@antirez

antirez May 26, 2014

Owner

@mattsta fix merged into all the branches. I'll release 2.8.10 in the next days with this fix.

Owner

antirez commented May 26, 2014

@mattsta fix merged into all the branches. I'll release 2.8.10 in the next days with this fix.

@antirez

This comment has been minimized.

Show comment
Hide comment
@antirez

antirez May 26, 2014

Owner

Reopening to wait for feedbacks from @andygrunwald

Owner

antirez commented May 26, 2014

Reopening to wait for feedbacks from @andygrunwald

@antirez antirez reopened this May 26, 2014

@andygrunwald

This comment has been minimized.

Show comment
Hide comment
@andygrunwald

andygrunwald May 26, 2014

Contributor

We will try it on a FreeBSD as well.
I try to do this tomorrow or Wednesday.

Contributor

andygrunwald commented May 26, 2014

We will try it on a FreeBSD as well.
I try to do this tomorrow or Wednesday.

@antirez

This comment has been minimized.

Show comment
Hide comment
@antirez

antirez May 26, 2014

Owner

Thanks Andy

Owner

antirez commented May 26, 2014

Thanks Andy

@andygrunwald

This comment has been minimized.

Show comment
Hide comment
@andygrunwald

andygrunwald May 26, 2014

Contributor

Current status: Compiling redis...

Contributor

andygrunwald commented May 26, 2014

Current status: Compiling redis...

@andygrunwald

This comment has been minimized.

Show comment
Hide comment
@andygrunwald

andygrunwald May 26, 2014

Contributor

Okay. I can reproduce this problem very easy on a FreeBSD system:

$ uname -a
FreeBSD xxx.xxx.com 9.2-RELEASE-p6 FreeBSD 9.2-RELEASE-p6 #0: Tue May 13 08:21:53 UTC 2014     root@amd64-builder.daemonology.net:/usr/obj/usr/src/sys/GENERIC  amd64
  • Install redis from ports and atart redis
  • CONFIG SET watchdog-period 3
  • redis-benchmark -r 1200000000 -t set -n 99999999
  • During the benchmark: DEBUG SLEEP 100
  • Redis chrash

Now i installed the current 2.8 branch:

  • Deinstall redis
  • git clone https://github.com/antirez/redis.git
  • cd redis
  • git checkout -b 2.8 origin/2.8
  • gmake && gmake install
  • Start redis /usr/local/bin/redis-server /tmp/redis/redis.conf &
  • Same Watchdog + Benchmark + Debug commands as above
  • ... aaaaand redis does not crash anymore:

Logfile

[11508] 26 May 18:29:59.860 # Server started, Redis version 2.8.9
[11508] 26 May 18:29:59.861 * The server is now ready to accept connections on port 6379
[11508] 26 May 18:31:00.026 * 10000 changes in 60 seconds. Saving...
[11508] 26 May 18:31:00.027 * Background saving started by pid 11515
[11515] 26 May 18:31:00.335 * DB saved on disk
[11508] 26 May 18:31:00.428 * Background saving terminated with success
[11508 | signal handler] (1401121874)
--- WATCHDOG TIMER EXPIRED ---
[11508 | signal handler] (1401121874) Sorry: no support for backtrace().
[11508 | signal handler] (1401121874) --------
[11508 | signal handler] (1401121890)
--- WATCHDOG TIMER EXPIRED ---
[11508 | signal handler] (1401121890) Sorry: no support for backtrace().
[11508 | signal handler] (1401121890) --------
[11508] 26 May 18:32:01.003 * 10000 changes in 60 seconds. Saving...
[11508] 26 May 18:32:01.015 * Background saving started by pid 11516
[11516] 26 May 18:32:05.016 * DB saved on disk
[11508] 26 May 18:32:05.117 * Background saving terminated with success

Thanks for fixing!

Contributor

andygrunwald commented May 26, 2014

Okay. I can reproduce this problem very easy on a FreeBSD system:

$ uname -a
FreeBSD xxx.xxx.com 9.2-RELEASE-p6 FreeBSD 9.2-RELEASE-p6 #0: Tue May 13 08:21:53 UTC 2014     root@amd64-builder.daemonology.net:/usr/obj/usr/src/sys/GENERIC  amd64
  • Install redis from ports and atart redis
  • CONFIG SET watchdog-period 3
  • redis-benchmark -r 1200000000 -t set -n 99999999
  • During the benchmark: DEBUG SLEEP 100
  • Redis chrash

Now i installed the current 2.8 branch:

  • Deinstall redis
  • git clone https://github.com/antirez/redis.git
  • cd redis
  • git checkout -b 2.8 origin/2.8
  • gmake && gmake install
  • Start redis /usr/local/bin/redis-server /tmp/redis/redis.conf &
  • Same Watchdog + Benchmark + Debug commands as above
  • ... aaaaand redis does not crash anymore:

Logfile

[11508] 26 May 18:29:59.860 # Server started, Redis version 2.8.9
[11508] 26 May 18:29:59.861 * The server is now ready to accept connections on port 6379
[11508] 26 May 18:31:00.026 * 10000 changes in 60 seconds. Saving...
[11508] 26 May 18:31:00.027 * Background saving started by pid 11515
[11515] 26 May 18:31:00.335 * DB saved on disk
[11508] 26 May 18:31:00.428 * Background saving terminated with success
[11508 | signal handler] (1401121874)
--- WATCHDOG TIMER EXPIRED ---
[11508 | signal handler] (1401121874) Sorry: no support for backtrace().
[11508 | signal handler] (1401121874) --------
[11508 | signal handler] (1401121890)
--- WATCHDOG TIMER EXPIRED ---
[11508 | signal handler] (1401121890) Sorry: no support for backtrace().
[11508 | signal handler] (1401121890) --------
[11508] 26 May 18:32:01.003 * 10000 changes in 60 seconds. Saving...
[11508] 26 May 18:32:01.015 * Background saving started by pid 11516
[11516] 26 May 18:32:05.016 * DB saved on disk
[11508] 26 May 18:32:05.117 * Background saving terminated with success

Thanks for fixing!

@mattsta

This comment has been minimized.

Show comment
Hide comment
@mattsta

mattsta May 26, 2014

Contributor

Note: compiling on FreeBSD outside of the ports tree disables backtrace support, which could be contributing to the problem. It's best to compile with the patches from ports tree applied for full behavior.

Contributor

mattsta commented May 26, 2014

Note: compiling on FreeBSD outside of the ports tree disables backtrace support, which could be contributing to the problem. It's best to compile with the patches from ports tree applied for full behavior.

@andygrunwald

This comment has been minimized.

Show comment
Hide comment
@andygrunwald

andygrunwald May 26, 2014

Contributor

@mattsta you are right. Thanks for this information.
Should i repeat it again or is my testing with your note enough for this fix?

Contributor

andygrunwald commented May 26, 2014

@mattsta you are right. Thanks for this information.
Should i repeat it again or is my testing with your note enough for this fix?

@mattsta

This comment has been minimized.

Show comment
Hide comment
@mattsta

mattsta May 26, 2014

Contributor

The fix is tiny (just delete SA_NODEFER: mattsta@36ab9cf). To get it running from the ports tree:

  • edit that one line in your ports/databases/redis/.../src download
  • run the port make install again (or build and test locally in the src/ dir)
  • re-test

That should cover everything. :)

Contributor

mattsta commented May 26, 2014

The fix is tiny (just delete SA_NODEFER: mattsta@36ab9cf). To get it running from the ports tree:

  • edit that one line in your ports/databases/redis/.../src download
  • run the port make install again (or build and test locally in the src/ dir)
  • re-test

That should cover everything. :)

@andygrunwald

This comment has been minimized.

Show comment
Hide comment
@andygrunwald

andygrunwald May 26, 2014

Contributor

Okay. Then i would just skip the new test.
Thanks for everyone to track this issue down!
Now we can debug more things to improve the redis infrastructure :)

Contributor

andygrunwald commented May 26, 2014

Okay. Then i would just skip the new test.
Thanks for everyone to track this issue down!
Now we can debug more things to improve the redis infrastructure :)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment