性能優(yōu)化一向是后端服務(wù)優(yōu)化的重點(diǎn)，但是線上性能故障問題不是經(jīng)常出現(xiàn)，或者受限于業(yè)務(wù)產(chǎn)品，根本就沒辦法出現(xiàn)性能問題，包括筆者自己遇到的性能問題也不多，所以為了提前儲(chǔ)備知識(shí)，當(dāng)出現(xiàn)問題的時(shí)候不會(huì)手忙腳亂，我們本篇文章來模擬下常見的幾個(gè)Java性能故障，來學(xué)習(xí)怎么去分析和定位。
既然是定位問題，肯定是需要借助工具，我們先了解下需要哪些工具可以幫忙定位問題。
top命令
top命令是我們最常用的Linux命令之一，它可以實(shí)時(shí)的顯示當(dāng)前正在執(zhí)行的進(jìn)程的CPU使用率，內(nèi)存使用率等系統(tǒng)信息。top -Hp pid 可以查看線程的系統(tǒng)資源使用情況。
vmstat命令
vmstat是一個(gè)指定周期和采集次數(shù)的虛擬內(nèi)存檢測工具，可以統(tǒng)計(jì)內(nèi)存，CPU，swap的使用情況，它還有一個(gè)重要的常用功能，用來觀察進(jìn)程的上下文切換。字段說明如下:
pidstat命令
pidstat 是 Sysstat 中的一個(gè)組件，也是一款功能強(qiáng)大的性能監(jiān)測工具，top 和 vmstat 兩個(gè)命令都是監(jiān)測進(jìn)程的內(nèi)存、CPU 以及 I/O 使用情況，而 pidstat 命令可以檢測到線程級(jí)別的。pidstat命令線程切換字段說明如下：
jstack命令
jstack是JDK工具命令，它是一種線程堆棧分析工具，最常用的功能就是使用 jstack pid 命令查看線程的堆棧信息，也經(jīng)常用來排除死鎖情況。
jstat 命令
它可以檢測Java程序運(yùn)行的實(shí)時(shí)情況，包括堆內(nèi)存信息和垃圾回收信息，我們常常用來查看程序垃圾回收情況。常用的命令是jstat -gc pid。信息字段說明如下：
jmap命令
jmap也是JDK工具命令，他可以查看堆內(nèi)存的初始化信息以及堆內(nèi)存的使用情況，還可以生成dump文件來進(jìn)行詳細(xì)分析。查看堆內(nèi)存情況命令jmap -heap pid。
mat內(nèi)存工具
MAT(Memory Analyzer Tool)工具是eclipse的一個(gè)插件(MAT也可以單獨(dú)使用)，它分析大內(nèi)存的dump文件時(shí)，可以非常直觀的看到各個(gè)對(duì)象在堆空間中所占用的內(nèi)存大小、類實(shí)例數(shù)量、對(duì)象引用關(guān)系、利用OQL對(duì)象查詢，以及可以很方便的找出對(duì)象GC Roots的相關(guān)信息。
idea中也有這么一個(gè)插件，就是JProfiler。
相關(guān)閱讀：
基礎(chǔ)環(huán)境jdk1.8，采用SpringBoot框架來寫幾個(gè)接口來觸發(fā)模擬場景，首先是模擬CPU占滿情況
模擬CPU占滿還是比較簡單，直接寫一個(gè)死循環(huán)計(jì)算消耗CPU即可。
/**
* 模擬CPU占滿
*/
@GetMapping('/cpu/loop')
public void testCPULoop() throws InterruptedException {
System.out.println('請求cpu死循環(huán)');
Thread.currentThread().setName('loop-thread-cpu');
int num = 0;
while (true) {
num++;
if (num == Integer.MAX_VALUE) {
System.out.println('reset');
}
num = 0;
}
}
請求接口地址測試curl localhost:8080/cpu/loop,發(fā)現(xiàn)CPU立馬飆升到100%
通過執(zhí)行top -Hp 32805 查看Java線程情況
執(zhí)行 printf '%x' 32826 獲取16進(jìn)制的線程id，用于dump信息查詢，結(jié)果為 803a。最后我們執(zhí)行jstack 32805 |grep -A 20 803a來查看下詳細(xì)的dump信息。
這里dump信息直接定位出了問題方法以及代碼行，這就定位出了CPU占滿的問題。
模擬內(nèi)存泄漏借助了ThreadLocal對(duì)象來完成，ThreadLocal是一個(gè)線程私有變量，可以綁定到線程上，在整個(gè)線程的生命周期都會(huì)存在，但是由于ThreadLocal的特殊性，ThreadLocal是基于ThreadLocalMap實(shí)現(xiàn)的，ThreadLocalMap的Entry繼承WeakReference，而Entry的Key是WeakReference的封裝，換句話說Key就是弱引用，弱引用在下次GC之后就會(huì)被回收，如果ThreadLocal在set之后不進(jìn)行后續(xù)的操作，因?yàn)镚C會(huì)把Key清除掉，但是Value由于線程還在存活，所以Value一直不會(huì)被回收，最后就會(huì)發(fā)生內(nèi)存泄漏。
/**
* 模擬內(nèi)存泄漏
*/
@GetMapping(value = '/memory/leak')
public String leak() {
System.out.println('模擬內(nèi)存泄漏');
ThreadLocal<Byte[]> localVariable = new ThreadLocal<Byte[]>();
localVariable.set(new Byte[4096 * 1024]);// 為線程添加變量
return 'ok';
}
我們給啟動(dòng)加上堆內(nèi)存大小限制，同時(shí)設(shè)置內(nèi)存溢出的時(shí)候輸出堆?？煺詹⑤敵鋈罩尽?/p>
java -jar -Xms500m -Xmx500m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/tmp/heapdump.hprof -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -Xloggc:/tmp/heaplog.log analysis-demo-0.0.1-SNAPSHOT.jar
啟動(dòng)成功后我們循環(huán)執(zhí)行100次,for i in {1..500}; do curl localhost:8080/memory/leak;done,還沒執(zhí)行完畢，系統(tǒng)已經(jīng)返回500錯(cuò)誤了。查看系統(tǒng)日志出現(xiàn)了如下異常：
java.lang.OutOfMemoryError: Java heap space
我們用jstat -gc pid 命令來看看程序的GC情況。
很明顯，內(nèi)存溢出了，堆內(nèi)存經(jīng)過45次 Full Gc 之后都沒釋放出可用內(nèi)存，這說明當(dāng)前堆內(nèi)存中的對(duì)象都是存活的，有GC Roots引用，無法回收。那是什么原因?qū)е聝?nèi)存溢出呢？是不是我只要加大內(nèi)存就行了呢？如果是普通的內(nèi)存溢出也許擴(kuò)大內(nèi)存就行了，但是如果是內(nèi)存泄漏的話，擴(kuò)大的內(nèi)存不一會(huì)就會(huì)被占滿，所以我們還需要確定是不是內(nèi)存泄漏。我們之前保存了堆 Dump 文件，這個(gè)時(shí)候借助我們的MAT工具來分析下。導(dǎo)入工具選擇Leak Suspects Report，工具直接就會(huì)給你列出問題報(bào)告。
這里已經(jīng)列出了可疑的4個(gè)內(nèi)存泄漏問題，我們點(diǎn)擊其中一個(gè)查看詳情。
這里已經(jīng)指出了內(nèi)存被線程占用了接近50M的內(nèi)存，占用的對(duì)象就是ThreadLocal。如果想詳細(xì)的通過手動(dòng)去分析的話，可以點(diǎn)擊Histogram,查看最大的對(duì)象占用是誰，然后再分析它的引用關(guān)系，即可確定是誰導(dǎo)致的內(nèi)存溢出。
上圖發(fā)現(xiàn)占用內(nèi)存最大的對(duì)象是一個(gè)Byte數(shù)組，我們看看它到底被那個(gè)GC Root引用導(dǎo)致沒有被回收。按照上圖紅框操作指引，結(jié)果如下圖：
我們發(fā)現(xiàn)Byte數(shù)組是被線程對(duì)象引用的，圖中也標(biāo)明，Byte數(shù)組對(duì)像的GC Root是線程，所以它是不會(huì)被回收的，展開詳細(xì)信息查看，我們發(fā)現(xiàn)最終的內(nèi)存占用對(duì)象是被ThreadLocal對(duì)象占據(jù)了。這也和MAT工具自動(dòng)幫我們分析的結(jié)果一致。
死鎖會(huì)導(dǎo)致耗盡線程資源，占用內(nèi)存，表現(xiàn)就是內(nèi)存占用升高，CPU不一定會(huì)飆升(看場景決定)，如果是直接new線程，會(huì)導(dǎo)致JVM內(nèi)存被耗盡，報(bào)無法創(chuàng)建線程的錯(cuò)誤，這也是體現(xiàn)了使用線程池的好處。
ExecutorService service = new ThreadPoolExecutor(4, 10,
0, TimeUnit.SECONDS, new LinkedBlockingQueue<Runnable>(1024),
Executors.defaultThreadFactory(),
new ThreadPoolExecutor.AbortPolicy());
/**
* 模擬死鎖
*/
@GetMapping('/cpu/test')
public String testCPU() throws InterruptedException {
System.out.println('請求cpu');
Object lock1 = new Object();
Object lock2 = new Object();
service.submit(new DeadLockThread(lock1, lock2), 'deadLookThread-' + new Random().nextInt());
service.submit(new DeadLockThread(lock2, lock1), 'deadLookThread-' + new Random().nextInt());
return 'ok';
}
public class DeadLockThread implements Runnable {
private Object lock1;
private Object lock2;
public DeadLockThread1(Object lock1, Object lock2) {
this.lock1 = lock1;
this.lock2 = lock2;
}
@Override
public void run() {
synchronized (lock2) {
System.out.println(Thread.currentThread().getName()+'get lock2 and wait lock1');
try {
TimeUnit.MILLISECONDS.sleep(2000);
} catch (InterruptedException e) {
e.printStackTrace();
}
synchronized (lock1) {
System.out.println(Thread.currentThread().getName()+'get lock1 and lock2 ');
}
}
}
}
我們循環(huán)請求接口2000次，發(fā)現(xiàn)不一會(huì)系統(tǒng)就出現(xiàn)了日志錯(cuò)誤，線程池和隊(duì)列都滿了,由于我選擇的當(dāng)隊(duì)列滿了就拒絕的策略，所以系統(tǒng)直接拋出異常。
java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.FutureTask@2760298 rejected from java.util.concurrent.ThreadPoolExecutor@7ea7cd51[Running, pool size = 10, active threads = 10, queued tasks = 1024, completed tasks = 846]
通過ps -ef|grep java命令找出 Java 進(jìn)程 pid，執(zhí)行jstack pid 即可出現(xiàn)java線程堆棧信息，這里發(fā)現(xiàn)了5個(gè)死鎖，我們只列出其中一個(gè)，很明顯線程pool-1-thread-2鎖住了0x00000000f8387d88等待0x00000000f8387d98鎖，線程pool-1-thread-1鎖住了0x00000000f8387d98等待鎖0x00000000f8387d88,這就產(chǎn)生了死鎖。
Java stack information for the threads listed above:
===================================================
'pool-1-thread-2':
at top.luozhou.analysisdemo.controller.DeadLockThread2.run(DeadLockThread.java:30)
- waiting to lock <0x00000000f8387d98> (a java.lang.Object)
- locked <0x00000000f8387d88> (a java.lang.Object)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
'pool-1-thread-1':
at top.luozhou.analysisdemo.controller.DeadLockThread1.run(DeadLockThread.java:30)
- waiting to lock <0x00000000f8387d88> (a java.lang.Object)
- locked <0x00000000f8387d98> (a java.lang.Object)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Found 5 deadlocks.
上下文切換會(huì)導(dǎo)致將大量CPU時(shí)間浪費(fèi)在寄存器、內(nèi)核棧以及虛擬內(nèi)存的保存和恢復(fù)上，導(dǎo)致系統(tǒng)整體性能下降。當(dāng)你發(fā)現(xiàn)系統(tǒng)的性能出現(xiàn)明顯的下降時(shí)候，需要考慮是否發(fā)生了大量的線程上下文切換。
@GetMapping(value = '/thread/swap')
public String theadSwap(int num) {
System.out.println('模擬線程切換');
for (int i = 0; i < num; i++) {
new Thread(new ThreadSwap1(new AtomicInteger(0)),'thread-swap'+i).start();
}
return 'ok';
}
public class ThreadSwap1 implements Runnable {
private AtomicInteger integer;
public ThreadSwap1(AtomicInteger integer) {
this.integer = integer;
}
@Override
public void run() {
while (true) {
integer.addAndGet(1);
Thread.yield(); //讓出CPU資源
}
}
}
這里我創(chuàng)建多個(gè)線程去執(zhí)行基礎(chǔ)的原子+1操作，然后讓出 CPU 資源，理論上 CPU 就會(huì)去調(diào)度別的線程，我們請求接口創(chuàng)建100個(gè)線程看看效果如何，curl localhost:8080/thread/swap?num=100。接口請求成功后，我們執(zhí)行`vmstat 1 10，表示每1秒打印一次，打印10次，線程切換采集結(jié)果如下：
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
r b swpd free buff cache si so bi bo in cs us sy id wa st
101 0 128000 878384 908 468684 0 0 0 0 4071 8110498 14 86 0 0 0
100 0 128000 878384 908 468684 0 0 0 0 4065 8312463 15 85 0 0 0
100 0 128000 878384 908 468684 0 0 0 0 4107 8207718 14 87 0 0 0
100 0 128000 878384 908 468684 0 0 0 0 4083 8410174 14 86 0 0 0
100 0 128000 878384 908 468684 0 0 0 0 4083 8264377 14 86 0 0 0
100 0 128000 878384 908 468688 0 0 0 108 4182 8346826 14 86 0 0 0
這里我們關(guān)注4個(gè)指標(biāo)，r,cs,us,sy。
r=100,說明等待的進(jìn)程數(shù)量是100，線程有阻塞。
cs=800多萬，說明每秒上下文切換了800多萬次，這個(gè)數(shù)字相當(dāng)大了。
us=14，說明用戶態(tài)占用了14%的CPU時(shí)間片去處理邏輯。
sy=86，說明內(nèi)核態(tài)占用了86%的CPU，這里明顯就是做上下文切換工作了。
我們通過top命令以及top -Hp pid查看進(jìn)程和線程CPU情況，發(fā)現(xiàn)Java線程CPU占滿了，但是線程CPU使用情況很平均，沒有某一個(gè)線程把CPU吃滿的情況。
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
87093 root 20 0 4194788 299056 13252 S 399.7 16.1 65:34.67 java
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
87189 root 20 0 4194788 299056 13252 R 4.7 16.1 0:41.11 java
87129 root 20 0 4194788 299056 13252 R 4.3 16.1 0:41.14 java
87130 root 20 0 4194788 299056 13252 R 4.3 16.1 0:40.51 java
87133 root 20 0 4194788 299056 13252 R 4.3 16.1 0:40.59 java
87134 root 20 0 4194788 299056 13252 R 4.3 16.1 0:40.95 java
結(jié)合上面用戶態(tài)CPU只使用了14%，內(nèi)核態(tài)CPU占用了86%，可以基本判斷是Java程序線程上下文切換導(dǎo)致性能問題。
我們使用pidstat命令來看看Java進(jìn)程內(nèi)部的線程切換數(shù)據(jù)，執(zhí)行pidstat -p 87093 -w 1 10,采集數(shù)據(jù)如下：
11:04:30 PM UID TGID TID cswch/s nvcswch/s Command
11:04:30 PM 0 - 87128 0.00 16.07 |__java
11:04:30 PM 0 - 87129 0.00 15.60 |__java
11:04:30 PM 0 - 87130 0.00 15.54 |__java
11:04:30 PM 0 - 87131 0.00 15.60 |__java
11:04:30 PM 0 - 87132 0.00 15.43 |__java
11:04:30 PM 0 - 87133 0.00 16.02 |__java
11:04:30 PM 0 - 87134 0.00 15.66 |__java
11:04:30 PM 0 - 87135 0.00 15.23 |__java
11:04:30 PM 0 - 87136 0.00 15.33 |__java
11:04:30 PM 0 - 87137 0.00 16.04 |__java
根據(jù)上面采集的信息，我們知道Java的線程每秒切換15次左右，正常情況下，應(yīng)該是個(gè)位數(shù)或者小數(shù)。結(jié)合這些信息我們可以斷定Java線程開啟過多，導(dǎo)致頻繁上下文切換，從而影響了整體性能。
為什么系統(tǒng)的上下文切換是每秒800多萬，而 Java 進(jìn)程中的某一個(gè)線程切換才15次左右？
系統(tǒng)上下文切換分為三種情況:
1、多任務(wù)：在多任務(wù)環(huán)境中，一個(gè)進(jìn)程被切換出CPU，運(yùn)行另外一個(gè)進(jìn)程，這里會(huì)發(fā)生上下文切換。
2、中斷處理：發(fā)生中斷時(shí)，硬件會(huì)切換上下文。在vmstat命令中是in
3、用戶和內(nèi)核模式切換：當(dāng)操作系統(tǒng)中需要在用戶模式和內(nèi)核模式之間進(jìn)行轉(zhuǎn)換時(shí)，需要進(jìn)行上下文切換,比如進(jìn)行系統(tǒng)函數(shù)調(diào)用。
Linux 為每個(gè) CPU 維護(hù)了一個(gè)就緒隊(duì)列，將活躍進(jìn)程按照優(yōu)先級(jí)和等待 CPU 的時(shí)間排序，然后選擇最需要 CPU 的進(jìn)程，也就是優(yōu)先級(jí)最高和等待 CPU 時(shí)間最長的進(jìn)程來運(yùn)行。也就是vmstat命令中的r。
那么，進(jìn)程在什么時(shí)候才會(huì)被調(diào)度到 CPU 上運(yùn)行呢？
結(jié)合我們之前的內(nèi)容分析，阻塞的就緒隊(duì)列是100左右，而我們的CPU只有4核，這部分原因造成的上下文切換就可能會(huì)相當(dāng)高，再加上中斷次數(shù)是4000左右和系統(tǒng)的函數(shù)調(diào)用等，整個(gè)系統(tǒng)的上下文切換到800萬也不足為奇了。Java內(nèi)部的線程切換才15次，是因?yàn)榫€程使用Thread.yield()來讓出CPU資源，但是CPU有可能繼續(xù)調(diào)度該線程，這個(gè)時(shí)候線程之間并沒有切換，這也是為什么內(nèi)部的某個(gè)線程切換次數(shù)并不是非常大的原因。
本文模擬了常見的性能問題場景，分析了如何定位CPU100%、內(nèi)存泄漏、死鎖、線程頻繁切換問題。分析問題我們需要做好兩件事:
本文也列舉了分析問題的常用工具和命令，希望對(duì)你解決問題有所幫助。當(dāng)然真正的線上環(huán)境可能十分復(fù)雜，并沒有模擬的環(huán)境那么簡單，但是原理是一樣的，問題的表現(xiàn)也是類似的，我們重點(diǎn)抓住原理，活學(xué)活用，相信復(fù)雜的線上問題也可以順利解決。
聯(lián)系客服
