一次系统宕机认识系统日志

今天开发小伙伴给我说，哥，你帮我看下吧，系统无缘无故的宕机了。之前跑了一个多月好好的。

我问了下这台机器的配置是啥？

虚拟机：1核2G

jvm配置：xms:1gxmx:1g

我就开始着手查看

监控指标怎么样？

监控系统这两天在升级，暂时看不了；

开发反馈，load在1左右，cpu高峰也就80%，我先信了。
现场有无保留（堆栈信息）？

没有OOM的输出
gc日志有没有？

有，gc看着都正常
jvm的errorFile呢？

没有配置。

好吧。这些都没有咋排查。

突然想起linux应该会把这些行为都记录下来的。

百度一下，发现发现在/var/log/目录下记录了好多行为日志。其中messages中记录的最齐全。先看下吧。

申请权限，开工。

less /var/log/messages找到临近的时间点  Jun  6 22:46

# 这里有个oom-killer,这是什么鬼？带着疑问往下看Jun  6 22:46:12 主机名 kernel: rpm invoked oom-killer: gfp_mask=0x201da, order=0, oom_score_adj=0Jun  6 22:46:12 主机名 kernel: rpm cpuset=/ mems_allowed=0Jun  6 22:46:12 主机名 kernel: CPU: 0 PID: 10109 Comm: rpm Not tainted 3.10.0-514.6.2.el7.x86_64 #1Jun  6 22:46:12 主机名 kernel: Hardware name: Alibaba Cloud Alibaba Cloud ECS, BIOS 8c24b4c 04/01/2014Jun  6 22:46:12 主机名 kernel: intel_powerclamp: No package C-state availableJun  6 22:46:12 主机名 kernel: ffff8800399c8fb0Jun  6 22:46:12 主机名 kernel: 00000000fdecda58 ffff88000414b910 ffffffff816862acJun  6 22:46:12 主机名 kernel: ffff88000414b9a0 ffffffff81681257 ffffffff810eab9c ffff880079ce8ec0Jun  6 22:46:12 主机名 kernel: ffff880079ce8ed8 0000000000000202 ffff8800399c8fb0 ffff88000414b990Jun  6 22:46:12 主机名 kernel: Call Trace:Jun  6 22:46:12 主机名 kernel: [<ffffffff816862ac>] dump_stack+0x19/0x1bJun  6 22:46:12 主机名 kernel: [<ffffffff81681257>] dump_header+0x8e/0x225Jun  6 22:46:12 主机名 kernel: [<ffffffff810eab9c>] ? ktime_get_ts64+0x4c/0xf0Jun  6 22:46:12 主机名 kernel: [<ffffffff8113ccaf>] ? delayacct_end+0x8f/0xb0# 因为oom kill掉进程？Jun  6 22:46:12 主机名 kernel: [<ffffffff8118475e>] oom_kill_process+0x24e/0x3c0Jun  6 22:46:12 主机名 kernel: [<ffffffff811841fd>] ? oom_unkillable_task+0xcd/0x120Jun  6 22:46:12 主机名 kernel: [<ffffffff811842a6>] ? find_lock_task_mm+0x56/0xc0Jun  6 22:46:12 主机名 kernel: [<ffffffff810937ee>] ? has_capability_noaudit+0x1e/0x30# oom Jun  6 22:46:12 主机名 kernel: [<ffffffff81184f96>] out_of_memory+0x4b6/0x4f0Jun  6 22:46:12 主机名 kernel: [<ffffffff81681d60>] __alloc_pages_slowpath+0x5d7/0x725Jun  6 22:46:12 主机名 kernel: [<ffffffff8118b0a5>] __alloc_pages_nodemask+0x405/0x420Jun  6 22:46:12 主机名 kernel: [<ffffffff811cf25a>] alloc_pages_current+0xaa/0x170Jun  6 22:46:12 主机名 kernel: [<ffffffff81180667>] __page_cache_alloc+0x97/0xb0Jun  6 22:46:12 主机名 kernel: [<ffffffff811831b0>] filemap_fault+0x170/0x410Jun  6 22:46:12 主机名 kernel: [<ffffffffa01bc016>] ext4_filemap_fault+0x36/0x50 [ext4]Jun  6 22:46:12 主机名 kernel: [<ffffffff811ac2ec>] __do_fault+0x4c/0xc0Jun  6 22:46:12 主机名 kernel: [<ffffffff811ac783>] do_read_fault.isra.42+0x43/0x130Jun  6 22:46:12 主机名 kernel: [<ffffffff811b0f11>] handle_mm_fault+0x6b1/0xfe0Jun  6 22:46:12 主机名 kernel: [<ffffffff81691d94>] __do_page_fault+0x154/0x450Jun  6 22:46:12 主机名 kernel: [<ffffffff81692176>] trace_do_page_fault+0x56/0x150Jun  6 22:46:12 主机名 kernel: [<ffffffff8169181b>] do_async_page_fault+0x1b/0xd0Jun  6 22:46:12 主机名 kernel: [<ffffffff8168e3b8>] async_page_fault+0x28/0x30Jun  6 22:46:12 主机名 kernel: Mem-Info:Jun  6 22:46:12 主机名 kernel: active_anon:407746 inactive_anon:71 isolated_anon:0#012 active_file:3018 inactive_file:3845 isolated_file:0#012 unevictable:0 dirty:7 writeback:0 unstable:0#012 slab_reclaimable:5853 slab_unreclaimable:5531#012 mapped:392 shmem:160 pagetables:2252 bounce:0#012 free:13070 free_pcp:30 free_cma:0# DMA，零拷贝的时候学习过，这块操作磁盘或网卡？Jun  6 22:46:12 主机名 kernel: Node 0 DMA free:7660kB min:380kB low:472kB high:568kB active_anon:6100kB inactive_anon:4kB active_file:48kB inactive_file:376kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15992kB managed:15908kB mlocked:0kB dirty:0kB writeback:0kB mapped:8kB shmem:4kB slab_reclaimable:152kB slab_unreclaimable:132kB kernel_stack:176kB pagetables:252kB unstable:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:2378 all_unreclaimable? yesJun  6 22:46:12 主机名 kernel: lowmem_reserve[]: 0 1822 1822 1822# 这又一个DMAJun  6 22:46:12 主机名 kernel: Node 0 DMA32 free:44620kB min:44672kB low:55840kB high:67008kB active_anon:1624884kB inactive_anon:280kB active_file:12024kB inactive_file:15004kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:2080640kB managed:1867832kB mlocked:0kB dirty:28kB writeback:0kB mapped:1560kB shmem:636kB slab_reclaimable:23260kB slab_unreclaimable:21992kB kernel_stack:18976kB pagetables:8756kB unstable:0kB bounce:0kB free_pcp:120kB local_pcp:120kB free_cma:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? noJun  6 22:46:12 主机名 kernel: lowmem_reserve[]: 0 0 0 0# 7mb左右的读写Jun  6 22:46:12 主机名 kernel: Node 0 DMA: 37*4kB (UEM) 17*8kB (UEM) 17*16kB (UEM) 8*32kB (UEM) 7*64kB (UEM) 6*128kB (UEM) 2*256kB (EM) 2*512kB (EM) 0*1024kB 2*2048kB (UM) 0*4096kB = 7660kB# 44mb左右的读写Jun  6 22:46:12 主机名 kernel: Node 0 DMA32: 545*4kB (UE) 211*8kB (UE) 312*16kB (UEM) 228*32kB (UEM) 151*64kB (UE) 81*128kB (E) 25*256kB (EM) 4*512kB (E) 0*1024kB 0*2048kB 0*4096kB = 44636kB# 大页 total 为0，free 为0Jun  6 22:46:12 主机名 kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kBJun  6 22:46:12 主机名 kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB# 一共7028个pagecacheJun  6 22:46:12 主机名 kernel: 7028 total pagecache pages# 0个页面在swap cache里（难道没开启虚拟内存？）Jun  6 22:46:12 主机名 kernel: 0 pages in swap cacheJun  6 22:46:12 主机名 kernel: Swap cache stats: add 0, delete 0, find 0/0Jun  6 22:46:12 主机名 kernel: Free swap  = 0kBJun  6 22:46:12 主机名 kernel: Total swap = 0kBJun  6 22:46:12 主机名 kernel: 524158 pages RAMJun  6 22:46:12 主机名 kernel: 0 pages HighMem/MovableOnlyJun  6 22:46:12 主机名 kernel: 53223 pages reserved# 这是列出的所有进程以及占用的内存Jun  6 22:46:12 主机名 kernel: [ pid ]   uid  tgid total_vm      rss nr_ptes swapents oom_score_adj nameJun  6 22:46:12 主机名 kernel: [  326]     0   326    17396       90      37        0             0 systemd-journalJun  6 22:46:12 主机名 kernel: [  349]     0   349    10793      145      22        0         -1000 systemd-udevdJun  6 22:46:12 主机名 kernel: [  369]     0   369    28638      120      26        0         -1000 auditdJun  6 22:46:12 主机名 kernel: [  398]     0   398     6107      177      17        0             0 systemd-logindJun  6 22:46:12 主机名 kernel: [  400]    81   400     6130      115      17        0          -900 dbus-daemonJun  6 22:46:12 主机名 kernel: [  417]     0   417   163839      212     140        0             0 rsyslogdJun  6 22:46:12 主机名 kernel: [  422]     0   422    31043      186      16        0             0 crondJun  6 22:46:12 主机名 kernel: [  429]     0   429     5942       50      16        0             0 atdJun  6 22:46:12 主机名 kernel: [  462]     0   462    27509       47      10        0             0 agettyJun  6 22:46:12 主机名 kernel: [  463]     0   463    27509       45      10        0             0 agettyJun  6 22:46:12 主机名 kernel: [  664]     0   664    27632     3116      51        0             0 dhclientJun  6 22:46:12 主机名 kernel: [ 1002]     0  1002   138267     2670      87        0             0 tunedJun  6 22:46:12 主机名 kernel: [ 1003]     0  1003     5637       80       8        0             0 aliyun-serviceJun  6 22:46:12 主机名 kernel: [ 1038]    38  1038     7353      174      19        0             0 ntpdJun  6 22:46:12 主机名 kernel: [ 2172]     0  2172    20611      213      41        0         -1000 sshdJun  6 22:46:12 主机名 kernel: [15215]     0 15215    19959      214      39        0             0 zabbix_agentdJun  6 22:46:12 主机名 kernel: [15216]     0 15216    19959      252      39        0             0 zabbix_agentdJun  6 22:46:12 主机名 kernel: [15217]     0 15217    19959      197      39        0             0 zabbix_agentdJun  6 22:46:12 主机名 kernel: [15218]     0 15218    19959      197      39        0             0 zabbix_agentdJun  6 22:46:12 主机名 kernel: [15219]     0 15219    19959      197      39        0             0 zabbix_agentdJun  6 22:46:12 主机名 kernel: [15220]     0 15220    19959      217      39        0             0 zabbix_agentdJun  6 22:46:13 主机名 kernel: [  812]     0   812    11963      441      28        0             0 AliYunDunUpdateJun  6 22:46:13 主机名 kernel: [25084]     0 25084    45266    10302      86        0             0 AliYunDunJun  6 22:46:13 主机名 kernel: [29154]  1000 29154   887243   244986     654        0             0 javaJun  6 22:46:13 主机名 kernel: [ 1536]     0  1536   131429    11796     121        0             0 titanagentJun  6 22:46:13 主机名 kernel: [ 1538]     0  1538    21913       89      13        0             0 titan_monitorJun  6 22:46:13 主机名 kernel: [26827]     0 26827    17027      438      30        0             0 ilogtailJun  6 22:46:13 主机名 kernel: [26829]     0 26829   169139   102961     261        0             0 ilogtailJun  6 22:46:13 主机名 kernel: [30857]     0 30857    30509      160      13        0             0 wrapperJun  6 22:46:13 主机名 kernel: [30859]     0 30859   516227    12519      82        0             0 javaJun  6 22:46:13 主机名 kernel: [10097]     0 10097    50491     1321      51        0             0 AliSecureCheckAJun  6 22:46:13 主机名 kernel: [10109]     0 10109    45002     1700      44        0             0 rpmJun  6 22:46:13 主机名 kernel: [10112]     0 10112    44013      235      40        0             0 crondJun  6 22:46:13 主机名 kernel: [10113]     0 10113    44013      235      40        0             0 crondJun  6 22:46:13 主机名 kernel: [10114]     0 10114     1386       11       7        0             0 shJun  6 22:46:13 主机名 kernel: [10115]     0 10115     1386       11       7        0             0 sh# 综合评估进程29154的评分达到521（难道是最大）Jun  6 22:46:13 主机名 kernel: Out of memory: Kill process 29154 (java) score 521 or sacrifice child# 内核kill掉了进程29154Jun  6 22:46:13 主机名 kernel: Killed process 29154 (java) total-vm:3548972kB, anon-rss:979944kB, file-rss:0kB, shmem-rss:0kB

简单的看了下上面的日志。

连蒙带猜推测出结论：
1，有大对象的创建，申请内存时，物理内存不够了；

开发确认，大对象正常，这台机器主要是跑批，任务比较多。

2，内核经过综合评估，评估了一个最大价值的进程29154并进行kill，以保证系统能正常运行；

但是一想，2g的内存，最大堆只有1g，不应该啊。

又一扫前面，29154 只占887mb左右。

算下这些进程的占用内存的总数呗：

163839 rsyslogd 138267 tuned  887243 java131429 titanagent  这哥们熟悉吧，上次堆外内存就它引起的169139 ilogtail 我x这几个加起来就1.9G了

我说，这都1.9个G了，你还想咋跑，不oom才怪。

他说，之前没有这样啊。

我说最近运维动了什么东西么？

貌似运维这两天要把日志都收集走，加了logtail。

得，找运维升级吧。

这里也简单的说下messsages的内容：

大致意思就是什么时间什么地方谁发生了什么，基本上就是一个日志采集的标准模板。

举个例子：

Jun  6 22:46:12 主机名 kernel: Node 0 DMA32: 545*4kB (UE) 211*8kB (UE) 312*16kB (UEM) 228*32kB (UEM) 151*64kB (UE) 81*128kB (E) 25*256kB (EM) 4*512kB (E) 0*1024kB 0*2048kB 0*4096kB = 44636kB时间：Jun  6 22:46:12地点：对应的主机名谁：kernel(内核)发生了什么：Node 0 DMA32: 545*4kB (UE）....

过程中百度的关键文章

https://www.vpsee.com/2013/10/how-to-configure-the-linux-oom-killer/

这一次排查发现自己的linux底层差的还蛮多的，后续要好好的规整下。

一次系统宕机认识系统日志

相关文章：

文章评论