记录一次服务器宕机分析过程(1)-排查问题

发现宕机&启动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参数对比

随着pause参数的扩大,GC cycle触发周期变长,有更多垃圾内存未释放。但是,对比没有那么稳定,跟Lua GC中部分核心变量是估算的有关系。

step multiplier参数对比

随着step multiplier参数的增大,一次GC cycle执行时间变短,触发周期也变短,垃圾内存会更快被回收。对step multiplier参数调低后,Lua GC非常敏感,第一次GC cycle的执行很久都没有完成。

出问题服务的内存上涨状态比较类似于(step multiplier=190)的曲线,一直处在上涨状态,这大概是因为step multiplier不够,一直无法完成第一次GC cycle。最后改动的方案是调高了那个服务的step multiplier(=300,ps:似乎高了些)。内存就不再持续上涨。


在这个宕机挖坑过程中,还是有几个值得思考的地方:

  1. 为什么服务器进程运行几天都无法完成第一次GC cycle?想了想,可能有几点原因:
    (1)第一次GC需要处理的垃圾内存本来就很大。
    (2)Lua程序绝大部分时间都在休眠,导致GC cycle很少有执行机会(但是这个只是猜测)。
    以上两点导致很久没都没有完成第一次GC cycle。
  2. Lua GC默认参数大部分情况是没有问题的,但是对于需要平衡GC耗时和内存使用量的Lua程序,需要自己调整GC 参数。但是参数怎么调才是好的,还是需要经过充分的实验验证。
最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 151,688评论 1 330
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 64,559评论 1 273
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 101,749评论 0 226
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 42,581评论 0 191
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 50,741评论 3 271
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 39,684评论 1 192
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 31,122评论 2 292
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 29,847评论 0 182
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 33,441评论 0 228
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 29,939评论 2 232
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 31,333评论 1 242
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 27,783评论 2 236
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 32,275评论 3 220
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 25,830评论 0 8
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 26,444评论 0 180
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 34,553评论 2 249
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 34,618评论 2 249

推荐阅读更多精彩内容