受害人口述悲惨的遭遇——

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这个时间点,找到:

Jun2004:05:14***.pre.cm3kernel::javainvokedoom-killer:gfp_mask=0x201d2,order=0,oomkilladj=0

Jun2004:05:14***.pre.cm3kernel::

Jun2004:05:14***.pre.cm3kernel::CallTrace:

Jun2004:05:14***.pre.cm3kernel::[]out_of_memory+0x8b/0x203

...

Jun2004:05:18***.pre.cm3kernel::Mem-info:

...

oom-killer,之前不知道有这个东西,想想JVM自己不可能发生OOM,因为即没OOM日志也没CrashCore日志,而且还每次都是同一时间点!应用中也木有这种定时任务。

关于LinuxOOM-killer机制——

linuxoom-killer是一种自我保护机制,当系统分配不出内存时(触发条件)会触发这个机制,由操作系统在己有进程中挑选一个占用内存较多,回收内存收益最大的进程kill掉来释放内存。

系统为每个进程做评估(/proc/<pid>/oom_score中数值最大的进程被kill掉),参考这里

前面的问题,Java进程占用内存足够多,进程生存又比较短,正是OOM-killer的首选啊,所以中招。

  1. /**

  2. *badness–calculateanumericvalueforhowbadthistaskhasbeen

  3. *@p:taskstructofwhichtaskweshouldcalculate

  4. *@uptime:currentuptimeinseconds

  5. *

  6. *Theformulausedisrelativelysimpleanddocumentedinlineinthe

  7. *function.Themainrationaleisthatwewanttoselectagoodtask

  8. *tokillwhenwerunoutofmemory.

  9. *

  10. *Goodinthiscontextmeansthat:

  11. *1)welosetheminimumamountofworkdone

  12. *2)werecoveralargeamountofmemory

  13. *3)wedon’tkillanythinginnocentofeatingtonsofmemory

  14. *4)wewanttokilltheminimumamountofprocesses(one)

  15. *5)wetrytokilltheprocesstheuserexpectsustokill,this

  16. *algorithmhasbeenmeticulouslytunedtomeettheprinciple

  17. *ofleastsurprise…(becarefulwhenyouchangeit)

  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:01AMCPU%user%nice%system%iowait%steal%idle

  2. 04:00:01AMall0.010.000.000.000.0199.98

  3. 04:10:02AMall0.550.0020.7137.970.0640.71

  4. 04:20:01AMall0.010.000.040.240.0199.71

systemcpu占的比较多,应该是kernelOOM-killer执行所占掉的。再看没有启java进程情况下这个时间点的日志,CPU是正常的。

cat/proc/sys/vm/overcommit_memory值0,即启发式策略,允许Overcommit。

总可用内存才2G(更换机器之前为4G,后面的配置是按4G来配的),JVM就申请了2G+,再加上nginx所占申请内存,远超实际物理内存2G+Swap1G范围了,应用之所以正常是应用启动不久,实际用的内存并没用那么多,到晚上达到临界值,其实一个不相干的定时任务申请内存,刚好就触发了OOM-killer了。

nginx和java应用线上长时间验证是稳定的,不存在内存泄露,至于机器上4:03启动了什么任务,其实都不那么重要了。

参考资料:

Linux系统日志管理

HowtheLinuxOOMkillerworks

TamingtheOOMkiller

WhenLinuxRunsOutofMemory

OOMKiller

Linux下OOMKiller机制详解

Linux的Out-of-Memory(OOM)Killer

MemoryovercommitinLinux