Redis 引发系统OOM Killer

昨晚（2016-9-5），生产环境的Redis发生警报，一段时间后，内存被降到50%多（之前一直在90%左右），然后发现Redis的进程挂了。第一时间看Redis的log文件，发现有如下信息:

1
2
3
4
5
6
7
8
9
10866:M 05 Sep 20:15:19.711 # Background saving terminated by signal 9
10866:M 05 Sep 20:18:43.898 # Background saving terminated by signal 9
10866:M 05 Sep 20:26:46.434 # Background saving terminated by signal 9
10866:M 05 Sep 20:34:49.161 # Background saving terminated by signal 9
10866:M 05 Sep 20:42:52.406 # Background saving terminated by signal 9
10866:M 05 Sep 20:42:55.332 # Background saving terminated by signal 9
1758:M 05 Sep 21:28:11.114 # Background saving terminated by signal 9
1758:M 05 Sep 21:30:18.479 # Background saving terminated by signal 9
1758:M 05 Sep 21:32:55.275 # Background saving terminated by signal 9

可知Redis收到kill -9的信号终止了.然后，当时第一反应，应该是“有人”人工去kill Redis进程吗？不知道怎么的，当时自己就去查看操作系统日志dmesg -T | grep redis，真的发现是有内幕：

1
2
3
4
5
6
7
8
9
10
11
12
dmesg -T | grep redis | grep "Out of memory"
[Mon Sep  5 20:15:18 2016] Out of memory: Kill process 725 (redis-server) score 517 or sacrifice child
[Mon Sep  5 20:18:42 2016] Out of memory: Kill process 786 (redis-server) score 517 or sacrifice child
[Mon Sep  5 20:26:45 2016] Out of memory: Kill process 914 (redis-server) score 517 or sacrifice child
[Mon Sep  5 20:34:48 2016] Out of memory: Kill process 1022 (redis-server) score 517 or sacrifice child
[Mon Sep  5 20:42:50 2016] Out of memory: Kill process 1127 (redis-server) score 517 or sacrifice child
[Mon Sep  5 20:42:52 2016] Out of memory: Kill process 10866 (redis-server) score 517 or sacrifice child
[Mon Sep  5 20:50:57 2016] Out of memory: Kill process 1235 (redis-server) score 517 or sacrifice child
[Mon Sep  5 20:50:57 2016] Out of memory: Kill process 10866 (redis-server) score 517 or sacrifice child
[Mon Sep  5 21:28:10 2016] Out of memory: Kill process 1886 (redis-server) score 479 or sacrifice child
[Mon Sep  5 21:30:17 2016] Out of memory: Kill process 1758 (redis-server) score 479 or sacrifice child
[Mon Sep  5 21:32:54 2016] Out of memory: Kill process 1972 (redis-server) score 479 or sacrifice child
1
2
3
dmesg -T | grep redis | grep "oom-killer"
[Mon Sep  5 20:26:44 2016] redis-server invoked oom-killer: gfp_mask=0x10200da, order=0, oom_score_adj=0
[Mon Sep  5 21:32:53 2016] redis-server invoked oom-killer: gfp_mask=0x8200da, order=0, oom_score_adj=0

当天查看的Redis内存信息如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
# Memory
used_memory:7877146344
used_memory_human:7.34G
used_memory_rss:8699490304
used_memory_rss_human:8.10G
used_memory_peak:8462552976
used_memory_peak_human:7.88G
total_system_memory:16828653568
total_system_memory_human:15.67G
used_memory_lua:37888
used_memory_lua_human:37.00K
maxmemory:9573741824
maxmemory_human:8.92G
maxmemory_policy:noeviction
mem_fragmentation_ratio:1.10
mem_allocator:jemalloc-4.0.3

原因

当时服务器还有个MySQL slave在进行复制备份，服务器一共16GB的内存，然后MySQL用掉了5GB，还有11GB内存，除去一些其他的简单的占用和消耗外，估计还有10GB的内存真正给Redis可用。

可以看到上面的INFO，当时分配给Redis最大的内存为差不多9GB，那应试还有1GB可用空间，那到底是什么导致了OS触发OOM Killer机制呢？

原来，Redis当时开启了RDB功能，而Redis自身是通过fork()进程来处理RDB文件的。可以man fork知道，它是精确复制与父进程来处理RDB文件的。

Redis在后台的存储机制依赖于操作系统中fork的copy-on-write：也就是redis fork（创建一个子进程）是父进程的一个完整精确拷贝。子进程转储到磁盘上的数据库然后退出。理论上来说，子进程作为一个副本应该使用和父亲一样多的内存，但是实际上由于大部分现代操作系统的copy-on-write的实现，父进程和子进程将共享内存页。当他被父进程或者子进程改变的时候，一个内存页将被复制。因此，从理论上讲，当子进程存储的时候，所有内存页可能被改变，Linux不能提前告诉子进程多少内存被使用，所以如果overcommit_memory设置被设置为0，创建将会失败，除非有同样多的空闲内存。结果是，如果你有3GB的redis数据并且只有2GB的空闲内存，它将会失败。

把overcommit_memory设置为1来告诉Linux以更加乐观的方式来执行fork操作，并且这确实是你想要的。

参考资料:

Redis FAQ ifeve redis faq中文翻译

overcommit_memory 对fork的影响

我们可以来做一个实验，来一步一步理解这个参数到fork的影响. 测试的环境是:

1
2
3
4
5
6
7
8
9
┌─[sky@sky-linux] - [~] - [2016-09-06 02:43:37]
└─[0] <> uname -a
Linux sky-linux 3.19.0-32-generic #37~14.04.1-Ubuntu SMP Thu Oct 22 09:41:40 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux
┌─[sky@sky-linux] - [~] - [2016-09-06 02:46:14]
└─[0] <> free -h 
             total       used       free     shared    buffers     cached
Mem:           15G        10G       4.6G       750M       209M       3.8G
-/+ buffers/cache:       7.0G       8.6G
Swap:           0B         0B         0B

可以看到，还有8.6GB空闲内存。默认的情况下，overcommit_memory的值是：

1
2
3
┌─[sky@sky-linux] - [~] - [2016-09-06 02:47:16]
└─[0] <> cat /proc/sys/vm/overcommit_memory 
0

即它是以试探式分配内存，如果不够的话，就直接拒绝该次的内存分配.

示例代码：父进程分配了5GB，这时再fork()一个子进程，看看会发生什么事：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
#include<stdio.h>
#include <unistd.h>
int main()
{
  void *ptr_one;
  pid_t childPID;
  ptr_one = calloc(1342177280, sizeof(int));
  if (ptr_one == 0)
		{
			printf("ERROR: Out of memory\n");
			return 1;
		}
  childPID = fork();
  if(childPID >= 0) // fork was successful
    {
      if(childPID == 0) // child process
        {
          printf("\n child process\n");
          sleep(60);
        }
      else //Parent process
        {
          printf("\n parent process\n");
          sleep(60);
        }
    }
  else // fork failed
    {
      printf("\n Fork failed, quitting!!!!!!\n");
      return 1;
    }
  return 0;
}

overcommit_memory = 0

编译运行：

1
2
3
4
5
6
7
8
9
10
┌─[sky@sky-linux] - [/tmp] - [2016-09-06 02:56:40]
└─[0] <> gcc mall.c 
mall.c: In function ‘main’:
mall.c:7:13: warning: incompatible implicit declaration of built-in function ‘calloc’ [enabled by default]
   ptr_one = calloc(1342177280, sizeof(int));
             ^
┌─[sky@sky-linux] - [/tmp] - [2016-09-06 02:56:44]
└─[0] <> ./a.out 
 Fork failed, quitting!!!!!!

因为空闲内存是8.6G，而父进程使用了5GB，这时再fork一个子进程的话，那5GB+5GB=10GB，这时是不够内存分配的，所以OS直接拒绝了该次内存申请.

overcommit_memory = 1

1
2
3
4
5
6
7
8
9
sky-linux# echo "1" > /proc/sys/vm/overcommit_memory
┌─[sky@sky-linux] - [/tmp] - [2016-09-06 02:56:48]
└─[1] <> ./a.out 
 parent process
 child process

这时查看内存使用情况:

1
2
3
4
sky-linux# free -h
             total       used       free     shared    buffers     cached
Mem:           15G        15G       227M       606M       116M       3.2G
-/+ buffers/cache:        11G       3.6G

8.6GB-5GB=3.6GB，那为什么不是占用10GB，而只是5GB呢？这是因为Linux使用copy-on-write机制.它只对要修改的数据块进行copy-and-write。

overcommit_memory = 2

于禁止overcommit (vm.overcommit_memory=2) 还需要细说： 首先，如何才算是overcommit呢？kernel设有一个阈值，申请的内存总数超过这个阈值就算overcommit，在/proc/meminfo中可以看到这个阈值的大小：

1
2
3
4
5
6
7
8
9
# grep -i commit /proc/meminfo
CommitLimit:     5967744 kB
Committed_AS:    5363236 kB
1
2
3
# grep -i commit /proc/meminfo
CommitLimit:     5967744 kB
Committed_AS:    5363236 kB

CommitLimit: 就是overcommit的阈值，申请的内存总数超过CommitLimit的话就算是overcommit。那么这个阈值是如何计算出来的呢？它既不是物理内存的大小，也不是free memory的大小，它是通过内核参数间接设置的，公式如下： CommitLimit = (Physical RAM * vm.overcommit_ratio / 100) + Swap

这个是非常严格的，这样子，因为它是never overcommit。运行上面的代码:

1
2
3
┌─[sky@sky-linux] - [/tmp] - [2016-09-06 04:23:00]
└─[1] <> ./a.out
ERROR: Out of memory

可以看到它直接报错了，即申请5GB内存不成功。因为CommitLimit=15GB * 50 /100 = 7.5GB，即最多可以分配7.5GB空间，但已经用了7GB，这时再申请5GB的话，已经超过了7.5GB的限制，所以OS直接拒绝了该次内存申请。

参考资料: * linuxperf * coolshell

解决

  • 加内存咯（如果已经充分利用了Redis的存储结构来保存了最适合的数据，即Redis层已经最优了，不然的话，可以先优化Redis层先）

  • 将Redis的Maxmemory调到可用的物理内存的3/5，并且将overcommit_memory=1，这样子虽然可以避免OOM，不过，这样子可以让我们知道，物理内存是瓶颈了。

  • 调整Redis的OOM权重，即不能让OS的OOM机制Kill掉redis，但这样子会导致OOM Killer其他进程哦:

    1
    2
    3
    4
    5
    6
    echo "-17" > /proc/redis的进程IP/oom_adj
    新版本的Linux参数修改为：
    [Tue Sep  6 16:50:06 2016] echo (349): /proc/5360/oom_adj is deprecated, please use /proc/5360/oom_score_adj instead.
    即使用 oom_score_adj 来代替.

OOM Killer是会kill掉 /proc/PID/oom_score（新版本为oom_score_adj)中分数越高的进程.(oom_score_adj的范围为-1000到1000)

可以模拟触发OOM：

1
echo f > /proc/sysrq-trigger

执行完上面的命令后，查看

1
dmesg -T

查找出系统中首先会被Kill的进程

1
dstat --top-oom
1
for i in /proc/*/oom_score; do pid=$(echo "${i}" | cut -d/ -f3); echo "oom_score=$(cat "${i}"), PID=${pid}, exe=$(readlink -e /proc/${pid}/exe)"; done 2> /dev/null | sort -rn -t, -k 1.11 | head -n 50

参考资料

查看历史命令的执行时间

1
export HISTTIMEFORMAT="%d/%m/%y %T "

这有个问题，就是之前的历史命令，会统一为执行这个export的命令，然后之后的命令才会记录下时间.