发现宕机&启动coredump
最近给版署审核版本用的服务器每隔几天就会宕机,情况比较类似,都是大厅服的进程直接没有掉了。查看服务器log,没有发现什么线索。怀疑是服务器进程崩溃掉了,于是开启了服务器的coredump,等待下次宕机通过gdb查询问题出在什么地方。
coredump无效
过了几天,服务器再次宕机,查看coredump文件夹,发现并没有生成dump文件。仔细想了一下,dump文件只有在程序崩溃时才会生成,那么可能是程序没有崩溃,而且通过其他方式退出了(自己退出,或者被kill)。
怀疑内存问题
这个时候想到内存问题,于是重启服务器运行一段时间后查看服务器内存,果然发现服务器进程中某个服务(一个服务运行在一个独立的lua虚拟机上)内存占用异常(占用了几百M,并且一直上涨)。为了验证问题,手写了一个10几行代码的C程序,不停申请内存并且不释放。果然程序在吃光系统内存后闪退了,并且没有产生coredump文件。留下打印信息:Memor已杀死。
引出OOM killer
google了一下这个打印信息,发现linux有一个叫做OOM-killer(Out Of Memory killer)的机制。
OOM killer会在系统内存耗尽的情况下触发,选择性的干掉一些进程,以求释放一些内存。OOM killer是通过
/proc/<pid>/oom_score
这个值来决定哪个进程被干掉的。这个值是系统综合进程的内存消耗量、CPU时间(utime + stime
)、存活时间(uptime - start time
)和oom_adj
计算出的,消耗内存越多分越高,存活时间越长分越低。总之,总的策略是:损失最少的工作,释放最大的内存同时不伤及无辜的用了很大内存的进程,并且杀掉的进程数尽量少。
找到系统日志文件(/var/log/messages),发现几条对应的信息:
Jul 27 14:54:11 iZbp1gq49eb2h8qr5ktv1gZ kernel: Out of memory: Kill process 1119 (test) score 865 or sacrifice child
Jul 27 14:54:11 iZbp1gq49eb2h8qr5ktv1gZ kernel: Killed process 1119 (test) total-vm:962016kB, anon-rss:903972kB, file-rss:80kB
果然是OOM-killer杀死了我的例子程序,那么log里会不会有服务器进程被杀死的痕迹呢,继续翻日志,又发现几条可疑的信息:
Jul 23 20:48:33 iZ23n1006xeZ kernel: [17045726.198604] mongod invoked oom-killer: gfp_mask=0x201da, order=0, oom_score_adj=0
...
这个时间点(Jul 23 20:48:33)打印的信息很长,大概意思是mongod触发了OOM-killer。log里没有游戏服务器进程相关的信息,而服务器进程也确实是在Jul 23时间点附近挂掉的,应该是mongod触发了OOM-killer,然后OOM-killer杀死了服务器进程。为了确认服务器挂掉的时间点和日志信息产生的时间点吻和,我通过crontab起了一个定时shell脚本,用来监测服务器进程的执行情况。继续等待下次宕机。
追踪内存泄漏
这个时候已经大概确定,是内存问题导致服务器进程被杀死。于是开始追踪内存的泄漏问题。
首先查看这个有问题的服务的代码特征,这个服务主要的工作是,不停的向中心服务器请求最新的排行榜数据,并且替换本地的旧排行榜数据,也就是说在整个程序的执行过程中,会不停的产生大量的临时内存。
然后,我观察了一下这个服务的内存上涨特征,发现它的内存是一直在周期上涨(内存上涨周期 == 请求数据的周期)的。是Lua GC失效了吗?我在debug console输入GC命令强制执行了一次GC(在后面的研究中明白,它实际是强制执行了一次完整的GC cycle),发现内存马上降下来了,这说明内存是可以回收掉的。是GC无法被自动触发吗?
Lua GC
于是,研究了一下Lua的GC机制。根据lua官方文档(www.lua.org/manual/5.3/manual.html#2.5)描述,Lua的GC实现了一个叫做incremental mark-and-sweep collector内存回收机制(wiki.luajit.org/New-Garbage-Collector)。大概意思就是一个基于三种状态的可分步执行的GC机制,每个GC cycle可以分多个GC step完成。GC算法可以设置两个核心参数garbage-collector pause、garbage-collector step multiplier.;在官方文档给出的对两个参数的大概的解释(具体的描述可以看官方文档)是:
pause :控制多久开始一次新的GC cycle,默认是200,表示内存是2(
200/100
)倍时开始一次新的GC cycle。
step multiplier :GC速度相对于内存分配速度的倍数,默认是200,即2倍(200/100
)。
单看以上的解释还是很难理解这两个参数,参看云风对Lua GC分析的文档(blog.codingnow.com/2011/03/lua_gc_3.html)。对两个参数进一步的理解是:
pause:当前内存如果是估算的实际使用内存的(
pause/100
)倍时触发GC cycle。比如,估算的实际使用的内存是100KB,当内存占用达到200KB时会触发GC cycle。
step multiplier:整个GC cycle是分多个GC step完成的,step multiplier调节每个GC step中会执行多少个GC single-step。
两者的直观意义是:
pause:越小,回收越积极(aggressive);越大回收越不积极(less aggressive)。默认:
200
。
step multiplier:越小,回收越不积极(less aggressive);越大回收越积极(aggressive)。默认:200
。
接着,我写了一个周期性执行,并且产生大量临时内存的Lua程序,通过设置这两个参数来看一下,这两个参数对Lua GC的实际影响(X轴为执行次数;Y轴为程序内存单位KB
):
随着pause参数的扩大,GC cycle触发周期变长,有更多垃圾内存未释放。但是,对比没有那么稳定,跟Lua GC中部分核心变量是估算的有关系。
随着step multiplier参数的增大,一次GC cycle执行时间变短,触发周期也变短,垃圾内存会更快被回收。对step multiplier参数调低后,Lua GC非常敏感,第一次GC cycle的执行很久都没有完成。
出问题服务的内存上涨状态比较类似于(step multiplier=190)的曲线,一直处在上涨状态,这大概是因为step multiplier不够,一直无法完成第一次GC cycle。最后改动的方案是调高了那个服务的step multiplier(=300
,ps:似乎高了些)。内存就不再持续上涨。
在这个宕机挖坑过程中,还是有几个值得思考的地方:
- 为什么服务器进程运行几天都无法完成第一次GC cycle?想了想,可能有几点原因:
(1)第一次GC需要处理的垃圾内存本来就很大。
(2)Lua程序绝大部分时间都在休眠,导致GC cycle很少有执行机会(但是这个只是猜测)。
以上两点导致很久没都没有完成第一次GC cycle。- Lua GC默认参数大部分情况是没有问题的,但是对于需要平衡GC耗时和内存使用量的Lua程序,需要自己调整GC 参数。但是参数怎么调才是好的,还是需要经过充分的实验验证。