前言
前面分析了linux的平均负载，在分析的时候自己也顺便实际测试了一番，测试例子记录如下，防止遗忘。
先说测试结论：load average平均负载和cpu使用率以及磁盘IO有关，和网络IO无关。
1.cpu使用率高问题分析
首先先确定什么操作会导致cpu使用率飚高，在我们java应用中，通常会有下面一些代码，下面那些情况会对cpu的开销大呢？
1.多层的 if switch。对cpu开销很小。
2.网络传输(接入请求和响应请求要经过网络)。网络传输是瓶颈在IO上，对cpu开销小。
3.线程阻塞(同步锁、wait)。线程既然阻塞了，就暂时不再使用cpu资源，因此对cpu开销也小。线程阻塞会对性能造成影响，直接感觉就是系统运行缓慢。
4.多层循环嵌套或者递归。这种可能会对cpu的开销不小，如果在循环内又做了比如排序等操作。
5.字符串处理。常见的消耗cpu的操作是json解析、正则表达式
6.日期格式化。比如使用jdk的SimpleDateFormat.format耗费cpu，建议使用apache的FaseDateFormat。
7.大量的sql数据处理。一次查询多大量数据，需要对数据进行处理返回，对cpu开销也大，这个情况经常有。
8.线程上下文频繁切换。对cpu的开销也大。
9.死循环或者while(true){}情况无限执行
10.频繁full gc导致cpu 100%
1.1.实测正则表达式开销cpu100%
测试代码如下
//controller
@RequestMapping(value = "/test/cpu/regex", method = RequestMethod.GET)
public CommonResult<String> cpuRegex() {
allocateService.cpuRegex();
return CommonResult.success(null);
}
//service方法
/**
* 使用正则表达式让cpu达到100%，这个结果计算要15s
*/
@Override
public void cpuRegex() {
String regex = "(\\w+,?)+";
String val = "abcdefghijklmno,abcdefghijklmno+";
log.info("正则结果->{}", val.matches(regex));//val.matches耗费cpu
}
使用jmeter并发2，压测5min。(因为这个正则表达式执行特殊，直接会把cpu打满，我测试服务器是2C，因此开2个线程就可以把cpu打满)
压测一段时间后通过top命令查看，发现cpu被打满了，平均负载已经超过了2*0.7
1.1.1.使用传统方式top -Hp PID 和jstack PID确定开销cpu最高的线程
step1：间隔几秒多次执行jstack PID >> regex ，多次执行是为了查出共性
step2：top -Hp PID 查看并记录几个线程ID，如下图
上图中的1443,1458,20023就是线程ID，转换为16进制数
printf "%x\n" 20023结果为4e37，在jstack结果文件regex1问题内进行搜索，比如执行grep -A 50 4e37 regex1 查询4e37后面50行
在确定cpu消耗上，只查看java.lang.Thread.State: RUNNABLE的堆栈，这个符合，但是这个堆栈是阻塞在socket读取上，并不会消耗CPU的，因此这个忽略（这也是为什么要多次执行jstack的原因，多次执行找能找出共性）
printf "%x\n" 1443结果为5a3，在jstack结果文件regex1问题内进行搜索，比如执行grep -A 100 5a3 regex1 查询4e37后面50行
发现业务方法内的org.allocate.memory.allocate.service.impl.AllocateServiceImpl.cpuRegex()对cpu的开销大，比较可疑，再同查看其它占用cpu资源高的线程，进行查询进行验证。最终确定是这个代码问题导致cpu100%。
1.1.2.使用show-busy-java-threads脚本确定cpu开销大问题
github有个大神专门写了个脚本show-busy-java-threads (地址https://github.com/oldratlee/useful-scripts/blob/master/docs/java.md#-show-busy-java-threads)分析cpu100%问题，超级好用，在这里我直接执行 show-busy-java-threads 2 5 > regex2 打印最消耗cpu的线程堆栈，直接查看结果文件regex2，内容和分析结果如下：
================================================================================
2020-12-03 14:21:00.086099451 [1/5]: /home/baseuser/bin/show-busy-java-threads 2 5
================================================================================
[1] Busy(99.9%) thread(32256/0x7e00) stack of java process(32178) under user(baseuser)://确定查看到
"http-nio-8111-exec-10" #38 daemon prio=5 os_prio=0 tid=0x00007f6eb9a31000 nid=0x7e00 runnable [0x00007f6e802bd000]
java.lang.Thread.State: RUNNABLE
at java.util.regex.Pattern$GroupTail.match(Pattern.java:4717)
at java.util.regex.Pattern$Ques.match(Pattern.java:4182)
//省略其它堆栈
at java.lang.String.matches(String.java:2121)
at org.allocate.memory.allocate.service.impl.AllocateServiceImpl.cpuRegex(AllocateServiceImpl.java:114)
at org.allocate.memory.allocate.controller.AllocateController.cpuRegex(AllocateController.java:34)
//省略其它堆栈
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1415)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
- locked <0x00000000a242f908> (a org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)
[2] Busy(98.0%) thread(1399/0x577) stack of java process(32178) under user(baseuser):
"http-nio-8111-exec-12" #45 daemon prio=5 os_prio=0 tid=0x00007f6e90001800 nid=0x577 runnable [0x00007f6e63af8000]
java.lang.Thread.State: RUNNABLE
at java.util.regex.Pattern$Curly.match(Pattern.java:4226)
at java.util.regex.Pattern$GroupHead.match(Pattern.java:4658)
at java.util.regex.Pattern$Loop.match(Pattern.java:4785)
//省略其它堆栈
at java.lang.String.matches(String.java:2121)
at org.allocate.memory.allocate.service.impl.AllocateServiceImpl.cpuRegex(AllocateServiceImpl.java:114)
at org.allocate.memory.allocate.controller.AllocateController.cpuRegex(AllocateController.java:34)
//省略其它堆栈
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1415)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
- locked <0x00000000a242fce0> (a org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)
[3] Busy(0.0%) thread(1415/0x587) stack of java process(32178) under user(baseuser):
"http-nio-8111-exec-29" #61 daemon prio=5 os_prio=0 tid=0x00007f6e98015800 nid=0x587 waiting on condition [0x00007f6e62aeb000]
java.lang.Thread.State: WAITING (parking)//非RUNNABLE状态不消耗cpu，忽略
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000d00215f8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:107)
at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:33)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)
[4] Busy(0.0%) thread(1420/0x58c) stack of java process(32178) under user(baseuser):
"http-nio-8111-exec-34" #66 daemon prio=5 os_prio=0 tid=0x00007f6e9801d000 nid=0x58c waiting on condition [0x00007f6e625e6000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000d00215f8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:107)
at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:33)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)
[5] Busy(0.0%) thread(1428/0x594) stack of java process(32178) under user(baseuser):
"http-nio-8111-exec-41" #73 daemon prio=5 os_prio=0 tid=0x00007f6e90018000 nid=0x594 waiting on condition [0x00007f6e61edf000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000d00215f8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:107)
at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:33)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)
直接查看busy最大的即可，这个很神器。
1.2.实测日期格式化对cpu资源的开销
SimpleDateFormat.format操作比较耗费cpu，测试代码如下
/**
* 使用jdk的SimpleDateFormat.format耗费cpu，建议使用apache的FaseDateFormat
*/
@Override
public void cpuDateFormat() {
for (int i=0;i<10;i++) {
String current = format.format(new Date());
String date = format.format(System.currentTimeMillis()+1000);
}
}
并发200，压测10min情况下top如图
top -Hp PID结果如下图
发现线程对cpu的开销比较均衡，再通过查看show-busy-java-threads 2 10 > format.log查看结果，在format.log文件内搜索Busy(，截图如下：
每个线程对cpu的消耗是差不多的，和通过top -Hp PID结果是相同的。接着搜索farmat.log文件内的java.lang.Thread.State:查看线程整体状态，发现基本处于TIMED_WAITING (parking)，截图如下，这个状态是由于执行了有超时时间限制的LockSupport.parkXXX操作
具体的堆栈如下
这个堆栈说明tomcat线程阻塞在从队列获取执行任务。继而说明大多数线程都是处于阻塞状态，cpu频繁处于线程切换状态(线程在cpu执行，只有在阻塞情况下，cpu才会切换到其它线程执行)，通过vmstat 2 10000查看cs每秒上下文切换数指标如下：
每秒线程要切换5000次左右，我跟生产服务器的vmstat cs指标对比了下，生产是2000~3000，cpu使用率是个位数，看来这个5000次切换并不大。
和别人说的日期格式开销cpu大并不是很契合呀。
1.3.线程上下文大量切换导致cpu使用率高测试
再做测试，测试下线程上下文大量切换对cpu使用率的影响。测试代码如下，每次请求让阻塞两次，这样cpu切换至少2次
@Override
public void cpuSwitch() {
try {
Thread.sleep(1);//线程切换，释放cpu资源，休眠1ms再去抢占cpu资源
} catch (InterruptedException e) {
//ignore
}
int i = 1+1;
Thread.yield();//线程切换，释放cpu使用权接着又去抢占cpu资源
int j = 1+1;
}
使用vmstat 1 1000 查看结果截图如下
这次代码里面没有耗费cpu的操作，但是线程阻塞两次，查看到每秒上下文切换是3w多次，cpu用户使用率是70%左右，系统使用率是30%左右，发现系统使用cpu也高了，通过top命令查看cpu使用率基本在200%(我测试机是2C，打满就是200%)，截图如下
top -Hp PID截图如下图，看到每个线程使用cpu资源很均衡
通过show-busy-java-thread 2 10 查看堆栈，发现cpu使用很均衡，截图如下
查看栈的dump结果，基本都是TIMED_WAITING (parking)
这些TIMED_WAITING (parking)状态对应的栈都是
[3] Busy(3.1%) thread(21241/0x52f9) stack of java process(18059) under user(baseuser):
"http-nio-8111-exec-404" #445 daemon prio=5 os_prio=0 tid=0x00007f4e48012800 nid=0x52f9 waiting on condition [0x00007f4e0ffc0000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000d0177bd0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
at java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:89)
at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:33)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1066)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)
这个堆栈说明tomcat线程阻塞在从队列获取执行任务，又通过线程切换上下文那么多，说明这个场景cpu高是消耗在线程上下文切换中。
总结：通过测试发现，线程上下文大量切换的时候，内核使用cpu也会变高，因为此时需要内核进行协调，进而内核消耗cpu资源也会高些（上面测试例子中内核使用cpu资源是20%~30%）。
但是有个疑问：线程上下文切换到底多少是多？认为需要引起注意呢？
1.4.实测fastjson解析字符串对cpu资源开销
找了个字符串较大，使用fastjson进行解析
@Override
public void cpuJson() {
JSONArray jsonArray = JSON.parseArray(testJsonStr);//testJsonStr是应用启动加载的一个较大的json字符串
List<DetailVO> listVO = jsonArray.toJavaList(DetailVO.class);
}
jmeter并发100，持续10min
压测期间top的两张截图，发现平均负载上升很快
vmstat结果如下图，可以看出等待cpu执行的线程比较多，瓶颈在cpu上。cs表示线程上下文，数量并不大，2000左右。 us使用率较高。
使用show-busy-java-threads 2 5查看结果，筛选Busy结果如下图，说明每个线程使用的cpu资源均衡。
接着筛选线程状态java.lang.Thread.State，大部分处于TIMED_WAITING状态。
选取其中一个TIMED_WAITING状态如下
[5] Busy(3.2%) thread(15329/0x3be1) stack of java process(15276) under user(baseuser):
"http-nio-8111-exec-7" #35 daemon prio=5 os_prio=0 tid=0x00007f6d7dadb800 nid=0x3be1 waiting on condition [0x00007f6d27bfa000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000d015b238> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
at java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:89)
at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:33)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1066)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)
阻塞在网络IO上，感觉json解析字符串并不会很消耗cpu。
通过jemeter查看tps，结果是2778
感觉自己这个测试翻车了，莫非自己这个测试fastjson很快？但是自己通常debug到json解析方法时候执行是较慢的。
1.5.大量的sql数据处理(待测)
一次查询大量的sql，对sql数据进行处理，这个处理过程通常不会有阻塞操作的，因此cpu一直在计算过程中，对cpu的开销也大。模拟大量数据并处理不是很方便，留待后面测试。
1.6.死循环导致cpu使用率飚高
自己以前测试过对于while(tue)无限循环，直接会导致一颗cpu打满(有4C，这样情况是实际cpu使用率是25%)，但是现实是我们代码是不会这样写的，只是会有些异常情况导致进入while(true)死循环，这样情况在写代码过程中很难发现的。
比如下面代码
public byte[] readBytes(int length) throws IOException {
if ((this.socket == null) || (!this.socket.isConnected())) {
throw new IOException("++++ attempting to read from closed socket");
}
byte[] result = null;
ByteArrayOutputStream bos = new ByteArrayOutputStream();
if (this.recIndex >= length) {
bos.write(this.recBuf, 0, length);
byte[] newBuf = new byte[this.recBufSize];
if (this.recIndex > length) {
System.arraycopy(this.recBuf, length, newBuf, 0, this.recIndex - length);
}
this.recBuf = newBuf;
this.recIndex -= length;
} else {
int totalread = length;
if (this.recIndex > 0) {
totalread -= this.recIndex;
bos.write(this.recBuf, 0, this.recIndex);
this.recBuf = new byte[this.recBufSize];
this.recIndex = 0;
}
}
int readCount = 0;
while (totalread > 0) {
if ((readCount = this.in.read(this.recBuf)) > 0) {//如果结果为0，则进入while死循环
if (totalread > readCount) {
bos.write(this.recBuf, 0, readCount);
this.recBuf = new byte[this.recBufSize];
this.recIndex = 0;
} else {
bos.write(this.recBuf, 0, totalread);
byte[] newBuf = new byte[this.recBufSize];
System.arraycopy(this.recBuf, totalread, newBuf, 0, readCount - totalread);
this.recBuf = newBuf;
this.recIndex = (readCount - totalread);
}
totalread -= readCount;
}
}
}
对于this.in.read(this.recBuf))来说，如果连接状态是CLOSED_WAIT状态，读取返回就是0，这样就演变成了while(true)死循环，直接导致一颗cpu就一直是100%。这样情况在网络不好的情况下可能出现，但是自己暂时没发模拟到。以后看如何模拟到再写下这个例子。
1.7.full gc导致cpu 100%(待测)
1.8.cpu使用率高的总结
通过前面测试，只是测试了正则表达式导致cpu100%，大量线程上下文切换导致cpu使用率高。日期格式化和json解析并没有达到预期效果。本次测试更加熟悉了一些监控命令和stack，也并不是没有成果。
cpu使用率高的根本原因是cpu一直在工作，如何判断cpu实际是真正在干活还是在频繁切换呢？通过vmstat的cs指标确认。通常生产上给的硬件资源都是完全足够的，遇到资源不够了通常都是扩容，每台服务器节点的资源消耗通常是较小的。cpu使用率，排查了上下文频繁切换，那说明程序中有对cpu资源开销大的处理代码，这种情况通常是扩容解决，毕竟加机器是最快速能解决资源问题的。
写这个记录只是为了分析下load average而做。
2.磁盘IO分析
查看磁盘通常是先查看top的wa指标，如果较高(通常高与30就要注意了)，接着查看vmstat 的procs的b指标，接着具体用iostat和iotop来确定具体问题。
下面以一个每次请求都读取文件内容和写入文件内容来测试。该代码每次先从文件内读取，然后再写入到一个新文件到磁盘上。读取和写入都是阻塞动作。
private final AtomicInteger number = new AtomicInteger(1);
@Override
public void io() {
try {
ClassLoader classLoader = Thread.currentThread().getContextClassLoader();
URL url = (classLoader != null ?
classLoader.getResource("test-service.2020-01-09.log") :
ClassLoader.getSystemResource("test-service.2020-01-09.log"));//test-service.2020-01-09.log有200k
String logText = IOUtils.toString(url, Charset.forName("utf8"));//读取resources下的test-service.2020-01-09.log文件内
File targetFile = null;
String os = System.getProperty("os.name");
if (StrUtil.containsIgnoreCase(os, "linux")) {
targetFile = new File("/data/log/allocate/test-service-"+number.getAndIncrement()+".log");
} else {
targetFile = new File("D:\\data\\allocate\\test-service-"+number.getAndIncrement()+".log");
}
boolean exists = targetFile.exists();
if (!exists) {
targetFile.createNewFile();
}
FileOutputStream out = new FileOutputStream(targetFile);
out.write(logText.getBytes("utf8"));//阻塞io操作
out.close();
}
catch (IOException ex) {
throw new IllegalArgumentException("Unable to load factories from location [" +
"test-service.2020-01-09.log" + "]", ex);
}
}
在2C2G虚拟机上测试，jmeter并发100，压测10min，测试截图如下:
压测过程中，两次间隔几分钟时间的top截图如下，查看到load average远远超过了cpu的核数，但是cpu的使用率却不是很高。但是wa指标很高，说明可能磁盘IO问题。
接着用iostat -d -k -x 1查看磁盘IO，截图如下，发现%util指标都达到了100%，平均每次设备I/O操作的等待时间await达到了500多ms，确定到确实是磁盘IO压力太大导致，具体是哪个线程/进程的操作对导致的磁盘的读/写压力大的呢？下面使用iotop命令查看
通过iotop查看具体是哪些线程使用的磁盘IO资源大，截图如下，实际读取速率是60 k/s左右，写入是73.48m/s，说明是写操作导致的磁盘IO压力大。具体的线程就是TID，查看DISK_WRITE列，比如看到线程1631写入磁盘的速率是914.39k/s
iotop命令按p切换到进程模式，确实是自己这个java应用，看到磁盘写入速率是96.59m/s
这里忘记使用jstack查看线程堆栈了，查看线程堆栈结果线程应该是RUNNABLE状态，堆栈都在io()方法上。
测试完毕查看jemter的聚合报告如下：tps是290，吞吐量确实不高，瓶颈在磁盘IO上。
该例子证明磁盘IO会对load average有直接的影响。
解决磁盘IO瓶颈做饭
1.对集群扩容，这个效果最显著，成本也最高，不过实际工作中通常都是扩容。
2.减少磁盘IO操作，比如减少日志等打印，文件的写入。
3.如果必须要进行文件写入，考虑使用内存映射，比如java.nio.channels.FileChannel#transferTo(long, long, WritableByteChannel)
3.网络IO阻塞分析
那么网络IO阻塞会对load average造成影响吗？会导致load average飚高吗？
测试下网络阻塞io对load average的影响，测试代码如下：
//每次请求都会连接目标服务器的80端口，然后读取超时（因为目标服务器的nginx并不返回数据）
@Override
public void socketIO() {
Socket socket = new Socket();
try {
socket.setSoTimeout(60000);
socket.setTcpNoDelay(true);
socket.connect(new InetSocketAddress("xxx.xxx.xxx.xxx", 80));//目标ip机器上启动个nginx
InputStream in = socket.getInputStream();
byte[] b = new byte[1024];
int read = in.read(b);//网络io阻塞，阻塞60s后超时抛出异常。
} catch (IOException e) {
log.error("读取超时,异常{}", e.getMessage());
} finally {
try {
socket.close();
} catch (IOException e) {
log.error("socket关闭异常", e.getMessage());
}
}
}
使用jmeter压测100并发，压测10min，测试过程系统监控截图如下：
测试过程查看top命令结果
说明cpu和wa即磁盘io都没压力，而且负载很低。
通过jstack -l PID查看，线程状态基本处于java.lang.Thread.State: RUNNABLE，具体堆栈如下
"http-nio-8111-exec-372" #413 daemon prio=5 os_prio=0 tid=0x00007ff6a4072000 nid=0x166b runnable [0x00007ff668d9d000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:170)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at java.net.SocketInputStream.read(SocketInputStream.java:127)
at org.allocate.memory.allocate.service.impl.AllocateServiceImpl.socketIO(AllocateServiceImpl.java:178)
at org.allocate.memory.allocate.controller.AllocateController.socketIO(AllocateController.java:56)
//省略其它堆栈
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1038)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:942)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1005)
at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:897)
//省略其它堆栈
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:408)
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:834)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1415)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
- locked <0x00000000ae7e1638> (a org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)
Locked ownable synchronizers:
- <0x00000000aca06880> (a java.util.concurrent.ThreadPoolExecutor$Worker)
线程状态是可运行状态RUNNABLE，但是线程实际并没有消耗cpu，因为线程阻塞了。具体可以查看我的笔记 java线程生命周期
说明网络IO阻塞并不会对linux的平均负载造成影响。
4.linux系统监控命令
top
top命令截图解释
top命令截图如下：
按照图中的红色来说
1:任务队列信息
top - 15:29:10 当前时间
up 117days, 5:04, 是 系统运行时间 格式为时：分
1 user， 表示当前只有一个用户登录
load average:0.18, 0.11, 0.04, 系统平均负载。 分别为 1分钟、5分钟、15分钟前到现在的平均值。 这个指标重点关注
2:进程信息
Tasks: 176 total, 当前总共176个进程
1 running, 1个在运行中的进程
175 sleeping, 175个休眠的进程
0 stopped, 0个停止进程
0 zombie 0个僵尸进程，重点关注，有僵尸进程了需要注意
3:cpu信息，显示所有cpu需要top后按数字键1
显示2个说明是2个cpu，有多个cpu就显示多个。
us 用户空间占用CPU百分比。 重点关注，应用使用的cpu指标
sy 内核空间占用CPU百分比。 重点关注，使用率高，说明可能是线程上下文切换过多
ni 用户进程空间内改变过优先级的进程占用CPU百分比。 暂时没关注过，不知道用处
id idle的缩写，空闲cpu。
wa 等待输入输出的CPU时间百分比。磁盘io的监控指标。重点关注，磁盘io的指标，该值越大，说明磁盘的io压力越大。
hi si st，没关注过，不知道用处。忽略
4:物理内存使用情况
total 是物理空间总大小，单位是bytes
free 剩余物理空间大小
used 已使用的物理空间大小
buff/cache 用作内核缓存的内存量
查看内存也通常使用free -h
linux使用内存是尽可能都使用了，把文件缓存到内存(buff/cache)，这样可以快速使用，查看内存可用，并不是看free，要使用free+buff/cache项目。
buff/cache缓冲的交换区总量，即内存中的内容被换出到交换区，而后又被换入到内存，但使用过的交换区尚未被覆盖，该数值即为这些内容已存在于内存中的交换区的大小。相应的内存再次被换出时可不必再对交换区写入。
计算可用内存数有一个近似的公式： free + buff/cache
5:交换空间使用情况
如果有使用了，说明可能使用到了交换空间，这样会影响应用速度。应该关注，我这里显示为0是关闭了交换空间。
6:进程信息
PID 即进程的id 通过ps -fe |grep XXX查看
USER 进程所属的用户
PR 进程优先级，通常不用关注
NI nice值。负值表示高优先级，正值表示低优先级
VIRT 进程使用的虚拟内存总量，单位kb。VIRT=SWAP+RES
RES 进程常驻内存大小，单位kb。RES=CODE+DATA。通常可简单认为该值就表示当前进程使用的物理内存大小。
SHR 共享内存大小，单位kb
S 进程状态。D=不可中断的睡眠状态 R=运行 S=睡眠 T=跟踪/停止 Z=僵尸进程
%CPU% 上次更新到现在的CPU时间占用百分比。简单认为进程使用cpu的百分比
$MEM 进程使用的物理内存百分比
TIME+ 进程使用的CPU时间总计，单位1/100秒
COMMAND 命令名/命令行
top命令常用参数
top显示后，输入M按照内存排序，输入P按照cpu排序
top -Hp PID 按照线程维度显示，常用来分析cpu开销高的线程
vmstat
vmstat用法
vmstat用法格式：vmstat [选项参数] [数字] [数字]
选项参数:
1) -d: 显示磁盘相关统计信息。
2) -a： 显示活跃和非活跃内存
3) -f： 显示从系统启动至今的fork数量。
4) -p： 显示指定磁盘分区统计信息
5) -s： 显示内存相关统计信息及多种系统活动数量。
6) -m： 显示slabinfo
vmstat常用命令
通常vmstat工具的使用是通过两个数字参数来完成的，第一个参数是采样的时间间隔数，单位是秒，第二个参数是采样的次数，如:
如果使用vmstat 1 表示每秒采集一次，直至用户ctrl+c手动关闭该命令。
vmstat采集结果解释
procs 进程
r 即running，等待执行的任务数,展示了正在执行和等待cpu资源的任务个数。当这个值超过了cpu个数，就会出现cpu瓶颈。重点关注
b 即blocked，等待IO的进程数量。重点关注
---memory---
swpd 正在使用虚拟的内存大小，单位k
free 空闲内存大小
buff 已用的buff大小，对块设备的读写进行缓冲
cache 已用的cache大小，文件系统的cache
---swap---
si 每秒从交换区写入内存的大小（单位：kb/s），缩写是swap input。重点关注
so 每秒从内存写到交换区的大小（单位：kb/s）, 缩写是swap output。重点关注
注意:内存够用的时候，这2个值都是0，如果这2个值长期大于0时，系统性能会受到影响，磁盘IO和CPU资源都会被消耗。有些人看到空闲内存（free）很少的或接近于0时，就认为内存不够用了，不能光看这一点，还要结合si和so，如果free很少，但是si和so也很少（大多时候是0），那么不用担心，系统性能这时不会受到影响的。因为linux有缓存功能，buff/cache也是表示是可以使用的物理内存。
---io---
bi 每秒读取的块数（读磁盘）,块设备每秒接收的块数量，单位是block，这里的块设备是指系统上所有的磁盘和其他块设备，现在的Linux版本块的大小为1024bytes。重点关注
bo 每秒写入的块数（写磁盘），块设备每秒发送的块数量，单位是block。重点关注
注意:随机磁盘读写的时候，这2个值越大（如超出1024k)，能看到CPU在IO等待的值也会越大。
---system---
in 每秒中断数，包括时钟中断
cs 每秒上下文切换数。重点关注
注意：in和cs这两个值越大，会看到由内核消耗的cpu时间sy会越多，说明每秒线程上下文切换次数越多，说明cpu实际用来真正工作实际少了，都花费在了切换上。那么可以考虑减少线程数目。什么时候回进行切换呢？比如导致线程的阻塞动作都会进行切换，比如Thread.sleep，Thread.yield，Thread.join，synchronized同步代码块，Object.wait，LockSupport.park，网络调用(包括数据库调用)。
---cpu---
us 用户进程执行消耗cpu时间(user time)，us的值比较高时，说明用户进程消耗的cpu时间多，但是如果长期超过50%的使用，那么我们就该考虑优化程序了。重点关注
sy 系统进程消耗cpu时间(system time)，sy的值过高时，说明系统内核消耗的cpu资源多，说明是线程上下文切换过多。这里us + sy的参考值为80%，如果us+sy 大于 80%说明可能存在CPU不足。重点关注
id 空闲时间(包括IO等待时间)，一般来说 us+sy+id=100
wa 等待IO时间，wa过高时，说明io等待比较严重，这可能是由于磁盘大量随机访问造成的，也有可能是磁盘的带宽出现瓶颈。重点关注
st 虚拟机偷取的CPU时间的百分比 。没用过，忽略
如何认为到系统的cpu和io达到了瓶颈呢？什么指标可以分析呢？
通过vmstat判断系统瓶颈：
cpu瓶颈：
1.如果id持续为0且sy是us的两倍则系统则面临着CPU资源的短缺。
2.如果proce中的r持续高于cpu核数，说明有较多的进程在等待cpu资源，可能是有些对cpu开销大的进程在占用cpu，也可能是cpu资源不足。
IO瓶颈：
1.读写IO，bi bo增多超过2000
2.cpu等待时间用于 IO等待，wa增加 超过20
3.sy 系统调用时间长，IO操作频繁会导致上下文切换增加 sy>30%
4.wa io等待时间长
iowait% <20% 良好
iowait% <35% 一般
iowait% >50%
5.进一步使用iostat观察
vmstat -d显示磁盘相关统计信息
以sda磁盘为例
---reads---：总计读取了6411次，合并读请求23次，读取扇区(sectors)次数是464053次，每ms读取次数是5257bytes数据。
---writes---：总计写了3976次，合并写请求426次，写扇区是41075次，每ms写入129159bytes数据。
---IO---： cur和sec是什么含义呢？ 没找到资料
个人认为这个参数可以用来判断磁盘是否坏了。实际并没使用过。
iostat & iotop
iostat命令解释
iostat安装命令apt/yum install sysstat
来源http://linux.51yip.com/search/iostat
iostat 可以提供更丰富的IO性能状态数据
iostat提供几个用于定制输出的开关。最有用的有：
-c 只显示CPU行
-d 显示设备（磁盘）使用状态
-k 以千字节为单位显示磁盘输出
-t 在输出中包括时间戳
-x 在输出中包括扩展的磁盘指标
rrqm/s: 每秒进行 merge 的读操作数目。
wrqm/s: 每秒进行 merge 的写操作数目。
r/s: 每秒完成的读 I/O 设备次数。
w/s: 每秒完成的写 I/O 设备次数。
rsec/s: 每秒读扇区数。read-sectors sectors扇区
wsec/s: 每秒写扇区数。write-sectors
rkB/s: 每秒读K字节数。是 rsect/s 的一半，因为每扇区大小为512字节。(需要计算)
wkB/s: 每秒写K字节数。是 wsect/s 的一半。(需要计算)
avgrq-sz: 平均每次设备I/O操作的数据大小 (扇区)。
avgqu-sz: 平均I/O队列长度。
await: 平均每次设备I/O操作的等待时间 (毫秒)。 重点关注
svctm: 平均每次设备I/O操作的服务时间 (毫秒)。如果svctm的值与await很接近，表示几乎没有I/O等待，磁盘性能很好
%util: 一秒中有百分之多少的时间用于 I/O 操作。 重点关注
关于Merge的解释：当系统调用需要读取数据的时 候，VFS将请求发到各个FS，如果FS发现不同的读取请求读取的是相同Block的数据，FS会将这个请求合并Merge
await：每一个IO请求的处理的平均时间（单位是毫秒）。这里可以理解为IO的响应时间，一般地系统IO响应时间应该低于5ms，如果大于10ms就比较大了。
%util：在统计时间内所有处理IO时间，除以总共统计时间。例如，如果统计间隔1秒，该 设备有0.8秒在处理IO，而0.2秒闲置，那么该设备的%util = 0.8/1 = 80%，所以该参数暗示了设备的繁忙程度。一般地，如果该参数是100%表示设备已经接近满负荷运行了（当然如果是多磁盘，即使%util是100%，因 为磁盘的并发能力，所以磁盘使用未必就到了瓶颈）。
iostat常用命令参数组合
iostat -d -k 1 5 结果解释
Device表示设备，有4块磁盘sda,sdb,dm-0,dm-1
tps是每块磁盘的IO tps，即磁盘每秒传输次数
KB_read/s 每秒从该磁盘的读取速率
KB_wrtn/s 每秒写入该磁盘的速率
kB_read 累计从该磁盘读取的总量
kB_wrtn 累计写入该磁盘的总量
这个命令并不能看出io的平均，需要加-x参数
iostat -d -k -x 1 5
查看设备使用率（%util）、响应时间（await） iostat -d -k -x 1 5 ，其中1 5分别是间隔时间和总计执行次数， -d 后面可跟磁盘比如sda，只显示sda磁盘：iostat -d sda -k -x 1 5
rrqm/s: 每秒进行 merge 的读操作数目。read-request-merg的缩写
wrqm/s: 每秒进行 merge 的写操作数目。write-request-merg的缩写
r/s: 每秒完成的读 I/O 设备次数。
w/s: 每秒完成的写 I/O 设备次数。
rkB/s: 每秒读K字节数。是 rsect/s 的一半，因为每扇区大小为512字节。(需要计算)
wkB/s: 每秒写K字节数。是 wsect/s 的一半。(需要计算)
avgrq-sz: 平均每次设备I/O操作的数据大小 (扇区)。average-request-size
avgqu-sz: 平均I/O队列长度。average-queue-size
await: 简单理解为IO的响应时间(ms)。重点关注
svctm: 平均每次设备I/O操作的服务时间 (毫秒)。
%util: 一秒中有百分之多少的时间用于 I/O 操作。重点关注，该值越高，说明磁盘io压力越大。
iostat总结:
iostat 统计的是通用块层经过合并(rrqm/s, wrqm/s)后,直接向设备提交的IO数据,可以反映系统整体的IO状况,但是有以下2个缺点:
1 距离业务层比较遥远,跟代码中的write,read不对应(由于系统预读 + pagecache + IO调度算法等因素, 也很难对应)
2 是系统级,没办法精确到进程,比如只能告诉你现在磁盘很忙,但是没办法告诉你是哪个进程在忙,在忙什么？
因此需要使用到iotop命令，该命令可以确定是哪个进程/线程对磁盘的开销最大。
iotop命令解释
安装iotop工具： apt/yum install iotop -y
iotop是一个用来监视磁盘I/O使用状况的 top 类工具，可监测到哪一个程序使用的磁盘IO的信息
iotop 顾名思义, io版的top，该命令可以按进程统计IO状况,因此作为iostat的补充，可以解决以下2个问题：
1.当前系统哪些进程在占用IO,百分比是多少?
2.占用IO的进程是在读?还是在写?读写量是多少?
用法：iotop [OPTIONS]
--version #显示版本号
-h, --help #显示帮助信息
-o, --only #显示进程或者线程实际上正在做的I/O，而不是全部的，可以随时切换按o
-b, --batch #运行在非交互式的模式
-n NUM, --iter=NUM #在非交互式模式下，设置显示的次数，
-d SEC, --delay=SEC #设置显示的间隔秒数，支持非整数值
-p PID, --pid=PID #只显示指定PID的信息
-u USER, --user=USER #显示指定的用户的进程的信息
-P, --processes #只显示进程，一般为显示所有的线程
-a, --accumulated #显示从iotop启动后每个线程完成了的IO总数
-k, --kilobytes #以千字节显示
-t, --time #在每一行前添加一个当前的时间
在运行iotop命令后按相应键位：
使用left和right改变排序（方向键改变排序列），还可使用以下命令：
r：反向排序，
o：切换至选项--only，
p：切换至--processes选项，
a：切换至--accumulated选项
q：退出
i：改变线程的优先级
iotop常用命令参数
直接执行iotop即可，截图如下
前两行字面意思很简单，就是所有磁盘的读写速率
TID：线程id，按p可转换进程pid
PRIO：优先级
DISK READ：磁盘读取速率
DISK WRITE：磁盘写取速率
SWAPIN：swap交换百分比
IO>：IO等待所占用百分比。重点关注，该值越高，说明当前线程/进程对磁盘的压力越大。
COMMAND：线程/进程详细信息
磁盘IO的排查思路总结：
1.通常给服务器做压测时，容易碰到磁盘IO读取瓶颈，持续高的IO会导致磁盘读取密集读写磁盘IO成为短板，程序运行过慢；常见的IO操作有打印日志、操作数据库，网络调用。
2.使用top命令查看%wa指标，该项阈值表示io waiting等待磁盘磁盘写入完成的时间，一般不能高于30%，假如该值过大且持续较久，说明遇到了磁盘I/O瓶颈，需要对应用进行优化，或对服务器资源进行升级。
3.iostat -d -k -x 1输出磁盘相关统计信息，主要关注await，%util指标。
4.iotop定位负载来源于那个进程/线程。
5.通过jstack打印堆栈，分析iotop中开销IO资源高的几个线程。