Java问题排查工具箱

问题排查除了最重要的解决思路和逻辑推导能力外,工具也是不可缺少的一部分,一个好用的工具可以事半功倍,甚至在某些情况下会因为没有相应的工具而压根就没法继续进行下去,这篇文章就来讲讲在排查Java问题时通常要用到的一些工具(ps:这种文章值得收藏,看一遍其实很容易忘)。

日志相关工具
查问题的时候会非常依赖日志,因此看日志的相关工具非常重要,通常的话掌握好tail,find,fgrep,awk这几个常用工具的方法就可以,说到这个就必须说关键的异常和信息日志输出是多么的重要(看过太多异常的随意处理,例如很典型的是应用自己的ServletContextListener实现,很多的Listener实现都会变成往外抛RuntimeException,然后直接导致tomcat退出,而tomcat这个时候也不会输出这个异常信息,这种时候要查原因真的是让人很郁闷,尽管也有办法)。
日志的标准化也非常重要,日志的标准化一方面方便像我这种要查各种系统问题的人,不标准的话连日志在哪都找不到;另一方面对于分布式系统而言,如果标准化的话是很容易做日志tracing的,对问题定位会有很大帮助。

CPU相关工具
碰到一些CPU相关的问题时,通常需要用到的工具:
top (-H)
top可以实时的观察cpu的指标状况,尤其是每个core的指标状况,可以更有效的来帮助解决问题,-H则有助于看是什么线程造成的CPU消耗,这对解决一些简单的耗CPU的问题会有很大帮助。
sar
sar有助于查看历史指标数据,除了CPU外,其他内存,磁盘,网络等等各种指标都可以查看,毕竟大部分时候问题都发生在过去,所以翻历史记录非常重要。
jstack
jstack可以用来查看Java进程里的线程都在干什么,这通常对于应用没反应,非常慢等等场景都有不小的帮助,jstack默认只能看到Java栈,而jstack -m则可以看到线程的Java栈和native栈,但如果Java方法被编译过,则看不到(然而大部分经常访问的Java方法其实都被编译过)。
pstack
pstack可以用来看Java进程的native栈。
perf
一些简单的CPU消耗的问题靠着top -H + jstack通常能解决,复杂的话就需要借助perf这种超级利器了。
cat /proc/interrupts
之所以提这个是因为对于分布式应用而言,频繁的网络访问造成的网络中断处理消耗也是一个关键,而这个时候网卡的多队列以及均衡就非常重要了,所以如果观察到cpu的si指标不低,那么看看interrupts就有必要了。

内存相关工具
碰到一些内存相关的问题时,通常需要用到的工具:
jstat
jstat -gcutil或-gc等等有助于实时看gc的状况,不过我还是比较习惯看gc log。
jmap
在需要dump内存看看内存里都是什么的时候,jmap -dump可以帮助你;在需要强制执行fgc的时候(在CMS GC这种一定会产生碎片化的GC中,总是会找到这样的理由的),jmap -histo:live可以帮助你(显然,不要随便执行)。
gcore
相比jmap -dump,其实我更喜欢gcore,因为感觉就是更快,不过由于某些jdk版本貌似和gcore配合的不是那么好,所以那种时候还是要用jmap -dump的。
mat
有了内存dump后,没有分析工具的话然并卵,mat是个非常赞的工具,好用的没什么可说的。
btrace
少数的问题可以mat后直接看出,而多数会需要再用btrace去动态跟踪,btrace绝对是Java中的超级神器,举个简单例子,如果要你去查下一个运行的Java应用,哪里在创建一个数组大小>1000的ArrayList,你要怎么办呢,在有btrace的情况下,那就是秒秒钟搞定的事,:)
gperf
Java堆内的内存消耗用上面的一些工具基本能搞定,但堆外就悲催了,目前看起来还是只有gperf还算是比较好用的一个,或者从经验上来说Direct ByteBuffer、Deflater/Inflater这些是常见问题。
除了上面的工具外,同样内存信息的记录也非常重要,就如日志一样,所以像GC日志是一定要打开的,确保在出问题后可以翻查GC日志来对照是否GC有问题,所以像-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc: 这样的参数必须是启动参数的标配。

ClassLoader相关工具
作为Java程序员,不碰到ClassLoader问题那基本是不可能的,在排查此类问题时,最好办的还是-XX:+TraceClassLoading,或者如果知道是什么类的话,我的建议就是把所有会装载的lib目录里的jar用jar -tvf *.jar这样的方式来直接查看冲突的class,再不行的话就要呼唤btrace神器去跟踪Classloader.defineClass之类的了。

其他工具
jinfo
Java有N多的启动参数,N多的默认值,而任何文档都不一定准确,只有用jinfo -flags看到的才靠谱,甚至你还可以看看jinfo -flag,你会发现更好玩的。
dmesg
你的java进程突然不见了? 也许可以试试dmesg先看看。
systemtap
有些问题排查到java层面是不够的,当需要trace更底层的os层面的函数调用的时候,systemtap神器就可以派上用场了。
gdb
更高级的玩家们,拿着core dump可以用gdb来排查更诡异的一些问题。

io类型的问题我排查的很少,所以尽管知道一些工具,还是不在这里写了。

暂时就写这些,尽管工具的使用多数都可以临时学,但首先知道有哪些工具是最重要的,然后呢还是建议大家可以玩一玩这些工具,这样以后真的要用的时候也不至于一点印象都没有。

ps: 发现我的微信公众号还是写Java的文章阅读量高一些呀,本来我一直天真的认为像Borg这种文章应该阅读量也不低才对….

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

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

YGC越来越慢,为什么

近来被这个case折腾的很,现象是有个应用在压测时qps表现不太稳定,好和不好的时候差别还挺大的,对比好和不好的时候,看到的现象就是好的时候ygc时间会比较短,而不好的时候ygc时间比较长,然后看正常运行的时候,也看到一个现象就是ygc时间会越来越长,直到cms gc触发后才能降回到一个比较小的值,于是开始查为什么ygc会越来越慢。

YGC越来越慢,还真没什么太多信息可入手的,于是求助JVM团队的寒泉子(微信公众号:lovestblog,强烈推荐)帮忙输出一些ygc分阶段的耗时信息,以便来推测到底是哪部分造成的ygc慢,例如我有点怀疑的是oldgen碎片的问题造成的,但通常碎片问题呢cms gc后也很难有太大程度的缓解,所以和这个现象不太一样。

拿到有更多trace信息的JDK版本后,更新上线,根据ygc不断变慢的trace信息对比发现问题出在了StringTable部分,这是ygc速度正常的情况下StringTable部分的速度:
[StringTable::possibly_parallel_oops_do_21030, 0.0010919 secs]
而ygc越来越慢后,StringTable部分:
[StringTable::possibly_parallel_oops_do_11152162, 0.1101763 secs]
从输出信息来看,可以看到在ygc速度还正常的时候,StringTable去扫的一个桶里的item数才21030个,而到了ygc速度很慢的时候,item数增长到了11152162个,这样的数量增长StringTable处理的速度变慢也是正常的。

那就要查查为什么StringTable增长那么快了,StringTable增长基本都是String.intern搞的(关于StringTable和String.intern推荐看看这篇文章:http://java-performance.info/string-intern-in-java-6-7-8/),不过这个方法在native,btrace跟不了,所以寒泉子继续改了个JDK版本,采样的输出String.intern的栈信息,这个版本放上去跑后,很快看到这样的堆栈信息:
at java.lang.String.intern(Native Method)
at com.fasterxml.jackson.core.util.InternCache.intern(InternCache.java:45)
跟着这个栈信息翻对应的代码(话说不知道大家都用什么去查代码呢,我一般都用www.grepcode.com,觉得挺好用的),很容易明白问题所在,例如InternCache.intern部分的代码如下:
if (result == null) {
result = input.intern();
put(result, result);
}

jackson之所以用intern去处理,本来是想节省点cache的内存,没想到业务场景是每次都不一样的字符串,这样直接就导致了String.intern后StringTable的大小暴涨,所以在这种场景中,这样做反而得不偿失,还好jackson代码支持通过接口来把调用intern的部分关掉。

话说用String.intern不当造成的StringTable大,从而导致ygc速度慢这问题我好像碰过好几次了,而且到现在我都觉得StringTable这东西的设计不咋样,建议大家能不用String.intern还是别用好了,除非真的是重复量非常大的相同字符串处理。

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

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

从Netty到EPollSelectorImpl学习Java NIO

终于可以在写了几篇鸡汤文后,来篇技术文章了,:),题图是Trustin Lee,Mina/Netty都是他搞的,对Java程序员尤其是写通讯类的都产生了巨大影响,向他致敬!

在上周查一个内存OOM的问题之前,我一直觉得自己对Java NIO应该还是比较懂的,君不见N年前我曾经写过一篇《NFS-RPC框架优化过程(从37K到168K)》(尴尬的发现,上次导blog记录的时候竟然丢了一些文章,于是这文章link就不是自己的blog了),从那优化经历来说理论上对Netty的原理应该已经是比较清楚了才对,结果在查那个内存OOM的问题的时候,发现自己还是too young too navie,看到的现象是EPollSelectorImpl里的fdToKey有一大堆数据,就傻眼了,完全不知道这是为什么,当时就在公众号上发了个文本信息咨询大家,有不少同学给了我回复,另外滴滴打车的架构师欧阳康给了我一篇文章来说明EPollSelectorImpl这个部分的原理(强烈推荐,比我写的这篇会更深入到os层),本文就是综合了大家给我的点拨,来写写从Netty到EPollSelectorImpl的相关逻辑。

带着问题去看代码会比较的快和容易,我这次带着这几个问题:
1. EPollSelector里的fdToKey里的一大堆数据是怎么出现的;
2. Netty以及Java的EPoll部分代码是如何让N多连接的处理做到高效的,当然这主要是因为epoll,不过Java部分的相关实现也是重要的。

由于公众号贴代码不太方便,在这我就不贴大段的代码了,只摘取一些非常关键的代),代码部分我看的是Server部分,毕竟Server尤其是长连接类型的,通常会需要处理大量的连接,而且会主要是贴近我所关注的两个问题的相关代码。

Netty在初始化Server过程中主要做的事:
1. 启动用于处理连接事件的线程,线程数默认为1;
2. 创建一个EPollSelectorImpl对象;

在bind时主要做的事:
1. 开启端口监听;
2. 注册OP_ACCEPT事件;

处理连接的线程通过Selector来触发动作:

int selected = select(selector);

这个会对应到EPollSelectorImpl.doSelect,最关键的几行代码:

pollWrapper.poll(timeout);
int numKeysUpdated = updateSelectedKeys(); // 更新有事件变化的selectedKeys,selectedKeys是个Set结构

当numKeysUpdated>0时,就开始处理其中发生了事件的Channel,对连接事件而言,就是去完成连接的建立,连接建立的具体动作交给NioWorker来实现,每个NioWorker在初始化时会创建一个EPollSelectorImpl实例,意味着每个NioWorker线程会管理很多的连接,当建连完成后,注册OP_READ事件,注册的这个过程会调用到EPollSelectorImpl的下面的方法:

protected void implRegister(SelectionKeyImpl ski) {
SelChImpl ch = ski.channel;
fdToKey.put(Integer.valueOf(ch.getFDVal()), ski);
pollWrapper.add(ch);
keys.add(ski);
}

从这段代码就明白了EPollSelectorImpl的fdToKey的数据是在连接建立后产生的。

那什么时候会从fdToKey里删掉数据呢,既然放数据是建连接的时候,那猜测删除就是关连接的时候,翻看关连接的代码,最终会调到EPollSelectorImpl的下面的方法:

protected void implDereg(SelectionKeyImpl ski) throws IOException {
assert (ski.getIndex() >= 0);
SelChImpl ch = ski.channel;
int fd = ch.getFDVal();
fdToKey.remove(new Integer(fd));
pollWrapper.release(ch);
ski.setIndex(-1);
keys.remove(ski);
selectedKeys.remove(ski);
deregister((AbstractSelectionKey)ski);
SelectableChannel selch = ski.channel();
if (!selch.isOpen() && !selch.isRegistered())
((SelChImpl)selch).kill();
}

从上面代码可以看到,在这个过程中会从fdToKey中删除相应的数据。

翻代码后,基本明白了fdToKey这个部分,在Netty的实现下,默认会创建一个NioServerBoss的线程,cpu * 2的NioWorker的线程,每个线程都会创建一个EPollSelectorImpl,例如如果CPU为4核,那么总共会创建9个EPollSelectorImpl,每建立一个连接,就会在其中一个NioWorker的EPollSelectorImpl的fdToKey中放入SelectionKeyImpl,当连接断开时,就会相应的从fdToKey中删除数据,所以对于长连接server的场景而言,fdToKey里有很多的数据是正常的。

——————————-

第一个问题解决后,继续看第二个问题,怎么用比较少的资源高效的处理那么多连接的各种事件。

根据上面翻看代码的记录,可以看到在Netty默认的情况下,采用的是1个线程来处理连接事件,cpu * 2个NioWorker线程来处理读写事件。

连接动作因为很轻量,因此1个线程处理通常足够了,当然,客户端在设计重连的时候就得有避让机制,否则所有机器同一时间点重连,那就悲催了。

在分布式应用中,网络的读写会非常频繁,因此读写事件的高效处理就非常重要了,在Netty之上怎么做到高效也很重要,具体可以看看我之前写的那篇优化的文章,这里就只讲Netty之下的部分了,NioWorker线程通过
int selected = select(selector);
来看是否有需要处理的,selected>0就说明有需要处理,EPollSelectorImpl.doSelect中可以看到一堆的连接都放在了pollWrapper中,如果有读写的事件要处理,这里会有,这块的具体实现还得往下继续翻代码,这块没再继续翻了,在pollWrapper之后,就会updateSelectedKeys();,这里会把有相应事件发生的SelectionKeyImpl放到SelectedKeys里,在netty这层就会拿着这个selectedKeys进行遍历,一个一个处理,这里用多个线程去处理没意义的原因是:从网卡上读写的动作是串行的,所以再多线程也没意义。

所以基本可以看到,网络读写的高效主要还是ePoll本身做到,因为到了上层其实每次要处理的已经是有相应事件发生的连接,netty部分通过较少的几个线程来有效的处理了读写事件,之所以读写事件不能像连接事件一样用一个线程去处理,是因为读的处理过程其实是比较复杂的,从网卡cp出数据后,还得去看数据是否完整(对业务请求而言),把数据封装扔给业务线程等等,另外也正因为netty是要用NioWorker线程处理很多连接的事件,因此在高并发场景中保持NioWorker整个处理过程的快速,简单是非常重要的。

——————————

带着这两个问题比以前更往下的翻了一些代码后,确实比以前更了解Java NIO了,但其实还是说不到深入和精通,因为要更细其实还得往下翻代码,到OS层,所以我一如既往的觉得,其实Java程序员要做到精通,是比C程序员难不少的,因为技术栈更长,而如果不是从上往下全部打通技术栈的话,在查问题的时候很容易出现查到某层就卡壳,我就属于这种,所以我从来不认为自己精通Java的某部分。

最近碰到的另外一个问题也是由于自己技术栈不够完整造成排查进展一直缓慢,这问题现在还没结果,碰到的现象就是已经触发了netty避免ePoll bug的workaround,日志里出现:
Selector.select() returned prematurely 512 times in a row; rebuilding selector.
这个日志的意思是Selector.select里没有数据,但被连续唤醒了512次,这样的情况很容易导致一个cpu core 100%,netty认为这种情况出现时ePoll bug造成的,在这种情况下会采取一个workaround方法,就是rebuilding selector,这个操作会造成连接重建,对高并发场景来说,这个会造成超时等现象,所以影响还挺大的。
由于这个问题已经要查到os层,我完全无能为力,找了公司的一个超级高手帮忙查,目前的进展是看到有一个domain socket被close了,但epoll_wait的时候还是会选出这个fd,但目前还不知道为什么会出现这现象,所以暂时这问题还是存在着,有同学有想法的也欢迎给些建议。

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

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

Java NIO之EPollSelectorImpl详解

这是滴滴的架构师欧阳康同学写的,非常赞,从EPollSelectorImpl到OS层面实现的详细解释,可以让大家对Java NIO的实现有更完整的理解,强烈推荐。

本文简述JDK1.7的NIO在linux平台上的实现,对java NIO的一些核心概念如Selector,Channel,Buffer等,不会做过多解释,这些请参考JDK的文档。JDK 1.7 NIO Selector在linux平台上的实现类是sun.nio.ch.EPollSelectorImpl,这个类通过linux下的epoll系列系统调用实现NIO,因此在介绍这个类的实现之前,先介绍一下linux的epoll。epoll是poll/select系统调用的一个改进版本,能以更高的性能实现IO事件的检测和分发(主要归功于epoll的事件回调机制,下文详述),主要包含以下3个系统调用:

#include
int epoll_create(int size);
int epoll_ctl(int epfd, int op, int fd, struct epoll_event *event);
int epoll_wait(int epfd, struct epoll_event *events,int maxevents, int timeout);

上述函数中,epoll_create函数负责创建一个检测IO事件的epoll实例,size参数用于“暗示”操作系统事件队列的长度,在linux-2.6.32内核中,此参数被忽略。epoll_ctl函数用于管理文件描述符的事件集,使用此函数可以注册、修改、删除一个或多个事件。epoll_wait负责检测事件,这三个函数的详细描,请参阅epoll的man文档。
Java类sun.nio.ch.EPollSelectorImpl主要的功能都委托给sun.nio.ch. EPollArrayWrapper实现 (下文所引java代码反编译自linux版jdk_1.7.0_17/lib/rt.jar):

package sun.nio.ch;
class EPollArrayWrapper{
private native int epollCreate();
private native void epollCtl(int paramInt1, int paramInt2, int paramInt3, int paramInt4);
private native int epollWait(long paramLong1, int paramInt1, long paramLong2, int paramInt2) throws IOException;
}

EPollArrayWrapper的三个native方法的实现代码可参阅openjdk7/jdk/src/solaris/native/sun/nio/ch/ EPollArrayWrapper.c,可看到这三个native方法正是对上述epoll系列系统调用的包装。(其他jdk的实现代码会有所不同,但归根结底都是对epoll系列系统调用的包装)。
EPollSelectorImpl. implRegister方法(Selector.register方法的具体实现),通过调用epoll_ctl向epoll实例中注册事件:

protected void implRegister(SelectionKeyImpl paramSelectionKeyImpl) {
if (this.closed)
throw new ClosedSelectorException();
SelChImpl localSelChImpl = paramSelectionKeyImpl.channel;
this.fdToKey.put(Integer.valueOf(localSelChImpl.getFDVal()), paramSelectionKeyImpl);
this.pollWrapper.add(localSelChImpl);
this.keys.add(paramSelectionKeyImpl);
}

上述方法中,除了向epoll实例注册事件外,还将注册的文件描述符(fd)与SelectionKey的对应关系添加到fdToKey中,这个map维护了文件描述符与SelectionKey的映射。每当向Selector中注册一个Channel时,向此map中添加一条记录,而当Channel.close、SelectionKey.cancel方法调用时,则从fdToKey中移除与Channel的fd相关联的SelectionKey,具体代码在EPollSelectorImpl.implDereg方法中:

protected void implDereg(SelectionKeyImpl paramSelectionKeyImpl) throws IOException {
assert (paramSelectionKeyImpl.getIndex() >= 0);
SelChImpl localSelChImpl = paramSelectionKeyImpl.channel;
int i = localSelChImpl.getFDVal();
this.fdToKey.remove(Integer.valueOf(i));
this.pollWrapper.release(localSelChImpl);
paramSelectionKeyImpl.setIndex(-1);
this.keys.remove(paramSelectionKeyImpl);
this.selectedKeys.remove(paramSelectionKeyImpl);
deregister(paramSelectionKeyImpl);
SelectableChannel localSelectableChannel = paramSelectionKeyImpl.channel();
if ((!localSelectableChannel.isOpen()) && (!localSelectableChannel.isRegistered()))
((SelChImpl)localSelectableChannel).kill();
}

EPollSelectorImpl. doSelect(Selector.select方法的实现),则通过调用epoll_wait实现事件检测:

protected int doSelect(long paramLong)
throws IOException
{
if (this.closed)
throw new ClosedSelectorException();
processDeregisterQueue();
try {
begin();
this.pollWrapper.poll(paramLong);
} finally {
end();
}
processDeregisterQueue();
int i = updateSelectedKeys();
if (this.pollWrapper.interrupted())
{
this.pollWrapper.putEventOps(this.pollWrapper.interruptedIndex(), 0);
synchronized (this.interruptLock) {
this.pollWrapper.clearInterrupted();
IOUtil.drain(this.fd0);
this.interruptTriggered = false;
}
}
return i;
}

此方法的主要流程概括如下:
1. 通过epoll_wait调用(this.pollWrapper.poll)获取已就绪的文件描述符集合
2. 通过fdToKey查找文件描述符对应的SelectionKey,并更新之,更新SelectionKey的具体代码在EPollSelectorImpl .updateSelectedKeys中:

private int updateSelectedKeys()
{
int i = this.pollWrapper.updated;
int j = 0;
for (int k = 0; k < i; k++) { int m = this.pollWrapper.getDescriptor(k); SelectionKeyImpl localSelectionKeyImpl = (SelectionKeyImpl)this.fdToKey.get(Integer.valueOf(m)); if (localSelectionKeyImpl != null) { int n = this.pollWrapper.getEventOps(k); if (this.selectedKeys.contains(localSelectionKeyImpl)) { if (localSelectionKeyImpl.channel.translateAndSetReadyOps(n, localSelectionKeyImpl)) j++; } else { localSelectionKeyImpl.channel.translateAndSetReadyOps(n, localSelectionKeyImpl); if ((localSelectionKeyImpl.nioReadyOps() & localSelectionKeyImpl.nioInterestOps()) != 0) { this.selectedKeys.add(localSelectionKeyImpl); j++; } } } } return j; }

关于fdToKey,有几个问题:
一、为何fdToKey会变得非常大?由上述代码可知,fdToKey变得非常大的可能原因有2个:
1.注册到Selector上的Channel非常多,例如一个长连接服务器可能要同时维持数十万条连接;
2.过期或失效的Channel没有及时关闭,因而对应的记录会一直留在fdToKey中,时间久了就会越积越多;
二、为何fdToKey总是串行读取?fdToKey中记录的读取,是在select方法中进行的,而select方法一般而言总是单线程调用(Selector不是线程安全的)。
三、tcp发包堆积对导致fdToKey变大吗?一般而言不会,因为fdToKey只负责管理注册到Selector上的channel,与数据传输过程无关。当然,如果tcp发包堆积导致IO框架的空闲连接检测机制失效,无法及时检测并关闭空闲的连接,则有可能导致fdToKey变大。

下面聊一聊epoll系统调用的具体实现,它的实现代码在(linux-2.6.32.65)fs/eventpoll.c中(下文所引内核代码,由于较长,所以只贴出主流程,省略了错误处理及一些相对次要的细节如参数检查、并发控制等),先看epoll_create 系统调用的实现:
fs/eventpoll.c

SYSCALL_DEFINE1(epoll_create, int, size)
{
if (size <= 0) return -EINVAL; return sys_epoll_create1(0); }

SYSCALL_DEFINE1是一个宏,用于定义有一个参数的系统调用函数,上述宏展开后即成为:
int sys_epoll_create(int size)
这就是epoll_create系统调用的入口。至于为何要用宏而不是直接声明,主要是因为系统调用的参数个数、传参方式都有严格限制,最多六个参数, SYSCALL_DEFINE2 -SYSCALL_DEFINE6分别用来定义有2-6个参数的系统调用。由上述代码可知,epoll_create函数最终调用sys_epoll_create1实现具体功能,同时也可以看出size参数被忽略了。sys_epoll_create1的主要代码如下(省略了错误处理及一些次要的细节如参数检查等):
fs/eventpoll.c

SYSCALL_DEFINE1(epoll_create1, int, flags)
{
int error, fd;
struct eventpoll *ep = NULL;
struct file *file;
error = ep_alloc(&ep);
file = anon_inode_getfile("[eventpoll]", &eventpoll_fops, ep,
O_RDWR | (flags & O_CLOEXEC));
fd_install(fd, file);
ep->file = file;
return fd;
}

上述代码主要是分配一个struct eventpoll实例,并分配与此实例相关联的文件描述符,后续的epoll_ctl,epoll_wait调用通过此文件描述符引用此实例。struct eventpoll的结构如下:
fs/eventpoll.c

struct eventpoll {
spinlock_t lock;
struct mutex mtx;
wait_queue_head_t wq;
wait_queue_head_t poll_wait;
struct list_head rdllist;
struct rb_root rbr;
struct epitem *ovflist;
struct user_struct *user;
struct file *file;
int visited;
struct list_head visited_list_link;
}

上述数据结构的关键部分是:
1. 一个等待队列wq,epoll正是通过此等待队列实现的事件回调
2. 一个就绪列表rdllist,此列表以双链表的形式保存了已就绪的文件描述符
3. 一个红黑树rbr,用于保存已注册过的文件描述符,若重复注册相同的文件描述符,则会返回错误
等待队列是epoll系统调用的核心机制(不只是epoll,linux下事件的通知、回调等机制大都依赖于等待队列),在讲述epoll_ctl,epoll_wait的实现之前,先来看看等待队列。等待队列可以使一组进程/线程在等待某个事件时睡眠,当等待的事件发生时,内核会唤醒睡眠的进程/线程。注意,下文并不区分进程和线程,在linux下,进程和线程在调度这个意义下(调度就是指linux的进程调度,包括进程的切换、睡眠、唤醒等)并无差别。此机制可以类比java.lang.Object类的wait和notify/notifyAll方法,其中wait方法使线程睡眠,notify/notifyAll方法则唤醒睡眠的一个或全部线程。等待队列主要涉及两个数据结构:
include/linux/wait.h

struct __wait_queue_head {
spinlock_t lock;
list_head task_list;
};
struct __wait_queue {
unsigned int flags;
#define WQ_FLAG_EXCLUSIVE 0x01
void *private;
wait_queue_func_t func;
struct list_head task_list;
};

struct __wait_queue_head是队头结构,task_list 保存了添加到此队列上的元素,struct list_head是标准的linux双链表, 定义如下:
include/linux/list.h

struct list_head {
struct list_head *next, *prev;
};

注意,此结构既可以表示双链表的表头,也可以表示一个链表元素,且next,prev这两个指针可以指向任意数据结构。
struct __wait_queue是等待队列的元素结构,成员func是等待的进程被唤醒时执行的回调函数,其定义如下:
include/linux/wait.h

typedef int (*wait_queue_func_t)(wait_queue_t *wait, unsigned mode, int flags, void *key);

struct __wait_queue的成员task_list是一个链表元素用于将此结构放置到struct __wait_queue_head中(这和此结构的task_list成员含义是不同的,此成员的含义为双链表的头),private成员一般指向等待进程的task_struct实例(该结构成员很多,在此就不贴出了,只需要知道linux下每个进程都对应一个task_struct 实例)。
在使用上,等待队列主要涉及以下函数(或者宏):
include/linux/wait.h
__add_wait_queue(wait_queue_head_t *q, wait_queue_t *wait);
#define wait_event(wq, condition)
#define wake_up_xxx(x,…)
__add_wait_queue用于将一个进程添加到等待队列,wait_event是一个宏,它用于等待一个事件,当事件未发生时使等待的进程休眠,wake_up_xxx是一系列的宏,包括wake_up,wake_up_all,wake_up_locked,wake_up_interruptible等,负责唤醒休眠在某个事件上的一个或一组进程。关于等待队列的具体实现细节,由于牵涉较广(涉及到进程调度、中断处理等),这里不再详述,可以将add_wait_queue,wait_event类比java.lang.Object的wait方法,而wake_up则可以类比java.lang.Object的notify/notifyAll方法。
介绍完等待队列后,就可以进一步研究epoll_ctl的实现了,其代码实现中核心的部分是:
fs/eventpoll.c

SYSCALL_DEFINE4(epoll_ctl, int, epfd, int, op, int, fd,
struct epoll_event __user *, event)
{
if (!tfile->f_op || !tfile->f_op->poll)
goto error_tgt_fput;
switch (op) {
case EPOLL_CTL_ADD:
error=ep_insert(ep, &epds, tfile, fd);
break;
case EPOLL_CTL_DEL:
error=ep_remove(ep, epi);
break;
case EPOLL_CTL_MOD:
error = ep_modify(ep, epi, &epds);
break;
}
return error;
}

什么样的文件描述符可以注册?从那个if判断可以看出,只有文件描述符对应的文件实现了poll方法的才可以,一般而言,字符设备的文件都实现了此方法,网络相关的套接字也实现了此方法,而块设备文件例如ext2/ext3/ext4文件系统文件,都没有实现此方法。实现了poll方法的文件,对应于java NIO的java.nio.channels.SelectableChannel,这也是为何只有 SelectableChannel 才能注册到Selector上的原因。ep_insert,ep_remove,ep_modify分别对应事件的注册、删除、修改,我们以ep_insert为例,看一下事件注册的过程,其关键代码如下:
fs/eventpoll.c

static int ep_insert(struct eventpoll *ep, struct epoll_event *event,
struct file *tfile, int fd)
{
init_poll_funcptr(&epq.pt, ep_ptable_queue_proc);
revents = tfile->f_op->poll(tfile, &epq.pt);
ep_rbtree_insert(ep, epi);
if ((revents & event->events) && !ep_is_linked(&epi->rdllink)) {
list_add_tail(&epi->rdllink, &ep->rdllist);;
wake_up_locked(&ep->wq);
}
}

上述代码的主要做的事是:
1. 绑定等待队列的回调函数ep_ptable_queue_proc
2. 调用对应文件的实例的poll方法,此方法的具体实现差别非常大,但绝大多数都会调用wait_event相关方法,在没有事件发生时,使进程睡眠,例如socket对应的实现(代码在net/ipv4/af_inet.c的tcp_poll方法,在此不再详述);
3. 若注册的事件已经发生,则将已就绪的文件描述符插入到eventpoll实例的就绪列表(list_add_tail(&epi->rdllink, &ep->rdllist);),并唤醒睡眠的进程(wake_up_locked(&ep->wq))
第1步绑定的回调函数ep_ptable_queue_proc,会在等待的事件发生时执行,其主要功能是将就绪的文件描述符插入到eventpoll实例的就绪列表(具体是通过ep_ptable_queue_proc绑定的另一个回调函数ep_poll_callback实现的):
fs/eventpoll.c

static int ep_poll_callback(wait_queue_t *wait, unsigned mode, int sync, void *key){
if (!ep_is_linked(&epi->rdllink))
list_add_tail(&epi->rdllink, &ep->rdllist);
}

最后看epoll_wait的实现,有了就绪队列,epoll_wait的实现就比较简单了,只需检查就绪队列是否为空,若为空,则在必要时睡眠或等待:
fs/eventpoll.c

SYSCALL_DEFINE4(epoll_wait, int, epfd, struct epoll_event __user *, events,
int, maxevents, int, timeout)
{
int error;
struct file *file;
struct eventpoll *ep;
file = fget(epfd);
ep = file->private_data;
error = ep_poll(ep, events, maxevents, timeout);
return error;
}

此函数最终调用ep_poll完成其主要功能:

static int ep_poll(struct eventpoll *ep, struct epoll_event __user *events,
int maxevents, long timeout)
{
retry:
if (list_empty(&ep->rdllist)) {
init_waitqueue_entry(&wait, current);
wait.flags |= WQ_FLAG_EXCLUSIVE;
__add_wait_queue(&ep->wq, &wait);

for (;;) {
set_current_state(TASK_INTERRUPTIBLE);
if (!list_empty(&ep->rdllist) || !jtimeout)
break;
if (signal_pending(current)) {
res = -EINTR;
break;
}

spin_unlock_irqrestore(&ep->lock, flags);
jtimeout = schedule_timeout(jtimeout);
spin_lock_irqsave(&ep->lock, flags);
}
__remove_wait_queue(&ep->wq, &wait);

set_current_state(TASK_RUNNING);
}
eavail = !list_empty(&ep->rdllist) || ep->ovflist != EP_UNACTIVE_PTR;

spin_unlock_irqrestore(&ep->lock, flags);
if (!res && eavail &&
!(res = ep_send_events(ep, events, maxevents)) && jtimeout)
goto retry;

return res;
}

上述代码主要是检查就绪队列是否为空,若为空时,则根据超时设置判断是否需要睡眠(__add_wait_queue)或等待(jtimeout = schedule_timeout(jtimeout);)。

综上所述,epoll系统调用通过等待队列,其事件检测(epoll_wait系统调用)的时间复杂度为O(n),其中n是“活跃”的文件描述符总数,所谓的活跃,是指在该文件描述符上有频繁的读写操作,而对比poll或select系统调用(其实现代码在fs/select.c中),其时间复杂度也是O(n),但这个n却是注册的文件描述符的总数。因此,当活跃的文件描述符占总的文件描述符比例较小时,例如,在长连接服务器的场景中,虽然同时可能需要维持数十万条长连接,但其中只有少数的连接是活跃的,使用epoll就比较合适。

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

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

探讨下DevOPS

技术界一直就是新名词不断的风格,DevOPS这个词话说出来也挺长时间了,一直以来对这个不算太明白,以为就是指OPS应该不仅仅做OPS的工作,而是应该同时承担起开发自己OPS工作的系统,注意指的是系统,而不是脚本,因为很多的OPS操作是一个流程式的多步骤组成,并且多集群,多系统的交互,这个时候用脚本去实现是会比较难的,而且还要处理诸多的异常等,系统是一个工程性的东西,不仅仅是功能的实现,还要考虑很多异常、稳定性等的问题,但最近的一些思考,让自己对DevOPS有了更多的看法。

OPS去承担起开发自己OPS工作的系统这个比较容易理解,最大的原因在于自己的痛其实只有自己最清楚,很多家公司估计都尝试过让一个专职的团队来开发OPS用的系统,结果就是专职的这个团队和OPS团队挺容易引发争执,然后系统也通常不能很好的解决问题,而一旦转变为OPS自己来做系统给自己用,那问题被解决的可能性会大幅提高,而且有不少公司确实也是OPS采用OnCall轮转的机制,Oncall的时候专心干OPS的活,不OnCall的同学则专心写系统解决自己之前OnCall的时候手工干的活,不过这种方式下比较容易碰到的一个问题可能是写出来的系统的质量不够理想,例如对于运维系统来说,在成功率的要求上会远比在线系统高,但在性能、并发这两点上会远比在线系统低。

除了上面这个点外,运维团队通常还很容易碰到的一个问题是研发交付的系统可运维性不太好,这种时候通常只能是纯操作方面的事运维先人肉顶着,但碰到一些故障的时候,如果系统可运维性比较差,会导致排查过程极度复杂,耗时长,而在有研发和运维这两个独立岗位的时候,这种现象很容易导致的结果就是运维在苦逼的处理一堆的这样的事情,研发呢反正也不是很能感受到这样的痛(因为一个研发可能就负责一两个系统的开发,但一个运维通常可能负责几十个甚至更多系统的运维工作),于是也不是很在乎,最终导致很容易出现的现象就是运维推着研发做很多可运维性的改造,无论是运维体系标准的建设,监控体系标准的建设等,但这个推动通常其实不会那么容易,最重要的原因我自己觉得主要是体感的问题。

所以我现在理解中的DevOPS,我觉得是消除OPS这个独立岗位,让研发和运维合并成同一岗位,研发系统的团队轮值安排OnCall,这样会让研发系统的同学深刻感受到系统设计不靠谱的时候给运维阶段带来的痛苦,从而把本来就应该在设计阶段考虑的可运维性考虑进去,同时也避免了两个团队带来的协调成本等,并且对于研发而言,由于“偷懒”的特性,很容易就会去打造系统来解决手工干的活,站在这样的角度,我觉得就很容易理解为什么叫DevOPS,而不是OPSDev。

大家也可以探讨下你所感受到的运维是怎么样,你觉得变成什么样是比较不错的。

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

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

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

从一个故障说说Java的三个BlockingQueue

最近出了个故障,排查的时候耗费了很长的时间,回顾整个排查过程,经验主义在这里起了不好的作用,直接导致了整个故障排查的时间非常长,这个故障的根本原因在于BlockingQueue用的有问题,顺带展开说说Java中常用的几个BlockingQueue:ArrayBlockingQueue、LinkedBlockingQueue和SynchronousQueue。

当时故障的现象是应用处理请求的线程池满了,导致请求处理不了,于是dump线程,看线程都在做什么,结果发现线程都Block在写日志的地方,以前出现过很多次问题,去线程dump的时候看到也是一堆的block在写日志,但通常是别的原因引发的,所以这次也是按照这样的经验,认为肯定不会是写日志这个地方的问题,于是各种排查…折腾了N久后,回过头看发现持有那把日志锁的地方是自己人写的代码,那段代码在拿到了这个日志锁后,从线程堆栈上看,block在了ArrayBlockingQueue.put这个地方,于是翻看这段代码,结果发现这是个1024长度的BlockingQueue,那就意味着如果这个Queue被放了1024个对象的话,put就一定会被block住,而且其实翻代码的时候能看出写代码的同学是考虑到了BlockingQueue如果满了应该要处理的,代码里写着:

if (blockingQueue.remainingCapacity() < 1) { //todo } blockingQueue.put

这里两个悲催的问题,一是这个if判断完还是直接会走到put,而不是else,二是竟然关键的满了后的处理逻辑还在//todo...
另外我觉得这段代码还反应了同学对BlockingQueue的接口不太熟,要达到这个效果,不需要这样先去判断,更合适的做法是用blockingQueue.offer,返回false再做相应的异常处理。

BlockingQueue是在生产/消费者模式下经常会用到的数据结构,通常常用的主要会是ArrayBlockingQueue、LinkedBlockingQueue和SynchronousQueue。

ArrayBlockingQeue/LinkedBlockingQueue两者的最大不同主要在于存放Queue中对象方式,一个是数组,一个是链表,代码注释里也写到了两者的不同:
Linked queues typically have higher throughput than array-based queues but less predictable performance in most concurrent applications.

SynchronousQueue是一个非常特殊的BlockingQueue,它的模式是在offer的时候,如果没有另外一个线程正在take或poll的话,那么offer就会失败;在take的时候,如果没有另外的线程正好并发在offer,也会失败,这种特殊的模式非常适合用来做要求高响应并且线程出不固定的线程池的Queue。

对于在线业务场景而言,所有的并发,外部访问阻塞的地方的一个真理就是一定要有超时机制,我不知道见过多少次由于没有超时造成的在线业务的严重故障,在线业务最强调的是快速处理掉一次请求,所以fail fast是在线业务系统设计,代码编写中的最重要原则,按照这个原则上面的代码最起码明显犯的错误就是用put而不是带超时机制的offer,或者说如果是不重要的场景,完全就应该直接用offer,false了直接抛异常或记录下异常即可。

对于BlockingQueue这种场景呢,除了超时机制外,还有一个是队列长度一定要做限制,否则默认的是Integer.MAX_VALUE,万一代码出点bug的话,内存就被玩挂了。

说到BlockingQueue,就还是要提下BlockingQueue被用的最多的地方:线程池,Java的ThreadPoolExecutor中有个参数是BlockingQueue,如果这个地方用的是ArrayBlockingQueue或LinkedBlockingQueue,而线程池的coreSize和poolSize不一样的话,在coreSize线程满了后,这个时候线程池首先会做的是offer到BlockingQueue,成功的话就结束,这种场景同样不符合在线业务的需求,在线业务更希望的是快速处理,而不是先排队,而且其实在线业务最好是不要让请求堆在排队队列里,在线业务这样做很容易引发雪崩,超出处理能力范围直接拒绝抛错是相对比较好的做法,至于在前面页面上排队什么这个是可以的,那是另外一种限流机制。

所以说在写高并发、分布式的代码时,除了系统设计外,代码细节的功力是非常非常重要的。

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

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

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

深入JVM彻底剖析前面ygc越来越慢的case

阿里JVM团队的同学帮助从JVM层面继续深入的剖析了下前面那个ygc越来越慢的case,分析文章相当的赞,思路清晰,工具熟练,JVM代码熟练,请看这位同学(阿里JVM团队:寒泉子)写的文章,我转载到这。

Demo分析
虽然这个demo代码逻辑很简单,但是其实这是一个特殊的demo,并不简单,如果我们将XStream对象换成Object对象,会发现不存在这个问题,既然如此那有必要进去看看这个XStream的构造函数(请大家直接翻XStream的代码,这里就不贴了)。

这个构造函数还是很复杂的,里面会创建很多的对象,上面还有一些方法实现我就不贴了,总之都是在不断构建各种大大小小的对象,一个XStream对象构建出来的时候大概好像有12M的样子。

那到底是哪些对象会导致ygc不断增长呢,于是可能想到逐步替换上面这些逻辑,比如将最后一个构造函数里的那些逻辑都禁掉,然后我们再跑测试看看还会不会让ygc不断恶化,最终我们会发现,如果我们直接使用如下构造函数构造对象时,如果传入的classloader是AppClassLoader,那会发现这个问题不再出现了,代码如下:

[java]
public static void main(String[] args) throws Exception {
int i=0;
while (true) {
XStream xs = new XStream(null,null, new ClassLoaderReference(XStreamTest.class.getClassLoader()),null, new DefaultConverterLookup());
xs.toString();
xs=null;
}
}
[/java]

是不是觉得很神奇,由此可见,这个classloader至关重要。

不得不说的类加载器
这里着重要说的两个概念是初始类加载器和定义类加载器。举个栗子说吧,AClassLoader->BClassLoader->CClassLoader,表示AClassLoader在加载类的时候会委托BClassLoader类加载器来加载,BClassLoader加载类的时候会委托CClassLoader来加载,假如我们使用AClassLoader来加载X这个类,而X这个类最终是被CClassLoader来加载的,那么我们称CClassLoader为X类的定义类加载器,而AClassLoader和BClassLoader分别为X类的初始类加载器,JVM在加载某个类的时候对这三种类加载器都会记录,记录的数据结构是一个叫做SystemDictionary的hashtable,其key是根据ClassLoader对象和类名算出来的hash值,而value是真正的由定义类加载器加载的Klass对象,因为初始类加载器和定义类加载器是不同的classloader,因此算出来的hash值也是不同的,因此在SystemDictionary里会有多项值的value都是指向同一个Klass对象。

那么JVM为什么要分这两种类加载器呢,其实主要是为了快速找到已经加载的类,比如我们已经通过AClassLoader来触发了对X类的加载,当我们再次使用AClassLoader这个类加载器来加载X这个类的时候就不需要再委托给BClassLoader去找了,因为加载过的类在JVM里有这个类加载器的直接加载的记录,只需要直接返回对应的Klass对象即可。

Demo中的类加载器是否会加载类
我们的demo里发现构建了一个CompositeClassLoader的类加载器,那到底有没有用这个类加载器加载类呢,我们可以设置一个断点在CompositeClassLoader的loadClass方法上,可以看到会进入断点。
可见确实有类加载的动作,根据类加载委托机制,在这个Demo中我们能肯定类是交给AppClassLoader来加载的,这样一来CompositeClassLoader就变成了初始类加载器,而AppClassLoader会是定义类加载器,都会在SystemDictionary里存在,因此当我们不断new XStream的时候会不断new CompositeClassLoader对象,加载类的时候会不断往SystemDictionary里插入记录,从而使SystemDictionary越来越膨胀,那自然而然会想到如果GC过程不断去扫描这个SystemDictionary的话,那随着SystemDictionary不断膨胀,那么GC的效率也就越低,抱着验证下猜想的方式我们可以使用perf工具来看看,如果发现cpu占比排前的函数如果都是操作SystemDictionary的,那就基本验证了我们的说法,下面是perf工具的截图,基本证实了这一点。
perf

SystemDictionary为什么会影响GC过程
想象一下这么个情况,我们加载了一个类,然后构建了一个对象(这个对象在eden里构建)当一个属性设置到这个类里,如果gc发生的时候,这个对象是不是要被找出来标活才行,那么自然而然我们加载的类肯定是我们一项重要的gc root,这样SystemDictionary就成为了gc过程中的被扫描对象了,事实也是如此,可以看vm的具体代码(代码在:SharedHeap::process_strong_roots,感兴趣的同学可以直接翻这部分代码)。

看上面的SH_PS_SystemDictionary_oops_do task就知道了,这个就是对SystemDictionary进行扫描。

但是这里要说的是虽然有对SystemDictionary进行扫描,但是ygc的过程并不会对SystemDictionary进行处理,如果要对它进行处理需要开启类卸载的vm参数,CMS算法下,CMS GC和Full GC在开启CMSClassUnloadingEnabled的情况下是可能对类做卸载动作的,此时会对SystemDictionary进行清理,所以当我们在跑上面demo的时候,通过jmap -dump:live,format=b,file=heap.bin 命令执行完之后,ygc的时间瞬间降下来了,不过又会慢慢回去,这是因为jmap的这个命令会做一次gc,这个gc过程会对SystemDictionary进行清理。

修改VM代码验证
很遗憾hotspot目前没有对ygc的每个task做一个时间的统计,因此无法直接知道是不是SH_PS_SystemDictionary_oops_do这个task导致了ygc的时间变长,为了证明这个结论,我特地修改了一下代码,在上面的代码上加了一行:
GCTraceTime t(“SystemDictionary_OOPS_DO”,PrintGCDetails,true,NULL);
然后重新编译,跑我们的demo,测试结果如下:
2016-03-14T23:57:24.293+0800: [GC2016-03-14T23:57:24.294+0800: [ParNew2016-03-14T23:57:24.296+0800: [SystemDictionary_OOPS_DO, 0.0578430 secs]
: 81920K->3184K(92160K), 0.0889740 secs] 81920K->3184K(514048K), 0.0900970 secs] [Times: user=0.27 sys=0.00, real=0.09 secs]
2016-03-14T23:57:28.467+0800: [GC2016-03-14T23:57:28.468+0800: [ParNew2016-03-14T23:57:28.468+0800: [SystemDictionary_OOPS_DO, 0.0779210 secs]
: 85104K->5175K(92160K), 0.1071520 secs] 85104K->5175K(514048K), 0.1080490 secs] [Times: user=0.65 sys=0.00, real=0.11 secs]
2016-03-14T23:57:32.984+0800: [GC2016-03-14T23:57:32.984+0800: [ParNew2016-03-14T23:57:32.984+0800: [SystemDictionary_OOPS_DO, 0.1075680 secs]
: 87095K->8188K(92160K), 0.1434270 secs] 87095K->8188K(514048K), 0.1439870 secs] [Times: user=0.90 sys=0.01, real=0.14 secs]
2016-03-14T23:57:37.900+0800: [GC2016-03-14T23:57:37.900+0800: [ParNew2016-03-14T23:57:37.901+0800: [SystemDictionary_OOPS_DO, 0.1745390 secs]
: 90108K->7093K(92160K), 0.2876260 secs] 90108K->9992K(514048K), 0.2884150 secs] [Times: user=1.44 sys=0.02, real=0.29 secs]

我们会发现YGC的时间变长的时候,SystemDictionary_OOPS_DO的时间也会相应变长多少,因此验证了我们的说法。

有同学提到如果Demo代码改成不new XStream,而是直接new CompositeClassLoader或CustomClassLoader则不会出问题,按照上面的分析也很容易解释,就是因为如果直接new CustomClassLoader的话,并没触发loadClass这动作,而new XStream的话在构造器里就在loadClass。

有同学提到在JDK 8中跑这个case不会出现问题,原因是:jdk8在对SystemDictionary扫描时做了优化,增加了一层cache,大大减少了需要扫描的入口数。

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

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

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

上篇文章中ygc越来越慢的case的原因解读

上篇文章中附加了一个最近碰到的奇怪的case,有位同学看到这个后周末时间折腾了下,把原因给分析出来了,分析过程很赞,非常感谢这位同学(阿里的一位同事,花名叫彦贝),在征求他的同意后,我把他写的整个问题的分析文章转载到这里。

    上分析工具VisualVM

在解决很多问题的时候,工具起的作用往往是巨大,很多时候通过工具分析,很快便能找到原因,但是这次并没有,下图是VisualVM观察到Heap上的GC图表。
visualvm

从图标中可以看出,Perm区空间基本水平,但是Old区空间成增长态势与YGCT时间增长的倍率基本一直。熟悉YGC的朋友都知道YGC主要分为标记和收回两个阶段,YGCT也是基于这2个阶段统计的。由于每次回收的空间大小差不多,所以怀疑是标记阶段使用的时间比较长,下面回顾一下JVM的垃圾标记方式。

    JVM垃圾回收的标记方法-枚举根节点

在Java语言里面,可作为GC Roots的节点主要在全局性的引用(例如常量或类静态属性)与执行上下文(例如栈帧中的本地变量表)中。如果要使用可达性分析来判断内存是否可回收的,那分析工作必须在一个能保障一致性的快照中进行——这里“一致性”的意思是整个分析期间整个执行系统看起来就像被冻结在某个时间点上,不可以出现分析过程中,对象引用关系还在不断变化的情况,这点不满足的话分析结果准确性就无法保证。这点也是导致GC进行时必须“Stop The World”的其中一个重要原因,即使是号称(几乎)不会发生停顿的CMS收集器中,枚举根节点时也是必须要停顿的。

由于目前的主流JVM使用的都是准确式GC,所以当执行系统停顿下来之后,并不需要一个不漏地检查完所有执行上下文和全局的引用位置,虚拟机应当是有办法直接得到哪些地方存放着对象引用。在HotSpot的实现中,是使用一组成为OopMap的数据结构来达到这个目的,在类加载完成的时候,HotSpot就把对象内什么偏移量上是什么类型的数据计算出来,在JIT编译过程中,也会在特定的位置记录下栈里和寄存器里哪些位置是引用。这样GC在扫描时就就可以直接得知这些信息了。
上面这段引用自《深入理解Java虚拟机》,用个图简单表示一下,当然图也是源于书中:
gcrootset

基于对GC Roots的怀疑,猜测Old区中存在越来越多的gc root节点,那什么样的对象是root节点呢?不懂的我赶紧google了一下。
gcroots

(不要看我红色圈出来了,第一次看到这几个嫌疑犯时我也拿不准是哪个)

为了进一步验证是Old区的GC Roots造成YGCT 增加的,我们来做一次full gc,干掉Old区。代码如下:

public class SlowYGC {
public static void main(String[] args) throws Exception {
int i= 0;
while (true) {
XStream xs = new XStream();
xs.toString();
xs = null;
if(i++ % 10000 == 0)
{
System.gc();
}
}
}
}

可以看出Full GC后 YGCT锐减到初始状态。那是Full GC到底回收了哪些对象?进入到下一步,增加VM参数。

增加VM参数
为了看到Full GC前后对象的回收情况,我们增加下面2个VM参数
-XX:+PrintClassHistogramBeforeFullGC -XX:+PrintClassHistogramAfterFullGC。
重新运行上面的代码,可以观察到下面的日志:
vmlog

上图左边是FGC前的对象情况,右边是FGC后的情况,结合我之前给出的GC Root候选人中的Monitor锁,相信你很快就找到20026个[Ljava.util.concurrent.ConcurrentHashMap$Segment对象几乎被全部回收了,ConcurrentHashMap中正是通过Segment来实现分段锁的。那什么逻辑会导致出现大量的Segment锁对象。继续看Full GC日志com.thoughtworks.xstream.core.util.CompositeClassLoader这个对象也差不多在FGC的时候全军覆没,所以怀疑是ClassLoader引起的锁竞争,下面在ClassLoader的源码中继续查找。

ClassLoader中的ConcurrentHashMap
classloader

这里有个拿锁的动作,跟进去看看呗。
parallelLockMap

为了验证走到这块逻辑下了一个断点。剩下的就是putIfAbsent方法(这里就不详细分析实现了)有兴趣的同学可以看看源码中CAS和tryLock的使用。
至此基本分析和定位出了YGCT原因,在去看看Xstream的构造函数。
xstream
可以看出每次new XstreamI()的同时会new一个新的ClassLoader,基本上证明了上述怀疑和猜测。

推导一下按照上述分析,应该是所有自定义的ClassLoader都会YGCT变长的时间问题,于是手写一个ClassLoader验证一下。Java代码如下:

public class TestClassLoader4YGCT {
public static void main(String[] args) throws Exception{
while(true)
{
Object obj = newObject();
obj.toString();
obj = null;
}
}

private static Object newObject() throws Exception
{
ClassLoader classLoader = new ClassLoader() {
@Override
public Class loadClass(String s) throws ClassNotFoundException {
try{
String fileName = s.substring(s.lastIndexOf(“.”) + 1)+ “.class”;
InputStream inputStream = getClass().getResourceAsStream(fileName);
if(inputStream == null){
return super.loadClass(s);
}
byte[] b = new byte[inputStream.available()];
inputStream.read(b);
return defineClass(s,b,0,b.length);
}catch (Exception e)
{
System.out.println(e);
return null;
}
}
};
Class obj = classLoader.loadClass(“jvmstudy.classload.TestClassLoader4YGCT”);
return obj.newInstance();
}
}
VM 参数-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xms512m -Xmx512m -Xmn100m -XX:+UseConcMarkSweepGC

GC日志
lastgclog

结论
当大量new自定义的ClassLoader来加载时,会产生大量ClassLoader对象以及parallelLockMap(ConcurrentHashMap)对象,导致产生大量的Segment分段锁对象,大大增加了GC Roots的数量,导致YGC中的标记时间变长。如果能直接看到YGCT的详细使用情况,这个结论会显得更加严谨。这只是我自己的一个推导,并不一定是正确答案。

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

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

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

一个jstack/jmap等不能用的case

今天一个同学问我:”我排查问题时总是遇到,jmap -heap或-histo 不能用,是不是我们机器配置有啥问题哇? ” 分享下这个case的解决过程。

登上同学说的那台不能用的机器,执行jstack,报错:“get_thread_regs failed for a lwp”,这个问题以前碰到过,但忘了当时是什么原因了,执行其他的jmap -histo什么也卡着不动。

既然jstack没法弄,就pstack看看进程到底什么状况吧,于是pstack [pid]看,发现有一个线程的堆栈信息有点奇怪:
#0 0x00000038e720cd91 in sem_wait ()

对系统函数不太懂,但总觉得sem_wait这个有点奇怪,于是Google之,基本明白了这个是由于进程在等信号,这个时候通常会block住其他所有的线程,于是立刻ps看了下进程的状态,果然进程的状态变成了T,那上面碰到的所有现象都很容易解释了,于是执行:kill -CONT [pid],一切恢复正常。

继续查为什么进程状态会变成T,问问题的同学告诉了下我他在机器上执行过的一些命令,我看到其中一个很熟悉的命令:jmap -heap,看过我之前文章的同学估计会记得我很早以前分享过,在用cms gc的情况下,执行jmap -heap有些时候会导致进程变T,因此强烈建议别执行这个命令,如果想获取内存目前每个区域的使用状况,可通过jstat -gc或jstat -gccapacity来拿到。

到此为止,问题终于搞定,以后碰到jstack/jmap等不能用的时候,可以先看看进程的状态,因此还是那句话,执行任何一句命令都要清楚它带来的影响。

手头还有另外一个case,折腾了一个多星期了还是没太有头绪,case的现象是ygc越来越慢,但可以肯定不是由于cms gc碎片问题造成的,感兴趣的同学可以拿这个case去玩玩,如果能告诉我原因就更好了,:),执行下面的代码,启动参数可以为-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xms512m -Xmx512m -Xmn100m -XX:+UseConcMarkSweepGC:
[code]
import com.thoughtworks.xstream.XStream;

public class XStreamTest {

public static void main(String[] args) throws Exception {
while(true){
XStream xs = new XStream();
xs.toString();
xs = null;
}
}

}
[/code]

应该就可以看到ygc的速度从10+ms一直增长到100+ms之类的…

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

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

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

GC压垮了最后一根稻草

long time no see,:), 各种原因下导致了这么久没更新,准备再次捡起来了,先分享下最近碰到的一个case。

这个case的现象是:
整个集群fgc严重,导致无法为用户提供服务。

原因分析:
从现象来看,应该是个相当简单的类似内存泄露的问题,模式化的开始了OOM问题排查的过程。

拿到fgc严重时的heap dump进行分析,heap dump显示确实java heap基本被用满了,继续看Dominator tree,惊讶的发现排第一的才占了7%的内存;
切换到leakage的视图看,发现有一类型的类占据了超过40%的内存,用GC root跟是什么地方在引用这些类,看到的是很多的http线程在持有这些类的引用;
为什么这么多的http线程持有这些类的引用又不释放呢,需要看下这些线程都在做什么,于是切换到thread视图,发现这些http线程中除了一个在run,其他的都在等一把锁,run的那个线程持有了这把锁,继续看run的那个线程那行代码在做什么,发现那是个极为简单的动作,完全不可能运行很久,这样的现象说明是由于某些原因导致这个run的线程一直获取不到cpu资源;
翻查当时机器的状况,系统的状况是正常的,但Java应用一直在fgc,连续频繁的fgc导致了上面的那些线程压根就没有执行的机会,在这种情况下这个应用其实已经不可能恢复了。

上面分析了那么多,唯一能得到的结论就是应用本身没有内存泄露,但到底是什么原因触发了应用频繁fgc呢,继续翻查应用的gc log,发现有个现象是在频繁fgc之前cms gc的频率越来越近,并且每次回收后存活的空间占用的越来越大,造成这样的现象是应用的qps增高了太多,或者reponse time(rt)慢了很多造成的,查看应用的qps没什么变化,但应用的rt在cms gc频率变短前有些许的增长,这样基本能解释通:
应用rt增高,导致在cms gc执行的周期内存活的对象增多,于是cms gc频率开始缩短;
而cms gc频率缩短,又进一步导致了rt增高,开始形成了恶性循环。
因此说明这个应用在目前的机器数和qps下其实已经到达瓶颈了,稍微的rt或qps的波动都有可能导致整集群崩盘。

在这个结的情况下问题是没法解决的,要解决这个问题只能是提升应用的性能或扩容机器。

case带来的思考:
这种case其实挺折腾的,在以前讲线程池大小的帖子里也写过一次,就是线程池的最大值开的太大的话,看起来是能接更多的请求(如果cpu处理不是瓶颈的话),但不幸的是通常也会导致存活的对象增多,有可能触发gc,而gc的频繁介入很容易导致恶化的现象。

要预防这种case的另外一个更好的做法还是保持一定频率压测获得应用的单机qps能力,并做相应的限流,确保整体qps达到一定的水位后就扩容。

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

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

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