前言
前面分析了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資源高的幾個線程。