It's difficult to pin down the culprit when the Out-Of-Memory killer starts killing processes due to memory starvation, inevitably leaving the system crashed or catastrophically disabled and a long bloody trail of victims in /var/log/messages but not much in the way of a smoking gun. Meanwhile, the pixels of resource graphs shed no light on what memleak exactly went out of control. If it's a recurring problem you almost have to catch it in the act - and good luck to you if it is sporadic or only takes minutes once underway. I have battled this issue on critical systems for almost two decades.

Dec 11 16:40:44 router kernel: sshd invoked oom-killer: gfp_mask=0xd0, order=0, oomkilladj=0 Dec 11 16:40:44 router kernel: [out_of_memory+114/419] out_of_memory+0x72/0x1a3 Dec 11 16:40:44 router kernel: [<c0454b97>] out_of_memory+0x72/0x1a3 Dec 11 16:40:44 router kernel: [__alloc_pages+590/719] __alloc_pages+0x24e/0x2cf Dec 11 16:40:44 router kernel: [<c04561b3>] __alloc_pages+0x24e/0x2cf Dec 11 16:40:44 router kernel: [__get_free_pages+37/49] __get_free_pages+0x25/0x31 Dec 11 16:40:44 router kernel: [<c0456259>] __get_free_pages+0x25/0x31 Dec 11 16:40:44 router kernel: [proc_pid_readlink+93/215] proc_pid_readlink+0x5d/0xd7 Dec 11 16:40:44 router kernel: [<c04a279b>] proc_pid_readlink+0x5d/0xd7 Dec 11 16:40:44 router kernel: [sys_readlinkat+121/146] sys_readlinkat+0x79/0x92 Dec 11 16:40:44 router kernel: [<c047a8ae>] sys_readlinkat+0x79/0x92 Dec 11 16:40:44 router kernel: [do_softirq+28/174] do_softirq+0x1c/0xae Dec 11 16:40:44 router kernel: [<c0406dfb>] do_softirq+0x1c/0xae Dec 11 16:40:45 router fail2ban.actions: WARNING [ssh-iptables] Ban 128.199.194.1 Dec 11 16:40:45 router kernel: [__do_IRQ+0/214] __do_IRQ+0x0/0xd6 Dec 11 16:40:45 router kernel: [<c0447d98>] __do_IRQ+0x0/0xd6 Dec 11 16:40:45 router kernel: [do_IRQ+181/195] do_IRQ+0xb5/0xc3 Dec 11 16:40:45 router kernel: [<c0406f42>] do_IRQ+0xb5/0xc3 Dec 11 16:40:45 router kernel: [sys_readlink+19/23] sys_readlink+0x13/0x17 Dec 11 16:40:45 router kernel: [<c047a8da>] sys_readlink+0x13/0x17 Dec 11 16:40:45 router kernel: [syscall_call+7/11] syscall_call+0x7/0xb Dec 11 16:40:45 router kernel: [<c0405413>] syscall_call+0x7/0xb Dec 11 16:40:45 router kernel: ======================= Dec 11 16:40:45 router kernel: Mem-info: Dec 11 16:40:45 router kernel: DMA per-cpu: Dec 11 16:40:45 router kernel: cpu 0 hot: high 186, batch 31 used:71 Dec 11 16:40:45 router kernel: cpu 0 cold: high 62, batch 15 used:55 Dec 11 16:40:45 router kernel: cpu 1 hot: high 186, batch 31 used:149 Dec 11 16:40:45 router kernel: cpu 1 cold: high 62, batch 15 used:50 Dec 11 16:40:45 router kernel: cpu 2 hot: high 186, batch 31 used:154 Dec 11 16:40:45 router kernel: cpu 2 cold: high 62, batch 15 used:55 Dec 11 16:40:45 router kernel: cpu 3 hot: high 186, batch 31 used:164 Dec 11 16:40:45 router kernel: cpu 3 cold: high 62, batch 15 used:55 Dec 11 16:40:45 router kernel: cpu 4 hot: high 186, batch 31 used:34 Dec 11 16:40:45 router kernel: cpu 4 cold: high 62, batch 15 used:58 Dec 11 16:40:45 router kernel: DMA32 per-cpu: empty Dec 11 16:40:45 router kernel: Normal per-cpu: empty Dec 11 16:40:45 router kernel: HighMem per-cpu: Dec 11 16:40:45 router kernel: cpu 0 hot: high 186, batch 31 used:4 Dec 11 16:40:45 router kernel: cpu 0 cold: high 62, batch 15 used:5 Dec 11 16:40:45 router kernel: cpu 1 hot: high 186, batch 31 used:146 Dec 11 16:40:45 router kernel: cpu 1 cold: high 62, batch 15 used:14 Dec 11 16:40:45 router kernel: cpu 2 hot: high 186, batch 31 used:122 Dec 11 16:40:45 router kernel: cpu 2 cold: high 62, batch 15 used:14 Dec 11 16:40:45 router kernel: cpu 3 hot: high 186, batch 31 used:171 Dec 11 16:40:45 router kernel: cpu 3 cold: high 62, batch 15 used:4 Dec 11 16:40:45 router kernel: cpu 4 hot: high 186, batch 31 used:47 Dec 11 16:40:45 router kernel: cpu 4 cold: high 62, batch 15 used:13 Dec 11 16:40:45 router kernel: Free pages: 5447468kB (5444128kB HighMem) Dec 11 16:40:45 router kernel: Active:17178 inactive:6990 dirty:13 writeback:0 unstable:0 free:1361867 slab:167350 mapped-file:4536 mapped-anon:11829 pagetables:665 Dec 11 16:40:45 router kernel: DMA free:3340kB min:3452kB low:4312kB high:5176kB active:128kB inactive:0kB present:745464kB pages_scanned:93 all_unreclaimable? yes Dec 11 16:40:45 router kernel: lowmem_reserve[]: 0 0 0 5416 Dec 11 16:40:45 router kernel: DMA32 free:0kB min:0kB low:0kB high:0kB active:0kB inactive:0kB present:0kB pages_scanned:0 all_unreclaimable? no Dec 11 16:40:45 router kernel: lowmem_reserve[]: 0 0 0 5416 Dec 11 16:40:45 router kernel: Normal free:0kB min:0kB low:0kB high:0kB active:0kB inactive:0kB present:0kB pages_scanned:0 all_unreclaimable? no Dec 11 16:40:45 router kernel: lowmem_reserve[]: 0 0 0 43328 Dec 11 16:40:45 router kernel: HighMem free:5444128kB min:512kB low:6932kB high:13352kB active:68584kB inactive:27960kB present:5545992kB pages_scanned:0 all_unreclaimable? no Dec 11 16:40:45 router kernel: lowmem_reserve[]: 0 0 0 0 Dec 11 16:40:45 router kernel: DMA: 15*4kB 20*8kB 31*16kB 16*32kB 9*64kB 2*128kB 1*256kB 0*512kB 1*1024kB 0*2048kB 0*4096kB = 3340kB Dec 11 16:40:45 router kernel: DMA32: empty Dec 11 16:40:45 router kernel: Normal: empty Dec 11 16:40:45 router kernel: HighMem: 32*4kB 370*8kB 659*16kB 499*32kB 536*64kB 235*128kB 85*256kB 33*512kB 15*1024kB 8*2048kB 1289*4096kB = 5444128kB Dec 11 16:40:45 router kernel: 12253 pagecache pages Dec 11 16:40:45 router kernel: Swap cache: add 0, delete 0, find 0/0, race 0+0 Dec 11 16:40:45 router kernel: Free swap = 0kB Dec 11 16:40:45 router kernel: Total swap = 0kB Dec 11 16:40:45 router kernel: Free swap: 0kB Dec 11 16:40:45 router kernel: 1572864 pages of RAM Dec 11 16:40:45 router kernel: 1386498 pages of HIGHMEM Dec 11 16:40:45 router kernel: 15394 reserved pages Dec 11 16:40:45 router kernel: 21560 pages shared Dec 11 16:40:45 router kernel: 0 pages swap cached Dec 11 16:40:45 router kernel: 13 pages dirty Dec 11 16:40:45 router kernel: 0 pages writeback Dec 11 16:40:45 router kernel: 4536 pages mapped Dec 11 16:40:45 router kernel: 167350 pages slab Dec 11 16:40:45 router kernel: 665 pages pagetables Dec 11 16:40:45 router kernel: Out of memory: Killed process 6421, UID 416, (system-mysqld).

We can take steps like recording per-process memory use over time and make comparisons to attempt identification. Create /usr/sbin/psmon.sh:

#!/bin/bash # https://foxpa.ws/monitoring-memory-use-after-oom-killer-spree LOG_PATH=/var/log/ps/ FILE_NAME=ps.`date +%Y%m%d%H%M` RETAIN_DAYS=7 find $LOG_PATH -mtime +$RETAIN_DAYS -type f -delete ps -o pid,user,%mem,vsz,rss,command ax | head -n 1 > $LOG_PATH$FILE_NAME ps -o pid,user,%mem,vsz,rss,command ax --no-headers | sort -bnrk 5 >> $LOG_PATH$FILE_NAME

Note that the first call to ps is just to extract the column header names; by using an identical call for data and headers ps does all the work for us of making sure the spacing aligns properly. The call to sort will order the results by their RSS or Resident State Size. This is a better metric for our purposes than VSZ (virtual memory) which counts unused allocations that may be squeezed off as memory pressure builds up.

PID USER %MEM VSZ RSS COMMAND 6801 416 0.3 139892 19620 /usr/share/system-mysql/usr/libexec/system-mysqld --defaults-file=/usr/share/system-mysql/etc/my.cnf --basedir=/usr/share/system-mysql --datadir=/var/lib/system-mysql --user=system-mysql --pid-file=/var/run/system-mysqld/system-mysqld.pid --skip-external-locking --port=3308 --socket=/var/lib/system-mysql/mysql.sock 16679 ldap 0.2 465212 17984 /usr/sbin/slapd -h ldap://127.0.0.1/ -u ldap 6621 101 0.1 34300 9860 webconfig 26409 101 0.1 34300 9792 webconfig 6843 root 0.1 28436 8944 webconfig 6704 root 0.1 27872 7064 /usr/sbin/snmpd -Lsd -Lf /dev/null -p /var/run/snmpd.pid -a 7043 root 0.0 9764 5396 syswatch 6887 root 0.0 92804 4208 /usr/bin/python /usr/bin/fail2ban-server -b -s /var/run/fail2ban/fail2ban.sock -x 12516 root 0.0 14132 3952 sshd: root@pts/1 ...

This configuration, where the output from each run is placed into a separate file which includes a timestamp in the filename lends itself well to capturing detailed, multi-line output, in contrast with typical log files. It also lends itself well to our purpose here, where we want to inspect changes to a specific process over time, by using a simple batch grep:

grep webconfig * ps.202312150201:23383 101 0.1 34296 9876 webconfig ps.202312150301:23383 101 0.1 34296 9876 webconfig ps.202312150401:23383 101 0.1 34296 9876 webconfig ...

However this multi-file setup is not the kind of situation logrotate was made for and as we log every hour - or even less, if your particular memleak tends to rev up in minutes or seconds - there will soon be multitudes of files which will make haystack work of zeroing in, not to mention consume storage resources. Therefore, we perform our own garbage collection with find: simply set the maximum number of days you would like to retain data for as the RETAIN_DAYS variable.

Now we set the stage and configure crond to record hourly (or less, via crontab):
mkdir /var/log/ps chmod +x /usr/sbin/psmon.sh ln -s /usr/sbin/psmon.sh /etc/cron.hourly/

It now becomes possible to inspect changes to memory utilization on a per-process basis and hopefully identify the suspect after the next incident, then prevent it from striking again.