Java虚拟机性能调优（二）
学习JavaGuide性能调优时，场景模拟。（基础环境JDK1.8、SpringBoot）
一、模拟CPU占满场景
controller代码如下：
/** * 模拟CPU占满 */ @GetMapping("/test/cpuLoop") public void testCPULoop() throws InterruptedException { System.out.println("请求cpu死循环"); Thread.currentThread().setName("loop-thread-cpu"); int num = 0; while (true) { num++; if (num == Integer.MAX_VALUE) { System.out.println("reset"); num = 0; } // num = 0; } }
启动Jar包：
①java -jar -Xms256m -Xmx512m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=./heapump.hprof -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -Xloggc:./log.log ptDemo.jar&
②查看Linux进程：
jps -mlVv
11862 sun.tools.jps.Jps -mlVv -Dapplication.home=/usr/local/java/jdk1.8.0_144 -Xms8m
10319 ptDemo.jar
请求接口/test/cpuLoop。
1、查看Java进程10319的线程
[root@docker wangymd]# top -Hp 10319 top - 00:35:51 up 4:05, 1 user, load average: 1.00, 1.00, 1.04 Threads: 29 total, 1 running, 28 sleeping, 0 stopped, 0 zombie %Cpu(s): 50.4 us, 0.3 sy, 0.0 ni, 49.2 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st KiB Mem : 1863236 total, 396196 free, 493100 used, 973940 buff/cache KiB Swap: 2097148 total, 2097148 free, 0 used. 1166776 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 10339 root 20 0 2990792 290080 13588 R 99.7 15.6 239:05.43 java 10338 root 20 0 2990792 290080 13588 S 0.3 15.6 0:43.63 java 10341 root 20 0 2990792 290080 13588 S 0.3 15.6 0:43.91 java 10319 root 20 0 2990792 290080 13588 S 0.0 15.6 0:00.00 java 10320 root 20 0 2990792 290080 13588 S 0.0 15.6 0:14.85 java 10321 root 20 0 2990792 290080 13588 S 0.0 15.6 0:06.14 java 10322 root 20 0 2990792 290080 13588 S 0.0 15.6 0:06.12 java 10323 root 20 0 2990792 290080 13588 S 0.0 15.6 0:12.28 java 10324 root 20 0 2990792 290080 13588 S 0.0 15.6 0:00.03 java 10325 root 20 0 2990792 290080 13588 S 0.0 15.6 0:00.04 java
系统进程10319中线程PID10339使用CPU99.7%。
2、执行 printf '%x' 10339 转换为16进制的线程id，用于dump信息查询，结果为2863。最后我们执行jstack 10339 |grep -A 20 2863来查看下详细的dump信息。
[root@docker wangymd]# printf '%x' 10339 2863
[root@docker wangymd]# jstack 10319 |grep -A 20 2863 "loop-thread-cpu" #17 daemon prio=5 os_prio=0 tid=0x00007f7be09ec000 nid=0x2863 runnable [0x00007f7bc9222000] java.lang.Thread.State: RUNNABLE at com.javaguide.pt.Application.testCPULoop(Application.java:45) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:190) at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:138) at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:105) at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:879) at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:793) at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87) at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1040) at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:943) at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006) at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898) at javax.servlet.http.HttpServlet.service(HttpServlet.java:634) at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883) at javax.servlet.http.HttpServlet.service(HttpServlet.java:741) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
定位到问题，标红位置！
二、模拟内存泄漏场景
内存泄漏（Memory Leak）是指程序中己动态分配的堆内存由于某种原因程序未释放或无法释放，造成系统内存的浪费，导致程序运行速度减慢甚至系统崩溃等严重后果。
引用《JavaGuide》：
模拟内存泄漏借助了ThreadLocal对象来完成，ThreadLocal是一个线程私有变量，可以绑定到线程上，在整个线程的生命周期都会存在，但是由于ThreadLocal的特殊性，ThreadLocal是基于ThreadLocalMap实现的，ThreadLocalMap的Entry继承WeakReference，而Entry的Key是WeakReference的封装，换句话说Key就是弱引用，弱引用在下次GC之后就会被回收，如果ThreadLocal在set之后不进行后续的操作，因为GC会把Key清除掉，但是Value由于线程还在存活，所以Value一直不会被回收，最后就会发生内存泄漏。
1、controller代码如下：
1 /** 2 * 模拟内存泄漏 3 */ 4 @GetMapping(value = "/test/memoryLeak") 5 public String memoryLeak() { 6 System.out.println("模拟内存泄漏"); 7 ThreadLocal<Byte[]> localVariable = new ThreadLocal<Byte[]>(); 8 localVariable.set(new Byte[4096 * 1024]);// 为线程添加变量 9 return "ok"; 10 }
2、调用100次
for i in {1..100}; do curl localhost:8080/test/memoryLeak;done
调用未结束发生接口500错误。
3、日志错误信息：
java.lang.OutOfMemoryError: Java heap space at com.javaguide.pt.Application.memoryLeak(Application.java:57) ~[classes!/:0.0.1-SNAPSHOT] at sun.reflect.GeneratedMethodAccessor20.invoke(Unknown Source) ~[na:na] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_144] at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_144]
4、jstat命令查看GC情况
具体含义可参考我的文章：https://www.cnblogs.com/wangymd/p/11274808.html
[root@docker wangymd]# jstat -gc 10956 S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT 12288.0 11776.0 0.0 0.0 150528.0 21923.8 349696.0 255003.2 35456.0 33371.2 4480.0 4110.0 9 0.715 32 7.000 7.715 [root@docker wangymd]# jstat -gcutil 10956 S0 S1 E O M CCS YGC YGCT FGC FGCT GCT 0.00 0.00 22.34 72.92 94.12 91.74 9 0.715 32 7.000 7.715
Full GC发生32次，GC总耗时7.715秒。此时发生内存溢出，堆内存中的对象未被回收。堆内存中的对象被引用，不能进行回收，可能是内存泄漏导致。通过使用MAT工具进一步进行分析。
5、内存分析
具体含义可参考我的文章：https://www.cnblogs.com/wangymd/p/11277583.html
内存分析-概述：
内存分析-内存泄漏（存在4个可疑问题）：
内存分析-内存泄漏-怀疑问题1：
这里已经指出了内存被线程占用了接近50M的内存，占用的对象就是ThreadLocal。如果想详细的通过手动去分析的话，可以点击Histogram,查看最大的对象占用是谁，然后再分析它的引用关系，即可确定是谁导致的内存溢出。
内存分析-内存泄漏-怀疑问题1-Histogram：
上图发现占用内存最大的对象是一个Byte数组，我们看看它到底被那个GC Root引用导致没有被回收。按照上图红框操作指引，结果如下图：
发现Byte数组是被线程对象引用的，Byte数组对像的GC Root是线程，所以它是不会被回收的；展开详细信息，发现最终的内存占用对象是被ThreadLocal对象占据了。
这也和MAT工具自动帮我们分析的结果一致。
三、模拟死锁场景
死锁会导致耗尽线程资源，占用内存，表现就是内存占用升高，CPU不一定会飙升(看场景决定)，如果是直接new线程，会导致JVM内存被耗尽，报无法创建线程的错误，这也是体现了使用线程池的好处。
//线程池 ExecutorService service = new ThreadPoolExecutor(4, 10, 0, TimeUnit.SECONDS, new LinkedBlockingQueue<Runnable>(1024), Executors.defaultThreadFactory(), new ThreadPoolExecutor.AbortPolicy()); /** * 模拟死锁 */ @GetMapping("/test/deadlock") public String deadlock() 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 DeadLockThread(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 "); } } } }
请求接口：/test/deadlock
循环调用1000次接口：for i in {1..1000}; do curl localhost:8080/test/deadlock; done。接口报500错误详细信息如下：
{"timestamp":"2020-05-18T06:30:14.046+0000","status":500,"error":"Internal Server Error","message":"Task java.util.concurrent.FutureTask@4c8896c2 rejected from java.util.concurrent.ThreadPoolExecutor@50d9e1b6[Running, pool size = 10, active threads = 10, queued tasks = 1024, completed tasks = 0]","path":"/test/deadlock"}
线程池和队列都满了,由于选择拒绝策略，所以系统直接抛出异常。
通过jstack 10956查看线程堆栈跟踪信息，发现5个死锁，下面列出第一个。
"pool-1-thread-2": at com.javaguide.pt.Application$DeadLockThread.run(Application.java:97) - waiting to lock <0x00000000ec987e80> (a java.lang.Object) - locked <0x00000000ec987e90> (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 com.javaguide.pt.Application$DeadLockThread.run(Application.java:97) - waiting to lock <0x00000000ec987e90> (a java.lang.Object) - locked <0x00000000ec987e80> (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.
线程pool-1-thread-2锁定0x00000000ec987e80，等待0x00000000ec987e90锁；线程pool-1-thread-1锁定0x00000000ec987e90，等待锁0x00000000ec987e80,从而产生死锁。
四、线程频繁切换场景
重新启动服务，新的进程Id是14084。
上下文切换会导致将大量CPU时间浪费在寄存器、内核栈以及虚拟内存的保存和恢复上，导致系统整体性能下降。当你发现系统的性能出现明显的下降时候，需要考虑是否发生了大量的线程上下文切换。
@GetMapping(value = "/test/threadSwap") 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资源 } } }
1、创建多个线程去执行基础的原子+1操作，然后让出 CPU 资源，理论上 CPU 就会去调度别的线程，我们请求接口创建100个线程看看效果如何，curl localhost:8080/thread/swap?num=100。接口请求成功后，我们执行`vmstat 1 10，表示每1秒打印一次，打印10次，线程切换采集结果如下：
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu----- r b swpd free buff cache si so bi bo in cs us sy id wa st 5 0 1544 769336 316 559656 0 0 52 76 391 502 3 5 91 1 0 101 0 1544 769328 316 559664 0 0 0 0 2081 344337 30 70 0 0 0 103 0 1544 769328 316 559668 0 0 0 0 2096 390859 25 76 0 0 0 102 0 1544 769328 316 559668 0 0 0 0 794 462564 25 75 0 0 0 104 0 1544 769328 316 559672 0 0 0 0 773 461674 24 76 0 0 0 101 0 1544 769328 316 559672 0 0 0 0 1515 443980 24 76 0 0 0 101 0 1544 769328 316 559676 0 0 0 0 1712 441115 28 72 0 0 0 101 0 1544 769328 316 559676 0 0 0 0 1681 461222 24 75 1 0 0 101 0 1544 769204 316 559680 0 0 0 0 1966 404770 22 78 0 0 0 101 0 1544 769204 316 559680 0 0 0 0 2051 397209 24 77 0 0 0
r：进程数100；cs：每秒上线文及切换近40万；us：用户占用CPU24%的时间片；sy：系统占用CPU76%的时间片。
2、top命令：
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 14084 root 20 0 3152276 314796 13444 S 190.7 16.9 9:28.02 java
3、top -Hp 14084命令：
14138 root 20 0 3152276 335072 13444 R 2.3 18.0 0:07.14 java 14092 root 20 0 3152276 335072 13444 R 2.0 18.0 0:33.05 java 14131 root 20 0 3152276 335072 13444 R 2.0 18.0 0:07.09 java 14134 root 20 0 3152276 335072 13444 R 2.0 18.0 0:07.15 java 14136 root 20 0 3152276 335072 13444 R 2.0 18.0 0:07.14 java 14140 root 20 0 3152276 335072 13444 R 2.0 18.0 0:07.10 java 14144 root 20 0 3152276 335072 13444 R 2.0 18.0 0:07.03 java 14149 root 20 0 3152276 335072 13444 R 2.0 18.0 0:07.05 java 14153 root 20 0 3152276 335072 13444 R 2.0 18.0 0:07.03 java 14154 root 20 0 3152276 335072 13444 R 2.0 18.0 0:06.88 java 14158 root 20 0 3152276 335072 13444 R 2.0 18.0 0:07.00 java 14159 root 20 0 3152276 335072 13444 R 2.0 18.0 0:06.92 java 14160 root 20 0 3152276 335072 13444 R 2.0 18.0 0:06.89 java 14161 root 20 0 3152276 335072 13444 R 2.0 18.0 0:06.93 java 14162 root 20 0 3152276 335072 13444 R 2.0 18.0 0:06.87 java 14163 root 20 0 3152276 335072 13444 R 2.0 18.0 0:06.87 java 14164 root 20 0 3152276 335072 13444 R 2.0 18.0 0:06.86 java 14165 root 20 0 3152276 335072 13444 R 2.0 18.0 0:06.84 java 14166 root 20 0 3152276 335072 13444 R 2.0 18.0 0:06.88 java 14167 root 20 0 3152276 335072 13444 R 2.0 18.0 0:06.83 java 14170 root 20 0 3152276 335072 13444 R 2.0 18.0 0:06.90 java 14182 root 20 0 3152276 335072 13444 R 2.0 18.0 0:06.71 java 14185 root 20 0 3152276 335072 13444 R 2.0 18.0 0:06.65 java 14186 root 20 0 3152276 335072 13444 R 2.0 18.0 0:06.66 java 14187 root 20 0 3152276 335072 13444 R 2.0 18.0 0:06.75 java 14194 root 20 0 3152276 335072 13444 R 2.0 18.0 0:06.60 java 14195 root 20 0 3152276 335072 13444 R 2.0 18.0 0:06.55 java 14199 root 20 0 3152276 335072 13444 R 2.0 18.0 0:06.47 java 14202 root 20 0 3152276 335072 13444 R 2.0 18.0 0:06.52 java 14205 root 20 0 3152276 335072 13444 R 2.0 18.0 0:06.54 java 14208 root 20 0 3152276 335072 13444 R 2.0 18.0 0:06.45 java 14213 root 20 0 3152276 335072 13444 R 2.0 18.0 0:06.38 java 14216 root 20 0 3152276 335072 13444 R 2.0 18.0 0:06.35 java
Java进程将CPU占满，但是线程使用CPU很平均。
结合上面用户态CPU只使用了24%，内核态CPU占用了76%，可以基本判断是Java程序线程上下文切换导致性能问题。
4、使用pidstat命令来看看Java进程内部的线程切换数据，执行pidstat -p 14084 -w 1 10：
更多内容请参考《深入理解Linux的CPU上下文切换》https://www.linuxblogs.cn/articles/18120200.html
浙公网安备 33010602011771号