Мы тестировали наше Java-приложение, и оно было убито OOM Killer, логи ниже.
Пара замечаний: это веб-приложение на Java. Он работает с кучей 190G. Сервер представляет собой экземпляр EC2 с общим объемом памяти 240 ГБ. Мы пробовали новый экспериментальный ZGC в JDK 11. В то время приложение не находилось под нагрузкой и работало в тестовой среде, подобной продукту. В приложении есть некоторая обработка, которая запускается по расписанию и может потреблять много памяти и ЦП, но они выполняются часто и не дают сбоев.
Код приложения существенно не изменился по сравнению с тем, что мы имеем в производстве. Мы успешно протестировали его под нагрузкой, включая без проблем 12-часовой тест на выдержку.
Теперь к логам OOM-Killer. Полные журналы приведены ниже, но я считаю очень странной эту строку:
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.571217] Killed process 4973 (java) total-vm:17181703924kB, anon-rss:9740kB, file-rss:0kB, shmem-rss:0kB
Общий размер виртуальной машины составляет ~ 17 терабайт. Для меня это странно, так как наше приложение не может даже попытаться запросить это в обычном режиме. Я подозреваю, что, возможно, мы столкнулись с какой-то ошибкой в коде ZGC или ZGC +, но хочу убедиться, что читаю правильно.
Я очень благодарен за любую помощь, полные журналы для справки:
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.158902] java invoked oom-killer: gfp_mask=0x14200ca(GFP_HIGHUSER_MOVABLE), nodemask=(null), order=0, oom_score_adj=0
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.166556] java cpuset=/ mems_allowed=0
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.168975] CPU: 15 PID: 4974 Comm: java Not tainted 4.14.55-62.37.amzn1.x86_64 #1
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.173353] Hardware name: Xen HVM domU, BIOS 4.2.amazon 08/24/2006
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.177219] Call Trace:
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.178806] dump_stack+0x5c/0x82
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.180848] dump_header+0x94/0x21c
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.183087] ? get_page_from_freelist+0x525/0xba0
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.185945] oom_kill_process+0x213/0x410
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.188518] out_of_memory+0x296/0x4c0
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.190748] __alloc_pages_slowpath+0x9ef/0xdd0
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.193653] __alloc_pages_nodemask+0x207/0x220
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.196455] alloc_pages_vma+0x7c/0x1e0
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.198924] shmem_alloc_page+0x65/0xa0
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.201277] ? __radix_tree_insert+0x35/0x1f0
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.204022] ? __vm_enough_memory+0x23/0x130
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.206639] shmem_alloc_and_acct_page+0x72/0x1b0
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.209513] shmem_getpage_gfp+0x14b/0xb40
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.212102] ? __set_page_dirty+0xc0/0xc0
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.214705] shmem_fallocate+0x32d/0x440
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.217182] vfs_fallocate+0x13f/0x260
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.219525] SyS_fallocate+0x43/0x80
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.221657] do_syscall_64+0x67/0x100
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.223944] entry_SYSCALL_64_after_hwframe+0x3d/0xa2
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.227002] RIP: 0033:0x7fcc064ab1f9
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.229295] RSP: 002b:00007fcc071df800 EFLAGS: 00000246 ORIG_RAX: 000000000000011d
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.233706] RAX: ffffffffffffffda RBX: 0000002f80000000 RCX: 00007fcc064ab1f9
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.237896] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000005
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.242203] RBP: 00007fcc071df860 R08: 0000000000000005 R09: 0000000000000000
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.246538] R10: 0000002f80000000 R11: 0000000000000246 R12: 0000000000001000
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.250675] R13: 0000002f80000000 R14: 00007fcc00030d18 R15: 0000002f80000000
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.254948] Mem-Info:
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.256313] active_anon:46337469 inactive_anon:15816944 isolated_anon:0
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.256313] active_file:362 inactive_file:1424 isolated_file:0
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.256313] unevictable:0 dirty:87 writeback:0 unstable:0
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.256313] slab_reclaimable:146831 slab_unreclaimable:12432
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.256313] mapped:49788503 shmem:61099090 pagetables:297088 bounce:0
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.256313] free:264623 free_pcp:31 free_cma:0
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.276739] Node 0 active_anon:185857908kB inactive_anon:62759744kB active_file:1448kB inactive_file:5696kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:199154012kB dirty:348kB writeback:0kB shmem:244396360kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 0kB writeback_tmp:0kB unstable:0kB all_unreclaimable? yes
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.293799] Node 0 DMA free:15904kB min:4kB low:16kB high:28kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15988kB managed:15904kB mlocked:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.308882] lowmem_reserve[]: 0 1928 245809 245809
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.311710] Node 0 DMA32 free:976000kB min:528kB low:2500kB high:4472kB active_anon:0kB inactive_anon:1017428kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:2080768kB managed:1995880kB mlocked:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.327796] lowmem_reserve[]: 0 0 243881 243881
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.330558] Node 0 Normal free:66588kB min:67048kB low:316780kB high:566512kB active_anon:187190988kB inactive_anon:60409332kB active_file:1448kB inactive_file:5696kB unevictable:0kB writepending:0kB present:253755392kB managed:249734404kB mlocked:0kB kernel_stack:7280kB pagetables:1188352kB bounce:0kB free_pcp:124kB local_pcp:120kB free_cma:0kB
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.348446] lowmem_reserve[]: 0 0 0 0
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.350789] Node 0 DMA: 0*4kB 0*8kB 0*16kB 1*32kB (U) 2*64kB (U) 1*128kB (U) 1*256kB (U) 0*512kB 1*1024kB (U) 1*2048kB (M) 3*4096kB (M) = 15904kB
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.358404] Node 0 DMA32: 1*4kB (M) 1*8kB (U) 2*16kB (UM) 2*32kB (UE) 1*64kB (U) 1*128kB (U) 2*256kB (UE) 3*512kB (UME) 3*1024kB (UME) 2*2048kB (UM) 236*4096kB (M) = 976172kB
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.367499] Node 0 Normal: 2527*4kB (UME) 778*8kB (UME) 293*16kB (UME) 104*32kB (UME) 51*64kB (UME) 24*128kB (UME) 5*256kB (UM) 2*512kB (UM) 1*1024kB (U) 3*2048kB (UME) 8*4096kB (M) = 72924kB
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.377787] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.382919] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.387847] 61100730 total pagecache pages
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.390368] 0 pages in swap cache
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.392264] Swap cache stats: add 0, delete 0, find 0/0
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.395429] Free swap = 0kB
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.397195] Total swap = 0kB
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.398971] 63963037 pages RAM
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.400873] 0 pages HighMem/MovableOnly
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.403102] 1026490 pages reserved
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.405255] [ pid ] uid tgid total_vm rss nr_ptes nr_pmds swapents oom_score_adj name
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.410245] [ 2730] 0 2730 2833 194 11 3 0 -1000 udevd
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.415382] [ 2848] 0 2848 2812 165 10 3 0 -1000 udevd
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.420563] [ 2849] 0 2849 2812 161 10 3 0 -1000 udevd
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.425740] [ 3137] 0 3137 27285 57 21 3 0 0 lvmetad
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.430993] [ 3146] 0 3146 6799 48 18 3 0 0 lvmpolld
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.436187] [ 3354] 0 3354 2353 121 10 3 0 0 dhclient
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.441499] [ 3410] 0 3410 13251 98 27 3 0 -1000 auditd
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.446792] [ 3431] 0 3431 61878 132 23 3 0 0 rsyslogd
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.452140] [ 3451] 0 3451 23291 114 15 3 0 0 irqbalance
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.457538] [ 3461] 0 3461 1630 25 9 3 0 0 rngd
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.462533] [ 3478] 81 3478 5461 58 15 3 0 0 dbus-daemon
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.468050] [ 3513] 0 3513 1099 35 8 3 0 0 acpid
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.473222] [ 3609] 0 3609 20134 207 42 3 0 -1000 sshd
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.478262] [ 3622] 0 3622 28967 266 60 3 0 0 sshd
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.483118] [ 3624] 500 3624 28967 265 59 3 0 0 sshd
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.488272] [ 3625] 500 3625 28850 113 13 3 0 0 bash
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.493403] [ 3658] 38 3658 29129 204 29 3 0 0 ntpd
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.498490] [ 3702] 0 3702 22395 432 45 3 0 0 sendmail
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.503845] [ 3712] 51 3712 20259 374 40 3 0 0 sendmail
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.509091] [ 3724] 0 3724 30411 149 14 3 0 0 crond
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.514018] [ 3738] 0 3738 4797 42 13 3 0 0 atd
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.518902] [ 3773] 0 3773 1090 24 8 3 0 0 mingetty
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.524491] [ 3775] 0 3775 1627 31 9 3 0 0 agetty
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.529721] [ 3778] 0 3778 1090 24 8 3 0 0 mingetty
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.535029] [ 3781] 0 3781 1090 24 8 3 0 0 mingetty
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.540245] [ 3783] 0 3783 1090 24 8 3 0 0 mingetty
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.545404] [ 3785] 0 3785 1090 24 8 3 0 0 mingetty
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.550610] [ 3787] 0 3787 1090 25 8 3 0 0 mingetty
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.556012] [ 4948] 500 4948 28285 60 12 3 0 0 start_server.sh
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.561798] [ 4973] 500 4973 4295425981 2435 71 5 0 0 java
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.566936] Out of memory: Kill process 4973 (java) score 0 or sacrifice child
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.571217] Killed process 4973 (java) total-vm:17181703924kB, anon-rss:9740kB, file-rss:0kB, shmem-rss:0kB
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.578364] oom_reaper: reaped process 4973 (java), now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB
Обновить: Похоже, виртуальная память 17 ТБ (также видна в top во время работы приложения) не является проблемой.
Мы настроили простое приложение Spring Boot hello world с настройками по умолчанию, за исключением включенного ZGC, и произошло то же самое. Похоже, что ZGC выделяет 4 ТБ адресного пространства независимо от размера кучи, а также будет отображать один и тот же физический адрес несколько раз, так что это, по-видимому, нормально. Я не могу найти никого, кто это обсуждает, что удивительно.
OOM-Killer, кажется, вмешивается, когда мы пытаемся закрыть приложение. Учитывая, что мы все равно пытаемся его закрыть, меня это не особо беспокоит.
Опять же, благодарю всех за помощь.
Недостаточно памяти.
18 декабря 23:24:59 ip-10-0-3-36 ядро: [775.566936] Недостаточно памяти: Убить процесс 4973 (java) или принести в жертву ребенка
Из того же журнала (пс);
[775.561798] [4973] 500 4973 4295425981 2435 71 5 0 0 java
4295425.981 составляет около 4 ТБ. а строка total-vm: 17181703924kB показывает около 17TB.
Можете ли вы отладить процедуру выделения памяти? как по мне, ваше приложение где-то имеет плохой цикл и должно использовать все доступные ресурсы, а также доступный своп.
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.214705] shmem_fallocate+0x32d/0x440
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.217182] vfs_fallocate+0x13f/0x260
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.219525] SyS_fallocate+0x43/0x80
Dec 18 23:24:59 ip-10-0-3-36 kernel: [ 775.221657] do_syscall_64+0x67/0x100
Процесс вашего приложения пытается вызвать fallocate в файловой системе shmem. Из быстрый поиск в Google похоже, что ZGC использует fallocate для захвата начальной памяти кучи из файловой системы shm и продолжает использовать fallocate для расширения кучи. Такое использование системного вызова fallocate довольно необычно, поэтому либо это ошибка ZGC (как вы уже подозревали), либо что-то еще приводит к утечке большого количества памяти, что приводит к сбою расширения кучи.
Я предлагаю вам настроить ZGC, чтобы избежать дополнительных распределений времени выполнения (установите Xms и Xmx к тому же значению). Это может не решить вашу проблему, если утечка памяти происходит из-за чего-то не связанного с этим, но, по крайней мере, у вас будет больше шансов найти настоящего виновника.
Обратите внимание, что ваша общая настройка несколько опасна - ZGC, по-видимому, любит иметь много непрерывной памяти, но если у вас есть куча 190 ГБ на машине с ОЗУ 240 ГБ, может не быть достаточно большой смежной области для fallocate из. В этом случае ZGC вернется к сбору небольших областей памяти с дальнейшим fallocate вызовы (см. описание связанного отчета об ошибке), и проблема снова будет скрыта ... Включите поддержку огромных страниц в JVM (нормальные огромные страницыне прозрачные огромные страницы!) и предварительно выделить огромные страницы во время загрузки (с аргументом ядра) - в любом случае рекомендуется использовать огромные страницы для ваших размеров кучи.
Таким образом, длинная и короткая сторона этого оказалась некоторой утечкой собственной памяти (то есть не кучей). Мы пропатчили ОС, и она выросла от существенной (мы умрем через несколько дней) до практически нулевой (умрем через несколько месяцев). В примечаниях к патчу ОС были исправлены некоторые ошибки, связанные с управлением памятью, но это слишком низкий уровень, чтобы я мог разбираться в деталях.
Небольшая утечка собственной памяти все еще есть, но это уже не срочно. Будем и дальше следить. Я обновлю этот ответ, если какие-либо исправления разрешатся дальше.