Linux 의 OOM (Out of memory) killer 로 인한 mysqld shutdown 피하기

갑자기 MySQL 이 kill 되는 수가 있다. 이는 여러가지 원인이 있을 수 있다.

1. 해당 원인은 크게 3가지로 나눈다. 여기서 볼것은 oom으로 인해 O/S가 mysqld 를 죽인 경우이다.

  • 3가지는 다음과 같다.
    • 메모리 부족으로 인해 OS 가 kill 을 시킨 경우 (이는 /var/log/message 를 확인함으로서 알 수 있다.)
    • Hardware fault로 stop 된 경우 (이는 /var/log 및의 여러로그를 확인함으로서 알 수 있다.)
    • bug로 인해 restart 된 경우 (이는 mysql error log file 을 확인함으로서 알 수 있다.)
  • 대부분의 경우 mysql 이 restart 되면 /var/log/message 를 확인하지 않는 경우가 많고 갑자기 죽었다고 생각하는데 대부분의 경우 OOM killer에 의해 죽게된다.
    • err 을 살펴보자
    150317 11:21:46 mysqld_safe Number of processes running now: 0
    150317 11:21:46 mysqld_safe mysqld restarted
    2015-03-17 11:21:49 14235 [Note] Plugin 'FEDERATED' is disabled.
    2015-03-17 11:21:49 14235 [Note] InnoDB: Using atomics to ref count buffer pool pages
    2015-03-17 11:21:49 14235 [Note] InnoDB: The InnoDB memory heap is disabled
    2015-03-17 11:21:49 14235 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
    2015-03-17 11:21:49 14235 [Note] InnoDB: Compressed tables use zlib 1.2.3
    2015-03-17 11:21:49 14235 [Note] InnoDB: Using Linux native AIO
    2015-03-17 11:21:49 14235 [Note] InnoDB: Using CPU crc32 instructions
    2015-03-17 11:21:49 14235 [Note] InnoDB: Initializing buffer pool, size = 24.0G
    2015-03-17 11:21:51 14235 [Note] InnoDB: Completed initialization of buffer pool
    2015-03-17 11:21:51 14235 [Note] InnoDB: Highest supported file format is Barracuda.
    2015-03-17 11:21:51 14235 [Note] InnoDB: Log scan progressed past the checkpoint lsn 2603553789682
    2015-03-17 11:21:51 14235 [Note] InnoDB: Database was not shutdown normally!
    2015-03-17 11:21:51 14235 [Note] InnoDB: Starting crash recovery.
    2015-03-17 11:21:51 14235 [Note] InnoDB: Reading tablespace information from the .ibd files...
    2015-03-17 11:22:03 14235 [Note] InnoDB: Restoring possible half-written data pages
    2015-03-17 11:22:03 14235 [Note] InnoDB: from the doublewrite buffer...
    InnoDB: Doing recovery: scanned up to log sequence number 2603559032320
    InnoDB: Doing recovery: scanned up to log sequence number 2603564275200
    InnoDB: Doing recovery: scanned up to log sequence number 2603569518080
    --- 죽었다는 메세지 없이 다시 시작되었다.
  • system의 log message 를 살펴보자
    vi /var/log/message
    ....
    Mar 17 11:21:42 testvm1 kernel: mysqld invoked oom-killer: gfp_mask=0x200da, order=0, oom_adj=0, oom_score_adj=0
    Mar 17 11:21:42 testvm1 kernel: [ pid ]   uid  tgid total_vm      rss cpu oom_adj oom_score_adj name
    Mar 17 11:21:42 testvm1 kernel: [ 4144]   497  4144 10443009  7862020   0       0             0 mysqld
    Mar 17 11:21:42 testvm1 kernel: Out of memory: Kill process 4144 (mysqld) score 963 or sacrifice child
    Mar 17 11:21:42 testvm1 kernel: Killed process 4144, UID 497, (mysqld) total-vm:41772036kB, anon-rss:31443592kB, file-rss:4512kB
    ...
    --- OOM-Killer 에 의해 죽은것이 관찰된다.

2. 그렇다면 OOM killer를 피할 수 있는방법을 생각해보자

  • oom_score_adj 의 값을 조정함으로서 해결 할 수 있다.
  • 해당값은 1000 ~ -1000 까지 줄 수 있다. oom_score_adj 에 대한 공식이 궁금하다면 구글링을 해보자.
  • -1000 으로 값을 설정한다면, oom killer 는 해당 process를 죽이지 않을것이다.
    cat /proc/[pid]/oom_score_adj
    echo "-1000" > /proc/self/oom_score_adj

3. 그렇다면, mysqld에 대한 process id를 띄울때마다 확인해서 해당 작업을 해야하는것일까?

  • mysql 은 mysqld가 시작되기전에 특정 script를 호출할 수 있다.
  • my.cnf의 mysqld_safe section에 mysqld=xxx.sh 를 추가함으로서 mysqld 가 시작될때 해당 script를 실행시킬 수 있다.
  • https://dev.mysql.com/doc/refman/5.6/en/mysqld-safe.html#option_mysqld_safe_mysqld
    [root@testvm1 bin]# cat /db/5.6/conf/my.cnf
    ...
    [mysqld_safe]
    mysqld=pre_mysqld_safe.sh
    user=mysql
    ...

    [root@testvm1 bin]# pwd
    /db/5.6/bin
    [root@testvm1 bin]# ls -al pre_mysqld_safe.sh
    -rwxr-xr-x. 1 root root 94 Mar 31 01:38 pre_mysqld_safe.sh
    -- mysqld와 같은 디렉토리에 해당 sh를 놓자.

    [root@testvm1 bin]# cat pre_mysqld_safe.sh
    #!/bin/sh
    echo "-1000" > /proc/self/oom_score_adj
    BIN_DIR=$(dirname "$0")
    exec "$BIN_DIR/mysqld" "$@"


    [root@testvm1 db]# cd /db/5.6
    [root@testvm1 5.6]# ./bin/mysqld_safe --defaults-file=/db/5.6/conf/my.cnf &
    [1] 27626
    [root@testvm1 5.6]# 150331 01:42:07 mysqld_safe Logging to '/data1/5.6/data/mysql.err'.
    150331 01:42:07 mysqld_safe Starting pre_mysqld_safe.sh daemon with databases from /data1/5.6/data
    -- pre_mysqld_safe.sh 로 시작되었음을 알려준다.

    [root@testvm1 5.6]# ps -ef | grep mysql
    root     27626 27539  0 01:42 pts/0    00:00:00 /bin/sh ./bin/mysqld_safe --defaults-file=/db/5.6/conf/my.cnf
    mysql    27986 27626  0 01:42 pts/0    00:00:00 /db/5.6/bin/mysqld --defaults-file=/db/5.6/conf/my.cnf --basedir=/db/5.6 --datadir=/data1/5.6/data --plugin-dir=/db/5.6/lib/plugin --user=mysql --log-error=/data1/5.6/data/mysql.err --pid-file=/data1/5.6/data/testvm1.pid --socket=/tmp/mysql.sock --port=3306
    root     28011 27539  0 01:42 pts/0    00:00:00 grep mysql
    -- mysqld 의 process id 는 27986 이다. user 는 mysql로 뜬것도 확인할 수 있다.

    [root@testvm1 5.6]# cat /proc/27986/oom_score_adj
    -1000
    -- 값이 -1000 이 된것을 알 수 있다.

4. 해당 스크립트 이외에 또 어떤것을 쓸 수 있나?

  • ulimit 명령어로 해당 값을 조절할 수 있다. (echo “-1000” > /proc/self/oom_score_adj 대신 아래의 명령어를 사용한다)
    • ulimit -u 10000
    • ulimit -c unlimited
  • NUMA 도 조절가능하다.
    • exec /usr/bin/numactl –interleave all “BIN_DIR/mysqld” “$@”