问题排查总结

1.内存溢出

导致内存溢出的原因有很多,例如堆内存的不合理分配,内存泄漏导致的内存溢出,甚至是大对象创建速度大于GC回收的数据同样也会导致内存溢出。

1.1内存分配溢出

设置如下配置让堆内存溢出更快:

-Xms40m 初始堆大小设置为40m -Xmx70m 最大堆大小设置为70m

    @GetMapping("/memory/error2")
    public void outOfMemory2(){
        while(true){
           String[] stringArray = new String[10 * 1024 * 1024];
        }
    }

排查思路:

  1. 查找Java的进程id jps 可以查看java的进程;top|grep java 查看;ps -ef|grep java来查看执行启动项目命令的进程;
  2. jstat -gcutil PID 1000命令(1000指每隔一秒),查询 GC 情况, jmap -histo:live 3514 | head -7在线查看对象的内存占用
  3. dump堆内存数据到文件,该文件是二进制文件 sudo jmap -dump:file=./dump1.hprof PID,使用visualVM进行分析;

image-20230729175101826

S0: 新生代中Survivor space 0区已使用空间的百分比

S1: 新生代中Survivor space 1区已使用空间的百分比

E :新生代已使用空间的百分比 Eden space

O: 老年代已使用空间的百分比

M: 元空间

CCS: 压缩类空间利用率为百分比

YGC: YGC次数

YGCT: 年轻一代垃圾收集时间

FGC: FGC次数

FGCT: 完全垃圾收集时间

GCT: 垃圾回收总时间

上图是执行了步骤2的命令后显示JVM的垃圾回收信息,从红线开始你会发现YGC很频繁了,这时由于请求了内存溢出的方法,产生大量的内存分配操作。

后来通过VisualVM查看了过程,生成了下图所示:

image-20230728232359846

结果分析:

上述是有个请求线程在循环创建对象,然后有个GC线程在不对的回收对象,势均力敌。当GC回收速度慢于创建对象的速度,就会导致内存溢出。例如触发该请求的多次调用后就会导致内存溢出产生,同时在内存溢出发生后,我用别的请求进行调用时是可以正常返回的,因此在内存分配时产生的内存溢出时,别的请求可以访问,但这不能说明服务器是正常的。

1.2内存泄漏溢出

内存泄漏和内存分配的排查过程类似,根据下图你会发现,内存泄漏会导致FGC频率增加很明显,并且CPU的直接达到的600%。

image-20230729221856108

image-20230729222006986

在发生内存泄漏导致内存溢出时,会存在别的请求访问时也会导致内存溢出,而此时的现象是结果,不是原因。因此会影响排查的方向,为了能个正确的定位到内存溢出问题,需要使用工具对其进行分析。

总结:

当线程创建对象时,如果内存不足,会进行 GC,若GC 后还是内存不足,JVM 就会抛出OutOfMemoryError。当线程对异常没有处理时,异常会继续向外层抛出,kill 掉线程,线程本身和其持有的资源就可以被回收了。因此OOM 异常只会导致当前线程结束,对其他线程无影响,后续其他线程再申请内存空间时,当空间不足时会发起 GC,然后对于提供出新的空间来使用。

但是当内存泄漏时产生的内存溢出就不一样了,内存泄漏是一些对象没有正确的时候会导致内存溢出,这时即使发生GC也不能产生新的空间,所以会导致所有的请求都会阻塞,服务出现问题。

1.3栈内存溢出

一般栈内存溢出会有对应的日志打印,但是也有会栈溢出是结果的表现。也就是其他原因导致了栈溢出,然后别的请求在调用时发生了栈溢出,这同样会增加问题排查的难度。之前遇到一个栈溢出的问题,表现为连接池因为循环调用被停止了,那实际上是别的地方导致了这个栈溢出的。

发生栈溢出一般是方法循环递归调用,由于栈属于线程级别的,当线程执行发生错误后会自动回收,因此不影响别的线程的执行。

2.死锁排查

@GetMapping("/dead/lock")
    public void deadLock() throws InterruptedException {
        new Thread(() ->{
            synchronized (Object.class){
                log.info(Thread.currentThread().getName() + " Object");
                try {
                    Thread.sleep(3000l);
                } catch (InterruptedException e) {
                    throw new RuntimeException(e);
                }
                synchronized (this){
                    log.info(Thread.currentThread().getName() + " this");
                }
            }
        }).start();

        synchronized (this){
            log.info(Thread.currentThread().getName() + "this");
            Thread.sleep(3000l);
            synchronized (Object.class){
                log.info(Thread.currentThread().getName() + "Object");
            }
        }
    }

image-20230729170035660

可以首先将该进程的文件dump到某个文件: sudo jstack -l 8245 > ./stack.txt

可使用grep "deadlock" -C 10 stack.txt查看日志中死锁的关键字

image-20230729171223886

image-20230729171312027

上述两张图中,第一张图表示http-nio-80-exec-1这个线程想要执行76行代码但是得等java.lang.Object的对象锁,同时也使用IssueController对象上锁了,第二张图表示Thread-1这个线程想要执行67行代码,但是得等IssueController的对象锁,同时对java.lang.Object的对象锁。再者下面提示有deadlock的关键字,完全断定是发生了死锁了。

现在一般系统都是分布式系统,一般加锁的方式是采用的是分布式锁。对于分布式锁的话基于redis会存在过期时间自动释放锁的。

3.CPU高排查

首先使用top来查看cpu使用情况:

image-20230727072954870

发现PID为6285的进程CPU的使用率到了100%。可以使用jps -l命令查看Java的应用程序,可以确定是哪个Java应用,但是意义不大。

使用top -Hp PID查看该进程内的每个线程的详细信息

image-20230727073429191

发现有个http-nio-80-exe这个线程的cup占用很异常,可以拿到6355的PID进行分析。

对6355PID进行转成16进制:printf “0x%x\n” 6355

你有两种方式分析:一种是dump生成日志文件;一种是直接基于文件去分析;

jstack 6285 | vim +/0x18d3通过该命令直接可以定位到该线程,如下图所示

image-20230727074336781

image-20230727074435815

2.导出堆栈信息查看

jstack -l 6285 > ./6285.stack 到处进程6285的信息到6285.stack文件,基于这个文件分析

查看该文件: cat 6285.stack | grep "0x18d3" -C 8(-C是用于获取关键字上下文的日志,8就是在这个关键字的上下文都是8行)

同样也定位到了这里,如下图所示 image-20230727075346332