老年代一直增大,系统巨慢,内存泄漏

问题

线上系统接口响应很慢,完全不正常,有些接口长达2分多钟,甚至直接一直处理pending状态,之前做了SQL监控和优化,SQL查询和插入一般控制在了3S之内。

环境

k8s java1.8 spring cloud 持久层 JPA+H

过程

由于线上系统跑在K8S POD里,里面的jar启动就是1号进程
jstat 等一些工具无法attach1号进程,就只能用arthas了

  • dashboard 看看GC情况

image
copy 垃圾回收是针对新生代的,看到回收了217次. 时间50S
marksweepcompact 是针对老年代的 回到10次 20S
这个是jar启动4小时之后的统计

  • vmoption 可以临时设置JVM开启GC 默认日志是 JAVA日志在那儿显示,GC就显示在那儿

GPT说什么时候发生fullgc

Full GC(Full Garbage Collection)通常在以下情况下发生:

新生代空间不足:当新生代的Eden区域已经被占满,且无法容纳新的对象时,会触发一次Full GC。这是因为新生代的对象在经过多次垃圾回收后仍然存活,需要被转移到老年代中。

永久代/元空间空间不足:对于使用永久代(PermGen)或元空间(Metaspace)的Java版本,在永久代/元空间空间不足时,也可能触发Full GC。永久代/元空间主要用于存放类的元数据、静态变量等。

显式调用System.gc():当应用程序显式调用System.gc()方法来请求进行垃圾回收时,可能会触发Full GC。但调用System.gc()并不能保证立即进行Full GC,具体是否进行Full GC由JVM决定。

空间分配担保失败:在进行Minor GC(新生代垃圾回收)时,如果老年代的剩余空间不足以容纳新生代中所有存活的对象,就会触发Full GC。这种情况下,JVM会进行一次Full GC,以确保所有存活的对象都能被转移到老年代中。

长时间存活的对象:当老年代中的对象存活时间很长时,也可能会触发Full GC。这是因为老年代主要用于存放存活时间较长的对象,当老年代空间不足时,需要进行Full GC来回收无用的对象。

需要注意的是,并不是每次Full GC都是由以上情况引起的,具体触发Full GC的条件和策略会根据不同的垃圾收集器、JVM参数和应用程序的特点而有所不同。因此,在实际情况中,可以通过查看GC日志和使用监控工具来了解何时发生Full GC以及如何优化和调整应用程序的垃圾收集行为。

jmap -heap 进程 看看内存情况

可以看到metespace 只有20M 很明显metespace扩容会引起fullGC.
这里要说一下,虽然此处看到的是20M,但通过arthas的dashboard指令看到的metaspace却是160M,很明显,他自己扩容过了。。

加启动参数,限制扩容大小

-XX:MetaspaceSize=512m
-XX:MaxMetaspaceSize=512m

加了参数还是不能解决可以看看这个文章
https://zhuanlan.zhihu.com/p/537924677
这个文章大致的意思是说使用查看类加载的指令,看看哪些类加载的比较多.

用到的指令

  • jcmd PID GC.run
    这个指令比较有意思,可以直接上生产环境测试下fullgc 消耗的时间.. 反正卡都卡了,线上试试也不是不行

  • jmap -histo:live pid > 2.txt
    这个可以导出当前存活的对象的数量

  • jmap -heap pid 查看堆内存情况
    image

  • pmap -x pid |grep 这儿可以写要查看的内存大小

  • jcmd pid GC.heap_info 可以查看metaspace占用情况

  • jmap -dump:file=/path pid
    导出堆内存

  • pmap -x 1 | sort -n -k 2 排序看看最大的内存块

  • apt-get install binutils 二进制文件处理工具包 主要用到里面的strings 用于查看gdb导出的内存块中的字符串

  • strings -10 x.dump 查看x.dump这个内存块中 字符串长度超过10个的

然后,通过配置jvm启动参数,观察类的加载和卸载 目前是看看哪些类加载的比较多.
-XX:+TraceClassLoading -XX:+TraceClassUnloading

写到这儿,上面的参数和说法我还没加GC日志验证,明天加了GC日志,再来更新

又看了下,res涨到6G了
image

image

红线上面的堆区 下面的是非堆区,很明显 堆内存占用巨大,基本可以排除非堆的问题

堆外内存泄漏(上图反应出来的情况,并不是堆外内存泄漏)

最初是怀疑,堆外内存泄漏导致的内存上涨,想用tcmall 进行堆外内存跟踪 但k8s内的docker pod 死活也装不了这些东西,查了资料发现tcmall什么的内存泄漏跟踪工具,都是
利用linux 自己的拦截进程加载的SO的办法,拦截了进程中的malloc内存分配函数,这个东西可以 参考 LD_PRELOAD,
自己写个SO拦截了malloc函数后,再继续使用Libunwind这个库,输出进程调用你自己写的拦截SO时的整个调用堆栈,最终实现,调用链的记录。

又发现新情况 用 pmap -x pid|grep 65404 出来的64M的块 共106行 也就是106个 算下来6.7G 和上面的6G占用差不多...

开启GC日志后,重启服务

截个图

top -Hp pid

此处res 1.6g

  • 看看堆内存的情况
    arthas 的 memory指令

堆和非堆 加起来1.4G 和1.6G差不多

2小时候GC日志分析

  • 先总结
    日志中很多由于堆内存不足导致频繁的年轻代GC和老年代GC,以及由于metaspace不足导致的full gc,两小时内发生了5次full GC。
    而且由于老年代的对象特别多,导致GC时和full GC时花了很长时间,所以需要解决的问题有几个:
  • 调整年轻代和老年代的堆大小,减少GC次数
  • 解决老年代为什么存储了这么多对象的问题,而且是不断上涨(占用越多,GC越耗时)

日志片段

  • 老年代引发的GC

972.907: [GC (Allocation Failure) 5972.907: [DefNew: 331445K->3239K(350912K), 0.3575620 secs]5973.265: [Tenured: 861540K->548505K(861572K), 3.1592128 secs] 1107544K->548505K(1212484K), [Metaspace: 184994K->184994K(1222656K)], 3.5182106 secs] [Times: user=2.65 sys=0.87, real=3.52 secs]

  • metaspace引发fullgc(两小时内引发了5次full gc)
    342.710: [Full GC (Metadata GC Threshold) 342.711: [Tenured: 237537K->255779K(681344K), 2.0443248 secs] 257931K->255779K(988032K), [Metaspace: 155254K->155254K(1193984K)], 2.0450780 secs] [Times: user=1.78 sys=0.39, real=2.05 secs]
    可以看到此时老年代Tenured 空间足够,但由于metaspace引发了full gc 所以老年代也跟着GC了,耗时2S
    Metaspace 回收前155254K回收后还是155254K 但空间不够,所以引发了扩容metaspace增加到了1193984K,耗时2S

为什么回收后还是155254K?这证明Metaspace中的对象还被其他地方持有引用,导致GC时,无法清除这些对象,所以自动扩容

GC (Allocation Failure) 是堆内存不足引发的GC ?到底是哪个堆呢?日志给出了说明
可以看到年轻代DefNew 容量 350912K 实际只用了 331445K 这不足以引发GC
再看老年代 Tenured 容量 861572K 实际用了 861540K 很明显,这次GC是由于老年代不够了引发的GC,而且时间3s...
Metaspace 就不说了,此时空间还够。。

来揪出幕后黑手

  • 导出堆内存

    发现 这儿玩意儿占了2.1g内存.
    饼图最大块就是他,右键list objects -> with outgoing ref... 看看他到底泄漏了什么

进去记得先排序,把他持有的对象最多的排在前面


继续根据最多的跟进去,找到熟悉的内容 很多SQL。。。 如果是很多SQL的话,那且不是加载了很多char[] 或者String对象?

回到预览界面,我们看看加载的对象情况,记得排序

排序后 根据这个顺序似乎看的出从上到下是个引用链,最西面是String String下面当然是char[]了
看看String的内容

排序后大量的业务SQL句子....

随便找个String
list objects -> with incoming ref 看看是谁再引用他

由此可见到 最终还是到了这个对象身上.

如何优化

本质问题,内存泄漏且这些对象被引用导致老年大越来越大,一但GC就回很卡。。
1、调整hb的queryPlanCahe缓存相关的设置

  jpa:
    hibernate:
      plan_cache_max_size: 64
      plan_parameter_metadata_max_size: 32
      query.in_clause_parameter_padding: true

上面的配置好像没什么效果,最后直接关闭了hibernate所有的缓存功能,关闭后没有明显的性能下降

 plan_cache_max_size: 64
      plan_parameter_metadata_max_size: 32
      query.in_clause_parameter_padding: true
      #关闭二级缓存
      cache.use_second_level_cache: false
      #关闭查询缓存
      cache.use_query_cache: false

一些别人解决的摘录

大概的意思就是,QueryPlanCache会缓存sql,以便于后边的相同的sql重复编译,如果in后的参数不同,hibernate会把其当成不同的sql进行缓存,从而缓存大量的sql导致heap内存溢出。我的程序中没有使用in,但通过查看程序,我发现我的一条hql中同时采用paramter string拼接和占位符两种方式,这样会不会因为每一个paramter string都不同,hibernate认为这是不同的hql从而进行大量缓存喃?于是我全部采用站位符的方式,再进行测试,发现程序heap内存一直处于稳定状态,问题解决。

2、将新生代串行收集器改为并行收集器

-XX:NewSize=1024m     新生代 1G应该够了
-XX:MetaspaceSize=512m 这个可能有点小。。下次重启配大点
-XX:PermSize=2048m  这个参数在JDK1.8上没卵用。。。老年代会自己扩容..
-XX:+UseParNewGC  新生代启用并行收集器

解决内存泄漏且优化GC后的效果,除了matespace空间不足会扩容,虽然耗时最长的3S,但此时不会导致fullGC ,问题不大,观察几天看看.

由于效果不是很明显,最后换成了G1收集器

-XX:InitialHeapSize=4096m","-XX:MaxHeapSize=4096m","-XX:MetaspaceSize=1024m","-XX:MaxMetaspaceSize=1024m","-XX:+UseG1GC","-XX:MaxGCPauseMillis=100","-XX:ParallelGCThreads=5"

坑点

网上很多jvm的工具指令的参数,对你自己的环境来说不一定用的了
如果使用某个指令 参数报错 最好看下这个指令的Help

优化前全部日志

OpenJDK 64-Bit Server VM (25.312-b07) for linux-amd64 JRE (1.8.0_312-b07), built on Oct 15 2021 05:40:24 by "openjdk" with gcc 4.4.7 20120313 (Red Hat 4.4.7-23)
Memory: 4k page, physical 65293096k(65291512k free), swap 0k(0k free)
CommandLine flags: -XX:InitialHeapSize=1044689536 -XX:MaxHeapSize=16715032576 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops 
2.828: [GC (Allocation Failure) 2.829: [DefNew: 272512K->4386K(306560K), 0.0451689 secs] 272512K->4386K(987904K), 0.0453887 secs] [Times: user=0.04 sys=0.02, real=0.05 secs] 
3.800: [GC (Allocation Failure) 3.800: [DefNew: 276898K->6271K(306560K), 0.0528579 secs] 276898K->6271K(987904K), 0.0531354 secs] [Times: user=0.06 sys=0.01, real=0.06 secs] 
4.434: [Full GC (Metadata GC Threshold) 4.434: [Tenured: 0K->8215K(681344K), 0.1028772 secs] 198736K->8215K(987904K), [Metaspace: 20241K->20241K(1069056K)], 0.1030639 secs] [Times: user=0.11 sys=0.01, real=0.10 secs] 
6.384: [GC (Allocation Failure) 6.385: [DefNew: 272640K->2140K(306688K), 0.0142882 secs] 280855K->10356K(988032K), 0.0144099 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
7.626: [GC (Allocation Failure) 7.626: [DefNew: 274780K->2421K(306688K), 0.0109280 secs] 282996K->10636K(988032K), 0.0110222 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
8.309: [GC (Allocation Failure) 8.309: [DefNew: 275061K->3368K(306688K), 0.0128557 secs] 283276K->11583K(988032K), 0.0129517 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
8.812: [Full GC (Metadata GC Threshold) 8.812: [Tenured: 8215K->12002K(681344K), 0.1228985 secs] 217495K->12002K(988032K), [Metaspace: 34090K->34090K(1081344K)], 0.1230888 secs] [Times: user=0.11 sys=0.00, real=0.13 secs] 
10.691: [GC (Allocation Failure) 10.692: [DefNew: 272640K->3882K(306688K), 0.0428921 secs] 284642K->15885K(988032K), 0.0431057 secs] [Times: user=0.03 sys=0.01, real=0.05 secs] 
11.742: [GC (Allocation Failure) 11.742: [DefNew: 276522K->9656K(306688K), 0.0804945 secs] 288525K->21659K(988032K), 0.0806765 secs] [Times: user=0.07 sys=0.01, real=0.08 secs] 

18.093: [GC (Allocation Failure) 18.093: [DefNew: 289623K->19295K(306688K), 0.0474664 secs] 301626K->31298K(988032K), 0.0476189 secs] [Times: user=0.04 sys=0.00, real=0.04 secs] 
18.845: [Full GC (Metadata GC Threshold) 18.845: [Tenured: 12002K->31933K(681344K), 0.3761287 secs] 94851K->31933K(988032K), [Metaspace: 56790K->56790K(1101824K)], 0.3763483 secs] [Times: user=0.36 sys=0.04, real=0.37 secs] 
21.706: [GC (Allocation Failure) 21.706: [DefNew: 272640K->5904K(306688K), 0.0700657 secs] 304573K->37837K(988032K), 0.0703041 secs] [Times: user=0.07 sys=0.00, real=0.07 secs] 
23.746: [GC (Allocation Failure) 23.746: [DefNew: 278544K->11313K(306688K), 0.0444317 secs] 310477K->43246K(988032K), 0.0446261 secs] [Times: user=0.04 sys=0.00, real=0.04 secs] 
24.885: [GC (Allocation Failure) 24.885: [DefNew: 283953K->15012K(306688K), 0.0605599 secs] 315886K->46945K(988032K), 0.0606853 secs] [Times: user=0.06 sys=0.01, real=0.06 secs] 
26.501: [GC (Allocation Failure) 26.501: [DefNew: 287652K->20286K(306688K), 0.0732979 secs] 319585K->52219K(988032K), 0.0734128 secs] [Times: user=0.07 sys=0.00, real=0.08 secs] 
27.719: [GC (Allocation Failure) 27.719: [DefNew: 292926K->16069K(306688K), 0.0952460 secs] 324859K->53436K(988032K), 0.0954281 secs] [Times: user=0.08 sys=0.02, real=0.10 secs] 
29.144: [GC (Allocation Failure) 29.144: [DefNew: 288709K->20125K(306688K), 0.1084914 secs] 326076K->57492K(988032K), 0.1087023 secs] [Times: user=0.10 sys=0.01, real=0.11 secs] 
30.717: [Full GC (Metadata GC Threshold) 30.717: [Tenured: 37367K->52962K(681344K), 0.4952737 secs] 291288K->52962K(988032K), [Metaspace: 94109K->94109K(1134592K)], 0.4954589 secs] [Times: user=0.82 sys=0.05, real=0.50 secs] 


1257.478: [GC (Allocation Failure) 1257.478: [DefNew: 242316K->29707K(306816K), 0.5356358 secs]1258.014: [Tenured: 718311K->467689K(819452K), 2.6721233 secs] 822522K->467689K(1126268K), [Metaspace: 176951K->176951K(1214464K)], 3.2086182 secs] [Times: user=2.47 sys=0.74, real=3.21 secs] 
1261.062: [GC (Allocation Failure) 1261.062: [DefNew: 311936K->2894K(350912K), 0.2643887 secs] 779625K->608689K(1130396K), 0.2648144 secs] [Times: user=0.21 sys=0.14, real=0.27 secs] 
1261.455: [GC (Allocation Failure) 1261.455: [DefNew: 314830K->2947K(350912K), 0.0362270 secs] 920625K->608742K(1130396K), 0.0364520 secs] [Times: user=0.05 sys=0.02, real=0.03 secs] 

1329.071: [GC (Allocation Failure) 1329.072: [DefNew: 314469K->6847K(350912K), 0.1146619 secs] 920264K->612642K(1130396K), 0.1154181 secs] [Times: user=0.08 sys=0.04, real=0.12 secs] 
1367.587: [GC (Allocation Failure) 1367.587: [DefNew: 318783K->4626K(350912K), 0.0374704 secs] 924578K->610422K(1130396K), 0.0381221 secs] [Times: user=0.06 sys=0.02, real=0.04 secs] 
1473.660: [GC (Allocation Failure) 1473.660: [DefNew: 316562K->5726K(350912K), 0.0831708 secs] 922358K->611521K(1130396K), 0.0836858 secs] [Times: user=0.05 sys=0.03, real=0.09 secs] 
1532.514: [GC (Allocation Failure) 1532.514: [DefNew: 317662K->12979K(350912K), 0.1717818 secs] 923457K->618775K(1130396K), 0.1726229 secs] [Times: user=0.10 sys=0.07, real=0.17 secs] 

3157.846: [GC (Allocation Failure) 3157.846: [DefNew: 333913K->14056K(350912K), 0.2155066 secs]3158.062: [Tenured: 785563K->378616K(785572K), 2.0365184 secs] 1108373K->378616K(1136484K), [Metaspace: 182004K->182004K(1218560K)], 2.2558829 secs] [Times: user=1.76 sys=0.50, real=2.25 secs] 




5972.907: [GC (Allocation Failure) 5972.907: [DefNew: 331445K->3239K(350912K), 0.3575620 secs]5973.265: [Tenured: 861540K->548505K(861572K), 3.1592128 secs] 1107544K->548505K(1212484K), [Metaspace: 184994K->184994K(1222656K)], 3.5182106 secs] [Times: user=2.65 sys=0.87, real=3.52 secs] 
5977.912: [GC (Allocation Failure) 5977.912: [DefNew: 365888K->633K(411584K), 0.0714753 secs] 914393K->618230K(1325764K), 0.0717480 secs] [Times: user=0.05 sys=0.02, real=0.08 secs] 

5987.640: [GC (Allocation Failure) 5987.640: [DefNew: 368819K->4224K(411584K), 0.0472467 secs] 1262776K->898181K(1325764K), 0.0476013 secs] [Times: user=0.04 sys=0.01, real=0.05 secs] 
5988.796: [GC (Allocation Failure) 5988.796: [DefNew: 370112K->4856K(411584K), 0.1383424 secs]5988.934: [Tenured: 963046K->553136K(983272K), 1.8268052 secs] 1264069K->553136K(1394856K), [Metaspace: 185005K->185005K(1222656K)], 1.9710281 secs] [Times: user=1.54 sys=0.43, real=1.97 secs] 
5992.154: [GC (Allocation Failure) 5992.154: [DefNew: 368960K->662K(415040K), 0.0680225 secs] 922096K->622888K(1336936K), 0.0683050 secs] [Times: user=0.05 sys=0.01, real=0.06 secs] 
5993.121: [GC (Allocation Failure) 5993.121: [DefNew: 369622K->799K(415040K), 0.0690239 secs] 991848K->692116K(1336936K), 0.0692696 secs] [Times: user=0.04 sys=0.02, real=0.07 secs] 
5994.520: [GC (Allocation Failure) 5994.520: [DefNew: 369759K->5217K(415040K), 0.0838226 secs] 1061076K->765624K(1336936K), 0.0840447 secs] [Times: user=0.06 sys=0.02, real=0.09 secs] 
5996.017: [GC (Allocation Failure) 5996.017: [DefNew: 374177K->9746K(415040K), 0.0879409 secs] 1134584K->839242K(1336936K), 0.0881429 secs] [Times: user=0.06 sys=0.02, real=0.09 secs] 
5999.217: [GC (Allocation Failure) 5999.218: [DefNew: 378706K->10227K(415040K), 0.1710344 secs] 1208202K->908814K(1336936K), 0.1714577 secs] [Times: user=0.11 sys=0.05, real=0.17 secs] 
6002.421: [GC (Allocation Failure) 6002.421: [DefNew: 322546K->10714K(415040K), 0.0816380 secs] 1221133K->909300K(1336936K), 0.0821488 secs] [Times: user=0.06 sys=0.02, real=0.09 secs] 
6003.099: [GC (Allocation Failure) 6003.099: [DefNew: 379674K->11385K(415040K), 0.2083919 secs]6003.308: [Tenured: 967676K->564245K(990988K), 2.1042674 secs] 1278260K->564245K(1406028K), [Metaspace: 185018K->185018K(1222656K)], 2.3169234 secs] [Times: user=1.92 sys=0.40, real=2.32 secs] 
6007.577: [GC (Allocation Failure) 6007.578: [DefNew: 376320K->2193K(423360K), 0.1099151 secs] 940565K->635529K(1363772K), 0.1101776 secs] [Times: user=0.05 sys=0.06, real=0.11 secs] 

6014.209: [GC (GCLocker Initiated GC) 6014.209: [DefNew: 381118K->5451K(423360K), 0.0785015 secs] 1152634K->846057K(1363772K), 0.0787623 secs] [Times: user=0.05 sys=0.03, real=0.08 secs] 
6014.736: [GC (Allocation Failure) 6014.736: [DefNew: 381771K->6281K(423360K), 0.0715430 secs] 1222377K->915977K(1363772K), 0.0717758 secs] [Times: user=0.05 sys=0.02, real=0.07 secs] 
6014.918: [GC (Allocation Failure) 6014.918: [DefNew: 382601K->6293K(423360K), 0.0177022 secs] 1292297K->915989K(1363772K), 0.0178470 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 

6016.417: [GC (Allocation Failure) 6016.417: [DefNew: 381527K->4686K(423360K), 0.0162314 secs] 1294566K->918412K(1363772K), 0.0164098 secs] [Times: user=0.01 sys=0.00, real=0.02 secs] 
6016.543: [GC (Allocation Failure) 6016.543: [DefNew: 381006K->4546K(423360K), 0.0150262 secs] 1294732K->918321K(1363772K), 0.0151928 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
6018.243: [GC (Allocation Failure) 6018.243: [DefNew: 365758K->6625K(423360K), 0.0193289 secs] 1279533K->920785K(1363772K), 0.0195451 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
6018.406: [GC (Allocation Failure) 6018.407: [DefNew: 382945K->6153K(423360K), 0.0771226 secs]6018.484: [Tenured: 983791K->572329K(1009504K), 1.1978621 secs] 1297105K->572329K(1432864K), [Metaspace: 185178K->185178K(1222656K)], 1.2794009 secs] [Times: user=1.22 sys=0.06, real=1.28 secs] 
6019.811: [GC (Allocation Failure) 6019.811: [DefNew: 381760K->29K(429440K), 0.0100063 secs] 954089K->572359K(1383324K), 0.0101268 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 




保留一下如果堆内存和元空间正常 就得去看看这儿写的东西了。。

https://www.tulingxueyuan.cn/tlzx/jsp/3940.html
https://blog.csdn.net/weixin_45583158/article/details/100143231

参考

entityManager.unwrap(Session.class).evict(myObj);

posted @ 2023-12-05 20:08  方东信  阅读(749)  评论(0编辑  收藏  举报