症状:
使用Eclipse win 64位版本,indigo及kepler都重现了,使用tomcat 6.0.39,jdk1.6.u45及1.7u45均尝试了,也重现。
重现步骤很简单,使用debug模式启动时较容易出来,debug启动tomcat,(我的是webapp)然后在页面上随便点点即发现eclipse僵死,且任何从浏览器发出的请求都卡住不能被接收执行。
1、然后从任务管理器直接杀掉eclipse对应的javaw进程(有些可能是eclipse进程,根据指定的vm而定--eclipse.ini中 -vm指定)后,tomcat恢复正常,一切都正常了。
2、等待很久,真的很久,它自己又正常了,但过一会,又是这样。如果没事且有耐心的话,再等很久又会正常的?
排查步骤:
1、怀疑是eclipse或tomcat内存问题,于是乎jstat gc 查看发现一切正常。
2、从任务管理器查看tomcat 对应的java进程资源占用正常。
3、从任务管理器查看eclipse对应java进程,cpu占用 25%且持续很长时间。因为我是4核,所以实际已经占满了一个CPU资源了,这说明eclipse遇到了麻烦的问题。
4、使用Process Explorer 工具查看这个java进程中线程情况,发现有1个线程几乎占用了 这个进程绝大部分CPU资源(有时可能是两个线程),这个线程几乎是死循环了。
5、使用jstack连续对eclipse对应的java进程做threaddump,然后将Process Explorer中看到的进程ID做16进制转换,到ThreadDump中加上0x 前缀即能找到对应线程。通过这里,也就基本定位到问题的出处了。例如我的 TID:1372,转为16进制是55C,加上0x前缀则是 0x55c。
"Worker-10" prio=6 tid=0x0000000008d30800 nid=0x55c runnable [0x000000000d3cf000] java.lang.Thread.State: RUNNABLE at java.util.regex.Pattern$CharProperty.match(Pattern.java:3345) at java.util.regex.Pattern$Curly.match0(Pattern.java:3770) at java.util.regex.Pattern$Curly.match(Pattern.java:3744) at java.util.regex.Pattern$Start.match(Pattern.java:3055) at java.util.regex.Matcher.search(Matcher.java:1105) at java.util.regex.Matcher.find(Matcher.java:561) at org.eclipse.ui.internal.console.ConsolePatternMatcher$MatchJob.run(ConsolePatternMatcher.java:130) at org.eclipse.core.internal.jobs.Worker.run(Worker.java:53)
而且通过数次重现,均是
at org.eclipse.ui.internal.console.ConsolePatternMatcher$MatchJob.run(ConsolePatternMatcher.java:130)
这个从名称就能看出与console有关了。eclipse官方也报过类似bug,是在07年和11年报的,理论上早修复了。
6、差不多已经定位了,于是就从console下手了。
观察console,发现我们的框架竟然把所有给浏览器的请求和响应都输出了,因为有个请求将会返回 200K左右的数据,相当于在Console中一次直接输出了200K的日志而且是没换行的,所以一开始我也没注意到。
回过头看我Console配置,最大字符数是80000≈78K,我一条日志就远超出Console默认的展示量了。
7、接下来就开始解决问题
7.1)将Console字符限制取消,即无限制。这个日志多且程序要在Eclipse中跑很久不现实,但我这么设置后实际就正常了,没有再出现eclipse僵死的情况。然后我手贱的点了下Console窗口上的“Clear Console”操作,Eclipse又僵死了。
7.2)因为实际那个日志输出对我开发意义不大,是INFO级别的,有点类似访问日志。于是乎将其对应的LOG Append级别设置为WARN,不输出这个日志了,一切就回归正常了。