受害人口述悲惨的遭遇——
1、最近一段时间(更换了预发机器后)我负责的一个应用的预发环境(线上稳定得像个婴儿~)特别不稳定,最先是应用频频的过几天就发现提供的接口不工作了,但容器Jetty还在跑得欢,于是jstack/jmap看,发现没有一个线程在跑我的war包中的程序,但是容器里个中间件的sar还跑得很欢(-_-|||),dump出来的对象也没有一点蛛丝马迹,所有日志到04:03就什么也没有了。然后查发现一个中间件的sar(远程接口层)包刚好在那个时候升级了,这玩意用OSGI的CloassLoader来加载整个应用,自然就怀疑它怎么着把我的Class都卸载掉了。简单,回滚到前一版本试试。 2、诡异的第二天还是4:03分,又发作了!排除了新sar的原因,就百思不和其解了,发现-XX:+CMSClassUnloadingEnabled开着,关掉。第二天还是一样!各种看代码都没有问题,在一个无穷循环的线程里打日志,各种招都用上还是老样子,连Servlet消失了,突然对哥掌握的Java知识产生了莫名其妙的怀疑… 3、这个应用改过名字,上边2个应用的目录都存在的。发现老目录的log文件修改时间居然是当前时间,再PS一看,发现启的进程是老应用的!新老2个war变化非常大,之前验证的点在老war里都木有的,好,觉得终于找着原因了。删老目录,找PE查脚本,果然查到启老应用的脚本!停掉脚本。甚至把老的应用目录link到新应用,即使脚本改不干净也不致于把我应用杀掉,免受接口调用方骚扰啊。 4、奇迹再一次发生了。应用在4:03准时消失了,老的确实也不起来了。 因为是预发环境,线上完全无问题,怀疑是环境问题所以也就一直没花太多时间去查。PE也觉不再有脚本在跑了,好吧,决定好好查一下。 首先,看系统日志,希望能找到SSH登录日志、命令执行日志或进程启动/终止日志,搜4点这个时间,wtmp/secure都没有发现。 然后,找messages这个时间点,找到:Jun 20 04:05:14 ***.pre.cm3 kernel: : **java invoked oom-killer**: gfp_mask=0x201d2, order=0, oomkilladj=0 Jun 20 04:05:14 ***.pre.cm3 kernel: : Jun 20 04:05:14 ***.pre.cm3 kernel: : Call Trace: Jun 20 04:05:14 ***.pre.cm3 kernel: : [] out_of_memory+0x8b/0x203 ... Jun 20 04:05:18 ***.pre.cm3 kernel: : Mem-info: ... oom-killer,之前不知道有这个东西,想想JVM自己不可能发生OOM,因为即没OOM日志也没Crash Core日志,而且还每次都是同一时间点!应用中也木有这种定时任务。关于Linux OOM-killer机制——linux oom-killer是一种自我保护机制,当系统分配不出内存时(触发条件)会触发这个机制,由操作系统在己有进程中挑选一个占用内存较多,回收内存收益最大的进程kill掉来释放内存。 系统为每个进程做评估(/proc/<pid>/oom_score中数值最大的进程被kill掉),参考这里。 前面的问题,Java进程占用内存足够多,进程生存又比较短,正是OOM-killer的首选啊,所以中招。 1.
/ 2.
badness - calculate a numeric value for how bad this task has been 3.
@p: task struct of which task we should calculate 4.
@uptime: current uptime in seconds 5.
6.
The formula used is relatively simple and documented inline in the 7.
function. The main rationale is that we want to select a good task 8.
to kill when we run out of memory. 9.
10.
Good in this context means that: 11.
1) we lose the minimum amount of work done 12.
2) we recover a large amount of memory 13.
3) we don’t kill anything innocent of eating tons of memory 14.
4) we want to kill the minimum amount of processes (one) 15.
5) we try to kill the process the user expects us to kill, this 16.
algorithm has been meticulously tuned to meet the principle 17.
of least surprise … (be careful when you change it) 18.
/ 另外,Linux的malloc分配内存,也不是一次到位的真分配了指定大小的物理内存(Overcommit机制,另一篇也不错,这里Fenny一篇),而是先承诺你,实际用到的时候才去系统分配,如果刚好那个时候内存不够了,就会触发oom-killer。 > Linux下有3种Overcommit的策略(参考内核文档:vm/overcommit-accounting),可以在/proc/sys/vm/overcommit_memory配置。取0,1和2三个值,默认是0。 > > 0:启发式策略,比较严重的Overcommit将不能得逞,比如你突然申请了128TB的内存。而轻微的Overcommit将被允许。另外,root能Overcommit的值比普通用户要稍微多些。 > > 1:永远允许Overcommit,这种策略适合那些不能承受内存分配失败的应用,比如某些科学计算应用。 > > 2:永远禁止Overcommit,在这个情况下,系统所能分配的内存不会超过swap+RAM系数(/proc/sys/vm/overcmmit_ratio,默认50%,你可以调整),如果这么多资源已经用光,那么后面任何尝试申请内存的行为都会返回错误,这通常意味着此时没法运行任何新程序。 我的机器为什么会触发OOM-killer——** 先查了下sar的日志: 1.
12:00:01 AM CPU %user %nice %system %iowait %steal %idle 2.
04:00:01 AM all 0.01 0.00 0.00 0.00 0.01 99.98 3.
04:10:02 AM all 0.55 0.00 20.71 37.97 0.06 40.71 4.
04:20:01 AM all 0.01 0.00 0.04 0.24 0.01 99.71 system cpu占的比较多,应该是kernel OOM-killer执行所占掉的。再看没有启java进程情况下这个时间点的日志,CPU是正常的。 cat /proc/sys/vm/overcommit_memory 值0,即启发式策略,允许Overcommit。 总可用内存才2G(更换机器之前为4G,后面的配置是按4G来配的),JVM就申请了2G+,再加上nginx所占申请内存,远超实际物理内存2G+Swap 1G范围了,应用之所以正常是应用启动不久,实际用的内存并没用那么多,到晚上达到临界值,其实一个不相干的定时任务申请内存,刚好就触发了OOM-killer了。 nginx和java应用线上长时间验证是稳定的,不存在内存泄露,至于机器上4:03启动了什么任务,其实都不那么重要了。 参考资料:Linux系统日志管理How the Linux OOM killer worksTaming the OOM killerWhen Linux Runs Out of MemoryOOM KillerLinux下OOM Killer机制详解Linux 的 Out-of-Memory (OOM) KillerMemory overcommit in Linux
本文来源于"阿里中间件团队播客",原文发表时间"
2012-06-26 "
相关资源:敏捷开发V1.0.pptx