最近在部署rocketmq到物理机时， 发现并解决了一个主机Load异常飙高的问题， 觉得有必要记录一下。
我们采用了rocketmq（https://github.com/alibaba/RocketMQ）的3.4.6版本，并自己实现了一套dashboard(包括topic管理，producer管理 ，consumer管理，broker管理，消息跟踪等) 。
部署架构如下：
| 机器 | 角色 | 备注 | |
| ip1 | nameserver + broker master | 落盘方式:ASYNC_FLUSH | |
| ip2 | nameserver + broker slave | 同步方式:异步复制 | |
| ip3 | nameserver + benchmark app +tomcat |
三台机器都是物理机 ，机器配置如下：
| 操作系统 | centos 6.5 |
| linux 版本 | 2.6.32-431.el6.x86_64 |
| cpu | 40 核Intel(R) Xeon(R) CPU E5-2630 v4 @ 2.20GHz |
| 内存 | 64g |
| 磁盘 | SCSI 3.2T |
| 文件系统 | ext4 |
| io调度算法 | cfq(默认的完全公平算法， 并未采用官方文档提到的deadline) . |
| jdk | 1.7.0_71 |
启动rocketmq以后，我们创建了一个测试topic-a, 设置了5个队列（都具有读写权限）， 然后启动了5个Producer和5个consumer进行疲劳测试（投递采用的是队列轮询投递， 消费采用的是集群消费方式），启动压力测试，在第二天的早上发现dashboard里面已经查看不到master的机器了 ，这时候试图通过openssh 远程登录也登录不了， 但是22端口仍然可以telnet ,也可以ping通 ，找到运维同事，重新启动机器。
启动后，查看rocketmq本身的gc日志 ，也只看到一些新生代的垃圾回收信息：
2016-08-17T16:02:10.349+0800: 13552.986: [GC2016-08-17T16:02:10.349+0800: 13552.987: [ParNew: 3404557K->47713K(3774912K), 0.2118670 secs] 5311800K->1954963K(7969216K), 0.2121470 secs] [Times: user=2.78 sys=0.00, real=0.21 secs]
2016-08-17T16:02:20.945+0800: 13563.583: [GC2016-08-17T16:02:20.945+0800: 13563.583: [ParNew: 3403233K->49831K(3774912K), 0.2107390 secs] 5310483K->1957085K(7969216K), 0.2110130 secs] [Times: user=2.74 sys=0.00, real=0.21 secs]
2016-08-17T16:02:31.497+0800: 13574.135: [GC2016-08-17T16:02:31.497+0800: 13574.135: [ParNew: 3405351K->48942K(3774912K), 0.2087310 secs] 5312605K->1956200K(7969216K), 0.2090060 secs] [Times: user=2.71 sys=0.00, real=0.21 secs]
这时候查看/var/log/messages， 看linux 系统日志 ，抓到了如下日志：
Aug 15 20:10:11**** kernel: INFO: task java:97019 blocked for more than 120 seconds.
Aug 15 20:10:11**** kernel: Tainted: G --------------- H 2.6.32-431.el6.x86_64 #1
Aug 15 20:10:11**** kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug 15 20:10:11**** kernel: java D 0000000000000000 0 97019 96892 0x00000080
Aug 15 20:10:11**** kernel: ffff880eb8677cf0 0000000000000082 ffffffff810afa0a ffff880f199bf538
Aug 15 20:10:11**** kernel: 00000000000014bc 00000000199bf500 0000000000000000 ffffffffb8677ca8
Aug 15 20:10:11**** kernel: ffff880f198785f8 ffff880eb8677fd8 000000000000fbc8 ffff880f198785f8
Aug 15 20:10:11**** kernel: Call Trace:
Aug 15 20:10:11**** kernel: [<ffffffff810afa0a>] ? futex_wait+0x21a/0x380
Aug 15 20:10:11**** kernel: [<ffffffff81529f85>] rwsem_down_failed_common+0x95/0x1d0
Aug 15 20:10:11**** kernel: [<ffffffff8152a116>] rwsem_down_read_failed+0x26/0x30
Aug 15 20:10:11**** kernel: [<ffffffff8128e854>] call_rwsem_down_read_failed+0x14/0x30
Aug 15 20:10:11**** kernel: [<ffffffff81529614>] ? down_read+0x24/0x30
Aug 15 20:10:11**** kernel: [<ffffffff8104a92e>] __do_page_fault+0x18e/0x480
Aug 15 20:10:11**** kernel: [<ffffffff8152d45e>] do_page_fault+0x3e/0xa0
Aug 15 20:10:11**** kernel: [<ffffffff8152a815>] page_fault+0x25/0x30
Aug 15 20:10:11**** kernel: INFO: task java:97020 blocked for more than 120 seconds.
Aug 15 19:04:56 **** sssd: Killing service [hx], not responding to pings!
发现在晚上的八点多， 有java进程被阻塞了120秒 ，后面紧接着的红色信息大概意思是在开始杀服务，系统对ping操作都已经不响应了 ，询问运维，在这个时间段，也没有对问题主机做任何操作；
没有头绪的情况下，暂时只好重新再做一次benchmark了，发现问题依旧！！rocketmq master又登录不上，直观的感觉就是down掉了，但是端口却能telnet 通，只好再次让运维同事重启机器，登录到master, 通过sar命令，得到了如下信息：
cpu负载（sar -q 得到）
02:17:42 AM runq-sz plist-sz ldavg-1 ldavg-5 ldavg-15
03:15:22 AM 5 1120 14.43 17.30 14.87
cpu利用率：（sar -p 得到）
02:17:42 AM CPU %user %nice %system %iowait %steal %idle
03:15:16 AM all 0.25 0.00 23.40 0.04 0.00 76.30
03:15:22 AM all 0.02 0.00 13.83 0.04 0.00 86.11
内存：(sar -r 得到）
02:17:42 AM kbmemfree kbmemused %memused kbbuffers kbcached kbcommit %commit
03:15:16 AM 593108 65262556 99.10 197600 56394056 20486868 27.59
03:15:22 AM 592224 65263440 99.10 197648 56394296 20485052 27.59
磁盘：（sar -d得到）
02:17:42 AM DEV tps rd_sec/s wr_sec/s avgrq-sz avgqu-sz await svctm %util
03:15:16 AM dev8-0 0.37 0.45 4.77 14.24 0.00 1.06 0.71 0.03
03:15:16 AM dev253-0 0.47 0.42 3.65 8.60 0.00 1.16 0.46 0.02
03:15:16 AM dev253-1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
03:15:16 AM dev253-2 0.14 0.03 1.11 8.00 0.00 0.42 0.31 0.00
03:15:22 AM dev8-0 11.95 71.38 207.41 23.32 0.03 2.86 1.48 1.77
03:15:22 AM dev253-0 29.29 71.38 207.41 9.52 0.04 1.37 0.60 1.77
03:15:22 AM dev253-1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
03:15:22 AM dev253-2 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
04:01:19 AM dev8-0 0.59 3.01 5.61 14.49 0.00 0.85 0.70 0.04
04:01:19 AM dev253-0 0.31 2.98 2.05 16.06 0.00 1.77 0.98 0.03
04:01:19 AM dev253-1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
发现cpu的负载非常高，而且20%多的cpu都是在系统态，内存利用率已经到了99%以上， 磁盘几乎没有读写。
是什么引起了cpu load这么高，并且花在了系统态上呢，直观感觉就是内存已经很吃紧了.
结合rocketmq的commitlog ，consumequeue ,Index file 都采用了mmap做内存映射来操作文件，吃内存的地方就会是这三个地方，但是索引文件大概500M能索引2000万的消息， 而consumequeue的 一个item是20个字节（8字节commitlog offset+4字节 size+8字节message tag hashcode), 也不会吃太大内存，吃内存的地方就会在commitlog 了。
那疑问在于， 为什么吃内存会把系统的负载搞到这么高呢？我们做了一个mmap的测试程序：
import java.io.File;
import java.io.FileNotFoundException;
import java.io.IOException;
import java.io.RandomAccessFile;
import java.nio.ByteBuffer;
import java.nio.MappedByteBuffer;
import java.nio.channels.FileChannel;
import java.util.concurrent.atomic.AtomicInteger;
/**
* * * Created by lk on 2016/8/16.
* * */
public class MapfileTest {
private static final AtomicInteger wrotePostion = new AtomicInteger(0);
public static void main(String []args) {
File file = new File(args[0]);
int filesize = Integer.MAX_VALUE;
FileChannel fileChannel = null;
MappedByteBuffer mappedByteBuffer = null;
try {
fileChannel = new RandomAccessFile(file,"rw").getChannel();
mappedByteBuffer = fileChannel.map(FileChannel.MapMode.READ_WRITE, 0, filesize);
ByteBuffer byteBuffer = ByteBuffer.allocate(1024 * 1024 * 2);
for(int i = 0; i < 1000; ++i){
appendMessage(byteBuffer.array(),filesize,mappedByteBuffer);
try {
Thread.currentThread().sleep(50);
} catch (InterruptedException e) {
e.printStackTrace();
}
}
System.in.read();
} catch (FileNotFoundException e) {
e.printStackTrace();
} catch (IOException e) {
e.printStackTrace();
}finally{
if(fileChannel != null){
try {
fileChannel.close();
} catch (IOException e) {
e.printStackTrace();
}
}
}
}
private static boolean appendMessage(final byte[] data,long fileSize,MappedByteBuffer mappedByteBuffer) {
int currentPos = wrotePostion.get();
if ((currentPos + data.length) <= fileSize) {
ByteBuffer byteBuffer = mappedByteBuffer.slice();
byteBuffer.position(currentPos);
byteBuffer.put(data);
wrotePostion.addAndGet(data.length);
return true;
}
return false;
}
}
上面这个程序是一次创建一个大小为2g的内存映射文件，我们在一个只有5g free内存的虚拟机上 ，逐个启动多个进程：
/opt/jdk/jdk1.7.0_71/bin/java MapfileTest ./testfile1
/opt/jdk/jdk1.7.0_71/bin/java MapfileTest ./testfile2
/opt/jdk/jdk1.7.0_71/bin/java MapfileTest ./testfile3
/opt/jdk/jdk1.7.0_71/bin/java MapfileTest ./testfile4
再通过sudo cat /proc/pid/status 查看进程状态中的VmRSS 指标（实际占用内存） ， 得到一个结论，java内存映射文件只要内存够用，就尽量多消耗， 内存不够用的情况下，后起的进程会从先启的进程中抢占内存； 从这里看到，Java内存映射机制本身是没有什么问题的。
再结合前面的问题分析猜想， 虽然Java内存映射没问题 ，但是不是rocketmq的内存吃的太多 ，导致操作系统本身的内存不够用，而直接造成os crash呢？
我们试着调整内核参数：
#允许超量使用内存
echo 'vm.overcommit_memory=1' >> /etc/sysctl.conf
#给系统预留的内存，Kb, 保留16G
echo 'vm.min_free_kbytes=16777216' >> /etc/sysctl.conf
#释放pagecache;
echo 'vm.drop_caches=1' >> /etc/sysctl.conf
#节点内存不够，从其他节点获取内存
echo 'vm.zone_reclaim_mode=0' >> /etc/sysctl.conf
#限制进程的虚拟内存区域的数量
echo 'vm.max_map_count=655360' >> /etc/sysctl.conf
#最大限度使用内存，然后才是swap分区。
echo 'vm.swappiness=0' >> /etc/sysctl.conf
调整好内核参数以后，我们让内核参数实时生效
sudo sysctl -p
然后重启rocketmq ,继续进行benchmark，通过sar -r 3 命令，每3秒钟查看一次内存利用率，发现，
Linux 2.6.32-431.el6.x86_64 (s10-2-26-7.hx) 08/18/2016 _x86_64_ (40 CPU)
04:00:01 AM 23522004 42333660 64.28 151040 32570228 20337848 27.39
04:10:01 AM 22760760 43094904 65.44 153568 33319244 20337664 27.39
04:20:01 AM 22044920 43810744 66.53 154260 34011192 20338040 27.39
04:30:01 AM 21252440 44603224 67.73 154660 34765872 20337548 27.39
04:40:01 AM 24537392 41318272 62.74 153252 31503576 20338100 27.39
....
07:30:01 AM 21264948 44590716 67.71 156280 34532204 20337676 27.39
07:40:01 AM 24547740 41307924 62.72 156920 31266096 20337720 27.39
07:50:01 AM 23789356 42066308 63.88 157592 32016024 20337628 27.39
08:00:01 AM 23872952 41982712 63.75 156716 31929608 20338072 27.39
08:10:01 AM 23000656 42855008 65.07 157412 32785184 20338604 27.39
内存利用率每次达到接近68%的时候， 会立即下降到 62% ，
结合自己在前面设置的参数：
echo 'vm.min_free_kbytes=16777216' >> /etc/sysctl.conf
来分析，物理机器的内存是64g, 保留16g 给系统，
1-16/64= 75%
即从理论上看，内存利用率到75%的时候，就会禁止应用继续申请内存，而实际是到68%左右 ，会启动一次内存回收的动作。
调整完内核参数以后，继续压测一天， rocketmq运行平稳，没有出现之前的os crash的问题。
基本可以确认是之前rocketmq在做commitlog文件的内存映射操作时 ，因为持续的压测，导致commitlog的内存映射操作把内存吃满了，导致系统内存不足而造成。