extjs4

下面通过模拟实例分析排查Java应用程序CPU和内存占用过高的过程。如果是Java面试,这2个问题在面试过程中出现的概率很高,所以我打算在这里好好总结一下。

1、Java CPU过高的问题排查

举个例子,如下: 

package com.classloading;
public class Test {
	static class MyThread extends Thread {
		public void run() { // 死循环,消耗CPU
			int i = 0;
			while (true) {
				i++;
			}
		}
	}
	public static void main(String args[]) throws InterruptedException {
		new MyThread().start();
		Thread.sleep(10000000);
	}
}

使用top命令查看占用CPU过高的进程。如下图所示。

  

查看进程6102下线程的占用情况,如下图所示。

 

使用如下命令将6122转换为16进制表示,如下:

 

导出CPU占用高进程的线程栈。命令如下:

jstack pid >> java.txt 

内容如下:  

mazhi@mazhi:~$ cat java.txt 
Attaching to remote server pid, please wait...
2021-02-23 15:38:18
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.192-b12 mixed mode):

"Attach Listener" #10 daemon prio=9 os_prio=0 tid=0x00007f4ee0001000 nid=0x1956 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
// 这是0x17ea线程,也是占用CPU最高的线程
"Thread-0" #9 prio=5 os_prio=0 tid=0x00007f4f180d6000 nid=0x17ea runnable [0x00007f4f044da000]
   java.lang.Thread.State: RUNNABLE
	at com.cpuhigh.Test$MyThread.run(Test.java:8)  // 这里指示第8行,则正是死循环的代码开始

...

导出的堆栈信息有线程的状态(一般要找RUNNABLE状态)和调用堆栈结合来查找问题。线程dump分析:线程dump分析主要目的是定位线程长时间停顿的原因 

jstack是一个瞬时堆栈只记录瞬时状态

实际排查问题的时候jstack建议打印5次至少3次,根据多次的堆栈内容,再结合相关代码段进行分析,定位高cpu出现的原因,高cpu可能是代码段中某个bug导致的而不是堆栈打印出来的那几行导致的

 

cpu高的情况还有一种可能的原因,假如一个4核cpu的服务器我们看到总的cpu达到了100%+,按1之后观察每个cpu的us(用户空间占用cpu的百分比),只有一个达到了90%+,其他都在1%左右(下图只是演示top按1之后的效果并非真实场景):

 

这种情况下可以重点考虑是不是频繁Full GC引起的。因为我们知道Full GC的时候会有Stop The World这个动作,多核cpu的服务器,除了GC线程外,在Stop The World的时候都是会挂起的,直到Stop The World结束。以几种老年代垃圾收集器为例:

  • Serial Old收集器,全程Stop The World
  • Parallel Old收集器,全程Stop The World
  • CMS收集器,它在初始标记与并发标记两个过程中,为了准确标记出需要回收的对象,都会Stop The World,但是相比前两种大大减少了系统停顿时间

无论如何,当真正发生Stop The World的时候,就会出现GC线程在占用cpu工作而其他线程挂起的情况,自然表现也就为某个cpu的us很高而且他cpu的us很低。 

2、Java 内存过高的问题排查 

堆dump分析:堆dump分析主要目的是定位OOM异常的原因;解决oom问题四 部曲:
1.分析OOM异常的原因,堆溢出?栈溢出?本地内存溢出?

2.如果是堆溢出,导出堆dump,并对堆内存使用有个整体了解;

3.找到最有可能导致内存泄露的元凶,通常也就是消耗内存最多的对象;

4.使用辅助工具对dump文件进行分析;

注意其他几类造成OOM异常的原因

1.Direct Memory
2.线程堆栈:单线程:*Error 多线程:OutOfMemoryError:unable to create new native thread
3.Socket 缓冲区:IOException:Too many open files

举个例子如下:

package com.classloading;

import java.util.ArrayList;
import java.util.List;

public class Test {
	private static final int UNIT_MB = 1024 * 1024;
	
	public static void main(String args[]) throws InterruptedException{
		List<Object> x = new ArrayList<Object>();
		int i = 0;
		while(i<1000){
			x.add(new byte[UNIT_MB]);
			i++;
		}
		Thread.sleep(1000000000);
	}
}

通过jmap dump内存快照。如果是线上环境,注意dump之前必须先将流量切走,否则大内存dump是直接卡死服务。

命令行输入:

jmap -histo <pid> | head -20

就可以查看某个pid的java服务占用内存排名前20的类,如下图所示。

 

可以看到,占用内存最多的是byte字节数组,共有1008个实例。

jmap还有一个指令可以把整个内存情况转成文件形式保存下来,如下:

jmap -dump:format=b,file=filename.bin <pid>

执行命令如下图所示。

 

可以在JVM启动时设置,如果发生OOM,则dump出文件。命令如下:

-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/tmp/heapdump.hprof

如果快照文件不大,可以下载到本地,然后通过MAT分析,也可以在线分析(https://fastthread.io/);如果快照文件很大,可以在服务器上直接分析,使用的命令是:

jhat dump.hprof

jhat也是jdk内置的工具之一。主要是用来分析java堆的命令,可以将堆中的对象以html的形式显示出来,包括对象的数量,大小等等,并支持对象查询语言。命令执行后如下图所示。

 

访问如下图所示。

其中的Show heap histogram就会显示对象占用内在的大小。如下图所示。 

 

使用MAT时,有时候这个工具还会提示某个对象异常。我们可以在Histogram 页面,可以查看到对象数量排序,我们可以看到 Byte[] 数组排在了第一位,选中对象后右击选择 with incomming reference 功能,可以查看到具体哪个对象引用了这个对象。

3、JVM的Error日志

致命错误日志文件位置可以通过 -XX:ErrorFile进行指定,相关的信息如下:

这个文件主要包含如下内容:

  • 日志头文件
  • 导致 crash 的线程信息
  • 所有线程信息
  • 安全点和锁信息
  • 堆信息
  • 本地代码缓存
  • 编译事件
  • gc 相关记录
  • jvm 内存映射
  • jvm 启动参数
  • 服务器信息

这对于一般的开发人员来说不太容易读懂。在日志头文件中有常见的描述是“EXCEPTION_STACK_OVERFLOW”,该描述表示这是个栈溢出导致的错误,这往往是应用程序中存在深层递归导致的

4、Full GC的排查

如果FullGC只是发生在老年代区,比较有经验的开发人员还是容易发现问题的,一般都是一些代码bug引起的。MetaSpace发生的FullGC经常会是一些诡异、隐晦的问题,很多和引入的第三方框架使用不当有关或者就是第三方框架有bug导致的,排查起来就很费时间。

YGC如果频繁,会让对象过早进入老年代,如果回收时间过长,会造成系统停顿时间长,造成服务超时等问题。系统中有许多方法可以观察到Full GC,通常有3种方法,如下:

1、在系统中增加参数,记录相关信息,如下:

-XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:/home/mazhi/workspace/projectjava/projectjava01/gclog/gc.log

某一次记录的日志信息如下:

Java HotSpot(TM) 64-Bit Server VM (25.192-b12) for linux-amd64 JRE (1.8.0_192-b12), built on Oct  6 2018 06:46:09 by "java_re" with gcc 7.3.0
Memory: 4k page, physical 8064700k(2091464k free), swap 8276988k(8276988k free)
CommandLine flags: -XX:InitialHeapSize=129035200 -XX:MaxHeapSize=2064563200 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 
0.073: [GC (System.gc()) [PSYoungGen: 634K->320K(36864K)] 634K->320K(121856K), 0.0015284 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.075: [Full GC (System.gc()) [PSYoungGen: 320K->0K(36864K)] [ParOldGen: 0K->258K(84992K)] 320K->258K(121856K), [Metaspace: 2473K->2473K(1056768K)], 0.0035519 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
Heap
 PSYoungGen      total 36864K, used 1270K [0x00000000d6f80000, 0x00000000d9880000, 0x0000000100000000)
  eden space 31744K, 4% used [0x00000000d6f80000,0x00000000d70bd890,0x00000000d8e80000)
  from space 5120K, 0% used [0x00000000d8e80000,0x00000000d8e80000,0x00000000d9380000)
  to   space 5120K, 0% used [0x00000000d9380000,0x00000000d9380000,0x00000000d9880000)
 ParOldGen       total 84992K, used 258K [0x0000000084e00000, 0x000000008a100000, 0x00000000d6f80000)
  object space 84992K, 0% used [0x0000000084e00000,0x0000000084e40b30,0x000000008a100000)
 Metaspace       used 2479K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 265K, capacity 386K, committed 512K, reserved 1048576K

给出的信息还是比较全面详细的,包括堆和元空间GC前与GC后的变化,当前虚拟机使用的命令等。

2、通过监控查看,如Pinpoint APM监控工具等

3、通过Linux命令查看,如:

jstat -gc 4383 5000
即会每5秒一次显示进程号为4383的java进程的GC情况, -XX:+PrintGCDetails 用来打印详细的GC信息。如某次的详细信息如下图所示。

当发现是Full GC频繁时,首先要知道,哪些情况下会触发Full GC,原因如下:

  1. 程序执行了System.gc();
  2. 执行了jmap命令;
  3. 大对象直接进入了老年代导致老年代内存不足,达到了GC阈值;
  4. 程序中存在内存泄露,导致老年代内存缓慢增长,且无法被回收,达到了GC阈值;
  5. 老年代存在内存碎片,导致新晋升的对象空间不足,触发GC。

对于第1个原因,如果老年代还有大量空闲空间时就触发,则有可能是调用了System.gc()。对于后面3个原因,通常需要观察Full GC之前与之后堆的内存变化来确定。可以通过GC日志或jvisualvm等图形化工具来查看,如果Full GC前与后堆回不到原来的大小并且堆大小一直增大,则可能是内存泄露,否则可能就是对象过于频繁进入老年代了,需要找出这些对象。可以通过jmap命令来dump出文件。我们可以在线上开启了 -XX:+HeapDumpBeforeFullGC。使用jvisualvm查看哪些对象占用的比较大的内存(能给出实例占用的大小和占用内存的百分比)

常用到的一些命令及图形化工具如下图所示。

5、应用故障你怎么样排除问题?

应用故障一般指应用运行缓慢、用户体验差或者周期性的出现卡顿,排除的思路:
1.检查应用所在的生产环境的软硬件以及网络环境,排除外围因素;
2.确定是否为OOM异常,这类异常影响最恶劣,但是比较容易排查;
3.确定是否有大量长时间停顿的应用线程,非常占用cpu资源;
4.周期性的卡顿很可能是垃圾回收造成,web后端系统建议使用cms垃圾回收器

6、什么情况下会发生栈内存溢出?

如果线程请求的栈深度大于虚拟机所允许的深度,将抛出*Error异常。 如果虚拟机在动态扩展栈时无法申请到足够的内存空间,则抛出OutOfMemoryError异常。 

7、频繁minor gc怎么办?可能造成的原因是什么?如何避免?minor gc运行的很慢有可能是什么原因引起的? 

如下2个原因可能导致minor gc频繁:

1、 产生了太多朝生夕灭的对象导致需要频繁minor gc

2、 新生代空间设置的比较小

可以适当扩大新生代空间的大小,或者G1会根据实际的GC情况(主要是暂停时间)来动态的调整新生代的大小,主要是Eden Region的个数。

一个案例是,Object转xml,xml转Object,代码中每处都new XStream()去进行xml序列化与反序列化,回收速度跟不上new的速度,YoungGC次数陡增。

minor gc运行的很慢有可能是什么原因引起的?

1、新生代空间设置过大。

2、对象引用链较长,或者存活小对象的数量太多,进行可达性分析时间较长。

3、新生代survivor区设置的比较小,清理后剩余的对象不能装进去需要移动到老年代,造成移动开销。

4、内存分配担保失败,由minor gc转化为full gc

5、采用的垃圾收集器效率较低,比如新生代使用serial收集器

8、load飙升怎么处理?什么情况可能会遇到上述情况? 

可参考:https://www.cnblogs.com/xrq730/p/11041741.html 

对于load的理解如下:

一个单核的处理器可以形象得比喻成一条单车道,车辆依次行驶在这条单车道上,前车驶过之后后车才可以行驶。
如果前面没有车辆,那么你顺利通过;如果车辆众多,那么你需要等待前车通过之后才可以通过。 因此,需要些特定的代号表示目前的车流情况,例如: 

  1. 等于0.00,表示目前桥面上没有任何的车流。实际上这种情况0.00和1.00之间是相同的,总而言之很通畅,过往的车辆可以丝毫不用等待的通过
  2. 等于1.00,表示刚好是在这座桥的承受范围内。这种情况不算糟糕,只是车流会有些堵,不过这种情况可能会造成交通越来越慢 
  3. 大于1.00,那么说明这座桥已经超出负荷,交通严重的拥堵。那么情况有多糟糕? 例如2.00的情况说明车流已经超出了桥所能承受的一倍,那么将有多余过桥一倍的车辆正在焦急的等待  

系统load是处于运行状态或者不可中断状态的进程的平均数(标红部分表示被算入load的内容)。一个处于运行状态的进程表示正在使用cpu或者等待使用cpu,一个不可中断状态的进程表示正在等待IO,例如磁盘IO。load的平均值通过3个时间间隔来展示,就是我们看到的1分钟、5分钟、15分钟,load值和cpu核数有关,单核cpu的load=1表示系统一直处在负载状态,但是4核cpu的load=1表示系统有75%的空闲。

特别注意,load指的是所有核的平均值,这和cpu的值是有区别的。

还有一个重要的点是,查了资料发现,虽然上面一直强调的是"进程",但是进程中的线程数也是会被当作不同的进程来计算的,假如一个进程产生1000个线程同时运行,那运行队列的长度就是1000,load average就是1000。

load是以线程/进程作为统计指标,无论请求数是多少,最终都需要线程去处理,而工作线程的处理性能直接决定了最终的load值  

load高、cpu高的问题排查思路 

首先抛出一个观点:cpu高不是问题,由cpu高引起的load高才是问题,load是判断系统能力指标的依据 

前面说了这么多,这里总结一下load高常见的、可能的一些原因: 

  • 死循环或者不合理的大量循环操作,如果不是循环操作,按照现代cpu的处理速度来说处理一大段代码也就一会会儿的事,基本对能力无消耗
  • 频繁的YoungGC
  • 频繁的FullGC
  • 高磁盘IO
  • 高网络IO 

线上遇到问题的时候首先不要慌,因为大部分load高的问题都集中在以上几个点里面,以下分析问题的步骤或许能帮你整理思路: 

  • top先查看用户us与空闲us(id)的cpu占比,目的是确认load高是否高cpu起的
  • 如果是高cpu引起的,那么确认一下是否gc引起的,jstat命令 + gc日志基本就能确认
  • gc引起的高cpu直接dump,非gc引起的分析线程堆栈
  • 如果不是高cpu引起的,查看磁盘io占比(wa:cpu等待磁盘写入完成时间,如果一台机器看到wa特别高,那么一般说明是磁盘IO出现问题,可以使用iostat等命令继续进行详细分析
    ),如果是,那么打线程堆栈分析是否有大量的文件io
  • 如果不是高cpu引起的,且不是磁盘io导致的,检查各依赖子系统的调用耗时,高耗时的网络调用很可能是罪魁祸首 

最后还是不行,当束手无策时,jstack打印堆栈多分析分析吧,或许能灵光一现能找到错误原因。

9、问题排查之服务响应超时  

(1)JVM频繁做垃圾回收,或STW时间过长

(2)线程池中的线程执行任务太慢,可能导致阻塞,这样其它任务就压入队列中了 

抢购活动出现了大量超时报警,不过比我预料的要好一点,起码没有挂掉重启。

通过工具分析,我发现 cs(上下文切换每秒次数)指标已经接近了 60w ,平时的话最高 5w。再通过日志分析,我发现了大量带有 wait() 的 Exception,由此初步怀疑是大量线程处理不及时导致的,进一步锁定问题是连接池大小设置不合理。后来我就模拟了生产环境配置,对连接数压测进行调节,降低最大线程数,最后系统的性能就上去了。

 

 

 

 

 

  

 

  

 

 

分类:

技术点:

相关文章: