MongoDB触发oom-killer的简单处理（一)

今天正在处理问题，突然收到一封邮件，提示mongo的一个副本集出现了问题。邮件内容如下：
当前状态：PROBLEM
事件编号：11187790
发生时间：2015.12.21 13:30:01
持续时长：1h 20m
监控节点：mongo_mobile_gl_comment_sec.161
报警级别：高危(High)
事件信息：One or more replication members need attention
事件详情：Replication: Count of ReplicaSet Members Needing Attention: 1
DEBUG信息：
Replication: Count of ReplicaSet Members Needing Attention (mongo_mobile_gl_comment_sec.161:repl_member_attention_state_count): 1
对于这类问题，最开始以为是网络延时，结果邮件还是持续报警，这个时候感觉应该是哪里出了问题。连接到环境中，发现mongo进程已经消失了。
尝试连接，提示连接失败。
[root@mongo_mobile_gl_comment_sec ~]# mongo --port=27010
MongoDB shell version: 2.6.3
connecting to: 127.0.0.1:27010/test
2015-12-21T12:21:28.407+0530 warning: Failed to connect to 127.0.0.1:27010, reason: errno:111 Connection refused
2015-12-21T12:21:28.407+0530 Error: couldn't connect to server 127.0.0.1:27010 (127.0.0.1), connection attempt failed at src/mongo/shell/mongo.js:148
exception: connect failed
这个时候准备重启mongoDB，这个时候提示重启失败。
[root@mongo_mobile_gl_comment_sec ~]# /etc/init.d/mongod start
Starting mongod: [FAILED]
这个时候只能查看日志了，得到的日志信息如下，可以看到服务器重启的痕迹，但是mongo重启失败。
less /storage/mongodb/log/mongod.log
2015-12-21T11:06:02.893+0530 [PeriodicTaskRunner] task: DBConnectionPool-cleaner took: 8ms
2015-12-21T11:06:33.976+0530 [conn1675793] command admin.$cmd command: isMaster { ismaster: 1 } keyUpdates:0 numYields:0  reslen:434 1094ms
2015-12-21T11:06:33.976+0530 [conn1675786] command local.$cmd command: getnonce { getnonce: 1 } ntoreturn:1 keyUpdates:0 numYields:0  reslen:65 30244ms
2015-12-21T11:06:33.976+0530 [conn1675795] command admin.$cmd command: isMaster { ismaster: 1 } keyUpdates:0 numYields:0  reslen:434 1096ms
2015-12-21T11:06:33.976+0530 [conn1675794] command admin.$cmd command: buildInfo { buildinfo: 1 } keyUpdates:0 numYields:0  reslen:700 1039ms
2015-12-21T11:06:33.982+0530 [conn1675789] command local.$cmd command: getnonce { getnonce: 1 } ntoreturn:1 keyUpdates:0 numYields:0  reslen:65 31111ms
2015-12-21T11:06:33.982+0530 [conn1675788] command local.$cmd command: getnonce { getnonce: 1 } ntoreturn:1 keyUpdates:0 numYields:0  reslen:65 30028ms
2015-12-21T11:06:33.982+0530 [conn1675790] command local.$cmd command: getnonce { getnonce: 1 } ntoreturn:1 keyUpdates:0 numYields:0  reslen:65 31079ms
2015-12-21T11:06:33.982+0530 [conn1675791] command local.$cmd command: getnonce { getnonce: 1 } ntoreturn:1 keyUpdates:0 numYields:0  reslen:65 31095ms
2015-12-21T11:06:34.715+0530 [conn1675792] command admin.$cmd command: isMaster { ismaster: 1 } keyUpdates:0 numYields:0  reslen:434 30769ms
2015-12-21T11:06:34.769+0530 [conn271045] query mobile_UCENTER.scoreRecord query: { $and: [ { uid: 2093542 }, { createTime: { $lte: new Date(1450675608270) } }, { createTime: { $gte: new Date(1450636200270) } } ] } planSummary: IXSCAN { uid: 1 } ntoreturn:0 ntoskip:0 nscanned:125 nscannedObjects:125 keyUpdates:0 numYields:109 locks(micros) r:275071880 nreturned:0 reslen:20 576812ms
2015-12-21T11:06:43.649+0530 [PeriodicTaskRunner] task: WriteBackManager::cleaner took: 15ms
2015-12-21T12:25:31.762+0530 ***** SERVER RESTARTED *****
2015-12-21T12:25:31.775+0530 [initandlisten] MongoDB starting : pid=11668 port=27010 dbpath=/storage/mongodb/data/db/ 64-bit host=mongo_mobile_gl_comment_sec.126
2015-12-21T12:25:31.775+0530 [initandlisten] db version v2.6.3
2015-12-21T12:25:31.775+0530 [initandlisten] git version: 255f67a66f9603c59380b2a389e386910bbb52cb
2015-12-21T12:25:31.775+0530 [initandlisten] build info: Linux build12.nj1.10gen.cc 2.6.32-431.3.1.el6.x86_64 #1 SMP Fri Jan 3 21:39:27 UTC 2014 x86_64 BOOST_LIB_VERSION=1_49
2015-12-21T12:25:31.775+0530 [initandlisten] allocator: tcmalloc
2015-12-21T12:25:31.775+0530 [initandlisten] options: { config: "/etc/mongod.conf", net: { bindIp: "127.0.0.1,172.16.3.126", http: { enabled: false }, maxIncomingConnections: 5000, port: 27010 }, processManagement: { fork: true, pidFilePath: "/storage/mongodb/mongod.pid" }, replication: { oplogSizeMB: 30960, replSet: "rs_comment" }, security: { authorization: "enabled", keyFile: "/home/mongodb/key/rs_key" }, storage: { dbPath: "/storage/mongodb/data/db/", directoryPerDB: true, journal: { enabled: false } }, systemLog: { destination: "file", logAppend: true, path: "/storage/mongodb/log/mongod.log", quiet: true } }
2015-12-21T12:25:31.786+0530 [initandlisten] exception in initAndListen: 12596 old lock file, terminating
2015-12-21T12:25:31.786+0530 [initandlisten] dbexit:
2015-12-21T12:25:31.786+0530 [initandlisten] shutdown: going to close listening sockets...
2015-12-21T12:25:31.786+0530 [initandlisten] shutdown: going to flush diaglog...
2015-12-21T12:25:31.786+0530 [initandlisten] shutdown: going to close sockets...
2015-12-21T12:25:31.786+0530 [initandlisten] shutdown: waiting for fs preallocator...
2015-12-21T12:25:31.786+0530 [initandlisten] shutdown: closing all files...
2015-12-21T12:25:31.786+0530 [initandlisten] closeAllFiles() finished
2015-12-21T12:25:31.786+0530 [initandlisten] dbexit: really exiting now
对于这类问题，因为也算是菜鸟，所以有些不知所措，不过看了下日志错误，提示是存在一个锁文件，这个看起来和weblogic启动也有点类似，查了一下百度，也得到了印证，我就不继续靠谷歌了。开始备份这个锁文件
[root@mongo_mobile_gl_comment_sec db]# mv mongod.lock mongod.lock.bak
然后继续尝试重启，这次就没有问题了。
[root@mongo_mobile_gl_comment_sec db]# /etc/init.d/mongod start
Starting mongod: [  OK  ]
再次尝试登录就可以看到是成功了。
[root@mongo_mobile_gl_comment_sec db]# mongo --port=27010
MongoDB shell version: 2.6.3
connecting to: 127.0.0.1:27010/test
当然回过头来，为什么服务器会重启，重启之后可以看到，服务器的负载极高。几乎没有任何喘气的空隙了。
top - 15:29:37 up 364 days,  6:50,  1 user,  load average: 92.52, 59.74, 34.39
Tasks:  73 total,   1 running,  72 sleeping,   0 stopped,   0 zombie          
Cpu(s): 26.7%us,  7.8%sy,  0.0%ni,  0.7%id, 60.7%wa,  2.8%hi,  1.2%si,  0.2%st
Mem:  15408212k total, 15199732k used,   208480k free,     2732k buffers      
Swap: 16777212k total,     9540k used, 16767672k free, 13722616k cached  
使用sar得到的结果如下，可以看到idle没有什么空间了。
[root@mongo_mobile_gl_comment_sec db]# sar 1 3
Linux 3.10.42-52.145.amzn1.x86_64 (mongo_mobile_gl_comment_sec.126)       12/21/2015      _x86_64_        (2 CPU)
03:30:12 PM     CPU     %user     %nice   %system   %iowait    %steal     %idle
03:30:13 PM     all     46.84      0.00      8.95     43.68      0.53      0.00
03:30:14 PM     all     23.16      0.00      9.47     66.32      0.00      1.05
03:30:15 PM     all     18.18      0.00      5.88     75.40      0.53      0.00
Average:        all     29.45      0.00      8.11     61.73      0.35      0.35
查看系统日志，看看奔溃前的服务器情况。然后又看到了熟悉的oom-killer，又是out of memory,又是swap不足了。
Dec 21 10:47:51 template-mongodb-2-6-3 dhclient[1504]: bound to 172.16.3.126 -- renewal in 1415 seconds.
Dec 21 11:09:07 template-mongodb-2-6-3 kernel: [31458594.279409] mongod invoked oom-killer: gfp_mask=0x201da, order=0, oom_score_adj=0
Dec 21 11:09:07 template-mongodb-2-6-3 kernel: [31458594.286302] mongod cpuset=/ mems_allowed=0
Dec 21 11:09:07 template-mongodb-2-6-3 kernel: [31458594.288577] CPU: 0 PID: 11565 Comm: mongod Not tainted 3.10.42-52.145.amzn1.x86_64 #1
Dec 21 11:09:07 template-mongodb-2-6-3 kernel: [31458594.292344] Hardware name: Xen HVM domU, BIOS 4.2.amazon 12/03/2014
。。。
Dec 21 11:09:07 template-mongodb-2-6-3 kernel: [31458594.503711] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
Dec 21 11:09:07 template-mongodb-2-6-3 kernel: [31458594.508107] 37117 total pagecache pages
Dec 21 11:09:07 template-mongodb-2-6-3 kernel: [31458594.510198] 34175 pages in swap cache
Dec 21 11:09:07 template-mongodb-2-6-3 kernel: [31458594.512098] Swap cache stats: add 5987691, delete 5953516, find 100670521/100858969
Dec 21 11:09:07 template-mongodb-2-6-3 kernel: [31458594.515633] Free swap  = 8kB
Dec 21 11:09:07 template-mongodb-2-6-3 kernel: [31458594.517084] Total swap = 16777212kB
Dec 21 11:09:07 template-mongodb-2-6-3 kernel: [31458594.554801] 3999999 pages RAM
Dec 21 11:09:07 template-mongodb-2-6-3 kernel: [31458594.556423] 82410 pages reserved
Dec 21 11:09:07 template-mongodb-2-6-3 kernel: [31458594.558234] 526732 pages shared
Dec 21 11:09:07 template-mongodb-2-6-3 kernel: [31458594.559786] 3881988 pages non-shared
。。。
Dec 21 11:09:07 template-mongodb-2-6-3 kernel: [31458594.678772] [ 8407]     0  8407    63087      900      75        0             0 php
Dec 21 11:09:07 template-mongodb-2-6-3 kernel: [31458594.682439] Out of memory: Kill process 23821 (mongod) score 982 or sacrifice child
Dec 21 11:09:07 template-mongodb-2-6-3 kernel: [31458594.686761] Killed process 23821 (mongod) total-vm:794240260kB, anon-rss:13553192kB, file-rss:0kB

可以在重启之后看到swap的进程情况。
  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                                                                    
11830 mongod    20   0  728g  10g 9.9g S 82.2 70.0 106:53.68 /usr/bin/mongod -f /etc/mongod.conf                                                                        
  326 root      20   0     0    0    0 S  2.7  0.0   4989:16 [kswapd0]  
以10秒为间隔，可以看到产生了大量的读操作。
[root@mongo_mobile_gl_comment_sec ~]# mongotop -h 127.0.0.1 --port 27010 -u admin -p'xxxxxx' 10
connected to: 127.0.0.1:27010
                              ns       total        read       write            2015-12-21T10:33:56
        mobile_UCENTER.scoreRecord   1986786ms   1986786ms         0ms
                   social.t_user    117490ms    117490ms         0ms
 mobile_UCENTER.T_USER_INVITE_CODE     97416ms     97416ms         0ms
                social.t_comment     94913ms     94913ms         0ms
                  social.t_topic     74259ms     74259ms         0ms
          mobile_UCENTER.expRecord     48979ms     48979ms         0ms
                 social.t_praise      7286ms      7286ms         0ms
              social.t_topic_sub      4003ms      4003ms         0ms
       mobile_UCENTER.boughtRecord      1561ms      1561ms         0ms
使用mongostat查看统计信息。可以看到不同的db的负载情况，连dml的情况都能够统计的非常详细。
# mongostat -h 127.0.0.1 --port 27010 -u admin -p'xxxxxxx' 5
connected to: 127.0.0.1:27010
insert  query update delete getmore command flushes mapped  vsize    res faults   locked db idx miss %     qr|qw   ar|aw  netIn netOut  conn        set repl       time
    *9    955     *8     *0       0    11|0       0   726g   728g  10.1g   2371 social:0.3%          0     116|0     1|0   166k   308k  1527 rs_comment  SEC   16:05:19
   *20   2080     *7     *0       0    10|0       0   726g   728g  10.1g   2315 mobile_UCENTER:0.4%          0     700|0     2|0   342k   449k  1527 rs_comment  SEC   16:05:25
   *22   1963    *13     *0       0    14|0       0   726g   728g  10.2g   2909 mobile_UCENTER:0.2%          0       0|0   300|0   352k   426k  1527 rs_comment  SEC   16:05:30
   *18   1583     *5     *0       0    11|0       0   726g   728g  10.2g   2495 mobile_UCENTER:0.3%          0     282|0    10|0   275k   346k  1527 rs_comment  SEC   16:05:35
后续的就是持续深化，优化好之后再来收尾，看看为什么会负载突然提升，从系统层面怎么提升了。