CPU和磁碟IO實戰筆記總結
前言
前面分析了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資源高的幾個執行緒。