记录一次游戏服务器的批量掉线事故(iteye文章迁移，2014）

    我负责的手游项目先后在大陆和台湾上线，大陆服先上的，一直比较稳定，台湾服一个多月前出现了半夜无法登陆和批量掉线的问题,由于一开始判断错了方向,导致找到正确的原因花了不少时间,现在把这个问题记录下来,分享一下.也许以后碰上类似的问题能用的上.

问题描述:服务器运行一段时间后,玩家会无法登录,然后查gsx的日志,也没有发现死锁.解决的办法就是重启,但是重启之后同样的服务器隔一两天又会出现同样的问题,时间有时候在半夜有时候在白天. 台湾的服务器人数明显比大陆少,最火的1服高峰期也就是2000多人在线,但是大陆服跑5000人都没有问题.

    尝试解决:

1. 首先想到是不是代码出现死循环了,导致服务器失去响应,无法登录.用jstack命令在服务器宕的时候打出所有的线程并对照代码,没有发现有死循环的问题.然后因为是版本更新后出了这个问题,所以怀疑是不是新加的代码导致了这个问题,又把这个版本的源码和上个版本用beyond compare挨个对比了一遍,也没有发现什么可疑的点.

2. 回到原点,重新思考下问题的原因.因为台湾服的服务器功能相当于大陆服的子集,台湾有的功能大陆都有,但大陆服却一切正常.所以怀疑是不是软硬件的差异造成的.台湾的服务器cpu开启了超线程,能看见24个核心,比大陆的8核要强;内存跟大陆一样都是64G,但是硬盘是用dell的310raid卡做的raid1, 性能较弱.在gsx的日志里面也发现xdb  checkpoint要十几秒,大陆服一般1秒内就搞定了.所以当时觉得这个很可能是问题所在.请教了xdb作者,他觉得checkpoint要这么长时间肯定是有问题的,但是具体原因也不好说,可能跟磁盘的写入速度有关. 我又请系统部的同事把大陆的raid5和台湾的raid1做对比,发现写入性能确实差了一倍还要多,于是就让台湾的运营商找了几台服务器,把raid1升级成710的raid卡做raid10,并挪了几台出问题的服务器.

           结果是悲剧的,checkpoint 时间过长的问题解决了,但是还是会出现跑几天就出现无法登录的问题,说明这是两个问题

 

   3.无法登录的问题还没解决,台湾服又出了个新问题:每天会有1,2组服务器出现2,300人的掉线,看原因都是checkmove频率过快踢掉的,但是台湾目前还没有大面积的外挂出现,出现这种问题的原因是堆积了太多ccheckmove协议要处理,等到这些堆积的协议开始处理的时候,就会被判断为超速被踢掉. 那为什么协议会堆积呢,大陆服的人数比台湾服还多,也可以处理的过来啊.第一次怀疑到了GC的身上,可能是GC的时候STW(stop the world),导致协议被堆积起来没有处理.查看gc.log的日志,发现堆的大小确实比大陆服要大,而且在出现无法登陆的问题的时候,还出现了好多次full gc,应该是这些full gc导致服务器失去响应了.但是jvm的参数大陆服和台湾服都是一样的,GC的策略也应该是一样的,是不是因为台湾服的内核跟大陆不一样导致的? 因为之前更新内核解决了link的一个内存溢出的问题,所以这次也希望能解决这个奇怪的问题.由于系统部的同事也没有装过台湾的机器,最后还是请老兔帮忙,台湾那边提供远程卡控制服务器,老兔弄了一个下午,终于把机器装上了跟大陆服一模一样的操作系统和内核.

     结果再次悲剧,这次系统的升级没有解决问题...... 台湾方面觉得他们已经升级了机器但还没有解决问题, 开始质疑我们的办事效率,天天qq弹窗催, 鸭梨山大.

   4.回到原点,重新思考下现在拥有的线索.从GC的日志来看,堆的大小比大陆服要大,而且还会在短时间内冲到12G的上限,导致老年代的cms concurrent mode failed,引起full gc. 这些问题在大陆服是不

 存在的,而且升级到跟大陆服一样的os和内核也没有解决问题.那只能从GC的参数入手了.用PrintFlagsFinal命令打出所有的JVM 参数,再在大陆服上也打一份,对比下参数,总共600多个参数,只有3个不一样:

         大陆服                                                                                                                                台湾服

 

         uintx InitialHeapSize                          := 1055530816   uintx InitialHeapSize                          := 1054733184

 

         uintx MaxHeapSize                           := 16890462208  uintx MaxHeapSize                           := 16875782144

 

         uintx ParallelGCThreads                       := 8            uintx ParallelGCThreads                       := 18

 

         InitialHeapSize 和 MaxHeapSize 的差异应该是由于内存的大小的细微差别造成的, ParallelGCThreads是因为台湾服务器开启了超线程,而ParallelGCThreads是跟cpu的数目相关的,看起来也没什么问题,GC线程多了也不是坏事,不超过cpu的数目就好.

          再用jmap -heap pid 看了下runtime jvm 参数,基本上都是一样的,除了MaxNewSize,台湾是374m,大陆是170m左右.(这个地方逗比了,以为新生代多一百多M没什么问题)

          using parallel threads in the new generation.

     using thread-local object allocation.

     Concurrent Mark-Sweep GC

  

Heap Configuration:

    MinHeapFreeRatio = 40

    MaxHeapFreeRatio = 70

    MaxHeapSize      = 21474836480 (20480.0MB)

    NewSize          = 21757952 (20.75MB)

    MaxNewSize       = 392560640 (374.375MB)

    OldSize          = 65404928 (62.375MB)

    NewRatio         = 7

    SurvivorRatio    = 8

    PermSize         = 268435456 (256.0MB)

    MaxPermSize      = 268435456 (256.0MB)

 

   没看出有什么太大的问题,于是在gsxdb.properties里面加了几个参数,一是加大堆的上限,二是让cms gc尽快触发,三是略微提高下对象进入老年代的门槛(threshold 默认是4):

 

   -Xms4G  -Xmx20G -XX:CMSInitiatingOccupancyFraction=50 -XX:+UseCMSInitiatingOccupancyOnly -XX:MaxTenuringThreshold=5

 

      结果稍微好了一点,没有出现大面积的掉线,也没有出现无法登录的现象,但是从gc的日志来看,内存占用还是过高...... 这个方法应该是通过堆上限的提高规避了Full GC的问题,

 

但是治标不治本,还是得继续找原因.

 

          5.还是来回的看大陆和台湾服的gc.log文件,突然无意中发现大陆的gc的频率比台湾高好多,以前都光注意堆的大小了,没有注意时间. 想起来以前用过一个gclogviewer的软件,搜了一下,

 

已经停止更新了,但是java 6还是支持的.于是把大陆和台湾的gc.log做了个图形化的对比:

 

         台湾服:

 

 

 

 

大陆服:

 

 

 

 

         从图形上看,大陆服无论是young gc,还是cms gc,都比台湾服的频率高很多,而且这个工具还打出了具体的数字:台湾每0.74秒才做一个young gc,大陆是0.21秒就做一次;台湾每151秒才做一次cms gc,大陆是55秒就来一次. 再联想到MaxNewSize台湾服是大陆的一倍多,推测可能是MaxNewSize大导致young gc频率低,那么对象的年龄就增长的慢,进入老年代的速度也慢,导致cms gc的频率也低了.而大陆服是maxnewsize偏小,young gc的频率很高,这样会有较多对象进入老年代,导致cms gc的频率升高,虽然这样比较耗cpu,但是却可以保证堆维持在一个较低的水平.于是在台湾服的gsxdb.properties里面加上NewSize和MaxNewSize参数,把年轻代控制在170m左右.

 

          这次的结果终于是正能量的,堆的大小彻底降下来了.

  

         6.引申出来一个问题,为什么MaxNewSize会有一倍的差距? 我以前只知道没有手动设置的参数,会由java的ergonomic来设置,但是它会根据什么来设置就不知道了.这个问题也比较偏,在google

 

上搜,stackoverflow上提问都没有解答,看来没有什么捷径,只能从jdk的源码里找了.于是从oracle的官网上下了hotspot jdk的源码,在Arguments.cpp里找到了答案:

 

  if (CMSUseOldDefaults) {  // old defaults: "old" as of 6.0

 

if FLAG_IS_DEFAULT(CMSYoungGenPerWorker) {

 

  FLAG_SET_ERGO(intx, CMSYoungGenPerWorker, 4*M);

 

}

 

young_gen_per_worker = 4*M;

 

new_ratio = (intx)15;

 

min_new_default = 4*M;

 

tenuring_default = (intx)0;

 

} else { // new defaults: "new" as of 6.0

 

young_gen_per_worker = CMSYoungGenPerWorker;

 

new_ratio = (intx)7;

 

min_new_default = 16*M;

 

tenuring_default = (intx)4;

 

}

 

 

 

const uintx parallel_gc_threads =

 

(ParallelGCThreads == 0 ? 1 : ParallelGCThreads);

 

 

 

const size_t preferred_max_new_size_unaligned =

 

    ScaleForWordSize(young_gen_per_worker * parallel_gc_threads);

 

  const size_t preferred_max_new_size =

 

align_size_up(preferred_max_new_size_unaligned, os::vm_page_size());

 

         MaxNewSize的值是跟parallelgcthreads有关的,也就是说,因为台湾服开了超线程,导致parallelgcthreads的值变成了18,所以MaxNewSize变大了.大陆服因为没开超线程,而且之前的centos核心有问题,12核的cpu只能用8个核.导致MaxNewSize比台湾服小很多.