FULL GC这么多,139邮箱是不是有问题题

在Plumbr这和GC暂停检测打交道的这段日子里,我查阅了与这个主题相关的大量文章,书籍以及资料。在这当中,我经常会对新生代GC, 年老代GC以及Full GC的事件的使用(滥用)感到困惑。于是便有了这篇文章,希望能够清除一些困惑。
本文需要读者对JVM内建的GC相关的常用原理有一定的了解。像eden区,Survivor区以及年老区空间的划分,分代假设(generational hypothesis)以及不同的GC算法就不在本文的讨论范围之内了。
新生代GC(Minor GC)
新生代垃圾的回收被称作
Minor GC。这个定义非常清晰,理解起来也不会有什么歧义。不过当处理新生代GC事件时,还是有一些有意思的东西值得注意的:
只要JVM无法为新创建的对象分配空间,就肯定会触发新生代GC,比方说Eden区满了。因此对象创建得越频繁,新生代GC肯定也更频繁。
一旦内存池满了,它的所有内容就会被拷贝走,指针又将重新归零。因此和经典的标记(Mark),清除(Sweep),整理(Compact)的过程不同的是,Eden区和Survivor区的清理只涉及到标记和拷贝。在它们中是不会出现碎片的。写指针始终在当前使用区的顶部。
在一次新生代GC事件中,通常不涉及到年老代。年老代到年轻代的引用被认为是GC的根对象。而在标记阶段中,从年轻代到年老代的引用则会被忽略掉。
和通常所理解的不一样的是,所有的新生代GC都会触发“stop-the-world”暂停,这会中断应用程序的线程。对绝大多数应用而言,暂停的时间是可以忽略不计的。如果Eden区中的大多数对象都是垃圾对象并且永远不会被拷贝到Survivor区/年老代中的话,这么做是合理的。如果恰好相反的话,那么绝大多数的新生对象都不应该被回收,新生代GC的暂停时间就会变得相对较长了。
现在来看新生代GC还是很清晰的——
每一次新生代GC都会对年轻代进行垃圾清除。
年老代GC(ajor GC)与Full GC
你会发现关于这两种GC其实并没有明确的定义。JVM规范或者垃圾回收相关的论文中都没有提及。不过从直觉来说,根据新生代GC(Minor GC)清理的是年轻代空间的认识来看,不难得出以下推论(这里应当从英文出发来理解,Minor, Major与Full GC,翻译过来的名称已经带有明显的释义了):
Major GC清理的是年老代的空间。
Full GC清理的是整个堆——包括年轻代与年老代空间
不幸的是这么理解会有一点复杂与困惑。首先——许多年老代GC其实是由新生代GC触发的,因此在很多情况下两者无法孤立来看待。另一方面——许多现代的垃圾回收器会对年老代进行部分清理,因此,使用“清理”这个术语则显得有点牵强。
那么问题就来了,先别再纠结某次GC到底是年老代GC还是Full GC了,
你应该关注的是这次GC是否中断了应用线程还是能够和应用线程并发地执行。
即便是在JVM的官方工具中,也存在着这一困扰。通过一个例子来说明应该更容易理解一些。我们用两款工具来跟踪某个运行着CMS回收器的JVM,来比较下它们的输出有什么不同:
的输出来查看下GC的信息:
my-precious: me$ jstat -gc -t 4235 1s
6.7 48.0 .0
8.7 48.0 48.0
9.7 48.0 .0
640.0 56416.0
11.7 48.0 .0
13.7 48.0 .0
640.0 56416.0
16.7 48.0 .0
这段输出是从JVM启动后第17秒开始截取的。从中可以看出,在经过了12次新生代GC后出现了两次Full GC,共耗时50ms。通过GUI的工具也可以获取到同样的信息,比如说
在接受这一结论前,我们再来看下同样是这次JVM启动后所输出的GC日志。很明显-XX:+PrintGCDetails给我们讲述的是一段截然不同却更为详尽的故事:
java -XX:+PrintGCDetails -XX:+UseConcMarkSweepGC eu.plumbr.demo.GarbageProducer
3.157: [GC (Allocation Failure) 3.157: [ParNew: 272640K-&3K), 0.0844702 secs] 272640K-&64K), 0.0845560 secs] [Times: user=0.23 sys=0.03, real=0.09 secs]
4.092: [GC (Allocation Failure) 4.092: [ParNew: 306688K-&3K), 0.1013723 secs] 342214K-&63104K), 0.1014307 secs] [Times: user=0.25 sys=0.05, real=0.10 secs]
... cut for brevity ...
11.292: [GC (Allocation Failure) 11.292: [ParNew: 306686K-&3K), 0.0857219 secs] 971599K-&63104K), 0.0857875 secs] [Times: user=0.26 sys=0.04, real=0.09 secs]
12.140: [GC (Allocation Failure) 12.140: [ParNew: 306688K-&3K), 0.0821774 secs] 1051788K-&63104K), 0.0822400 secs] [Times: user=0.25 sys=0.03, real=0.08 secs]
12.989: [GC (Allocation Failure) 12.989: [ParNew: 306686K-&3K), 0.1086667 secs] 1128760K-&63104K), 0.1087416 secs] [Times: user=0.24 sys=0.04, real=0.11 secs]
13.098: [GC (CMS Initial Mark) [1 CMS-initial-mark: 56416K)] 63104K), 0.0041705 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
13.102: [CMS-concurrent-mark-start]
13.341: [CMS-concurrent-mark: 0.238/0.238 secs] [Times: user=0.36 sys=0.01, real=0.24 secs]
13.341: [CMS-concurrent-preclean-start]
13.350: [CMS-concurrent-preclean: 0.009/0.009 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
13.350: [CMS-concurrent-abortable-preclean-start]
13.878: [GC (Allocation Failure) 13.878: [ParNew: 306688K-&3K), 0.0960456 secs] 1204052K-&63104K), 0.0961542 secs] [Times: user=0.29 sys=0.04, real=0.09 secs]
14.366: [CMS-concurrent-abortable-preclean: 0.917/1.016 secs] [Times: user=2.22 sys=0.07, real=1.01 secs]
14.366: [GC (CMS Final Remark) [YG occupancy: 182593 K (306688 K)]14.366: [Rescan (parallel) , 0.0291598 secs]14.395: [weak refs processing, 0.0000232 secs]14.395: [class unloading, 0.0117661 secs]14.407: [scrub symbol table, 0.0015323 secs]14.409: [scrub string table, 0.0003221 secs][1 CMS-remark: 56416K)] 63104K), 0.0462010 secs] [Times: user=0.14 sys=0.00, real=0.05 secs]
14.412: [CMS-concurrent-sweep-start]
14.633: [CMS-concurrent-sweep: 0.221/0.221 secs] [Times: user=0.37 sys=0.00, real=0.22 secs]
14.633: [CMS-concurrent-reset-start]
14.636: [CMS-concurrent-reset: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
从以上能够看出,在运行了12次新生代GC后的确出现了一些“不太寻常”的事情。但并不是执行了两次Full GC,这个“不寻常”的事情其实只是在年老代中执行了一次包含了数个阶段的GC而已:
初始标记阶段,从0.0041705 秒或者说4ms的时候开始。这一阶段是一次“stop-the-world”事件,所有的应用线程都被暂停以便进行初始标记。
并发地执行标记和预清理(Preclean)的阶段。这是和应用线程一起并发执行的。
最终标记阶段,从0.0462010秒或者说46毫秒的时候开始。这一阶段也同样是“stop-the-world”的。
并发地进行清除操作。正如名字所说的,这一阶段也无需中断应用线程,可以并发地执行。
因此我们从实际的GC日志中所看到的是这样——其实没有什么两次所谓的Full GC,只有一次清理年老代空间的Major GC而已。
如果你再想想jstat所输出的结果再下结论的话,就能得出正确的结论了。它明确地列出了两次stop-the-world事件,总耗时50ms,这是影响到活跃线程的总的延迟时间。不过如果你想依据这来优化吞吐量的话,你可能就被误导了——jstat只列出了两次stop-the-world的初始标记和最终标记的阶段,它把并发执行的那部分工作给隐藏掉了。
基于上述事实来看,最好就是不要再考虑什么新生代GC,年老代GC,Full GC。你应该做的是监控应用的时延和吞吐量,并把GC事件与之结合来看。从这些事件中,你便能得知某个GC事件是否中断了应用程序或者只是并发地执行而已。
原创文章转载请注明出处:
相关 [full gc 存在] 推荐:
- Java译站
在Plumbr这和GC暂停检测打交道的这段日子里,我查阅了与这个主题相关的大量文章,书籍以及资料. 在这当中,我经常会对新生代GC, 年老代GC以及Full GC的事件的使用(滥用)感到困惑. 于是便有了这篇文章,希望能够清除一些困惑. 本文需要读者对JVM内建的GC相关的常用原理有一定的了解. 像eden区,Survivor区以及年老区空间的划分,分代假设(generational hypothesis)以及不同的GC算法就不在本文的讨论范围之内了.
- Web前端 - ITeye博客
除直接调用System.gc外,触发Full GC执行的情况有如下四种. 旧生代空间只有在新生代对象转入及创建为大对象、大数组时才会出现不足的现象,当执行Full GC后空间仍然不足,则抛出如下错误:. 为避免以上两种状况引起的Full GC,调优时应尽量做到让对象在Minor GC阶段被回收、让对象在新生代多存活一段时间及不要创建过大的对象及数组.
- Adam - 淘宝JAVA中间件团队博客
Arena Allocation,是一种GC优化技术,它可以有效地减少因内存碎片导致的Full GC,从而提高系统的整体性能. 本文介绍Arena Allocation的原理及其在Hbase中的应用-MSLAB. 假设有1G内存,我顺序创建了1百万个对象,每个对象大小1K,Heap会被渐渐充满且每个对象以创建顺序相邻.
- 高级语言虚拟机
qianhd . 链接: http://hllvm./group/topic/28745 . 发表时间: 日. 声明:本文系ITeye网站发布的原创文章,未经作者书面许可,严禁任何网站转载本文,否则必将追究法律责任. 与另外个程序交互有个心跳检测, 15s/次, 31s没有收到心跳检测的返回消息就认为连接断了,.
网上还是有蛮多解决方案,还是说说我最比较喜欢且常用的吧,. 1、添加gcDaemonProtection=&false&参数禁用JreMemoryLeakPreventionListener监听. 2、直接删除JreMemoryLeakPreventionListener监听. 已有
0 人发表留言,猛击-&&
这里&&-参与讨论.
- JavaRanger - 专注JAVA高性能程序开发、JVM、Mysql优化、算法
上周开始系统在业务高峰期一直收到Full gc报警,监控显示fgc频繁,下图是监控图,左边红框是优化前效果,右边是优化后,优化后fgc基本为0. 1.查看gc日志,发现old区fgc后大小没有变化,如下图:. 2.去线上dump内存看是什么对象,用memory analyzer分析,Retained Size竟然有2.4G,全是sun.awt.SunToolkit这个对象,其实到这一步已经可以确定是什么问题了,只是自己对系统不是很熟悉,导致定位具体的问题代码花了一些时间.
- Java - 编程语言 - ITeye博客
当频繁full gc时,jstack打印出堆栈信息如下:. 可以看到的确是在跑低价信息. 另外在应用频繁full gc时和应用正常时,也执行了如下2种命令:. sudo -u admin -H /opt/taobao/java/bin/jmap -histo:live `pgrep` & #your file path#(live会产生full gc).
- ImportNew
GCIH可以联想到:
将长期存活的对象(如Local Cache)移入堆外内存(off-heap, 又名. 直接内存/direct-memory), 从而减少CMS管理的对象数量, 以降低Full GC的次数和频率, 达到提高系统响应速度的目的.. 这个idea最初来源于TaobaoJVM对OpenJDK定制开发的GCIH部分(详见
撒迦的分享-
JVM定制改进@淘宝), 其中GCIH就是将CMS Old Heap区的一部分划分出来, 这部分内存虽然还在堆内, 但已不被GC所管理.
关于 Java GC 已经有很多好的文档了, 比如这些:. 但是这里还是想再重点整理一下 Java GC 日志的格式, 可以作为实战时的备忘录.. 同时也会再整理一下各种概念. 一, JDK 6 提供的各种垃圾收集器. 先整理一下各种垃圾收集器.. 新生代收集器: Serial, ParNew, Parallel Scavenge (MaxGCPauseMillis vs.
- PT - Wow! Ubuntu
How-to:Part 25 Python编程, Part 6 LibreOffice , Part 3 Ubuntu 开发, Part 2 使用KDE (4.6). Linux实验室:创建自己的源. 还有:Ubuntu 游戏,我的Ubuntu故事,等等更多. # 本文采用CC协议进行授权,转载本文请注明本文链接.
--> 坚持分享优质有趣的原创文章,并保留作者信息和版权声明,任何问题请联系:@。让天下没有难学的技术
并发环境下HashMap引起的full gc排查
并发环境下HashMap引起的full gc排查
资深工程师 at Stay hungry, stay foolish.
Latest posts by ol_beta ()
作者:佐井
最近上线一个需求,完成需求的过程对代码进行了一次重构。应用发布后半个小时左右,发现一个机器报警,load过高。登陆机器看CPU使用情况,发现load已经正常,看下CPU使用情况,发现有一个核跑满,其他CPU使用率很低。大概一个小时后,其他机器陆续报警,发现同样的问题,紧急回滚应用。
应用运行在16G内存的虚机上,整个JVM11G内存,其中新生代3G,CMS gc,JDK7。
第一反应是JVM可能在进行full gc,因为只有一个线程跑满,其他线程被JVM暂停了。先去应用日志看下应用运行情况,果然日志已经没有任何输出。jstat -gcutil查看JVM内存使用情况,发现Old区使用已经100%。
考虑到full gc导致RT变得超长,去ateye摘掉应用注册的HSF服务,但是操作失败,整个JVM已经没有响应。
jmap -F -dump:format=b,file=atw.bin `jid`
把整个堆dump到本地,dump失败,JVM已经僵死。
jmap -histo
`jid` & histo.log
保留histo内存快照成功;)
jstack `jid` & stack.log
JVM线程信息保存成功:)
现场保存完毕,重启应用。
首先看下JVM线程栈信息,看看下是否有应用线程阻赛,一般情况下,如果大量线程阻赛,每个线程都持有一定量的内存,很可能导致内存吃紧,而这些阻塞的线程又没有处理完请求,占用的heap空间不能被minor gc回收掉,导致产生full gc,
cat stack.log | grep atw | sort | uniq -c | sort -nr | head -10
结果如下(重新排版过):
...service.impl...searchInterProduct(AtwSearchServiceImpl.java:505)
at ...service.impl..searchOneWay(AtwSearchServiceImpl.java:260)
at ...service.impl.executor...execute(OneWayCommonAgentSearchExecutor.java:419)
at ...service.impl.executor...handleFlights(AbstractSearchExecutor.java:689)
at ...service.impl...searchOneWay(AtwSearchServiceImpl.java:257)
at ...service.impl.executor...getFlightInfoAndStock(AbstractSearchExecutor.java:1073)
at ...service.impl.executor...getFlightInfoAndStock(AbstractSearchExecutor.java:1087)
at ...util.stlog.FarePolicyCounter.addFail(FarePolicyCounter.java:249)
at ...service.impl.executor...execute(OneWayCommonAgentSearchExecutor.java:424)
at ...service.impl.executor...getAllFares(AbstractSearchExecutor.java:892)
HSF线程开了200个,应用相关的正在运行的线程最多的是com.taobao.trip.atw.service.impl.AtwSearchServiceImpl.searchInterProduct(AtwSearchServiceImpl.java:505),一共177个,小于HSF线程数,属于正常,其他线程数量也在正常范围内。线程的锁和其他信息也未发现异常。
接下来看下histo.log:
----------------------------------------------
com.taobao.trip.atw.domain.AtwInterFareDO
java.util.HashMap$Entry
java.lang.Long
com.taobao.trip.atw.util.LongReferenceConcurrentHashMap$HashEntry
com.taobao.trip.atw.domain.AtwInterFareSegmentDO
[Ljava.util.HashMap$Entry;
[Lcom.taobao.trip.atw.domain.AtwInterFareSegmentDO;
发现最大的内存对象是byte数组,204258个实例大约占用4G堆空间(整个堆11G),平均每个20k。
初步猜测可能本次上线代码还有new byte[]的地方,即查看代码,发现本次新增功能没有这样的代码。而且整个应用的代码也无可疑地方产生了byte数组。
继续分析可能是依赖的二方或者三方jar包引起,重新申请分支,提发布单,查看发布包变化:
通过对比发现,本次发布涉及jar包变更很小,而且无三方包变更,只有内部包发生变化。对变化的包进行分析没有找到new byte[]地方。
继续分析histo.log,找到一台线上正常机器,生成histo,用故障机器数据减去正常值,得到差值如下(top 10):
java.util.HashMap$Entry
java.lang.Long
[Ljava.util.HashMap$E
com.taobao.mon.dataobject.AtwMessage
java.util.HashMap
java.util.concurrent.LinkedBlockingQueue$Node
com.taobao.trip.atw.mon.LocalMessageReactor$1
com.mon.message.MessageExt
除了byte[] 外,java.util.HashMap$Entry比正常机器多2kw,查看代码也没有明显证据能解释HashMap和byte[]同时增大的场景。
至此,分析思路阻塞,需要找到新的线索。
通过GC日志找到新线索
通过上面的分析,已经找到现象:应用出现了full gc,而且伴随大量byte[]和java.util.HashMap$Entry不能回收。
然而,full gc最直接的产物gc.log还没有被挖掘。根据full gc时间点,发现新线索(重新排版过):)
==WARNNING==
allocating large array
prio=10 tid=0xb0800 nid=0x3f43e runnable
at com.mon.io.Bytes.copyOf(Bytes.java:59)
at com.mon.io...write(UnsafeByteArrayOutputStream.java:64)
at com..caucho.hessian.io...flushBuffer(Hessian2Output.java:1553)
at com..caucho.hessian.io...printString(Hessian2Output.java:1466)
at com..caucho.hessian.io...writeString(Hessian2Output.java:987)
at com..caucho.hessian.io...writeObject(BasicSerializer.java:149)
at com..caucho.hessian.io...writeObject(Hessian2Output.java:421)
at com..caucho.hessian.io...writeObject(MapSerializer.java:99)
at com..caucho.hessian.io...writeObject(Hessian2Output.java:421)
at com..caucho.hessian.io...serialize(UnsafeSerializer.java:293)
at com..caucho.hessian.io...writeInstance(UnsafeSerializer.java:212)
at com..caucho.hessian.io...writeObject(UnsafeSerializer.java:171)
at com..caucho.hessian.io.H..writeObject(Hessian2Output.java:421)
at com.taobao.hsf.remoting.serialize...encode(Hessian2Encoder.java:23)
at com.taobao.hsf.remoting.server.output...writeHSFResponse(RpcOutput.java:47)
at com.taobao.hsf.remoting.provider...handleRequest(ProviderProcessor.java:202)
at com.taobao.hsf.remoting.server...handleRequest(RPCServerHandler.java:47)
at com.taobao.hsf.remoting.server..r.handleRequest(RPCServerHandler.java:25)
阿里定制的JVM增加了许多自己的新特性,其中一个就是在full gc不能回收的情况下,会把当前分配最大内存的线程信息和分配的内存信息打印出来!
==WARNNING== allocating large array–thread_id[0xb0800]–thread_name[owc–]–array_size[ bytes]–array_length[ elememts]
线程owc--,这是一个应用自己处理HSF请求的线程,它在分配一个巨大的数据组!通过gc日志的堆栈信息发现当前这个线程正在处理byte[]的拷贝:
at com.mon.io.Bytes.copyOf(Bytes.java:59)
这个拷贝过程一般是,应用处理好HSF请求后,把处理结果序列化成byte[],然后通过网路传输到调用机器上。
至此找到了byte[]产生的原因,还有java.util.HashMap$Entry未解决。
根据线程名字owc--去JVM的线程日志查找信息,发现owc--是处理请求的主线程,下面有四个子线程都在处理这样的堆栈:
"owc--4" daemon prio=10 tid=0xf800 nid=0x3f414 runnable [0x6000]
java.lang.Thread.State: RUNNABLE
at java.util.HashMap.getEntry(HashMap.java:469)
at java.util.HashMap.get(HashMap.java:421)
at com.taobao.trip.atw.result.impl.DefaultPriceMergerOW.processHeightQuality(DefaultPriceMergerOW.java:327)
at com.taobao.trip.atw.result.impl.DefaultPriceMergerOW.extendedProductProcess(DefaultPriceMergerOW.java:179)
at com.taobao.trip.atw.result.impl.DefaultPriceMergerOW.mergeOneWay(DefaultPriceMergerOW.java:137)
at com.taobao.trip.atw.result.PriceMergerProxy.mergeOneWay(PriceMergerProxy.java:184)
子线程都在从HashMap中get数据!由于之前遇到过HashMap多线程操作导致成环形数据结构,继而get操作成死循环的教训,这里断定是HashMap问题!
HashMap多线程下成死循环原因
简短的说,多线程下对HashMap的put操作,会导致内部的Entry链表形成环形数据结构。
首先,put操作会检查容量是否充足,如果不足,会resize内部数组。
void addEntry(int hash, K key, V value, int bucketIndex) {
if ((size &= threshold) && (null != table[bucketIndex])) {
resize(2 * table.length);
hash = (null != key) ? hash(key) : 0;
bucketIndex = indexFor(hash, table.length);
createEntry(hash, key, value, bucketIndex);
问题就在于resize内部会遍历Entry的链表:
void addEntry(int hash, K key, V value, int bucketIndex) {
if ((size &= threshold) && (null != table[bucketIndex])) {
resize(2 * table.length);
hash = (null != key) ? hash(key) : 0;
bucketIndex = indexFor(hash, table.length);
createEntry(hash, key, value, bucketIndex);
这样的代码在多线程情况下,会出现环。
对于成环的Map,get遍历Entry链表时会导致死循环:
final Entry&K,V& getEntry(Object key) {
if (size == 0) {
return null;
int hash = (key == null) ? 0 : hash(key);
for (Entry&K,V& e = table[indexFor(hash, table.length)];
e != null;
e = e.next) {
if (e.hash == hash &&
((k = e.key) == key || (key != null && key.equals(k))))
return null;
为什么会出现多个线程同时操作一个HashMap?
主线程收到请求后,会分配4个子线程去计算结果,然后由主线程去完成对结果的合并。如果子线程处理失败或者超时,那么这个子线程的结果会被丢弃,不会被合并。
从日志上看,4个子线程的处理都已经超时,但是由于HashMap并发操作造成死循环,4个子线程仍然在运行,主线程丢弃了子线程的结果,那数量量应该非常小才对,为何会产生如此大的byte[]?
追根溯源,从主线程分配任务找到了端倪。4个子线程处理计算的结果对象都是从主线程拷贝过来的:
BeanUtils.copyProperties(main, rsp);
这次修改在结果对象上增加了一个HashMap:
private Map&Long,Map&ItemGroupType,ItemDO&& agentItemG
public Map&Long, Map&ItemGroupType, ItemDO&& getAgentItemGroup() {
if (agentItemGroup == null) {
agentItemGroup = new HashMap&Long, Map&ItemGroupType, ItemDO&&();
return agentItemG
public void setAgentItemGroup(Map&Long, Map&ItemGroupType, ItemDO&& agentItemGroup) {
this.agentItemGroup = agentItemG
agentItemGroup的get方法会判断是否null,如果是的话,会生成一个新的map。
在org.springframework.beans.BeanUtils#copyProperties(java.lang.Object, java.lang.Object)方法中,对象属性的赋值会调用get/set方法,(参考:org.springframework.beans.BeanUtils#copyProperties(java.lang.Object, java.lang.Object, java.lang.Class, java.lang.String[]))这样就导致4个子线程用的map跟主线程是同一个map,而且就算子线程的结果被放弃了,主线程的map已经被搞坏。
com..caucho.hessian.io.MapSerializer.writeObject(MapSerializer.java:99)
HSF在对Map的序列化时候,对遍历Map,进行序列化:
public void writeObject(Object obj, AbstractHessianOutput out) throws IOException {
if(!out.addRef(obj)) {
Map map = (Map)
Class cl = obj.getClass();
if(!cl.equals(HashMap.class) && this._isSendJavaType && obj instanceof Serializable) {
out.writeMapBegin(obj.getClass().getName());
out.writeMapBegin((String)null);
Iterator iter = map.entrySet().iterator();
while(iter.hasNext()) {
Entry entry = (Entry)iter.next();
out.writeObject(entry.getKey());
out.writeObject(entry.getValue());
out.writeMapEnd();
由于主线程的map已经成环形数据结构,遍历的迭代器会死循环执行。
至此,full gc现象全部排查完毕,解决方案,一行代码到搞定:
BeanUtils.copyProperties(main, rsp);
rsp.setAgentItemGroup(new HashMap&Long, Map&ItemGroupType, ItemDO&&());
并发环境下被HashMap坑不止一次,很多时候,写代码没有考虑并发场景,熟知写的代码已经是在并发环境运行了。这样就酿成大错,其实后来想想,HashMap也可以做一下改进,get中如果循环超过size次了,抛出个异常,也不会导致死循环和full gc了 ?
但这并不能根治问题,写代码还是要多想想,加强reivew!
Related posts:
(5 votes, average: 3.40 out of 5)
Loading...网站持久代引发Full GC问题分析
Dragoon(监控系统)的日报显示trade_us_wholelsale(美国wholesale集群),日均Young GC次数25w次左右,应用暂停295w毫秒(相当于40多分钟),Full GC次数600次左右,应用暂停190w毫秒(相当于30多分钟)。
GC,尤其是Full GC,每次都会导致JVM暂停工作,处理垃圾回收任务,短时间内无法响应用户请求,大量的Full GC会导致系统响应速度降低,而且引来OOM的巨大风险。
启动参数:
trade_us_wholesale应用的JVM启动参数如下:
-Xmx2g -Xms2g&-Xmn256m -XX:PermSize=128m -Xss256k-XX:+UseConcMarkSweepGC
堆内存=新生代+老年代:-Xmx2g -Xms2g
新生代:256M
老年代:1792M(2G-256M)
持久代:-XX:PermSize=128M
栈内存:-Xss256KB
新生代回收方式:并行回收
老年代回收方式:并发回收(CMS)
实时数据分析:
数据来源于Dragoon平台
l& 分代内存占比
使用内存量
注:明显看出,新生代以及持久代,内存使用较为紧张,旧生代较为宽裕。
l& Young GC
Young GC频繁,由于并行GC采用多线程回收方式,但是考虑到GC次数很高,由于GC每次都会暂停应用,因此对应用的影响是不可忽视的。
l& Full GC
Full GC是指新生代、旧生代、持久代一起进行GC。
引起Full GC的原因主要有三种:
旧生代内存不足
持久代内存不足
统计新生代 GC晋升到旧生代的平均大小大于旧生代的剩余空间
Full GC回收成本高,应用会因此暂停更长时间,无法响应用户的请求。
l& Class Load情况
绿线表示卸载类的数量的累加总数,红线表示总共装载过的类的数量的累加总数,蓝线表示当前装载的类的数量的累加总数。绿线和红线的发展趋势是极其一 致的,即有大量的类被加载之后,又被卸载。加载类的信息存放在持久代。这也就从某方面印证了,持久代可能是在反复的加载类和卸载类,什么原因造成这种现 象,GC的可能性较大,我们接着看后续的分析。
GC Log情况
我们截取线上GC log的中的一段进行分析:
T04:24:27.413-2: [Full GC 611.162: [CMS: 985319K-&35008K), 2.9525910 secs] 1152585K-&70976K), [CMS Perm : 131071K-&1072K)], 2.9528010 secs] [Times: user=2.87 sys=0.08, real=2.96 secs]
持久代:131071K-&103472K 总空间:131072K
旧生代:985319K-&721699K 总空间:1835008K
堆内存:1152585K-&721699K 总空间:2070976K
此次Full GC时间花费2.96秒,在用户态(user)占用CPU百分比2.87,系统态(sys)占用百分比0.08。
数据很清晰了,持久代的GC是导致Full GC的原因,这和我们之前看到的类信息的加载之后又卸载之后又加载的现象是相符的。持久代空间不够,引起GC,GC回收类的信息,但是由于回收的类信息 JVM之后还需要,因此JVM又去加载这些信息。JVM就在这反复加载和卸载中消耗着资源,无暇响应用户的请求。
Unloading Log情况
我们继续观察显示控制台打出的unload的日志,这里打印出卸载类的情况。
sun.reflect.GeneratedSerializationConstructorAccessor这是sun的反射机使用到的类,当 事业反射newInstance()时,JVM会根据-Dsun.reflect.noInflation和 -Dsun.reflect.inflationThreshold判断是使用本地代码的反射构造器还是使用动态生成字节码构造出来的构造器,默认配置是 将会使用后者,这种方式的构造上更慢,但运行速度更快,对于使用大量反射的框架来言,后者更加合适。 GeneratedSerializationConstructorAccessor就是动态生成字节码构造出来的,后面的数字是表示累计创建类的数 量。针对一个类,同一个类加载构造器,反射的ConstructorAccessor只有一个。
可是wholesale短短启动不到3小时,怎么会有这么多ConstructorAccessor产生而且还被卸载呢?这些类是为了反射什么类而创建的呢?继续分析,下面只能dump jvm,看看内存中的情况具体是怎样了?
还有一点,线上的预发布机没有这种现象,没有大量的unloading日志,没有Full GC,他们的硬件和软件都是一样的,唯一不同的就是PV,这点很重要。
我们去线上dump下来jvm的信息,使用MAT打开,看classloader Explorer,发现更多信息。
我们看到大量的DelegatingClassLoader,而且看到了GeneratedSerializationConstructorAccessor,
我们查看都有哪些类被加载,很明显JVM当中有大量的GeneratedSerializationConstructorAccessor+count类。
这说明JVM当中有很多ConstructorAccessor一大部分被卸载了,一小部分被留在JVM当中。而且,大家注意每个 ConstructorAccessor类都有自己独立的classloader,类信息的卸载规则是按照classloader来卸载,只有这个 loader中加载的所有类都不被使用,这些类信息才能被卸载。线上的信息好像就这么多了,我们看看DelegatingClassLoader能不能在 测试环境中debug到,看看具体是什么问题。
测试环境日志
我们在测试环境搭建一套wholesale环境,使用Jmeter小幅度压测wholesale的detail页面,随着wholesale稳 定,load日志出现明显的规律性现象。每次访问detail页面,都会有 GeneratedSerializationConstructorAccessor类
上图就是在10个线程并发访问wholesaledetail页面,load日志中的内容,问题应该是出现在这些类的加载上。我们debug一下,看看具体情况。
我们debug Classloader这个类的构造器,一次访问是有哪些classloader构造出来,最终debug到 DelegatingClassLoader,结合load日志,发现这个classloader加载后就会有 GeneratedSerializationConstructorAccessor被加载。依据堆栈查看调用信息。
我们看到ReflectionConverter的中的一段代码:
final Object result = instantiateNewInstance(context, reader.getAttribute(mapper.attributeForReadResolveField()));
ReflectionConverter是XStream的反射转换器,转换器是用来编码或解码Java对象的,也就是负责java对象和xml直 接的转换。instantiateNewInstance使用来初始化类的实例的,其中 reader.getAttribute(mapper.attributeForReadResolveField())就是 WholesaleProductPriceXstreamDTO类。
instantiateNewInstance方法中会先去context当中取这个类的实例,如果没有将会使用反射构造出类的实例,在构造实例时,他们创建新的类加载器,并执行下面的一段代码:
Constructor customConstructor = reflectionFactory.newConstructorForSerialization(type, javaLangObjectConstructor);
这段代码就是动态字节码创建类构造器的代码,我们debug发现customConstructor对象中正好包含sun.reflect.GeneratedSerializationConstructorAccessor对象。
而这段代码是在我们的业务二方库biz.wsproduct中调用的:
XStream xstream = new XStream();
xstream.alias(&root&, List.class);
xstream.alias(&record&, WholesaleProductPriceXstreamDTO.class);
问题很清楚了,就是这个XStream,业务代码中错误的new这个类,造成每次执行到这段代码都需要执行上面讲述的一段逻辑,都会load GeneratedSerializationConstructorAccessor类。
而且众所周知,wholesale detail pv巨大(200w以上),大量的类被加载,应该是造成PermGen使用吃紧的原因,而且由于是创造一个新的类加载器,这样一来一次访问结束,就可以回 收这个类加载器,回收其中的类信息,释放部分PermGen空间。这样我们就看到大量的unload出现,而且PermGen虽然空间紧张,但是从未 OOM的问题也就很容易解释了。
整体的堆栈信息如下(部分堆栈信息省略):
Daemon Thread [TP-Processor39] (Suspended)
DelegatingClassLoader(ClassLoader).&init&(ClassLoader) line: 207
DelegatingClassLoader.&init&(ClassLoader) line: 54
MethodAccessorGenerator.generate(Class, String, Class[], Class, Class[], int, boolean, boolean, Class) line: 377
MethodAccessorGenerator.generateSerializationConstructor(Class, Class[], Class[], int, Class) line: 95
ReflectionFactory.newConstructorForSerialization(Class, Constructor) line: 313
Sun14ReflectionProvider.getMungedConstructor(Class) line: 61
Sun14ReflectionProvider.newInstance(Class) line: 40
ReflectionConverter.instantiateNewInstance(UnmarshallingContext, String) line: 145
ReflectionConverter.unmarshal(HierarchicalStreamReader, UnmarshallingContext) line: 87
XStream.unmarshal(HierarchicalStreamReader, Object, DataHolder) line: 521
XStream.unmarshal(HierarchicalStreamReader, Object) line: 509
XStream.fromXML(Reader) line: 475
XStream.fromXML(String) line: 468
WholesaleProductPriceXstreamHelper.convertXmlToWholesaleProductPriceDtoList(String) line: 55
WholesaleDetailUtil.getPriceDetailDTOFormProduct(WsProductDO, String) line: 404
WholesaleDetailUtil.getProductInfoDTOFromProduct(WsProductDO, String) line: 158
WholesaleProductDetail.process(RunData, TemplateContext) line: 282
WholesaleProductDetail(BaseDetailScreen).execute(RunData, TemplateContext) line: 73
WholesaleProductDetail(TemplateModule).execute(RunData) line: 38
解决方案:
解决方案比较简单,我们将XStream的设置成static变量,保证JVM当中只有一个这样的实例,在static块当中初始化,代码如下:
&&& private static XStream xstream =
&&& static {
&&&&&&& xstream = new XStream();
&&&&&&& xstream.alias(&root&, List.class);
&xstream.alias(&record&, WholesaleProductPriceXstreamDTO.class);
解决效果:
根据最新的Dragoon监控日报显示:
Full GC的次数由原先的647次降至157次,
应用暂停时间由原来的 ms (30分钟左右)降至 ms (8分钟左右),大大缩短了集群的暂停时间,基本解决问题。
阅读(...) 评论()

我要回帖

更多关于 你这里是不是有问题 的文章

 

随机推荐