lizongbo at 618119.com 工作,生活,Android,前端,Linode,Ubuntu,nginx,java,apache,tomcat,Resin,mina,Hessian,XMPP,RPC

2009年02月21日

服务器从jdk1.6.0升级到1.6.0_12的过程记录

Filed under: Java,JVM,Linux — 标签:, , , , , — lizongbo @ 00:21

服务器从jdk1.6.0升级到1.6.0_12的过程记录

前段时间系统存在问题,在java程序运行几天之后,就会出现物理内存被耗尽的情况。
服务器8G内存,启动两个进程,Xmx=3000m,而程序运行一段时间后,物理内存消耗达到了95%,
然后再持续一段时间之后,服务器就出现死机现象,通过“-verbosegc -XX:+PrintGCDetails”生成的gc log里可以发现,死机前java进程通常会有一大堆Full GC记录。
top -s
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
618119 lizongbo 16 0 7533m 4.8G 1692 S 28 61.0 3309:35

当时采取的临时办法是在监控到内存超过95%十分钟后,就通过监控kill其中一个进程,并重启该进程。
这样的处理方式虽然避免了死机情况的出现,但是没想到的时候,没有kill的这个进程,
在持续运行一段时间后,居然占用物理内存到了60%。(linux通过top -s 看%MEM的值)
当时查遍所有的代码,没能找到出现问题的原因。
用命令jmap -heap 618119也没看出不对劲的地方。
然后jmap -histo:live 618119|head -n 40 查看数量最多的对象,发现
java.lang.ThreadLocal$ThreadLocalMap$Entry
[Ljava.lang.ThreadLocal$ThreadLocalMap$Entry;
java.util.concurrent.locks.ReentrantReadWriteLock$Sync$HoldCounter
java.util.concurrent.LinkedBlockingQueue$Node
java.util.concurrent.locks.ReentrantReadWriteLock$Sync$ThreadLocalHoldCounter这几个类的实例非常多。
在反复查找代码之后,怀疑是其中用到的ReentrantReadWriteLock出了问题。
关于ReentrantReadWriteLock,可参考:jdk中文本的java doc:
http://download.developers.sun.com.cn/javadoc/jdk6/docs/zh/api/java/util/concurrent/locks/ReentrantReadWriteLock.html
程序里用到了readLock和writeLock的lock与unlock方法,但是试用的方式和官方例子一致,看不出什么问题。
由于曾经看到 阿里的岑文初提到过LinkedBlockingQueue存在内存泄漏:
参考: http://www.blogjava.net/cenwenchu/archive/2008/09/18/229809.html
关于LinkedBlockingQueue可以参考:
http://download.developers.sun.com.cn/javadoc/jdk6/docs/zh/api/java/util/concurrent/LinkedBlockingDeque.html

于是查看linux服务器上的jdk版本:
java -version
java version “1.6.0”
Java(TM) SE Runtime Environment (build 1.6.0-b105)
Java HotSpot(TM) 64-Bit Server VM (build 1.6.0-b105, mixed mode)
原来jdk1.6正式发布时的第一个build正式版本。
因为程序改动并不大,而刚好最近发生这样奇怪的事情,但是拿不出直接证据证明。
于是初步猜测该问题是sun的jdk的bug所致,到sun的官方网站阅读jdk的Update Release Notes日志。

于是在Update Release Notes里找到了以下几个bug修复的记录:

1.6.0_01-b06 修复的关于并发和gc的bug有:
6433335 hotspot garbage_collector ParNewGC times spiking, eventually taking up 20 out of every 30 seconds
6459113 hotspot garbage_collector CMS+ParNew: wildly different ParNew pause times depending on heap shape caused by allocation spread
来源:http://java.sun.com/javase/6/webnotes/6u1.html

1.6.0_02-b06 修复的关于并发和gc的bug有:
6468516 hotspot garbage_collector CMS: deal correctly with concurrently cleared or enqueued Reference objects
6468290 hotspot garbage_collector Divide and allocate out of eden on a per cpu basis
6460501 java classes_util_concurrent Synchronizer timed acquire still leaks memory
6497138 java classes_util_concurrent Scalability limitation in ConcurrentHashMap on Java 6
来源:http://java.sun.com/javase/6/webnotes/6u2.html

1.6.0_04-b12 修复的关于并发和gc的bug有一大堆,就不列出来了:

来源:http://java.sun.com/javase/6/webnotes/6u4.html

1.6.0_10-b33 修复的关于并发和gc的bug有:
6635560 hotspot garbage_collector segv in reference processor on t1000
6642634 hotspot garbage_collector Test nsk/regression/b6186200 crashed with SIGSEGV
6662086 hotspot garbage_collector 6u4+, 7b11+: CMS never clears referents when -XX:+ParallelRefProcEnabled
6676016 hotspot garbage_collector ParallelOldGC leaks memory
6576792 java classes_util_concurrent ThreadPoolExecutor methods leak interrupts when run in pool threads
6639183 java classes_util_concurrent Scheduling large negative delay hangs entire ScheduledExecutor

来源:http://java.sun.com/javase/6/webnotes/6u10.html

1.6.0_12-b04 修复的关于并发和gc的bug有:
6722112 hotspot garbage_collector CMS: Incorrect encoding of overflown object arrays during concurrent precleaning
6722116 hotspot garbage_collector CMS: Incorrect overflow handling when using parallel concurrent marking
6739357 hotspot garbage_collector CMS: Switch off CMSPrecleanRefLists1 until 6722113 can be fixed

来源:http://java.sun.com/javase/6/webnotes/6u12.html

经过对jdk1.6修复bug的记录的分析,怀疑是重点是Synchronizer的这个bug引发的问题
http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6460501
从bug描述及java源代码分析,java并发库里的大量的并发组件都依赖于AbstractQueuedSynchronizer,
LinkedBlockingQueue,Semaphore,ReentrantLock,ReentrantReadWriteLock等,均有继承AbstractQueuedSynchronizer的Sync。

由此进一步怀疑是jdk的bug造成内存泄漏的问题。
于是先升级了其中一台服务器的jdk到最新版本,
java -version
java version “1.6.0_12”
Java(TM) SE Runtime Environment (build 1.6.0_12-b04)
Java HotSpot(TM) 64-Bit Server VM (build 11.2-b01, mixed mode)

升级之后,程序连续运行7天没出任何问题,内存回收也十分正常。
运行jmap -histo:live 618119|head -n 40 再次查看对象数量的时候,数量排在前10的实例和存在问题之前的顺序不再一样了。
num #instances #bytes class name
———————————————-
1: 12805991 813400696 [B
2: 8575933 205822392 java.lang.Integer
3: 246199 107685936 [[B
4: 344259 98264616 [Ljava.lang.Object;
5: 1621708 90815648 java.lang.ThreadLocal$ThreadLocalMap$Entry
6: 824 63288512 [Ljava.lang.ThreadLocal$ThreadLocalMap$Entry;
7: 1620504 51856128 java.util.concurrent.locks.ReentrantReadWriteLock$Sync$HoldCounter
8: 925444 37017760 java.lang.String
9: 333234 30753832 [C
10: 354863 17033424 java.util.HashMap$Entry

于是对改该程序的其它服务器也进行了jdk升级,升级为1.6.0_12-b04。
观察几天后发现,不再出现物理内存耗尽的情况,而且单进程的java内存消耗不再超过Xmx设置的值,在在线用户低谷时候内存也能够顺利回收了。观察一段时间确认jdk升级的效果后,对其他业务的jdk也进行了升级,相关业务也连续几天没在收到告警了。

7.0引入了新的jdk算法,叫做:G1 (The Garbage-First garbage collector),
尤其适合大用户,高并发,容易产生大量临时对象的业务。
参考:http://blogs.sun.com/theplanetarium/entry/java_vm_trying_a_new
该算法也将在jdk1.6的jdk1.6.0_14中引入,目前jdk1.6 u14已经有ea测试版了,
下载地址为:http://download.java.net/jdk6/binaries/ (http://download.java.net/jdk6/6u14/)
试用G1算法的命令行参数为:-XX:+UnlockExperimentalVMOptions -XX:+UseG1
参考:http://oss-tw.blogspot.com/2009/02/java-jvm-g1-java-hotspot-14.html

期待JDK1.6 u14早期发布正式版,也期待JDK1.7(JDK7.0)早日正式发布。
到那时候,有jdk的高性能支撑,一些需求就可以轻松搞定了。

2 Comments »

  1. […] 更新java hotspot VM,Garbage collection improvements。 http://618119.com/archives/2009/02/21/136.html 这是个相似案例,只是更老旧版本上的问题。 […]

    Pingback by jdk6不同小版本Garbage collection性能差异问题 | 墙角的小猫's Blog — 2013年09月4日 @ 16:56

  2. […] 更新java hotspot VM,Garbage collection improvements。 http://618119.com/archives/2009/02/21/136.html 这是个相似案例,只是更老旧版本上的问题。 […]

    Pingback by jdk6不同小版本Garbage collection性能差异问题 | OPS blog 聚合 — 2014年07月7日 @ 11:31

RSS feed for comments on this post. TrackBack URL

Leave a comment

Powered by WordPress