一段mongodb服务器读取数据超时的故事
转载:http://www.cnblogs.com/xinzhiyu/p/5907542.html
北京时间 2016年9月25日 22:58:30 PM
近期线上生产环境mongodb的总是发现读取数据超时的问题，今天下午坐下来细细的研究了一番，大致过程如下：
业务背景
线上有一对mongodb主从的服务器，只是简单做了mongodb的主从，master - slave。
开始以为做了主从就能确保数据不丢的问题了，确实，数据没有发生丢失的问题，但是近期发现好多用户在点击某些操作要读取mongo里面的数据内容的时候，要等待很长的时间，这样的等待是叫人无法忍受的。
最开始的时候，以为做了主从，然后在Tomcat的mong配置文件中设置好读写分离的步骤就能做到读写分离了，可是不然，并没有想象的那么好，实际的结果是不管读还是写都被无情的把任务分发到了主的上面，这样一来主的压力就很大了，导致了用户读取数据的时候，需要花费很长的时间来进行等待，沿着这个问题，我们就有了下文
问题排查：
问题排查之：网卡流量君
先使用sar命令查看了服务器的网卡流量信息，发现正常：
sar -n DEV 1 #1秒钟刷新一次网卡流量信息
23时05分26秒 IFACE rxpck/s txpck/s rxkB/s txkB/s rxcmp/s txcmp/s rxmcst/s 23时05分27秒 lo 0.00 0.00 0.00 0.00 0.00 0.00 0.00 23时05分27秒 eth1 909.18 818.37 64.31 148.47 0.00 0.00 0.00
问题排查之：服务器CPU君
查看了cpu之后发现并没有什么异常，8核的cpu使用率不到1%
top 时时显示服务器资源信息
Cpu0 : 57.4%us, 2.6%sy, 0.0%ni, 32.3%id, 0.0%wa, 2.6%hi, 5.2%si, 0.0%st Cpu1 : 0.0%us, 0.0%sy, 0.0%ni,100.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st Cpu2 : 0.6%us, 0.0%sy, 0.0%ni, 99.4%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st Cpu3 : 0.6%us, 0.0%sy, 0.0%ni, 99.4%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st Cpu4 : 0.0%us, 0.0%sy, 0.0%ni,100.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st Cpu5 : 0.0%us, 0.0%sy, 0.0%ni,100.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st Cpu6 : 0.0%us, 0.0%sy, 0.0%ni,100.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st Cpu7 : 0.0%us, 0.0%sy, 0.0%ni,100.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
问题排查之：服务器内存君
查看了内存使用情况，16GB的内存，我天已经爆满了，会不会是因为服务器内存不够了，要加内存呢？
free -m 显示内存信息
total used free shared buffers cached Mem: 15950 15338 612 0 105 8925 -/+ buffers/cache: 1307 14642 Swap: 1023 682 341
查了下为什么内存使用率如此之高，最后得到的结论是mongo并不会主动的释放内存资源，这就需要我们手动的进行内存的释放
内存君的手动释放
在清理前内存使用情况 free -m
total used free shared buffers cached Mem: 15950 15338 612 0 105 8925 -/+ buffers/cache: 1307 14642 Swap: 1023 682 341
用以下命令清理内存
echo 1 > /proc/sys/vm/drop_caches
清理后内存使用情况再用以下命令看看。
free –m
total used free shared buffers cached Mem: 15950 10432 5518 0 118 9034 -/+ buffers/cache: 1279 14671 Swap: 1023 681 342
虽然内存得到了解决，但是。。。。 mongo的读取数据慢的原因依旧未能找到
问题继续排查之：外来进程君
ps -ef 显示系统进程
这里不方便把服务器开启了那些进程罗列到此处，还请见谅；最后的分析结果就是，并无异常进程
这就奇怪了，到底是哪的问题呢？
此时io这个词，在我头脑中转悠，我想会不会硬盘io堵塞，导致读取数据超级慢呢？来，继续
问题继续排查之：系统io君
iostart -x 1 每一秒钟查看一下系统下所有磁盘的io使用状况
avg-cpu: %user %nice %system %iowait %steal %idle 11.64 0.00 1.13 0.00 0.00 7.23 Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 sdb 0.00 7.00 0.00 5.00 0.00 104.00 20.80 0.00 0.20 0.20 99.10 dm-0 0.00 0.00 0.00 12.00 0.00 104.00 8.67 0.01 0.67 0.08 0.10
找到了一个可疑的元凶，磁盘io的等待很高，磁盘超负荷运转。
沿着这个思路，顺藤摸瓜，找到了研发同事问了下对mongodb做了什么，他们淡定的说，就是简单的增加、查询之操作；好吧，那我就看看到底mongo的使用状态吧
顺藤摸瓜之：mongo的使用状况
mongostat -h xx.xx.xx.xx:DD --rowcount 20 1 xx.xx.xx.xx表示mongodb的服务器地址，DD表示mongodb的端口，20表示查看20s，1表示1秒钟刷新1次
insert query update delete getmore command flushes mapped vsize res faults locked db idx miss % qr|qw ar|aw netIn netOut conn repl time *0 *0 *0 *0 0 2|0 0 31g 62.7g 999m 0 young:0.0% 0 0|0 0|0 120b 3k 18 SLV 23:19:57 *0 *0 *0 *0 0 1|0 0 31g 62.7g 999m 0 young:0.0% 0 0|0 0|0 62b 3k 18 SLV 23:19:58 *0 *0 *0 *0 0 8|0 0 31g 62.7g 999m 0 local:0.0% 0 0|0 0|0 468b 5k 18 SLV 23:19:59 *0 *0 *0 *0 0 5|0 0 31g 62.7g 999m 0 young:0.0% 0 0|0 0|0 294b 4k 18 SLV 23:20:00 *1 *0 *0 *0 0 6|0 0 31g 62.7g 999m 0 .:0.1% 0 0|0 0|0 352b 4k 18 SLV 23:20:01 *0 *0 *0 *0 0 2|0 0 31g 62.7g 999m 0 young:0.0% 0 0|0 0|0 120b 3k 18 SLV 23:20:02
最终元凶：就这样发现了mongodb的写操作超级频繁，导致了磁盘I/O堵塞，致使最后的数据读取超级慢、超级慢、超级慢，由此可见java程序对mongodb的读写分离并
没有生效、没有生效、没有生效
既然找到了元凶，那么我们来想一个解决这个麻烦的办法----------“读写分离”。
解决麻烦之：读写分离
先看看读写分离的原理：这里借鉴了以为博友的思想 地址
1. Replica Sets 复制集 MongoDB 支持在多个机器中通过异步复制达到故障转移和实现冗余。多机器中同一时刻只有一台是用于写操作。正是由于这个情况，为 MongoDB 提供了数据一致性的保障。担当Primary角色的机器能把读操作分发给 slave。 那这样，是不是以后读取数据就不会跟主“惨祸（沧州话）”了呢？Of course MongoDB 高可用可用分两种: 1.1 Master-Slave ：主从复制 只需要在某一个服务启动时加上–master参数，而另一个服务加上–slave与–source参数，即可实现同步。MongoDB 的最新版本已不再推荐此方案。 1.2 Replica Sets复制集 MongoDB 在 1.6版本对开发了新功能replica set，这比之前的replication功能要强大一些，增加了故障自动切换和自动修复成员节点，各个DB之间数据完全一致，大大降低了维护成功。auto shard已经明确说明不支持replication paris，建议使用replica set，replica set故障切换完全自动。 如果上图所示，Replica Sets的结构非常类似一个集群。是的，你完全可以把它当成集群，因为它确实跟集群实现的作用是一样的，其中一个节点如果出现故障，其它节点马上会将业务接过来而无须停机操作。
Mongodb(M)表示主节点，Mongodb(S)表示备节点，Mongodb(A)表示仲裁节点。主备节点存储数据，仲裁节点不存储数据。客户端同时连接主节点与备节点，不连接仲裁节点。
默认设置下，主节点提供所有增删查改服务，备节点不提供任何服务。但是可以通过设置使备节点提供查询服务，这样就可以减少主节点的压力，当客户端进行数据查询时，请求自动转到备节点上。这个设置叫做Read Preference Modes，同时Java客户端提供了简单的配置方式，可以不必直接对数据库进行操作。
仲裁节点是一种特殊的节点，它本身并不存储数据，主要的作用是决定哪一个备节点在主节点挂掉之后提升为主节点，所以客户端不需要连接此节点。这里虽然只有一个备节点，但是仍然需要一个仲裁节点来提升备节点级别。我开始也不相信必须要有仲裁节点，但是自己也试过没仲裁节点的话，主节点挂了备节点还是备节点，所以咱们还是需要它的。
只是负责故障转移的群体投票，这样就少了数据复制的压力。
部署 Replica Sets
环境： ubuntu 14.04、mongod-2.6.3x64
一下所有步骤均为测试环境操作，线上操作还请朋友自己更改相应的路径
1. 建立数据文件夹
mkdir -p /mongodb/data/master --主
mkdir -p /mongodb/log/
mkdir -p /mongodb/data/slaver --备
mkdir -p /mongodb/log/
mkdir -p /mongodb/data/arbiter --仲裁
mkdir -p /mongodb/log/
touch /mongodb/log/master.log
touch /mongodb/log/slaver.log
touch /mongodb/log/arbiter.log
touch /mongodb/master.pid
touch /mongodb/slaver.pid
touch /mongodb/arbiter.pid
chmod -R 755 /mongodb --三个节点都执行
2.建立配置文件
# master.conf
dbpath=/mongodb/data/master
logpath=/mongodb/log/master.log
pidfilepath=/mongodb/master.pid
directoryperdb=true
logappend=true
replSet=testrs
bind_ip=192.168.1.101
port=27017
oplogSize=10000
fork=true
noprealloc=true
logpath=/mongodb/log/master.log
pidfilepath=/mongodb/master.pid
directoryperdb=true
logappend=true
replSet=testrs
bind_ip=192.168.1.101
port=27017
oplogSize=10000
fork=true
noprealloc=true
# slaver.conf
dbpath=/mongodb/data/slaver
logpath=/mongodb/log/slaver.log
pidfilepath=/mongodb/slaver.pid
directoryperdb=true
logappend=true
replSet=testrs
bind_ip=192.168.1.101
port=27018
oplogSize=10000
fork=true
noprealloc=true
logpath=/mongodb/log/slaver.log
pidfilepath=/mongodb/slaver.pid
directoryperdb=true
logappend=true
replSet=testrs
bind_ip=192.168.1.101
port=27018
oplogSize=10000
fork=true
noprealloc=true
#arbiter.conf
dbpath=/mongodb/data/arbiter
logpath=/mongodb/log/arbiter.log
logpath=/mongodb/log/arbiter.log
pidfilepath=/mongodb/arbiter.pid
directoryperdb=true
logappend=true
replSet=testrs
bind_ip=192.168.1.101
port=27019
oplogSize=10000
fork=true
noprealloc=true
logappend=true
replSet=testrs
bind_ip=192.168.1.101
port=27019
oplogSize=10000
fork=true
noprealloc=true
给以上文件加上读写执行的权限
[root@node1 bin]# chmod 755 master.conf
[root@node1 bin]# chmod 755 slaver.conf
[root@node1 bin]# chmod 755 arbiter.conf
注意： 把 .log 等文件也建好
参数解释：
dbpath：数据存放目录
logpath：日志存放路径
pidfilepath：进程文件，方便停止mongodb
directoryperdb：为每一个数据库按照数据库名建立文件夹存放
logappend：以追加的方式记录日志
replSet：replica set的名字
bind_ip：mongodb所绑定的ip地址
port：mongodb进程所使用的端口号，默认为27017
oplogSize：mongodb操作日志文件的最大大小。单位为Mb，默认为硬盘剩余空间的5%
fork：以后台方式运行进程
noprealloc：不预先分配存储
dbpath：数据存放目录
logpath：日志存放路径
pidfilepath：进程文件，方便停止mongodb
directoryperdb：为每一个数据库按照数据库名建立文件夹存放
logappend：以追加的方式记录日志
replSet：replica set的名字
bind_ip：mongodb所绑定的ip地址
port：mongodb进程所使用的端口号，默认为27017
oplogSize：mongodb操作日志文件的最大大小。单位为Mb，默认为硬盘剩余空间的5%
fork：以后台方式运行进程
noprealloc：不预先分配存储
3.启动mongodb
进入每个mongodb节点的bin目录下
进入每个mongodb节点的bin目录下
[root@node1 bin]# ./mongod -f master.conf
[root@node1 bin]# ./mongod -f slaver.conf
[root@node1 bin]# ./mongod -f arbiter.conf
注意配置文件的路径一定要保证正确，可以是相对路径也可以是绝对路径。
4.配置主，备，仲裁节点
可以通过客户端连接mongodb，也可以直接在三个节点中选择一个连接mongodb。
./mongo 192.168.1.101:27017 #ip和port是某个节点的地址
>use admin
>cfg={ _id:"testrs", members:[
{_id:0,host:'192.168.1.101:27017',priority:2},
{_id:1,host:'192.168.1.101:27018',priority:1},
{_id:2,host:'192.168.1.101:27019',arbiterOnly:true}] --永远不成为主节点
{_id:2,host:'192.168.1.101:27019',arbiterOnly:true}] --永远不成为主节点
};
>rs.initiate(cfg) #使配置生效
cfg是可以任意的名字，当然最好不要是mongodb的关键字，conf，config都可以。
最外层的_id表示replica set的名字，
members里包含的是所有节点的地址以及优先级。优先级最高的即成为主节点，即这里的192.168.56.87:27017。
特别注意的是，对于仲裁节点，
需要有个特别的配置——arbiterOnly:true。只能作为secondary副本节点，防止一些性能不高的节点成为主节点。
这个千万不能少了，不然主备模式就不能生效。
配置的生效时间根据不同的机器配置会有长有短，配置不错的话基本上十几秒内就能生效，有的配置需要一两分钟。
testrs:PRIMARY> rs.status()
{
"set" : "testrs",
"date" : ISODate("2015-05-08T03:27:59.706Z"),
"myState" : 1,
"members" : [
{
"_id" : 0,
"name" : "192.168.1.101:27017",
"health" : 1, --1表明正常; 0表明异常
"state" : 1, -- 1表明是Primary; 2 表明是Secondary;
"stateStr" : "PRIMARY", --表明此机器是主库
"uptime" : 620,
"optime" : Timestamp(1431055581, 1),
"optimeDate" : ISODate("2016-09-025T23:26:21Z"),
"electionTime" : Timestamp(1431055584, 1),
"electionDate" : ISODate("2015-09-25T23:26:24Z"),
"configVersion" : 1,
"self" : true
},
{
"_id" : 1,
"name" : "192.168.1.101:27018",
"health" : 1,
"state" : 2, -- 1表明是Primary; 2 表明是Secondary;
"stateStr" : "SECONDARY", --表明此机器是从库
"uptime" : 294,
"optime" : Timestamp(1431055581, 1),
"optimeDate" : ISODate("2016-09-25T23:26:21Z"),
"lastHeartbeat" : ISODate("2016-09-25T23:27:58.189Z"),
"lastHeartbeatRecv" : ISODate("2015-09-25T23:27:59.287Z"),
"pingMs" : 0,
"configVersion" : 1
},
{
"_id" : 2,
"name" : "192.168.1.101:27019",
"health" : 1,
"state" : 7,
"stateStr" : "ARBITER",
"uptime" : 294,
"lastHeartbeat" : ISODate("2016-09-25T23:27:59.686Z"),
"lastHeartbeatRecv" : ISODate("2015-09-25T23:27:58.028Z"),
"pingMs" : 0,
"configVersion" : 1
}
],
"ok" : 1
}
{
"set" : "testrs",
"date" : ISODate("2015-05-08T03:27:59.706Z"),
"myState" : 1,
"members" : [
{
"_id" : 0,
"name" : "192.168.1.101:27017",
"health" : 1, --1表明正常; 0表明异常
"state" : 1, -- 1表明是Primary; 2 表明是Secondary;
"stateStr" : "PRIMARY", --表明此机器是主库
"uptime" : 620,
"optime" : Timestamp(1431055581, 1),
"optimeDate" : ISODate("2016-09-025T23:26:21Z"),
"electionTime" : Timestamp(1431055584, 1),
"electionDate" : ISODate("2015-09-25T23:26:24Z"),
"configVersion" : 1,
"self" : true
},
{
"_id" : 1,
"name" : "192.168.1.101:27018",
"health" : 1,
"state" : 2, -- 1表明是Primary; 2 表明是Secondary;
"stateStr" : "SECONDARY", --表明此机器是从库
"uptime" : 294,
"optime" : Timestamp(1431055581, 1),
"optimeDate" : ISODate("2016-09-25T23:26:21Z"),
"lastHeartbeat" : ISODate("2016-09-25T23:27:58.189Z"),
"lastHeartbeatRecv" : ISODate("2015-09-25T23:27:59.287Z"),
"pingMs" : 0,
"configVersion" : 1
},
{
"_id" : 2,
"name" : "192.168.1.101:27019",
"health" : 1,
"state" : 7,
"stateStr" : "ARBITER",
"uptime" : 294,
"lastHeartbeat" : ISODate("2016-09-25T23:27:59.686Z"),
"lastHeartbeatRecv" : ISODate("2015-09-25T23:27:58.028Z"),
"pingMs" : 0,
"configVersion" : 1
}
],
"ok" : 1
}
5.配置从可以读的设置
db.person.find()
Error: error: { "$err" : "not master and slaveOk=false", "code" : 13435 }
Error: error: { "$err" : "not master and slaveOk=false", "code" : 13435 }
报错了：说明从库不能执行查询操作
让从库可以执行查询操作：
testrs:SECONDARY> db.getMongo().setSlaveOk()
testrs:SECONDARY> rs.slaveOk(); # 这是实现从库可读的两种的方法，但是我执行了第一种方法，发现想要的功能未能实现，故而又执行了第二个命令，达到了目的
6.验证
mongostat -h 192.168.1.101:27017 --rowcount 2000 1 连接主的服务器和端口，验证如果查询是否在主上不会产生
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 *0 *0 *0 *0 0 1|0 0 10.2g 20.8g 58m 0 dblog:0.0% 0 0|0 0|0 62b 3k 18 testrs PRI 23:52:51 *0 *0 *0 *0 1 3|0 0 10.2g 20.8g 58m 0 test:0.0% 0 0|0 0|0 395b 3k 18 testrs PRI 23:52:52 *0 *0 *0 *0 0 1|0 0 10.2g 20.8g 58m 0 test:0.0% 0 0|0 0|0 62b 3k 18 testrs PRI 23:52:53 *0 *0 *0 *0 0 6|0 0 10.2g 20.8g 58m 0 test:0.0% 0 0|0 0|0 522b 5k 18 testrs PRI 23:52:54 *0 *0 *0 *0 0 1|0 0 10.2g 20.8g 58m 0 test:0.0% 0 0|0 0|0 62b 3k 18 testrs PRI 23:52:55
mongostat -h 192.168.1.101:27018 --rowcount 2000 1 连接从的服务器和端口，验证查询是否在从上产生
*0 1 *0 *0 0 3|0 0 10.2g 20.8g 45m 0 dblog:0.0% 0 0|0 0|0 460b 5k 16 testrs SEC 23:54:17 *0 *0 *0 *0 0 5|0 0 10.2g 20.8g 45m 0 test:0.0% 0 0|0 0|0 379b 4k 16 testrs SEC 23:54:18 *0 *0 *0 *0 0 2|0 0 10.2g 20.8g 45m 0 test:0.0% 0 0|0 0|0 205b 3k 16 testrs SEC 23:54:19 *0 *0 *0 *0 0 2|0 0 10.2g 20.8g 45m 0 test:0.0% 0 0|0 0|0 205b 3k 16 testrs SEC 23:54:20 *0 2 *0 *0 0 4|0 0 10.2g 20.8g 45m 0 dblog:0.0% 0 0|0 0|0 717b 6k 16 testrs SEC 23:54:21 *0 *0 *0 *0 0 2|0 0 10.2g 20.8g 45m 0 test:0.0% 0 0|0 0|0 205b 3k 16 testrs SEC 23:54:22 *0 4 *0 *0 0 9|0 0 10.2g 20.8g 45m 0 dblog:0.0% 0 0|0 0|0 1k 12k 16 testrs SEC 23:54:23 *0 7 *0 *0 0 9|0 0 10.2g 20.8g 45m 0 dblog:0.0% 0 0|0 0|0 2k 17k 16 testrs SEC 23:54:24 *0 6 *0 *0 0 8|0 0 10.2g 20.8g 45m 0 dblog:0.0% 0 0|0 0|0 1k 15k 16 testrs SEC 23:54:25 *0 7 *0 *0 0 9|0 0 10.2g 20.8g 45m 0 dblog:0.0% 0 0|0 0|0 2k 17k 16 testrs SEC 23:54:26 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 *0 6 *0 *0 0 8|0 0 10.2g 20.8g 45m 0 dblog:0.0% 0 0|0 0|0 1k 15k 16 testrs SEC 23:54:27 *0 4 *0 *0 0 9|0 0 10.2g 20.8g 45m 0 dblog:0.0% 0 0|0 0|0 1k 12k 16 testrs SEC 23:54:28 *0 5 *0 *0 0 7|0 0 10.2g 20.8g 45m 0 dblog:0.0% 0 0|0 0|0 1k 13k 16 testrs SEC 23:54:29 *0 *0 *0 *0 0 2|0 0 10.2g 20.8g 45m 0 test:0.0% 0 0|0 0|0 205b 3k 16 testrs SEC 23:54:30
