一个RT下降的奇怪Case

前天碰到一个有点怪异的case,应用运行一段时间后,RT会开始突然下降,只要重启就恢复,也就是说理论上和后端没什么关系,应用本身在RT下降的时候唯一能看出的就是cpu us比较高,但从线程堆栈、gc情况、top -H + jstack等都看不出什么,悲催的是出问题的一些机器都是2.6.18的,用不了perf。

还好昨天整个集群中为数不多的几台2.6.32的也出现了问题,于是赶紧perf top看看,于是看到了如下信息:
samples pcnt function DSO
1223.00 11.8% _ZN9CodeCache9find_blobEPv libjvm.so

主要是消耗在_ZN9CodeCache9find_blobEPv,看到CodeCache,不得不瞎蒙下是不是因为Code Cache满了造成的,按照这个思路,先grep下日志里是不是有类似的信息,grep后很快看到日志里有如下信息:
VM warning: CodeCache is full. Compiler has been disabled.
话说主要是上面这一行日志在一堆的日志里太不显眼了,所以很难注意到,个人觉得这种情况下jvm都可以考虑更为激进的退出等。

Code Cache区域是JVM用来存储经过C1/C2编译优化后的代码的,因为是存在内存中的,所以肯定得限制大小,Code Cache的最大大小可通过jinfo -flag ReservedCodeCacheSize来获取,通常在64 bit机器上默认是48m,当code cache用满了后,编译优化就被禁掉了,此时会回归到解释执行,RT可想而知不会好到哪去。

为什么这个应用会造成这样的现象呢?
和应用方了解了下,应用会采用groovy来加载一些脚本,在这些脚本修改后会动态更新,而且更新的是比较频繁的,这些groovy script执行的也是比较多的,这样的话基本是可以解释通的,意味着C2需要在groovy script更新后和执行到达阈值时重新编译,这自然会导致随着运行时间越长,Code Cache使用的就越多。

解决方法
Code Cache用满一方面是因为空间可能不够用,另一方面是Code Cache是不会回收的,所以会累积的越来越多(其实在不采用groovy这种动态更新/装载class的情况下的话,是不会太多的),所以解法一可以是增大code cache的size,可通过在启动参数上增加-XX:ReservedCodeCacheSize=256m(Oracle JVM Team那边也是推荐把code cache调大的),二是启用code cache的回收机制(关于Code Cache flushing的具体策略请参见此文),可通过在启动参数上增加:-XX:+UseCodeCacheFlushing来启用。

如果想在运行时查看code cache的大小,需要写段代码,目前只能通过JMX来获取到Code Cache区域的使用状况,代码类似如下(JDK 6下可以这样,JDK 5不支持通过pid直接连上VM,只能通过jmx remote server):
[code]
import java.io.File;

import javax.management.MBeanServerConnection;
import javax.management.ObjectName;
import javax.management.remote.JMXConnector;
import javax.management.remote.JMXConnectorFactory;
import javax.management.remote.JMXServiceURL;

import com.sun.tools.attach.VirtualMachine;

public class CodeCacheUsage {

private static final String CONNECTOR_ADDRESS =
“com.sun.management.jmxremote.localConnectorAddress”;

public static void main(String[] args) throws Exception {
if(args.length != 1){
System.err.println(“Must enter one arg: pid”);
System.exit(0);
}
VirtualMachine vm = VirtualMachine.attach(args[0]);
JMXConnector connector = null;
try {
String connectorAddress = vm.getAgentProperties().getProperty(
CONNECTOR_ADDRESS);

if (connectorAddress == null) {
String agent = vm.getSystemProperties()
.getProperty(“java.home”)
+ File.separator
+ “lib”
+ File.separator + “management-agent.jar”;
vm.loadAgent(agent);

connectorAddress = vm.getAgentProperties().getProperty(
CONNECTOR_ADDRESS);
}

JMXServiceURL url = new JMXServiceURL(connectorAddress);
connector = JMXConnectorFactory.connect(url);
MBeanServerConnection mbeanConn = connector.getMBeanServerConnection();
ObjectName name = new ObjectName(
“java.lang:type=MemoryPool,name=Code Cache”);
System.out.println(mbeanConn.getAttribute(name, “Usage”));
}
finally {
if(connector != null)
connector.close();
vm.detach();
}
}

}
[/code]
传入pid,执行上面的代码后,会输出类似下面的信息:
javax.management.openmbean.CompositeDataSupport(compositeType=javax.management.openmbean.CompositeType(name=java.lang.management.MemoryUsage,items=((itemName=committed,itemType=javax.management.openmbean.SimpleType(name=java.lang.Long)),(itemName=init,itemType=javax.management.openmbean.SimpleType(name=java.lang.Long)),(itemName=max,itemType=javax.management.openmbean.SimpleType(name=java.lang.Long)),(itemName=used,itemType=javax.management.openmbean.SimpleType(name=java.lang.Long)))),contents={committed=50331648, init=2555904, max=50331648, used=48281152})
上面的信息显示Code Cache区域初始化的时候为2555904,最大为50331648,已占用了50331648,使用了48281152。

=============================
欢迎关注微信公众号:hellojavacases

关于此微信号:
分享Java问题排查的Case、Java业界的动态和新技术、Java的一些小知识点Test,以及和大家一起讨论一些Java问题或场景,这里只有Java细节的分享,没有大道理、大架构和大框架。

公众号上发布的消息都存放在http://hellojava.info上。

《一个RT下降的奇怪Case》有2个想法

发表评论

电子邮件地址不会被公开。 必填项已用*标注


*