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

2009年02月26日

又遇到一个jdk1.6的bug

Filed under: Java — 标签:, , — lizongbo @ 22:15

下午上线一个新功能,突然其中一台服务器出现问题,然后找到异常信息,如下:
[code]
[2009-02-26 17:27:40] java.io.IOException: Operation not permitted
[2009-02-26 17:27:40] at sun.nio.ch.EPollArrayWrapper.epollCtl(Native Method)
[2009-02-26 17:27:40] at sun.nio.ch.EPollArrayWrapper.updateRegistrations(EPollArrayWrapper.java:202)
[2009-02-26 17:27:40] at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:183)
[2009-02-26 17:27:40] at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:65)
[2009-02-26 17:27:40] at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
[2009-02-26 17:27:40] at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
[2009-02-26 17:27:40] at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:84)

[/code]
结果google一搜索,发现是jdk的bug:
(se) epoll based Selector throws java.io.IOException: Operation not permitted during load
http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6481709

再看一看服务器上的jdk版本:
lizongbo@618119_com:~> 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)

于是先重启resin,然后升级jdk。

上次遇到的问题,也是jdk的bug,参考:
服务器从jdk1.6.0升级到1.6.0_12的过程记录

http://618119.com/archives/2009/02/21/136.html

升级之后:

lizongbo@618119_com:~> 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)

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 java

当时采取的临时办法是在监控到内存超过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也进行了升级,相关业务也连续几天没在收到告警了。

JDK7.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:+UseG1GC
参考:http://oss-tw.blogspot.com/2009/02/java-jvm-g1-java-hotspot-14.html

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

2009年02月18日

调整resin的resin.conf优化access-log输出日志

Filed under: Resin — 标签:, — lizongbo @ 00:25

目前服务器上resin.conf的日志配置一般是:
《stdout -log path=”log/stdout.log” timestamp=”[%Y-%m-%d %H:%M:%S] ” rollover-size=”200mb” /》
《stderr -log path=”log/stderr.log” timestamp=”[%Y-%m-%d %H:%M:%S] ” rollover-size=”200mb” /》
《access -log path=”logs/access.log” rollover-period=”1D” rollover-size=”200mb”/》

在这种情况下,日志始终是先输出到logs/access.log这样的固定文件里,待文件大小满200M的时候,resin先锁住所有写日志操作,将文件的内容复制到文件名带时间戳的文件里,再清空当前日志文件的内容。
这种情况下,既多增加了磁盘io操作,也因为锁机制导致线程容易满,以至resin被webapp监控重启。
以前出现该问题的时候,只简单的通过关闭access-log绕了过去,而最近web网站的resin也出现了重启,
由于web是lvs负载均衡,因此不能通过关闭accesslog来解决问题。

经过查看resin的源代码分析,结合现在业务的实际情况,可以通过调整日志的配置为按时间周期切割来解决问题。
通过分析和实验,将resin的配置调整后大致为:

《stdout -log path-format=”log/stdout.log.%Y%m%d” timestamp=”[%Y-%m-%d %H:%M:%S] ” rollover-period=”1D” /》
《stderr -log path-format=”log/stderr.log.%Y%m%d” timestamp=”[%Y-%m-%d %H:%M:%S] ” rollover-period=”1D” /》
《access -log path-format=”logs/access.log.%Y%m%d_%H” rollover-period=”1h”/》
(默认format是combined格式)
上面的是stdout和stderr按天切割(如果代码里异常输出比较多的话,也可以配制成按小时打,例如有:ex.printStackTrace();),access.log按小时切割。

大致分析过程:

访问高峰期时,日志滚动时候,导致线程锁住了。
JMX监控查看线程堆栈可以得知,可以看出大量的线程都 在执行com.caucho.server.log.AccessLog.log的时候BLOCKED了。
[code]
==============================
“resin-tcp-connection-*:80-5973” Id=41812 in BLOCKED on lock=java.lang.Object@14dca59
owned by resin-tcp-connection-*:80-5545 Id=41588
at com.caucho.server.log.AccessLog.log(AccessLog.java:310)
at com.caucho.server.webapp.WebAppFilterChain.doFilter(WebAppFilterChain.java:206)
at com.caucho.server.dispatch.ServletInvocation.service(ServletInvocation.java:229)
at com.caucho.server.http.HttpRequest.handleRequest(HttpRequest.java:268)
at com.caucho.server.port.TcpConnection.run(TcpConnection.java:389)
at com.caucho.util.ThreadPool.runTasks(ThreadPool.java:507)
at com.caucho.util.ThreadPool.run(ThreadPool.java:433)
at java.lang.Thread.run(Thread.java:619)

[/code]

先下载resin的源代码: http://www.caucho.com/download/resin-3.0.19-src.tar.gz

接下来分析AccessLog的log方法。

可以看到:
if (_isSharedBuffer && ! _isAutoFlush) {
synchronized (_sharedBufferLock) {

而这两个选项的默认值是:_isSharedBuffer=true,_isAutoFlush=false;
(因为resin.conf没有配置对应的属性,例如: shared-buffer=”false” auto-flush=”false”)
而这两个属性在官方文档里并没有直接列出。
http://caucho.com/resin-3.0/config/log.xtp#rollover

(测试了不能设置 auto-flush=”true”,因为没缓冲,还没判断好滚动就直接打到文件了,rollover-size几乎等同失效)

com.caucho.vfs. AbstractRolloverLog.java中:
private static final long DEFAULT_ROLLOVER_CHECK_PERIOD = 600L * 1000L;

private long _rolloverCheckPeriod = DEFAULT_ROLLOVER_CHECK_PERIOD;
滚动日志检测周期默认是10分钟。
而该参数没法在resin.conf中动态配置。

在文件超过指定大小之后,日志滚动的方法为:com.caucho.vfs. AbstractRolloverLog 里的rolloverLog, 这个也是个同步方法:

而执行文件内容的操作是movePathToArchive方法:
而movePathToArchive的做法是:

关键代码是: path.writeToStream(out);和path.truncate()
前一个方法,是表示把当前文件的内容读出来,再写到out里。
后一个方法是,把当前文件内容清空。
而其对应的实现是:
com.caucho.vfs.Path和com.caucho.vfs.FilePath。

从整个代码分析可以得知,resin在按文件大小滚动日志的时候,是检测到当前文件超过200M,就先把缓冲全部写入当前日志文件access.log里,再将access.log的内容读出,再写到 access.log.20090206.1047 这样的文件里,写完之后,再通过truncate利用FileOutputStream的append为false将access.log内容清空。相当于先复制内容到新文件,然后再清空当前文件内容。

而这整个过程中,是同步的,因此在执行复制201M日志的时候,线程全部锁住,而这个时候大量的用户请求正在涌来,导致jmx线程过高且webapp监控告警,于是resin被监控重启。

解决办法:
使用path-format属性替代 path,
例如配置:
《access -log path-format=”logs/access.log.%Y%m%d_%H” rollover-period=”1h”/》
这样就是每小时打一个文件,切换日志输出时候,自动切换,不再产生movePathToArchive操作。
jvm.Log里也没了”Archiving access log to “这样的日志。
Stdout和stderr也是同样处理,有这两个日志的内不会太多,可以配置成按天滚动。
stdout-log元素和stderr-log也有path-format属性。

为什么resin不用File的renameTo通过重命名来切换日志呢,这是因为java的io里,只有所有的流都关闭之后,且操作系统中没有程序对文件持有引用时,文件重命名才能够成功,且renameTo是依赖操作系统的,而这种正在对文件进行读写操作的,执行renameTo无法做到一定成功的。Resin也是因为此,在按文件大小进行滚动的时候,才不得已使用复制文件加清空内容的做法。

Powered by WordPress