BlueDavy之技术Blog

Java内存管理问题案例分享

bluedavy — Fri, 16 Mar 2012 17:40:03 +0800

在这个slide中分享了Java内存管理常见的三类问题（OOM、Full GC频繁、CMS GC Promotion failed || Concurrent mode failure）的case，以及通常的解决方法。

Java内存管理问题案例分享

迁户口实录(深圳集体户到杭州个户)

bluedavy — Fri, 09 Mar 2012 09:53:00 +0800

迁户口这件事对于中国人而言，在一辈子中总是会发生那么几次的，但由于现在在迁户口的流程方面缺失透明性，往往会导致在这个过程中要折腾很多次才能办好，此篇blog记录了我的迁户口过程，整个过程从2011年12月19日折腾到2012年3月9日才办好，中途很多次折腾都是因为对过程需要提交的材料准备不足造成的，希望能给需要迁户口的同学们一点点帮助。

不同地方、不同关系的情况下，迁户口的手续会有不同，因此必须先介绍下我迁户口的一些相关背景材料：
1、性别：男；
2、原户口托管在深圳市人才大市场，集体户；
3、计划将户口迁入杭州市余杭区，落户地为自己的房子所在地；
4、已结婚，还没有生小孩。
如果你的背景材料（例如性别为女，或是投靠等）和我的不一样，本blog讲述的过程以及所需材料并不一定适合你。

#迁户口第一步：落户地所在社区开未婚未育调查函
1.说明
此调查函的作用是用来证明你在原户口所在地的时候没有结婚，也没有生小孩，主要是用来避免违法计划生育政策的。
2.需要出示的材料
为了顺利的开出这个调查函，请准备这些材料：
自己的身份证、户口本、女方的身份证、户口本、结婚证、如已怀孕再出示准生证。
另外一个前提是，你已经在社区登记过，例如有些社区会要求要住满一年以上才能迁。
有上面的材料的情况下，基本可以比较顺利的拿到社区开具的一张未婚未育的调查函，这张调查函需要给原户口所在地的社区填写并盖章。
3.吐槽
有两点特别要吐槽，一是需要户口本，自己跑深圳的话肯定不划算，只能把身份证先寄给深圳，委托别人帮忙去人才大市场把户口借出来，再寄到杭州，后面还要这样折腾N次；二是明明有结婚证、准生证了，竟然还要原户口所在地来证明是未婚未育，这太扯了，而且更扯的是，原户口所在地也无法证明你当时是未婚未育的，必须自己提供结婚证、准生证来证明。

#迁户口第二步：原户口所在地的社区盖未婚未育调查函的章
1.说明
就是为了证明你在原户口所在地的期间是没有结婚和没生过小孩的。
2.需要出示的材料
为了顺利的盖上这个章，请准备这些材料：
自己的身份证、户口本、女方的身份证、户口本（以及户口本的首页）、结婚证、如已怀孕再出示准生证、现所在单位的初婚未育证明。
有这些材料后，基本能比较顺利的盖到这个章。
3.吐槽
当时没有想到竟然还要出示女方的身份证、户口本（以及户口本的首页），于是中途又快递了一次，哎。

#迁户口第三步：落户所在地社区开准迁证明
1.说明
这个证明是为了告诉派出所，社区是允许这个人迁入的。
2.需要出示的材料
继续出示第一步中的所有资料，再加上已经盖了章的未婚未育调查函，基本可以顺利开好这个准迁证明。
3.吐槽
这步还好，就不吐槽了。

#迁户口第四步：落户所在地派出所办理准迁证
1.说明
这步就是为了拿到准迁证了，用来证明这边派出所是准许这个人迁入的。
2.需要出示的材料
因为是迁到自己房子的所在地，需要出示：
房子的三证、社区的准迁证明、本人的身份证、户口本。
提交了这些材料后，就可以干等了，我落户的所在地的派出所这步需要30个工作日，不过后来大概是30个自然日就拿到了准迁证。
3.吐槽
这步没什么吐槽的，有个值得表扬的是当准迁证可以领了，会短信通知，这还稍微人性化点了。

#迁户口第五步：原户口所在地派出所办理户口迁移证
1.说明
这步是为了说明你的户口已经从原户口所在地迁出了。
2.需要出示的材料
准迁证、委托公证书（如果是委托别人办）、本人身份证、户口本。
提交了这些材料后，基本可以顺利的拿到户口迁移证。
3.吐槽
这步的时候没想到要委托公证书，办委托公证书可以到杭州的任何一个公证处，需要出示本人身份证、户口本、受托人的身份证复印件，200元RMB，于是我又快递折腾了一次，哎。

#迁户口第六步：落户所在地派出所落户
1.说明
到达终点了，申报户口。
2.需要出示的材料
一寸照、房产证、本人身份证、已注销的原户口本、准迁证、户口迁移证、之前社区开的准迁证明。
提交了这些材料后，基本当场就可以拿到户口本了，然后可以办新的身份证。
3.吐槽
这步没什么吐槽的，非常顺利。

Java应用运维

bluedavy — Sun, 29 Jan 2012 11:34:33 +0800

对于互联网产品或长期运行的产品而言，运维工作非常重要，尤其是在产品复杂了以后，在这篇blog中就来说下Java应用的运维工作（ps：虽然看起来各种语言做的系统的运维工作都差不多，但细节上还是会有很多不同，so本文还是只讲Java的）。

苦逼的码农按照需求开发好了一个全新的Java Web应用，该发布上线给用户用了，要把一个Java Web应用发布上线，首先需要搭建运行的环境，运行的环境需要有JDK、APPServer，在已经装好了os的机器上装上JDK和APPServer，开发好的Java Web应用可以用maven直接打成war或ear，将这个打好的包scp或其他方式到目标机器上，准备妥当，就差启动了。
通常APPServer都带有启动脚本，在做好了上述准备后，直接运行启动脚本，通常就OK了（maybe需要修改appserver的一些配置文件，例如修改监听端口等）。
应用启动后，有一个问题需要解决，就是如何确认应用启动后成功与否，对于Java web应用通常可以放一个jsp文件，在这个文件里做一些必要的检查，以确保应用启动是正常的，例如通常Java web应用会基于spring之类的框架来写，为了确保spring的BeanFactory初始成功，可以在jsp文件里去获取下spring里的bean调用下。
应用完成了启动后，这个阶段的工作就算完成了，这个阶段完成后积累了一个应用启动的脚本，用来启动应用服务器以及在启动完毕了后检验应用是否启动成功。

只要不是一个一次性的应用，就必然会涉及修改的问题，修改完了后就得重新发布，对于Java Web应用，在修改完了后重新打应用的包，然后scp覆盖到目标机器上，重启，就可完成修改，但显然，每次修改完代码后都这么操作实在是痛苦不堪，于是喜欢“偷懒”的同学会专门搞台发布用的机器（或者就是运行应用的那台机器），然后写个脚本，每次需要发布时就通过脚本自动的将发布需要做的所有事情自动做好，:)，这下以后发布爽多了。
相应的这个时候通常还要支持回滚，即应用发布失败后自动的回滚到前一版本的功能，也可以折腾到脚本里。
但如果只是为了修改个页面，就得这么折腾，显然还是麻烦了点（主要是经常重启，用户受不了），于是需要支持仅更新页面的发布方式，为了支持这种方式，通常就要求打出的war/ear是解开了的，这样才比较方便直接覆盖页面，继续“偷懒”的本性，写些脚本，支持将需要发布的页面文件从svn或git下载，然后打成一个tgz或其他压缩包，scp到目标服务器，解包覆盖完成页面的更新（当然，对于编译jsp的运行方式这种发布方法就没法玩了）。
经过这个阶段的折腾，就积累了两个脚本，一个用来发布应用包，一个用来发布页面。

每次发布应用包的时候都会有短暂的不可用，这样总折腾下去用户受不了（如果哪天这唯一的一台服务器挂掉的话，就更糟糕了），于是就把应用的机器数从一台变成两台，通常这里对应用是有些技术要求的，这篇blog中只谈运维，通常情况下从部署在一台变成两台后，要做这些事：
1、可能会增加一台机器用来部署nginx/apache来做负载均衡，这个规模的情况下应该很少有会采用lb设备或lvs的（某些国企除外…），于是就得折腾下这台机器的环境等了；
2、增加了一台应用的机器后，就得又来搭建一次应用的运行环境了，通常这个时候“偷懒”的本性会发作，干脆折腾个脚本吧，来支持从另外一台运行的应用机器clone运行环境，做的更好点的话，就会把应用的运行环境记录在某个地方、然后把应用运行需要的软件也放在某个地方（例如yum），这样，当要搭建应用的运行环境时，就可通过记录的信息以及yum源等直接完成运行环境的搭建。
3、但这样还没完，为了避免发布的时候应用完全不能用，除了技术上要做的那点事外，在发布应用时就会多加一步，就是要先发一台，再发另外一台，由于之前有发布脚本，通常这也不是问题，:)。
经过这个阶段，就又积累了两个脚本，一个用来管理负载均衡的那台机器，另一个脚本用来搭建应用的运行环境。

随着应用越来越受欢迎，通常应用的机器就得继续加了，这个时候对运维工作又会带来新的挑战，主要还是在发布上，这个时候应用部署在了一堆的机器上了，每次发布的时候手工输入一堆的机器地址来发布显然很麻烦，于是需要有个地方来记录应用有哪些机器（还记得我们之前搞了个地方来记录应用的运行环境信息吧，可以放一起），除了要解决这个问题外，还需要解决的一个问题是这个时候通常对应用的发布方式会有了多种要求，例如分批发布（先发5台，再发10台，再全部发，或一半一半发等），更高级的话会有beta发布、灰度发布等要求，这个具体可以见facebook的大牛@魏小亮写的《代码和产品发布的几种方式》，这个时候显然，之前写的那个简单的发布脚本就无法支持了，于是得搞个更为复杂的脚本来支持这多种的发布方式（有些还需要应用架构上做配合改造才能实现），做的更好的就是提供一个web版本的发布系统，来更为方便的进行发布以及发布过程的管理。
经过这个阶段后，通常可以折腾出一个web版的应用运维系统了，包括应用信息的登记（依赖的运行环境、运行的机器地址）、应用的发布、页面的发布、增加应用的机器、下线应用的机器。

通常继续发展下去，会出现一些新的状况，主要是会开始多元化，有了很多个应用，这个时候原来的web版应用运维系统就要支持多应用了，这里主要会带来的问题是为了降低运维的复杂性，需要做一些通用性的工作，例如通用的启动脚本等，这个时候会产生一些要求，例如统一的应用名等，另外会带来的问题就是开发、运维的人多了，这个时候权限上就需要有些控制了，例如某些账号可以操作某些应用等，这个时候通常需要增加一套权限系统，集成到之前的运维系统。
应用多了后，还会带来的问题是应用部署的规范性（同时也是为了降低运维的复杂性），因为每个应用可能都会有一些特殊的配置，这个时候最好是能够通过搭建运行环境以及权限控制来保证一个应用部署后的目录控制。

经过上面的一些发展过程后，Java应用的运维工作基本就可以比较自动的去完成了，但通常其实应用运维除了上面的工作外，还有一件更重要的事，就是保障应用的稳定，应用运维人员需要能够排查大部分的应用故障问题，而不是交由后面的开发人员来解决，通常这个时候需要一套自动的故障处理系统，感兴趣的同学可以参与下facebook的FBAR。

发展到更大后，还可能会碰到例如一个负载设备无法支撑整个网络的请求，需要划分vlan，这个时候在做应用机器的扩容时就需要考虑vlan因素了，还有可能会碰到机器利用率不够高，需要引入虚拟机，更高级的就是引入弹性计算，这些对运维体系都会产生较大的冲击，:)。

从上面对一个Java应用运维的演变描述可以看到，大方向上来说是朝自动化、web化、智能化发展，但最最重要的都是如何和现有运行体系无缝的结合，而且这里谈到的还仅仅是Java应用运维的工作（还没提到开发人员其实也要仔细考虑自己写的产品的可运维性如何），而一个运维的体系还要包括机房、网络、硬件、安全等，就更加的复杂和且需要体系化的考虑，。

记录碰到的HBase问题

bluedavy — Mon, 24 Oct 2011 15:01:49 +0800

目前NoSQL产品最被人诟病的就是其稳定性，不得不承认，目前HBase离做到数据库那样的高稳定还有距离（丢数据、不能读写、DDL失败等严重问题），这篇blog将用来记录我们在运维HBase时碰到的问题（会不断更新），希望能给使用HBase的同学有一些帮助。

1、单台regionserver的region数很多后写速度疯狂下降
具体请见：http://koven2049.iteye.com/blog/1144526

2、region server OOM
碰到过两种造成region server OOM的状况：
* rowKey设计的问题，写的一直是同一行，version配置的又比较大，无法split，从而导致compact时候需要压缩一个巨大的文件；
* 应用方create table时，通过setMaxFileSize设置了一个3G的值，导致compact时需要消耗6G的空间，从而OOM。
造成这两次OOM的原因都是由于compact，因此需要修改compact，避免OOM，官方在0.92里做了一定的处理，具体可见：HBASE-3290。

3、master OOM
当系统中有很多region时，很容易就造成master OOM了，具体请见：HBASE-3906，HBase 0.90.4或以后版本的同学可忽略此问题。

4、.meta.表hole
hbck时，出现了Chain of regions in table … is broken; edges does not contain …，造成这个的原因是某张表的regions的startKey和endKey没有形成闭环，这会导致某些数据无法读写，出现这个问题时，最大的麻烦是不能随意去进行修复，因为有可能会导致丢数据。
我们之前碰到这个问题的原因是split的时候offlineParentInMeta超时了，具体描述大家请见：http://koven2049.iteye.com/blog/1199519，这个bug我们已修复并提交给官方，为HBASE-4562，使用HBASE 0.90.5或以后版本的同学可忽略此bug。
但我们并不确定修复了这个bug就能避免.meta.表不出现hole现象，因此后面会考虑做个工具来安全的修复这个问题。

5、.meta.表中出现重复的startKey/endKey
hbck时，出现了Chain of regions in table …contains less elements than are listed in META; visited=，出现此情况非常严重，此时客户端读写会出现混乱或挂起的现象，可能会导致丢数据，而且很难恢复。
我们出现这个现象的原因是官方的这个bug造成的，这个bug已经修复，具体请见HBASE-3946，使用HBASE 0.90.4或以后版本的同学可忽略此bug。
但我们并不确定修复了这个bug就能避免.meta.表不出现重复的startKey/endKey，因此后面会考虑做个工具来安全的修复这个问题。

6、master进行split hlog时有可能造成数据丢失
具体请见：http://koven2049.iteye.com/blog/1199669，目前官方未修复此bug，请使用HBase的同学自行评估进行修复。

7、在读取大数据时造成写的速度也下降
这个的原因在于HBase的单连接通信效率低的问题，目前官方未有此方面的修复方法，暂时来看只能是要么将读写分开，要么折腾成多个连接。

8、disable表失败
现象为disable表时导致master挂掉，无法disable。
造成master挂掉的原因为表中有region处于没有serverAddress的现象，而表此时又处于disabling的状态，导致无法enable，修复的方法可以是先从zk节点的table下删除此表，然后再去disable，通常是可以的。
官方相关的两个patch请见：HBASE-3892和HBASE-4064。

9、.meta.表和root表被重复分配到两台region server
具体请见：http://koven2049.iteye.com/blog/1199667。

NFS-RPC框架优化过程（从37k到168k）

bluedavy — Tue, 13 Sep 2011 10:33:46 +0800

NFS-RPC框架从编写之初，到现在为止（应该还会有些提升，不过估计不大），每秒支撑的请求数上升了好几倍，测试结果的演变为：
37k –> 56k –> 65k –> 88k –> 93k –> 143k –> 148k –> 153k –> 160k –> 163k –> 168k
以上测试结果为在100并发、100 request byte、100 response byte以及单连接下的背景下得出的，在这篇blog中来分享下这个框架所做的一些优化动作，希望能给编写rpc框架或使用mina/netty/grizzly的同学们一点点帮助，也希望得到高手们更多的指点。

1、37k –> 56k
由于目前大部分的NIO框架采用的均为1个socket io线程处理多个连接的io事件，如果io线程时间占用太长的话，就会导致收到的响应处理的比较慢的现象，这步优化就是针对反序列化过程占用io线程而做的，采用的方法即为在读取流时仅根据长度信息把所有的bytes都读好，然后直接作为收到的信息返回给业务线程，业务线程在进行处理前先做反序列化动作，感兴趣的同学可以看看NFS-RPC中：code.google.nfs.rpc.netty.serialize.NettyProtocolDecoder或code.google.nfs.rpc.mina.serialize.MinaProtocolDecoder，以及code.google.nfs.rpc.mina.server.MinaServerHandler或code.google.nfs.rpc.netty.server.NettyServerHandler。

2、56k –> 65k
在测试的过程中，发现YGC的耗时比较长，在咨询了sun的人后告诉我主要是由于有旧生代的数据结构引用了大量新生代对象造成的，经过对程序的分析，猜测是benchmark代码本身用于记录请求响应时间信息的ConcurrentLinkedQueue造成的，在某超级大牛的指示下，换成了在每个线程中用数组的方式，按区间来记录响应时间信息等，感兴趣的同学可以看看NFS-RPC中：code.google.nfs.rpc.benchmark.SimpleProcessorBenchmarkClientRunnable

3、65k –> 88k
在某超级大牛的分析下，发现目前的情况下io线程的上下文切换还是比较频繁，导致io线程处理效率不够高，默认情况下，NIO框架多数采用的均为接到一个包后，将这个包交由反序列化的处理器进行处理，对于包中有多个请求信息或响应信息的情况，则采用一个一个通知的方式，而rpc框架在接到一个请求或响应对象时的做法通常是唤醒等待的业务线程，因此对于一个包中有多个请求或响应的状况就会导致io线程需要多次唤醒业务线程，这个地方改造的方法是nio框架一次性的将包中所有的请求或响应对象通知给业务线程，然后由业务线程pipeline的去唤醒其他的业务线程，感兴趣的同学可以看看NFS-RPC中：code.google.nfs.rpc.netty.serialize.NettyProtocolDecoder或code.google.nfs.rpc.mina.serialize.MinaProtocolDecoder，以及code.google.nfs.rpc.netty.client.NettyClientHandler或code.google.nfs.rpc.mina.client.MinaClientProcessor。

4、88k –> 93k
这步没什么可说的，只是多支持了hessian序列化，然后这个结果是用hessian序列化测试得出的，注意的是hessian不要使用3.1.x或3.2.x版本，这两个系列的版本性能极差，建议使用hessian 4.0.x版本。

5、93k –> 143k
在到达93k时，看到测试的结果中有不少请求的响应时间会超过10ms，于是用btrace一步一步跟踪查找是什么地方会出现这种现象，后来发现是由于之前在确认写入os send buffer时采用的是await的方式，而这会导致需要等待io线程来唤醒，增加了线程上下文切换以及io线程的负担，但这个地方又不能不做处理，后来就改造成仅基于listener的方式进行处理，如写入失败会直接创建一个响应对象，这次改造后效果非常明显，感兴趣的同学可以看看nfs-rpc中：code.google.nfs.rpc.mina.client.MinaClient或code.google.nfs.rpc.netty.client.NettyClient。

6、143k –> 148k
这步是在@killme2008 的指点下，将tcpNoDelay设置为了false，但这个设置不适用于低压力的情况，在10个线程的情况下tps由3w降到了2k，因此tcpNoDelay这个建议还是设置成true。

7、148k –> 153k
这步没什么可说的，只是多支持了protobuf序列化，这个结果是用protobuf序列化测试得出的，之前还测试过下@bnu_chenshuo 写的一个protorpc，是基于protobuf的rpc加上netty实现的，结果也很强悍，测试出来是149k，看来protobuf的rpc也是有不少值得学习的地方的。

8、153k –> 160k
server接到消息的处理过程也修改成类似client的pipeline机制，同时将之前获取协议处理器和序列化/反序列化的处理器的地方由map改成了数组，具体可以参考NettyServerHandler、ProtocolFactory和Codecs。

9、160k –> 163k
Grizzly的leader对grizzly部分的代码做了很多的修改，结果创造了目前rpc benchmark的最高纪录：163k，更多优化的细节敬请大家期待后续的一篇grizzly rpc优化细节的blog…

10、163k –> 168k
@minzhou 对nfs-rpc的代码进行了优化，将之前在Decoder中做的构造String对象的部分挪到了业务线程中，于是TPS也有了一定的上升，感谢。

上面就是到目前为止的所有优化动作，其中的很多我估计高手的话是不会犯错的，我走的弯路多了些，总结来说rpc框架的优化动作为：
1、尽可能减少io线程的占用时间；
2、尽可能减少线程上下文切换；
3、尽可能使用高效的序列化/反序列化；

NFS-RPC框架在后面将继续做更多的测试和优化，例如采用aio、coroutine、测试CNK问题等，敬请关注：http://code.google.com/p/nfs-rpc

Let’s beat the rpc benchmark record,current is 168k!

bluedavy — Sat, 27 Aug 2011 14:36:53 +0800

Many applications need rpc to realize their business,in java world,we can choose rmi/webserivce to do rpc,but they’re not fast enough for most cases,so many of us choose some difference high performance network framework to realize rpc,such as mina,netty,grizzly,also we can choose some cross-language framework,such as thrift.
I wrote an abstract rpc framework to intergrate difference network framework more quickly,and also I intergrate mina/netty/grizzly and do a benchmark on them,hope some of u can give some advices or attend the project to modify code or integrate other network framework,current benchmark record(single connection,100 concurrents) is 168k created by grizzly-rpc & protobuf,let’s beat the rpc benchmark together,u can find more details at here.

benchmark machine:
CPU: E5620 (8 core HT to 16 core)
Memory: 24G

OS: Linux 2.6.18
JDK: 6u23
Java startup options: -Xms4g -Xmx4g -Xmn1g

This is current benchmark result.
100 concurrents,Single connection,Direct Call

100 concurrents,Single connection,Reflection Call

Different Concurrents,Direct Call

Different Concurrents,Reflection Call

Different Connections

More benchmark details u can download from here.

Did improvment:
1. move deserialization to business thread;
2. modify benchmark code,use array to record instead of ConcurrentLinkedQueue & File;
3. send message list to business thread instead of io thread notify one by one;

HBase随机写以及随机读性能测试

bluedavy — Sun, 14 Aug 2011 22:36:41 +0800

根据最近生产环境使用的经验，更多的项目的采用，以及采用了更加自动的测试平台，对HBase做了更多的场景的测试，在这篇blog中来分享下纯粹的随机写和随机读的性能数据，同时也分享下我们调整过后的参数。

测试环境说明：
1、Region Server： 5台，12块1T SATA盘(7200 RPM)，No Raid，物理内存24G，CPU型号为E5620；
启动参数为：-Xms16g -Xmx16g -Xmn2g -XX:SurvivorRatio=2 -XX:+UseCMSInitiatingOccupancyOnly -XX:CMSInitiatingOccupancyFraction=85
2、Data Node：35台，和Region Server同样的硬件配置，启动参数上-Xms2g -Xmx2g，未设置-Xmn；

服务端参数：
hbase.replication false
hbase.balancer.period 1200000
hfile.block.cache.size 0.4，随机读20%命中场景使用0.01
hbase.regionserver.global.memstore.upperLimit 0.35
hbase.hregion.memstore.block.multiplier 8
hbase.server.thread.wakefrequency 100
hbase.regionserver.handler.count 300
hbase.master.distributed.log.splitting false
hbase.regionserver.hlog.splitlog.writer.threads 3
hbase.hregion.max.filesize 1073741824
hbase.hstore.blockingStoreFiles 20
hbase.hregion.memstore.flush.size 134217728

客户端参数：
hbase.client.retries.number 11
hbase.client.pause 20
hbase.ipc.client.tcpnodelay true
ipc.ping.interval 3000

最终随机写的测试性能结果如下（点开可看大图）：

从写的测试来看，可以看到，当客户端线程数在250左右时，此时的响应时间在6ms左右，tps在7.5k左右，差不多是比较好的一个状态。
在随机写的测试中，以及我们的一些项目的测试中，看到的一些现象和问题：
1、随着单台机器的region数变多了，tps下降的比较明显，team的同事做了一个改进，保障了随着region数的增多，tps基本不会有太多的下降，具体请见同事的这篇blog；
2、当hbase.regionserver.handler.count为100（默认为10，更正常了）时，压力大的情况下差不多100个线程都会BLOCKED，增加到300后差不多足够了，此时tps也到达瓶颈了；
3、当datanode数量比较少时，会导致写tps比较低，原因是此时compact会消耗掉太多的网络IO；
4、当写采用gz压缩时，会造成堆外内存泄露，具体请参见同事的这篇blog；
5、在压力增大、region数增多的情况下，split和flush会对写的平稳性造成比较大的影响，而通常内存是够用的，因此可以调整split file size和memstore flush size，这个要根据场景来决定是否可调整。
对写的速度影响比较大的因素主要是：请求次数的分布均衡、是否出现Blocking Update或Delaying flush、HLog数量、DataNode数量、Split File Size。

随机读的测试性能结果如下（点开可看大图）：

从读的测试来看，可以看到，读的tps随cache命中率降低会下降的比较厉害，命中率为90%时、客户端线程数为250时，此时的响应时间和tps是比较不错的状况。
在随机读的测试中，以及我们的一些项目的测试中，看到的一些现象和问题：
1、随机读的tps随着命中率下降，下降的有点太快，具体原因还在查找和分析中；
2、当命中率很低时，读bloomfilter的索引信息需要耗费掉比较多的时间，主要原因是bloomfilter的索引信息并没有在cache优先级中占优，这是一个可以改进的点。
对读的速度影响比较大的因素主要是：请求次数的分布均衡、StoreFile数量、BloomFilter是否打开、Cache大小以及命中率。

ps: 强烈推荐同事的blog，其中记录了很多我们对HBase的改进，以及我们在运维HBase项目时碰到的各种奇怪、诡异的问题。

记录帖：碰到的一些Java问题（更新于2012-04-17）

bluedavy — Tue, 09 Aug 2011 22:48:03 +0800

这个贴用于记录自己碰到过的一些Java问题，会根据经验不断增加，以便总结，:)

case: 某应用在运行个一两天后就会把物理内存耗光
解决过程：
1、先按经验查了下有没有错误使用Inflater和Deflater，没有，于是继续；
2、继续上perftools，看看到底什么原因造成的，结果在6u21版本上看到的很诡异，是JVM_handle_linux_signal占了最多，觉得不靠谱，于是先升级成了6u26；
3、再分析，看到os::malloc占用了最多，但其他的就完全没头绪了；
4、在@JosephWang_CN的帮助下，图形分析下了perftools的stack trace，才发现还是unsafe_allocate的地方，但这次现象和上个case不同，不同点在于这次是由于cms gc的bug造成的，bug id为7112034，这个bug会造成即使direct bytebuffer已经无引用了，但在cms gc时其并不会被清除掉，而要等到full gc才会清除，官方版本在6u32中修复此bug（这个很容易验证，如果没开启ExplicitGCInvokesConcurrent，用jmap -histo:live强制触发下）；
5、在fix了这个bug的前提下，还需要限制-XX:MaxDirectMemorySize的大小才行，否则可能会出现还没到触发cms gc时，物理内存就用完了的现象。
总结：
根据多次排查Java Heap外内存泄露的问题，目前的经验为：
1、先查查看有没有错误使用Inflater和Deflater，如有则基本就搞定了；
2、多执行几次jmap -histo:live，看看内存会不会下降，如果会的话，多数和GC的bug有关；
3、perftools，对调用次数的那列进行排序(pprof –text … | sort -n -r -k4)，如果看到是Unsafe_Allocate比较多，且为server端应用，则通常说明是哪个地方分配了Direct ByteBuffer，但来不及释放引用，然后嘛，就是用btrace跟踪下看看谁干的，分析原因。

case: 某应用在压测一段时间后就会把物理内存耗光
解决过程：
1、从gc log以及jstat信息来看，java heap内的内存消耗并不多，但堆外消耗非常严重，导致了物理内存被耗光；
2、于是装上google perftools，看看堆外到底是什么原因造成的消耗；
3、分析了下google perftools的内存malloc消耗，主要是调用Unsafe.allocate造成的；
4、通常调用Unsafe.allocateMemory来分配内存的，只有Direct ByteBuffer和AWT，这应用是没用AWT的，Direct ByteBuffer倒是用到了；
5、网上google了一会，找到一个貌似和这个应用的场景很像的内存泄露的现象，具体信息请见：http://t.co/S9jvDt8O，号称是SocketChannel.write的时候，如果是Direct ByteBuffer会导致memory leak，而且Trustin Lee(Mina/Netty的作者)也这么说的：”it’s a known bug”;
6、于是建议应用的同学将ByteBuffer的地方改成不用direct方式；
7、改完后，重新压测，物理内存消耗是没那么严重了，但java heap用满了后回收不了了；
8、于是dump内存，用mat分析后发现是由于这个应用本身处理上的一些缺失造成的，简单说下，这个应用是一个基于mina的应用，而应用没有对session上的发送请求做限流，而mina来不及发送，导致积压了很多WriteRequest，从而内存被耗光了；
9、对这个问题的解决方法是：限流，当未发送的字节数到达某个比率后，就暂时先不发送了，或者报错等等，用netty能对这个现象有一定的缓解，但限流动作还是要做，否则可能会出现接收方处理慢，从而导致发送方内存用完的现象。

case: 某应用在压测时很容易出现promotion failed的现象
解决过程：
1、从promotion failed时的gc日志来看，状况为新生代中有1.5g的对象存活，旧生代此时的空余空间为4g，足以放下新生代存活的这些对象，于是只能猜测可能是cms gc的情况下旧生代的碎片问题导致的，其实心里是不太相信的，因为这空间空闲了如此的多呀；
2、首先增加-XX:+PrintPromotionFailure看看Promotion Failed的时候是不是有很大的对象要晋升到旧生代，结果打出来的日志显示在晋升的时候失败的竟然只是申请262146个block的空间而已，这是在开启了压缩指针的情况，因此每个block为4个字节；
3、还是不能确定，于是增加-XX:+CMSDumpAtPromotionFailure，看看OLD Gen的碎片状况；
4、打出来的信息显示old gen拥有最多free block的chunk也只有99977个而已，有53w+个chunk，里面大部分都只有999个free block，可见碎片相当严重；
5、到这步只是确定了碎片很严重，暂时能想到的只有每天半夜的时候主动执行下jmap -histo:live，尽可能减少碎片吧，如果后续有什么改进的动作，再来记录。

case: 某应用在发布的过程中突然crash了几台
解决过程：
1、应用crash后hs_err*.log以及core.[pid]文件都没生成；
2、先打开core dump;
3、crash后gdb core dump看：

(gdb) bt
#0  0x00002ba466f82971 in ?? () from /opt/jdk-1.6.0_26/jre/lib/amd64/server/libjvm.so
#1  0x00002aab78a7e20d in Java_java_net_SocketOutputStream_socketWrite0 ()
   from /opt/jdk-1.6.0_26/jre/lib/amd64/libnet.so

4、看到上面的core dump完全木有头绪，后来@rednaxelafx 介入处理，才知道原来jstack是可以跟core dump文件提取出当时java程序的状况的；
5、jstack出来一看，发现程序里有个地方无限递归…so…
总结：
@rednaxelafx接着又进一步分析了为什么没有生成hs_err*.log，是因为从jdk 5.0以后的版本，hs_err*.log就是在crash的那个线程来生成，而这个案例中crash时的那个线程无限递归，而且正在native栈上，栈空间被消耗光了，所以hs_err*.log文件就没生成出来。

Case: 某应用偶尔会出现极为频繁的Promotion failed，导致cms gc切换为串行full gc，从而响应变得超级慢
解决过程：
1、从promotion failed的日志来看，应该是在那段时间内内存被消耗光了造成的，因此在promotion failed的时候dump了内存；
2、可惜dump出来的那个内存文件打不开，几次都是如此；
3、还好我们自己定制的jdk版本这个时候发挥了作用，这个版本中有个功能是如果代码中有地方分配了超级大的数组，会打印出堆栈；
4、在某次出问题的时候，我们看到了这样的堆栈信息：

==WARNNING==  allocating large array: thread_id[0x00002aaac2d85800], thread_name[ajp-0.0.0.0-8009-48], array_size[782611408 bytes], array_length[195652847 el
ememts]
        at java.util.Arrays.copyOf(Arrays.java:2734)
        at java.util.ArrayList.ensureCapacity(ArrayList.java:167)
        at java.util.ArrayList.add(ArrayList.java:351)
        at net.sf.json.JSONArray._fromJSONTokener(JSONArray.java:1154)
        at net.sf.json.JSONArray.fromObject(JSONArray.java:147)
        at net.sf.json.util.JSONTokener.nextValue(JSONTokener.java:358)
        at net.sf.json.JSONObject._fromJSONTokener(JSONObject.java:1128)
        at net.sf.json.JSONObject._fromString(JSONObject.java:1317)
        at net.sf.json.JSONObject.fromObject(JSONObject.java:185)
        at net.sf.json.JSONObject.fromObject(JSONObject.java:154)
        at 我们自己的代码...

5、有这个堆栈后就可以知道是由于自己的代码这个地方触发了json创建了一个巨大的array；
6、于是怀疑是我们传给了json一个很大的String，就先在应用层做了个保护，超过一定大小的String就直接抛错；
7、加上了这个保护后还是出问题了；
8、因此怀疑是json内部有bug，导致传了某种格式的String后就会出现死循环什么的；
9、“神”看代码后，构造了一个这样的String s = “{tag:[0,1,”;然后调用JSONObject.fromObject(s)，就会OOM；
10、于是修改了json的代码，修复此bug…

Case: 某应用cms gc时concurrent-mark阶段应用竟然没有响应…
解决过程：
1、在cms gc进行的过程中用pstack采集目前java进程正在做什么；
2、从日志分析来看貌似是在concurrent-mark时，很多的java线程在分配内存的时候被锁住了…
3、将相关信息发给官方的gc dev maillist，只是得到了升级到6u28试试的建议…
目前问题尚未解决，先在此mark下，和这个url提到的问题基本一致：http://t.co/EU92I8nN

Case: 某应用cms gc非常频繁，并且很容易出现concurrent mode failure造成Full GC
解决过程：
1、从gc日志来看，cms gc每次在旧生代使用才到18%左右的时候就触发了，而设置的触发比率是80%，并且不允许JVM自行触发；
2、每几次cms gc还会偶尔出现concurrent mode failure的现象，看了下，这时旧生代的空间是非常充足的；
3、根据cms gc的触发机制，猜测是permGen的问题造成的，于是通过jstat -gcutil看了下permGen的占用比例，果然过一会就超过下92%（不过这里有个问题，就是permGen其实是还没达到MaxPermSize的，看来在cms gc的情况下，maxPermSize要采用不同策略）；
4、于是适当的调大permGen，不过仍然没有解决，原因是permGen增长实在太快了；
5、应用方发现有地方会不断的创建classLoader，加载class，因此导致了permGen的增长，修改后问题解决。
总结：
CMS GC的日志其实打的有些问题，应该把cms gc触发时的原因输出下；
另外就是在大部分情况下，只要不是cms gc触发的比例设置的太有问题，如果cms gc频繁或full gc频繁都是应用本身的问题造成的。

Case: 某应用出现启动后集群中部分node成功，部分node失败
解决过程：
1、失败的node抛出的是NoClassDefFoundError，这些node在环境上和应用包上是完全一致的，因此猜想是classloader装载class时出现了什么问题；
2、在启动参数上增加了-XX:+TraceClassLoading，想看看成功的node和失败的node是不是从第一个地方加载的相应的类，悲催的是成功的node加上了这参数后启动超慢，于是只好放弃；
3、由于不能用TraceClassLoading，只好从ClassLoader方面来跟踪这个类的加载，于是从应用层上做了相应的分析，找出了相应的classloader，然后用btrace相应的进行了跟踪，才终于发现成功的node和失败的node装载此类时不是从同一地方装载的，而其中有一个地方的这个类引用了一个不存在的类，于是就出现了NoClassDefFoundError。
总结：
在经过分析后，猜想是在这两个不同的node上classloader在list一个目录下的文件时，出现了顺序不同的现象，于是后来写了一个简单的程序在两个node上list那个目录的文件，发现返回的顺序果然不同，这个具体的原因为File.listFiles最后会调用到readdir函数，而这个函数返回的文件列表是按inode number排序的，因此在每台linux机器上确实有可能不同，当一个目录下有两个jar中有相同名字但不同内容的class时（话说这也是java应用中比较麻烦的问题，这个专门写篇blog来说下，java 8的模块化真的非常重要），就悲催了，一个保护做法是在实现classloader时，最好是先对listFiles排下序，避免集群中node出现表现不一致的问题。

Case: 某应用GC频繁但不一直不抛OOM的问题
解决过程：
这个应用是期待在内存不够的情况下快速抛出OOM的，但在执行中却发现执行了4个多小时的Full GC，就是没有抛OOM，导致应用出现了问题，从GC代码来看，目前要比较快的触发OOM，只能是调整GCTimeLimit和GCHeapFreeLimit，不过都不好调，后来暂时是靠调整了GCHeapFreeLimit来帮助快速抛出OOM。

Case: 某应用堆外内存泄露的bug
具体解决过程可参考这篇blog：http://blog.bluedavy.com/?p=205和这篇blog。
总结：
堆外内存泄露基本就是靠google perf-tools来查找了，目前来看堆外内存泄露基本都是使用Deflater，却没有显式调用end造成的。

Case: 某应用压测时压力上不去的问题
解决过程：
1、查看压测的目标服务器的cpu、网卡流量，发现都没到瓶颈；
2、继续查看压测的目标Server的线程状况，发现Server的线程数也没到瓶颈，有个诡异的现象是随着客户端施加的压力上升，服务器端线程数也没上升，而且网卡流量也没上升；
3、于是猜测是客户端本身的问题，客户端的CPU、网卡流量也没到瓶颈，但发现客户端的线程数随着施加的请求数增加，也没上升，因此猜想是客户端这个地方的线程数已经达到了最大值；
4、由于代码是第三方的，于是用btrace写了个脚本，跟踪查找了该线程池的最大线程数，发现果然是这个最大线程数比较小，因此做了相应的修改，放大最大线程数，继续压测就OK了。
ps: 这个Case还出现了一个状况，就是客户端的网卡流量随着施加的压力上升，却没发生变化，因此猜测是网络上有流量限制…
总结：
从查这次的问题来看，在压测时压力上不去时，需要查看从请求发起到响应返回的整个过程，资源的消耗状况，是否某个地方资源消耗到极限了，如果硬件资源未到极限，通常会是线程blocked或线程被消耗完了。

Case: 某应用GC频繁的问题
这个专门写了一篇blog来描述，具体请见：http://blog.bluedavy.com/?p=290

Case: 某应用一直没响应。
解决过程：
1、jstack多次后分析，很多的线程都在Blocked状态，等待一把锁，而持有这把锁的线程一直停在了Log4j的ConsoleLog的write上；
2、于是问题就集中到为什么ConsoleLog write的时候竟然会停住，最早猜测的原因是console是不是也输出到了一个文件，而这个文件出问题了，但经过检查发现一切正常；
3、通过ps auxf查看脚本看看console有没有输出到文件，发现这个脚本嵌套了好几层，但都输出到了外部的文件，而外部这个文件是没什么问题的；
4、仔细查看发现这个Java进程是在代码里通过调用脚本启动的，猜想是不是没有正确处理标准输出流和错误流造成的，于是翻看代码，发现代码只处理了输出流，但没处理错误流，并且在处理输出流时只处理了10000行，超过10000的时候就没再去读了，对于这种未将console重定向到外部文件的场景，linux会将其写到一个缓冲区，缓冲区写满后就会导致应用程序阻塞住，这个在Java的API上也有说明：
The parent process uses these streams(Process.getOutputStream(), Process.getInputStream(), Process.getErrorStream()) to feed input to and get output from the subprocess. Because some native platforms only provide limited buffer size for standard input and output streams, failure to promptly write the input stream or read the output stream of the subprocess may cause the subprocess to block, and even deadlock.
5、到这步后就可以确认问题的原因了。
解决方法：
1、把输出到Console的Logger方式去掉了，这样自然就没问题了；
2、程序上修改，不是读到1w行就不读了，而是一直读到没有输出流和错误流了才结束，通常来说比较正确的做法请见这篇贴：http://goo.gl/sllmv
总结：
在Java中启动外部程序时一定要注意正确处理输出流和错误流。

一个GC频繁的Case

bluedavy — Sun, 17 Jul 2011 12:20:58 +0800

前两天碰到一个很诡异的GC频繁的现象，走了不少弯路，N种方法查找后才终于查明原因了，在这篇blog中记录下，以便以后碰到这类问题时能更快的解决。

前两天一位同学找到我，说有个应用在启动后就一直Full GC，拿到GC log先看了下，确实是非常的诡异，截取的部分log如下：
2011-07-16T14:55:57.733+0800: 174042.063: [Full GC [PSYoungGen: 786432K->0K(917504K)] [ParOldGen: 728400K->728457K(1048576K)] 1514832K->728457K(1966080K) [PSPermGen: 84814K->84812K(262144K)], 1.5426550 secs] [Times: user=4.58 sys=0.21, real=1.54 secs]
2011-07-16T14:56:07.144+0800: 174051.475: [Full GC [PSYoungGen: 786432K->0K(917504K)] [ParOldGen: 728457K->728611K(1048576K)] 1514889K->728611K(1966080K) [PSPermGen: 84814K->84812K(262144K)], 1.5428850 secs] [Times: user=4.57 sys=0.17, real=1.54 secs]
2011-07-16T14:56:16.699+0800: 174061.030: [Full GC [PSYoungGen: 786432K->0K(917504K)] [ParOldGen: 728611K->729096K(1048576K)] 1515043K->729096K(1966080K) [PSPermGen: 84814K->84812K(262144K)], 1.5064200 secs] [Times: user=4.36 sys=0.21, real=1.50 secs]
2011-07-16T14:56:26.420+0800: 174070.750: [Full GC [PSYoungGen: 786432K->0K(917504K)] [ParOldGen: 729096K->729654K(1048576K)] 1515528K->729654K(1966080K) [PSPermGen: 84814K->84812K(262144K)], 1.5519220 secs] [Times: user=4.47 sys=0.18, real=1.54 secs]
2011-07-16T14:56:35.634+0800: 174079.965: [Full GC [PSYoungGen: 786432K->0K(917504K)] [ParOldGen: 729654K->728743K(1048576K)] 1516086K->728743K(1966080K) [PSPermGen: 84814K->84812K(262144K)], 1.5002720 secs] [Times: user=4.67 sys=0.11, real=1.50 secs]
2011-07-16T14:56:45.938+0800: 174090.269: [Full GC [PSYoungGen: 786432K->0K(917504K)] [ParOldGen: 728743K->729132K(1048576K)] 1515175K->729132K(1966080K) [PSPermGen: 84814K->84812K(262144K)], 1.6175360 secs] [Times: user=4.47 sys=0.25, real=1.61 secs]
2011-07-16T14:56:55.682+0800: 174100.012: [Full GC [PSYoungGen: 786432K->0K(917504K)] [ParOldGen: 729132K->728950K(1048576K)] 1515564K->728950K(1966080K) [PSPermGen: 84814K->84812K(262144K)], 1.5780950 secs] [Times: user=4.50 sys=0.07, real=1.58 secs]
2011-07-16T14:57:05.228+0800: 174109.559: [Full GC [PSYoungGen: 786408K->0K(917504K)] [ParOldGen: 728950K->729466K(1048576K)] 1515359K->729466K(1966080K) [PSPermGen: 84814K->84812K(262144K)], 1.5868130 secs] [Times: user=4.43 sys=0.09, real=1.60 secs]
2011-07-16T14:57:14.812+0800: 174119.142: [Full GC [PSYoungGen: 786432K->0K(917504K)] [ParOldGen: 729466K->729277K(1048576K)] 1515898K->729277K(1966080K) [PSPermGen: 84814K->84812K(262144K)], 1.5460140 secs] [Times: user=4.44 sys=0.19, real=1.54 secs]

这个日志中诡异的地方在于每次Full GC的时候旧生代都还有很多的空间，于是去看来下启动参数，此时的启动参数如下：
-Xmx2048m -Xms2048m -Xmn1024m -Xss512k -XX:PermSize=256m -XX:+UseParallelGC -XX:ParallelGCThreads=20 -XX:+UseParallelOldGC -XX:MaxGCPauseMillis=100 -XX:+UseAdaptiveSizePolicy -XX:+DisableExplicitGC
可以看到，这个启动参数有很多的问题，最重要的在于MaxGCPauseMillis，因为目前版本的jdk其实很难做到达成这个目标，于是猜测可能是这个参数造成的，顺带把启动参数简单修改了下：
-Xmx2g -Xms2g -Xmn1g -Xss512k -XX:PermSize=256m -XX:+UseParallelOldGC -XX:+DisableExplicitGC
修改完毕，重新启动了一台，发现OK了，于是认为就是这个参数造成的，可惜的是后面又重启了几次后，还是出现了GC频繁的现象。

从GC日志来看，Full GC是在旧生代没满的情况下就频繁触发，以前有碰到过一个现象是代码中死循环，导致会GC频繁，于是先jmap -histo [pid]看了下，char数组占用的比较多一些，但也是正常现象。

还有可能是程序中有地方在分配巨大的对象，导致新生代放不下，旧生代剩余的空间也放不下，于是想通过jstack先看看程序现在在干嘛，于是jstack了很多次程序的状况，杯具的是什么异常状况都没发现。

jstack中无法发现，于是决定通过pstack来看看c堆栈上的allocate的状况，想从此来关联到java的线程堆栈，多次执行pstack [pid] | grep ‘allocate’后，看到了一些信息：
11284-#8 0x000000329b8d3c2d in clone () from /lib64/libc.so.6
11341-Thread 259 (Thread 0x40b25940 (LWP 20346)):
11385-#0 0x000000329c40ab99 in pthread_cond_wait@@GLIBC_2.3.2 ()
11445-#1 0x00002b57b7843727 in os::PlatformEvent::park ()
11498-#2 0x00002b57b781c7c2 in Monitor::IWait ()
11542-#3 0x00002b57b781cf8e in Monitor::wait ()
11585-#4 0x00002b57b75e6aa2 in WaitForBarrierGCTask::wait_for ()
11645-#5 0x00002b57b7887d8b in PSParallelCompact::marking_phase ()
11707-#6 0x00002b57b7886e11 in PSParallelCompact::invoke_no_policy ()
11772-#7 0x00002b57b788d296 in PSScavenge::invoke ()
11820:#8 0x00002b57b7855d7e in ParallelScavengeHeap::failed_mem_allocate ()
11891-#9 0x00002b57b796b379 in VM_ParallelGCFailedAllocation::doit ()
11956-#10 0x00002b57b7977d0a in VM_Operation::evaluate ()
12008-#11 0x00002b57b79772b2 in VMThread::evaluate_operation ()
12066-#12 0x00002b57b7977534 in VMThread::loop ()
12110-#13 0x00002b57b797702e in VMThread::run ()
12153-#14 0x00002b57b7843f9f in java_start ()
12193-#15 0x000000329c4064a7 in start_thread () from /lib64/libpthread.so.0
12263-#16 0x000000329b8d3c2d in clone () from /lib64/libc.so.6
12320-Thread 258 (Thread 0x40ba6940 (LWP 20347)):
12364-#0 0x000000329c40ab99 in pthread_cond_wait@@GLIBC_2.3.2 ()
–
69798-#3 0x00002b57b78f56c3 in ObjectSynchronizer::wait ()
69852-#4 0x00002b57b76bd34b in JVM_MonitorWait ()
69897-#5 0x00002aaaab141ece in ?? ()
69929-#6 0×0000000000000000 in ?? ()
69961-Thread 141 (Thread 0x45f27940 (LWP 20532)):
70005-#0 0x000000329c40ab99 in pthread_cond_wait@@GLIBC_2.3.2 ()
70065-#1 0x00002b57b7843727 in os::PlatformEvent::park ()
70118-#2 0x00002b57b781c7c2 in Monitor::IWait ()
70162-#3 0x00002b57b781ce2a in Monitor::wait ()
70205-#4 0x00002b57b7977b39 in VMThread::execute ()
70252:#5 0x00002b57b7855c0b in ParallelScavengeHeap::mem_allocate ()
70316:#6 0x00002b57b747873b in CollectedHeap::common_mem_allocate_noinit ()
70387-#7 0x00002b57b7626ce2 in instanceKlass::allocate_instance ()
70449-#8 0x00002b57b78aa076 in OptoRuntime::new_instance_C ()
70506-#9 0x00002aaaab1948fb in ?? ()
70538-#10 0x00002aaac0741768 in ?? ()
70570-#11 0x00002aaaab761a0c in ?? ()
70602-#12 0x00002aab2dae03c8 in ?? ()
70634-#13 0x00002aaac4035fb0 in ?? ()
70666-#14 0x00002aab2dae2c00 in ?? ()
70698-#15 0x00002aaac0218af0 in ?? ()
70730-#16 0×0000000000000001 in ?? ()
拿到这个堆栈后，猜测是由于该线程在分配一个对象时分配失败，导致触发了Full GC，于是根据线程ID去找jstack中的信息，很杯具的是由于有时间差，每次都抓不到什么信息。

于是仔细的重新看上面的堆栈，发现在ParallelScavengeHeap::mem_allocate后，进入了VMThread::execute，根据ParallelScavengeHeap的代码：

// Generate a VM operation
VM_ParallelGCFailedAllocation op(size, is_tlab, gc_count);
VMThread::execute(&op);

在分配失败时，会通过VMThread来执行failed_mem_allocate，这和堆栈信息也对应上了，于是继续看上面的堆栈信息，最关键的是这几段：
11707-#6 0x00002b57b7886e11 in PSParallelCompact::invoke_no_policy ()
11772-#7 0x00002b57b788d296 in PSScavenge::invoke ()
11820:#8 0x00002b57b7855d7e in ParallelScavengeHeap::failed_mem_allocate ()
11891-#9 0x00002b57b796b379 in VM_ParallelGCFailedAllocation::doit ()
根据这个堆栈来看，ParallelScavengeHeap::failed_mem_allocate调到了PSScavenge::invoke()，这个动作是用于执行新生代回收的，但诡异的是这个堆栈上PSScavenge::invoke后，竟然进入了PSParallelCompact代码，也就是Full GC，这也就说明并不是应用分配了一个巨大的对象，而是正常的Young GC的触发（其实这个从jstat中就证明了，只是当时太不细心了），到这一步了，那么关键的问题就是为什么在触发YGC的时候，变成了直接触发Full GC，从代码上来看如下：

    bool scavenge_was_done = PSScavenge::invoke_no_policy();

    PSGCAdaptivePolicyCounters* counters = heap->gc_policy_counters();
    if (UsePerfData)
      counters->update_full_follows_scavenge(0);
    if (!scavenge_was_done ||
        policy->should_full_GC(heap->old_gen()->free_in_bytes())) {
      if (UsePerfData)
        counters->update_full_follows_scavenge(full_follows_scavenge);

      GCCauseSetter gccs(heap, GCCause::_adaptive_size_policy);
      if (UseParallelOldGC) {
        PSParallelCompact::invoke_no_policy(false);
      } else {
        PSMarkSweep::invoke_no_policy(false);
      }
    }

从上面代码来看，只有scavenge_was_done为false或policy->should_full_GC(heap->old_gen()->free_in_bytes())为true时，才会触发PSParallelCompact，而从GC日志来看，是没有触发YGC的，于是继续看PSScavenge::invoke_no_policy代码，从代码来看，只有在下面的代码已经返回的情况下，才会没有任何YGC的日志信息：

   // Check for potential problems.
  if (!should_attempt_scavenge()) {
    return false;
  }

而should_attempt_scavenge这段代码中最关键的部分如下：

  size_t avg_promoted = (size_t) policy->padded_average_promoted_in_bytes();
  size_t promotion_estimate = MIN2(avg_promoted, young_gen->used_in_bytes());
  bool result = promotion_estimate < old_gen->free_in_bytes();

这也就是常说的GC悲观策略了，也就是说旧生代剩余的空间小于了YGC平均晋升的大小，在GC频繁时，可以看到旧生代剩余还有300多M，觉得这不太可能呀，不过还是决定通过jstat来看看到底怎么样，于是，执行了：
jstat -J-Djstat.showUnsupported=true -snap [pid]
截取部分最重要的信息如下：
sun.gc.generation.1.name=”old”
sun.gc.generation.1.space.0.capacity=1073741824
sun.gc.generation.1.space.0.initCapacity=1073741824
sun.gc.generation.1.space.0.maxCapacity=1073741824
sun.gc.generation.1.space.0.name=”old”
sun.gc.generation.1.space.0.used=744389904

sun.gc.policy.avgBaseFootprint=355284672
sun.gc.policy.avgMajorIntervalTime=9105
sun.gc.policy.avgMajorPauseTime=1640
sun.gc.policy.avgMinorIntervalTime=5171
sun.gc.policy.avgMinorPauseTime=330
sun.gc.policy.avgOldLive=744361216
sun.gc.policy.avgPretenuredPaddedAvg=251
sun.gc.policy.avgPromotedAvg=178848128
sun.gc.policy.avgPromotedDev=106732344
sun.gc.policy.avgPromotedPaddedAvg=499045152
悲观策略检查的其实就是avgPromotedPaddedAvg < space.0.capacity - space.0.used。
于是原因终于清楚了，由于平均晋升的大小一直 > 旧生代的剩余空间（因为每次FGC后旧生代都只有300多M是空余的，这个在这个应用中是正常的），导致每次YGC的时候悲观策略一直触发，于是看到的就是频繁Full GC了，在这个应用中的解决方法比较简单，就是把旧生代放大一点，避免这个现象，例如：-Xms3g -Xmx3g。

可能有同学要关心为什么平均晋升大小会那么大，重启了个别机器，看到刚重启时的gc log如下：
2011-07-17T10:59:03.481+0800: 10.160: [GC [PSYoungGen: 786432K->23851K(917504K)] 786432K->23851K(3014656K), 0.0967130 secs] [Times: user=0.08 sys=0.03, real=0.09 secs]
2011-07-17T10:59:12.633+0800: 19.312: [GC [PSYoungGen: 810283K->64502K(917504K)] 810283K->64502K(3014656K), 0.0728670 secs] [Times: user=0.17 sys=0.06, real=0.07 secs]
2011-07-17T10:59:16.286+0800: 22.965: [GC [PSYoungGen: 850934K->131064K(917504K)] 850934K->284737K(3014656K), 0.3072120 secs] [Times: user=0.91 sys=0.29, real=0.31 secs]
2011-07-17T10:59:19.405+0800: 26.084: [GC [PSYoungGen: 917496K->131047K(917504K)] 1071169K->606647K(3014656K), 0.5184690 secs] [Times: user=1.73 sys=0.32, real=0.52 secs]
2011-07-17T10:59:21.590+0800: 28.268: [GC [PSYoungGen: 917479K->131048K(917504K)] 1393079K->1019546K(3014656K), 0.5787500 secs] [Times: user=1.78 sys=0.38, real=0.58 secs]
可以看到，这几次YGC后的平均晋升大小就是：310m+，因此如果此时旧生代只剩300m了，那么就会导致下一次YGC变成FGC，而如果下一次FGC后旧生代剩余的仍然是300m，那么就开始频繁的FGC了，在这个应用中这个现象比较正常的原因是需要cache一个700多m的东西。
为什么把旧生代空间放大点就能好呢？因为在这个应用中，只是因为刚启动的时候需要加载如此大的cache，所以其实后面随着YGC的进行，这个平均晋升大小会越来越小，另外一个调整了参数的，运行了一天后，平均晋升大小的值为：
sun.gc.policy.avgPromotedPaddedAvg=403000

总结来看，这次排查过程还是绕了很多弯路，其实一开始就应该通过pstack来看，full gc是什么地方在触发，然后反推就会更快的查出问题了。

从这个Case来看，对于需要Cache比较多内容的场景而言（尤其是启动时既要加载的），还是要给old留有一定的空间，否则悲观策略就要发威了，:)。

《分布式Java应用:基础与实践》样章、代码、纠错、补充

bluedavy — Sun, 30 May 2010 15:54:25 +0800

《分布式Java应用：基础与实践》一书中会存在一些错误的地方，以及一些尚未深入讲解的部分，在这篇文章里会提供纠错的信息以及补充的内容的文章的链接，关于书中错误的部分，还请各位海涵和帮助指正。

样章请从此下载：
http://bluedavy.com/book/booksample.pdf

随书的代码请从此处下载：
http://bluedavy.com/book/source.zip

===============纠错===============

第257页 — 感谢@偶系阿萌的反馈
“当节点较少时，有可能会出现这些机器节点是均匀分布的现象”
应修改为：
“当节点较少时，有可能会出现这些机器节点是不均匀分布的现象”

第41页 — 感谢dongtalk的反馈
“各厂商在实现JDK时通常会将符合Java语言规范的源代码编译为class文件的编译器”
应修改为：
“各厂商在实现JDK时通常会提供将符合Java语言规范的源代码编译为class文件的编译器”

第46页 — 感谢yeshucheng的反馈
图3.4中的“Booksrap ClassLoader”应为“BootStrap ClassLoader”

第68页
图3.13用来说明Sun hotspot中可用的GC，其中旧生代可用的GC的图有错误的地方，准确来说，在Sun Hotspot V 1.6.0中并行GC应该有两种：Parallel Mark Sweep和Parallel Compacting。

第71页
“只有经历过几次Minor GC仍然存活的对象，才放入旧生代中，这个在Minor GC中存活的次数在串行和ParNew方式时可通过-XX:MaxTenuringThreshold来设置，在Parallel Scavenge时则由Hotspot根据运行状况来决定。”
这句话准确的应为：
“只有经历过几次Minor GC仍然存活的对象，才放入旧生代中，这个在Minor GC中存活的最大次数在串行和ParNew方式时可通过-XX:MaxTenuringThreshold来设置，但并不代表对象一定会存活MaxTenuringThreshold次才会晋升到旧生代，串行和ParNew采用一个规则在每次Minor GC后计算可存活的次数，规则为累积每个age的对象所占的内存，一直计算到占用大小超过survivor space一半的age，如计算了所有的age，均未超过则以MaxTenuringThreshold为准，否则则以age为准，在Parallel Scavenge时默认情况下由Hotspot根据运行状况来决定。”。

第73页
“并行GC在基于SurvivorRatio值划分eden space和两块survivor space的方式上和串行GC一样。”
修正为
“默认情况下并行GC在基于SurvivorRatio值划分eden space和两块survivor space的方式上和串行GC一样，在开启-XX:+UseAdaptiveSizePolicy后则为每次Minor GC后动态计算eden、to的大小。”

第73页
“当在Eden Space上分配内存时Eden Space空间不足，JVM即触发Minor GC的执行，也可在程序中通过System.gc的方式（可通过在启动参数中增加-XX:+DisableExplicitGC来避免程序中调用System.gc触发GC）来触发。”
修正为
“当在Eden Space上分配内存时Eden Space空间不足，JVM即触发Minor GC的执行，当旧生代采用并行GC时，也可在程序中通过System.gc的方式（可通过在启动参数中增加-XX:+DisableExplicitGC来避免程序中调用System.gc触发GC）来触发。”

第77页 — 感谢dongtalk的反馈
“首先将代空间划分为并行线程个数的区域（regions）”
应修改为
“首先将旧生代空间划分为并行线程个数的区域（regions）”

第77页
并行应为并行Compacting，书中没有介绍Parallel Mark Sweep，在后续的blog中会进行完善；

第78页
这句话是错误的：“并行是server级别机器（非32位Windows）上默认采用的GC方式，也可通过-XX:+UseParallelGC或-XX:+UseParallelOldGC来强制指定。”
修正为
“并行是server级别机器（非32位Windows）上默认采用的GC方式，可通过-XX:+UseParallelGC来指定使用Parallel Mark Sweep，通过-XX:+UseParallelOldGC来指定使用Parallel Compacting。”；

第80页
“CMS GC触发的条件为旧生代已使用的空间达到设定的CMSInitiatingOccupancyFraction百分比，例如默认CMSInitiatingOccupancyFraction为68%，如旧生代空间为1 000MB，那么当旧生代已使用的空间达到680MB时，CMS GC即开始执行；”
修正为
”CMS GC触发的条件为旧生代已使用的空间达到设定的CMSInitiatingOccupancyFraction百分比或持久代已使用的空间达到设定的CMSInitiatingPermOccupancyFraction百分比，例如在JDK 6.0中默认值为92，如旧生代空间为1000MB，那么当旧生代已使用的空间达到920MB时，CMS GC即开始执行；“

第80页
”持久代的GC也可采用CMS方式，方式为设置以下参数：-XX:+CMSPermGenSweepingEnabled -XX:+CMSClassUnloadingEnabled。“
修正为
”持久代的GC也可采用CMS方式，方式为设置此参数：-XX:+CMSClassUnloadingEnabled。“；

第87页
表3.1中：Server模式下旧生代和持久代GC方式准确的说应为Parallel Mark Sweep；

第87页
表3.2中：”-XX:+UseParallelGC 并行回收GC 并行GC“准确的说应为：”-XX:+UseParallelGC 并行回收GC Parallel Mark Sweep GC“；

第87页
表3.2中：“-XX:+UseParallelOldGC 并行回收GC 并行GC”准确的说应为：“-XX:+UseParallelOldGC 并行回收GC 并行Compacting GC”；

第99页 — 感谢liang xie的反馈
“如果要分析jvm堆dumap文件”
应为：
“如果要分析jvm堆dump文件”

第112页 — 感谢liang xie的反馈
“JDK常用package中的常用类进行分析……….，对根据需求合理地选择类会有一定的帮助”产生了重复。

第113页 — 感谢libai的反馈
”super调用的为AbstractList的默认构造器方法….ArrayList采用的是数组的方式来存放对象“
这段话出现了重复。

第183页 — 感谢liang xie的反馈
“在没有安装pidstat或内核版本为2.6.20以后”
应为
“在没有安装pidstat或内核版本为2.6.20之前”

===============内容补充===============
1、说说MaxTenuringThreshold这个参数
2、Sun JDK OOM