我在一组 Linux 主机上遇到了一个问题(我可以可靠地重现),当某个进程大量消耗内存后,系统变得完全无响应。我在内核日志中看到类似以下内容:
2017-09-14 19:53:51.252365 kernel: hyperkube: page allocation stalls for 62933ms, order:0, mode:0x14201ca(GFP_HIGHUSER_MOVABLE|__GFP_COLD), nodemask=(null)
2017-09-14 19:53:51.252402 kernel: hyperkube cpuset=kube-proxy mems_allowed=0
2017-09-14 19:53:51.252440 kernel: CPU: 1 PID: 1438 Comm: hyperkube Not tainted 4.11.9-coreos #1
2017-09-14 19:53:51.252478 kernel: Hardware name: Xen HVM domU, BIOS 4.2.amazon 11/11/2016
2017-09-14 19:53:51.252512 kernel: Call Trace:
2017-09-14 19:53:51.252591 kernel: dump_stack+0x63/0x90
2017-09-14 19:53:51.252628 kernel: warn_alloc+0x11c/0x1b0
2017-09-14 19:53:51.252682 kernel: __alloc_pages_slowpath+0x811/0xe50
2017-09-14 19:53:51.252720 kernel: ? alloc_pages_current+0x8c/0x110
2017-09-14 19:53:51.258910 kernel: __alloc_pages_nodemask+0x21b/0x230
2017-09-14 19:53:51.258951 kernel: alloc_pages_current+0x8c/0x110
2017-09-14 19:53:51.259009 kernel: __page_cache_alloc+0xae/0xc0
2017-09-14 19:53:51.259041 kernel: filemap_fault+0x338/0x630
2017-09-14 19:53:51.268298 kernel: ? filemap_map_pages+0x19d/0x390
2017-09-14 19:53:51.268360 kernel: ext4_filemap_fault+0x31/0x50 [ext4]
2017-09-14 19:53:51.268397 kernel: __do_fault+0x1e/0xc0
2017-09-14 19:53:51.268436 kernel: __handle_mm_fault+0xb06/0x1090
2017-09-14 19:53:51.268471 kernel: handle_mm_fault+0xd1/0x240
2017-09-14 19:53:51.268504 kernel: __do_page_fault+0x222/0x4b0
2017-09-14 19:53:51.268539 kernel: do_page_fault+0x22/0x30
2017-09-14 19:53:51.268572 kernel: page_fault+0x28/0x30
2017-09-14 19:53:51.268605 kernel: RIP: 0033:0x45d561
2017-09-14 19:53:51.268666 kernel: RSP: 002b:00007f64d3ef2de8 EFLAGS: 00010246
2017-09-14 19:53:51.268717 kernel: RAX: 0000000000000000 RBX: 000000000000007c RCX: 000000000045d561
2017-09-14 19:53:51.268757 kernel: RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
2017-09-14 19:53:51.277186 kernel: RBP: 00007f64d3ef2df8 R08: 00007f64d3ef2de8 R09: 0000000000000000
2017-09-14 19:53:51.277239 kernel: R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
2017-09-14 19:53:51.277283 kernel: R13: 0000000000000034 R14: 0000000000000000 R15: 00000000000000f3
2017-09-14 19:53:51.277322 kernel: Mem-Info:
2017-09-14 19:53:51.277355 kernel: active_anon:903273 inactive_anon:164 isolated_anon:0
active_file:166 inactive_file:754 isolated_file:0
unevictable:0 dirty:0 writeback:0 unstable:0
slab_reclaimable:8251 slab_unreclaimable:17340
mapped:591 shmem:2354 pagetables:4389 bounce:0
free:14896 free_pcp:73 free_cma:0
2017-09-14 19:53:51.277393 kernel: Node 0 active_anon:3613092kB inactive_anon:656kB active_file:864kB inactive_file:2744kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:2364kB dirty:0kB writeback:0kB shmem:9416kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 606208kB writeback_tmp:0kB unstable:0kB pages_scanned:246 all_unreclaimable? no
2017-09-14 19:53:51.288390 kernel: Node 0 DMA free:15052kB min:184kB low:228kB high:272kB active_anon:764kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15988kB managed:15900kB mlocked:0kB slab_reclaimable:0kB slab_unreclaimable:84kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
2017-09-14 19:53:51.288448 kernel: lowmem_reserve[]: 0 3717 3717 3717
2017-09-14 19:53:51.288483 kernel: Node 0 DMA32 free:44532kB min:44868kB low:56084kB high:67300kB active_anon:3612328kB inactive_anon:656kB active_file:912kB inactive_file:2516kB unevictable:0kB writepending:0kB present:3915776kB managed:3841148kB mlocked:0kB slab_reclaimable:33004kB slab_unreclaimable:69276kB kernel_stack:10096kB pagetables:17556kB bounce:0kB free_pcp:412kB local_pcp:156kB free_cma:0kB
2017-09-14 19:53:51.288520 kernel: lowmem_reserve[]: 0 0 0 0
2017-09-14 19:53:51.288553 kernel: Node 0 DMA: 5*4kB (UM) 1*8kB (M) 3*16kB (UM) 2*32kB (UM) 1*64kB (M) 2*128kB (UM) 1*256kB (U) 0*512kB 2*1024kB (UM) 0*2048kB 3*4096kB (ME) = 15052kB
2017-09-14 19:53:51.288609 kernel: Node 0 DMA32: 537*4kB (UMEH) 360*8kB (UMEH) 397*16kB (UMEH) 238*32kB (UMEH) 141*64kB (UMEH) 61*128kB (E) 22*256kB (E) 4*512kB (ME) 1*1024kB (M) 0*2048kB 0*4096kB = 44532kB
2017-09-14 19:53:51.288735 kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
2017-09-14 19:53:51.288784 kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
2017-09-14 19:53:51.294569 kernel: 3234 total pagecache pages
2017-09-14 19:53:51.294619 kernel: 0 pages in swap cache
2017-09-14 19:53:51.294670 kernel: Swap cache stats: add 0, delete 0, find 0/0
2017-09-14 19:53:51.294747 kernel: Free swap = 0kB
2017-09-14 19:53:51.294781 kernel: Total swap = 0kB
2017-09-14 19:53:51.294825 kernel: 982941 pages RAM
2017-09-14 19:53:51.300569 kernel: 0 pages HighMem/MovableOnly
2017-09-14 19:53:51.300616 kernel: 18679 pages reserved
2017-09-14 19:53:51.300673 kernel: 0 pages hwpoisoned
如您所见,系统似乎停滞了 60 多秒,试图分配内存。在系统完全无法使用约 10 分钟后,OOM 终止程序介入并终止了贪婪进程。
如果有人能帮助我理解我会非常高兴:
- 为何 OOM 杀手要花这么长时间才能采取行动?
- 为什么这些分配需要这么长时间?如果没有可用内存,为什么这不会失败?
答案1
依赖 OOM 杀手意味着你已经失败了。OOM 只是防止内核崩溃的最后一次机会。
收集性能数据将向您展示无响应的症状。特别是,如果平均负载远大于 CPU 数量,则有太多准备运行的任务堆积如山。可能是因为花费了太多系统时间来扫描内存页面。这将导致响应时间变长。
关于为什么确定没有记忆并不是一件容易的事,请看一下文档/sysctl/vm.txt特别是 overcommit_memory。内核非常善于假装有更多内存可用,因为实际物理使用量通常比分配的内存要小得多。这会占用一点 CPU 时间,在内存极低的情况下,这种情况会更加严重。
我看到这是一个 Xen VM,可能位于 EC2 中。在云中,如果您想投入资源来解决问题,可以轻松启动更大的 VM。
如果您怀疑分配的内存对于应用程序来说太多了,请让其开发人员查看其内存配置文件,例如使用 Valgrind 或在因 OOM 而崩溃时查看 kdump。
答案2
在我看来,这是 MM 中的一个内核错误/性能问题。内核应该尽快退出,要么启动 OOM 终止程序,要么分配失败。
是的,这台机器内存完全用完了,因为这是 0 级分配(额外的几 MB 不算在内,因为它们可能是内核内存保留池,而这个特定的分配不允许触及)。也许内核很难满足 __GFP_COLD 分配,但它不应该花费 62 秒!