我学了这套性能优化方法论,领导年终奖给我发了 6 个月
目录
概述性能优化一向是后端服务优化的重点,但是线上性能故障问题不是经常出现,或者受限于业务产品,根本就没办法出现性能问题,包括笔者自己遇到的性能问题也不多,所以为了提前储备知识,当出现问题的时候不会手忙脚乱,我们本篇文章来模拟下常见的几个 Java 性能故障,来学习怎么去分析和定位。
预备知识
既然是定位问题,肯定是需要借助工具,我们先了解下需要哪些工具可以帮忙定位问题。
top 命令
top 命令使我们最常用的 Linux 命令之一,它可以实时的显示当前正在执行的进程的 CPU 使用率,内存使用率等系统信息。top -Hp pid 可以查看线程的系统资源使用情况。
vmstat 命令
vmstat 是一个指定周期和采集次数的虚拟内存检测工具,可以统计内存,CPU,swap 的使用情况,它还有一个重要的常用功能,用来观察进程的上下文切换。字段说明如下:
pidstat 是 Sysstat 中的一个组件,也是一款功能强大的性能监测工具,top 和 vmstat 两个命令都是监测进程的内存、CPU 以及 I/O 使用情况,而 pidstat 命令可以检测到线程级别的。pidstat 命令线程切换字段说明如下:
jstack 是 JDK 工具命令,它是一种线程堆栈分析工具,最常用的功能就是使用 jstack pid 命令查看线程的堆栈信息,也经常用来排除死锁情况。
jstat 命令
它可以检测 Java 程序运行的实时情况,包括堆内存信息和垃圾回收信息,我们常常用来查看程序垃圾回收情况。常用的命令是 jstat -gc pid。信息字段说明如下:
jmap 也是 JDK 工具命令,他可以查看堆内存的初始化信息以及堆内存的使用情况,还可以生成 dump 文件来进行详细分析。查看堆内存情况命令 jmap -heap pid。
mat 内存工具
MAT(Memory Analyzer Tool)工具是 eclipse 的一个插件(MAT 也可以单独使用),它分析大内存的 dump 文件时,可以非常直观的看到各个对象在堆空间中所占用的内存大小、类实例数量、对象引用关系、利用 OQL 对象查询,以及可以很方便的找出对象 GC Roots 的相关信息。
idea 中也有这么一个插件,就是 JProfiler。
相关阅读:《性能诊断利器 JProfiler 快速入门和最佳实践》
模拟环境准备基础环境 jdk1.8,采用 SpringBoot 框架来写几个接口来触发模拟场景,首先是模拟 CPU 占满情况
CPU 占满模拟 CPU 占满还是比较简单,直接写一个死循环计算消耗 CPU 即可。
Copy to clipboardErrorCopied 请求接口地址测试 curl localhost:8080/cpu/loop,发现 CPU 立马飙升到 100%
通过执行 top -Hp 32805 查看 Java 线程情况
执行 printf '%x' 32826 获取 16 进制的线程 id,用于 dump 信息查询,结果为 803a。最后我们执行 jstack 32805 |grep -A 20 803a 来查看下详细的 dump 信息。
这里 dump 信息直接定位出了问题方法以及代码行,这就定位出了 CPU 占满的问题。
内存泄露
模拟内存泄漏借助了 ThreadLocal 对象来完成,ThreadLocal 是一个线程私有变量,可以绑定到线程上,在整个线程的生命周期都会存在,但是由于 ThreadLocal 的特殊性,ThreadLocal 是基于 ThreadLocalMap 实现的,ThreadLocalMap 的 Entry 继承 WeakReference,而 Entry 的 Key 是 WeakReference 的封装,换句话说 Key 就是弱引用,弱引用在下次 GC 之后就会被回收,如果 ThreadLocal 在 set 之后不进行后续的操作,因为 GC 会把 Key 清除掉,但是 Value 由于线程还在存活,所以 Value 一直不会被回收,最后就会发生内存泄漏。
/*** 模拟内存泄漏*/@GetMapping(value = "/memory/leak")public String leak() {System.out.println("模拟内存泄漏");ThreadLocal<Byte[]> localVariable = new ThreadLocal<Byte[]>();localVariable.set(new Byte[4096 * 1024]);// 为线程添加变量 return "ok";}Copy to clipboardErrorCopied 我们给启动加上堆内存大小限制,同时设置内存溢出的时候输出堆栈快照并输出日志。
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.jarCopy to clipboardErrorCopied 启动成功后我们循环执行 100 次,for i in {1..500}; do curl localhost:8080/memory/leak;done,还没执行完毕,系统已经返回 500 错误了。查看系统日志出现了如下异常:
java.lang.OutOfMemoryError: Java heap spaceCopy to clipboardErrorCopied 我们用 jstat -gc pid 命令来看看程序的 GC 情况。
很明显,内存溢出了,堆内存经过 45 次 Full Gc 之后都没释放出可用内存,这说明当前堆内存中的对象都是存活的,有 GC Roots 引用,无法回收。那是什么原因导致内存溢出呢?是不是我只要加大内存就行了呢?如果是普通的内存溢出也许扩大内存就行了,但是如果是内存泄漏的话,扩大的内存不一会就会被占满,所以我们还需要确定是不是内存泄漏。我们之前保存了堆 Dump 文件,这个时候借助我们的 MAT 工具来分析下。导入工具选择 Leak Suspects Report,工具直接就会给你列出问题报告。
这里已经列出了可疑的 4 个内存泄漏问题,我们点击其中一个查看详情。
这里已经指出了内存被线程占用了接近 50M 的内存,占用的对象就是 ThreadLocal。如果想详细的通过手动去分析的话,可以点击 Histogram,查看最大的对象占用是谁,然后再分析它的引用关系,即可确定是谁导致的内存溢出。
上图发现占用内存最大的对象是一个 Byte 数组,我们看看它到底被那个 GC Root 引用导致没有被回收。按照上图红框操作指引,结果如下图:
我们发现 Byte 数组是被线程对象引用的,图中也标明,Byte 数组对像的 GC Root 是线程,所以它是不会被回收的,展开详细信息查看,我们发现最终的内存占用对象是被 ThreadLocal 对象占据了。这也和 MAT 工具自动帮我们分析的结果一致。
死锁死锁会导致耗尽线程资源,占用内存,表现就是内存占用升高,CPU 不一定会飙升(看场景决定),如果是直接 new 线程,会导致 JVM 内存被耗尽,报无法创建线程的错误,这也是体现了使用线程池的好处。
}我们循环请求接口 2000 次,发现不一会系统就出现了日志错误,线程池和队列都满了,由于我选择的当队列满了就拒绝的策略,所以系统直接抛出异常。
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]Copy to clipboardErrorCopied 通过 ps -ef|grep java 命令找出 Java 进程 pid,执行 jstack pid 即可出现 java 线程堆栈信息,这里发现了 5 个死锁,我们只列出其中一个,很明显线程 pool-1-thread-2 锁住了 0x00000000f8387d88 等待 0x00000000f8387d98 锁,线程 pool-1-thread-1 锁住了 0x00000000f8387d98 等待锁 0x00000000f8387d88,这就产生了死锁。
Found 5 deadlocks.Copy to clipboardErrorCopied 线程频繁切换上下文切换会导致将大量 CPU 时间浪费在寄存器、内核栈以及虚拟内存的保存和恢复上,导致系统整体性能下降。当你发现系统的性能出现明显的下降时候,需要考虑是否发生了大量的线程上下文切换。
}Copy to clipboardErrorCopied 这里我创建多个线程去执行基础的原子+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 st101 0 128000 878384 908 468684 0 0 0 0 4071 8110498 14 86 0 0 0100 0 128000 878384 908 468684 0 0 0 0 4065 8312463 15 85 0 0 0100 0 128000 878384 908 468684 0 0 0 0 4107 8207718 14 87 0 0 0100 0 128000 878384 908 468684 0 0 0 0 4083 8410174 14 86 0 0 0100 0 128000 878384 908 468684 0 0 0 0 4083 8264377 14 86 0 0 0100 0 128000 878384 908 468688 0 0 0 108 4182 8346826 14 86 0 0 0Copy to clipboardErrorCopied 这里我们关注 4 个指标,r,cs,us,sy。
r=100,说明等待的进程数量是 100,线程有阻塞。
cs=800 多万,说明每秒上下文切换了 800 多万次,这个数字相当大了。
us=14,说明用户态占用了 14%的 CPU 时间片去处理逻辑。
sy=86,说明内核态占用了 86%的 CPU,这里明显就是做上下文切换工作了。
我们通过 top 命令以及 top -Hp pid 查看进程和线程 CPU 情况,发现 Java 进程 CPU 占满了,但是线程 CPU 使用情况很平均,没有某一个线程把 CPU 吃满的情况。
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND87093 root 20 0 4194788 299056 13252 S 399.7 16.1 65:34.67 javaCopy to clipboardErrorCopiedPID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND87189 root 20 0 4194788 299056 13252 R 4.7 16.1 0:41.11 java87129 root 20 0 4194788 299056 13252 R 4.3 16.1 0:41.14 java87130 root 20 0 4194788 299056 13252 R 4.3 16.1 0:40.51 java87133 root 20 0 4194788 299056 13252 R 4.3 16.1 0:40.59 java87134 root 20 0 4194788 299056 13252 R 4.3 16.1 0:40.95 javaCopy to clipboardErrorCopied 结合上面用户态 CPU 只使用了 14%,内核态 CPU 占用了 86%,可以基本判断是 Java 程序线程上下文切换导致性能问题。
我们使用 pidstat 命令来看看 Java 进程内部的线程切换数据,执行 pidstat -p 87093 -w 1 10,采集数据如下:
11:04:30 PM UID TGID TID cswch/s nvcswch/s Command11:04:30 PM 0 - 87128 0.00 16.07 |__java11:04:30 PM 0 - 87129 0.00 15.60 |__java11:04:30 PM 0 - 87130 0.00 15.54 |__java11:04:30 PM 0 - 87131 0.00 15.60 |__java11:04:30 PM 0 - 87132 0.00 15.43 |__java11:04:30 PM 0 - 87133 0.00 16.02 |__java11:04:30 PM 0 - 87134 0.00 15.66 |__java11:04:30 PM 0 - 87135 0.00 15.23 |__java11:04:30 PM 0 - 87136 0.00 15.33 |__java11:04:30 PM 0 - 87137 0.00 16.04 |__javaCopy to clipboardErrorCopied 根据上面采集的信息,我们知道 Java 的线程每秒切换 15 次左右,正常情况下,应该是个位数或者小数。结合这些信息我们可以断定 Java 线程开启过多,导致频繁上下文切换,从而影响了整体性能。
为什么系统的上下文切换是每秒 800 多万,而 Java 进程中的某一个线程切换才 15 次左右?
系统上下文切换分为三种情况:
1、多任务:在多任务环境中,一个进程被切换出 CPU,运行另外一个进程,这里会发生上下文切换。
2、中断处理:发生中断时,硬件会切换上下文。在 vmstat 命令中是 in
3、用户和内核模式切换:当操作系统中需要在用户模式和内核模式之间进行转换时,需要进行上下文切换,比如进行系统函数调用。
Linux 为每个 CPU 维护了一个就绪队列,将活跃进程按照优先级和等待 CPU 的时间排序,然后选择最需要 CPU 的进程,也就是优先级最高和等待 CPU 时间最长的进程来运行。也就是 vmstat 命令中的 r。
那么,进程在什么时候才会被调度到 CPU 上运行呢?
进程执行完终止了,它之前使用的 CPU 会释放出来,这时再从就绪队列中拿一个新的进程来运行为了保证所有进程可以得到公平调度,CPU 时间被划分为一段段的时间片,这些时间片被轮流分配给各个进程。当某个进程时间片耗尽了就会被系统挂起,切换到其它等待 CPU 的进程运行。进程在系统资源不足时,要等待资源满足后才可以运行,这时进程也会被挂起,并由系统调度其它进程运行。当进程通过睡眠函数 sleep 主动挂起时,也会重新调度。当有优先级更高的进程运行时,为了保证高优先级进程的运行,当前进程会被挂起,由高优先级进程来运行。发生硬件中断时,CPU 上的进程会被中断挂起,转而执行内核中的中断服务程序。结合我们之前的内容分析,阻塞的就绪队列是 100 左右,而我们的 CPU 只有 4 核,这部分原因造成的上下文切换就可能会相当高,再加上中断次数是 4000 左右和系统的函数调用等,整个系统的上下文切换到 800 万也不足为奇了。Java 内部的线程切换才 15 次,是因为线程使用 Thread.yield()来让出 CPU 资源,但是 CPU 有可能继续调度该线程,这个时候线程之间并没有切换,这也是为什么内部的某个线程切换次数并不是非常大的原因。
总结本文模拟了常见的性能问题场景,分析了如何定位 CPU100%、内存泄漏、死锁、线程频繁切换问题。分析问题我们需要做好两件事,第一,掌握基本的原理,第二,借助好工具。本文也列举了分析问题的常用工具和命令,希望对你解决问题有所帮助。当然真正的线上环境可能十分复杂,并没有模拟的环境那么简单,但是原理是一样的,问题的表现也是类似的,我们重点抓住原理,活学活用,相信复杂的线上问题也可以顺利解决。
大家一定记得点赞,收藏,关注
防止下次找不到了
你们的支持是我持续创作的动力!!!
评论