Recently moved a Wordpress site to an Ubuntu 18.04 server running Apache, hosted by Armor (they're useless). This has happened twice now about a week apart. Happened early morning while not working on the server. I suspect a memory leak or hacker attack. The first time I was able to restart MySQL or the server to fix the problem. After seeing the out of memory errors, I set innodb_buffer_pool_size = 1G. The second time those fixes didn't work, I had to use innodb_force_recovery = 1 for the database to start.
I found this page https://www.percona.com/blog/2018/06/28/what-to-do-when-mysql-runs-out-of-memory-troubleshooting-guide/ and have been keeping an eye on those results. After a day, the only things that stick out to me are results from memory allocation in performance_schema. memory/innodb/mem0mem was at one point (high_aloc) 618.35 MiB, and memory/sql/String::value was 3.37 GiB. They're both only a few MB at time of running the query.
Here's syslog. One thing to point out here are the processes running towards the end. I'm only showing MySQL and some of the apache entries. Emphasis on some. I'm used to seeing 10-20 apache processes but syslong had a lot more, possibly over 100:
Apr 13 05:21:17 100-065-025-010 kernel: [478043.208080] TCP: request_sock_TCP: Possible SYN flooding on port 443. Sending cookies. Check SNMP counters.
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276249] mysqld invoked oom-killer: gfp_mask=0x14280ca(GFP_HIGHUSER_MOVABLE|__GFP_ZERO), nodemask=(null), order=0, oom_score_adj=0
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276251] mysqld cpuset=/ mems_allowed=0
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276255] CPU: 3 PID: 20882 Comm: mysqld Tainted: P OE 4.15.0-96-generic #97-Ubuntu
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276256] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 12/12/2018
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276256] Call Trace:
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276285] dump_stack+0x6d/0x8e
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276288] dump_header+0x71/0x285
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276292] ? security_capable+0x51/0x70
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276294] oom_kill_process+0x21f/0x420
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276295] out_of_memory+0x116/0x4e0
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276297] __alloc_pages_slowpath+0xa53/0xe00
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276299] __alloc_pages_nodemask+0x29a/0x2c0
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276301] alloc_pages_vma+0x88/0x1f0
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276305] __handle_mm_fault+0x8b7/0x1290
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276306] handle_mm_fault+0xb1/0x210
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276311] __do_page_fault+0x281/0x4b0
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276312] do_page_fault+0x2e/0xe0
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276316] ? page_fault+0x2f/0x50
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276318] page_fault+0x45/0x50
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276325] RIP: 0033:0x12a2c2d
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276325] RSP: 002b:00007f7ef74c9b70 EFLAGS: 00010206
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276327] RAX: 0000000000d0003a RBX: 0000000001d5a480 RCX: 00007f7ea6289239
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276327] RDX: 0000000001d5a480 RSI: 00000000034000e8 RDI: 00007f7dfd7f6001
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276328] RBP: 00007f7ef74c9b80 R08: 0000000000d0003a R09: 0000000001d6cea0
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276328] R10: 0000000000503069 R11: 0000000000000075 R12: 00007f7ef74c9c24
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276329] R13: 0000000000d0003a R14: 00000000034000e8 R15: 0000000001d6cea0
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276330] Mem-Info:
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276333] active_anon:754890 inactive_anon:150984 isolated_anon:0
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276333] active_file:78 inactive_file:46 isolated_file:0
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276333] unevictable:2441 dirty:10 writeback:37 unstable:0
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276333] slab_reclaimable:5636 slab_unreclaimable:18309
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276333] mapped:8927 shmem:10020 pagetables:26880 bounce:0
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276333] free:21601 free_pcp:6 free_cma:0
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276338] Node 0 active_anon:3019560kB inactive_anon:603936kB active_file:312kB inactive_file:184kB unevictable:9764kB isolated(anon):0kB isolated(file):0kB mapped:35708kB dirty:40kB writeback:148kB shmem:40080kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 0kB writebac$
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276339] Node 0 DMA free:15900kB min:268kB low:332kB high:396kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15992kB managed:15908kB mlocked:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local$
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276341] lowmem_reserve[]: 0 2970 3929 3929 3929
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276342] Node 0 DMA32 free:54176kB min:50648kB low:63308kB high:75968kB active_anon:2250028kB inactive_anon:519700kB active_file:52kB inactive_file:232kB unevictable:1284kB writepending:36kB present:3129280kB managed:3041788kB mlocked:1284kB kernel_stack:4848kB pagetabl$
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276344] lowmem_reserve[]: 0 0 958 958 958
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276345] Node 0 Normal free:16328kB min:16660kB low:20824kB high:24988kB active_anon:768748kB inactive_anon:83740kB active_file:308kB inactive_file:628kB unevictable:8480kB writepending:152kB present:1048576kB managed:981696kB mlocked:8480kB kernel_stack:3216kB pagetabl$
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276347] lowmem_reserve[]: 0 0 0 0 0
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276348] Node 0 DMA: 1*4kB (U) 1*8kB (U) 1*16kB (U) 0*32kB 2*64kB (U) 1*128kB (U) 1*256kB (U) 0*512kB 1*1024kB (U) 1*2048kB (M) 3*4096kB (M) = 15900kB
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276352] Node 0 DMA32: 897*4kB (UME) 583*8kB (UME) 815*16kB (UME) 341*32kB (UME) 186*64kB (UME) 77*128kB (UME) 3*256kB (M) 0*512kB 0*1024kB 0*2048kB 0*4096kB = 54732kB
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276356] Node 0 Normal: 389*4kB (UME) 779*8kB (UME) 310*16kB (UME) 77*32kB (UME) 19*64kB (UM) 5*128kB (UM) 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 17068kB
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276359] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276360] 12802 total pagecache pages
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276361] 1452 pages in swap cache
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276362] Swap cache stats: add 2148758, delete 2146723, find 12860894/13144554
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276362] Free swap = 0kB
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276362] Total swap = 1003516kB
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276363] 1048462 pages RAM
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276363] 0 pages HighMem/MovableOnly
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276363] 38614 pages reserved
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276364] 0 pages cma reserved
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276364] 0 pages hwpoisoned
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276364] [ pid ] uid tgid total_vm rss pgtables_bytes swapents oom_score_adj name
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276400] [ 6701] 109 6701 1442839 432247 6557696 131794 0 mysqld
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276508] [20838] 33 20838 115542 1984 593920 198 0 apache2
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276509] [20839] 33 20839 115542 1977 593920 198 0 apache2
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276510] [20840] 33 20840 115542 1961 593920 198 0 apache2
Apr 13 05:21:56 100-065-025-010 kernel: [478082.276540] Out of memory: Kill process 6701 (mysqld) score 448 or sacrifice child
Apr 13 05:21:56 100-065-025-010 kernel: [478082.277341] Killed process 6701 (mysqld) total-vm:5771356kB, anon-rss:1728988kB, file-rss:0kB, shmem-rss:0kB
Apr 13 05:21:56 100-065-025-010 kernel: [478082.377275] oom_reaper: reaped process 6701 (mysqld), now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB
Apr 13 05:21:57 100-065-025-010 systemd[1]: mysql.service: Main process exited, code=killed, status=9/KILL
Apr 13 05:21:57 100-065-025-010 systemd[1]: mysql.service: Failed with result 'signal'.
Apr 13 05:21:57 100-065-025-010 systemd[1]: mysql.service: Service hold-off time over, scheduling restart.
Apr 13 05:21:57 100-065-025-010 systemd[1]: mysql.service: Scheduled restart job, restart counter is at 45.
Apr 13 05:21:57 100-065-025-010 systemd[1]: Stopped MySQL Community Server.
Apr 13 05:21:57 100-065-025-010 systemd[1]: Starting MySQL Community Server...
Apr 13 05:21:58 100-065-025-010 systemd[1]: Started MySQL Community Server.
Apr 13 05:22:02 100-065-025-010 CRON[21036]: (panopta-agent) CMD ( /usr/bin/python /usr/bin/panopta-agent/panopta_agent.py --from-cron &> /dev/null)
Apr 13 05:22:04 100-065-025-010 kernel: [478089.831152] mysqld invoked oom-killer: gfp_mask=0x14280ca(GFP_HIGHUSER_MOVABLE|__GFP_ZERO), nodemask=(null), order=0, oom_score_adj=0
Apr 13 05:22:04 100-065-025-010 kernel: [478089.831154] mysqld cpuset=/ mems_allowed=0
Apr 13 05:22:04 100-065-025-010 kernel: [478089.831157] CPU: 3 PID: 20999 Comm: mysqld Tainted: P OE 4.15.0-96-generic #97-Ubuntu
Apr 13 05:22:04 100-065-025-010 kernel: [478089.831158] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 12/12/2018
MySQL log:
Thread pointer: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0 thread_stack 0x30000
/usr/sbin/mysqld(my_print_stacktrace+0x3b)[0xeaf22b]
/usr/sbin/mysqld(handle_fatal_signal+0x48b)[0x7794ab]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x12890)[0x7f13ed77d890]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0xc7)[0x7f13eca79e97]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x141)[0x7f13eca7b801]
/usr/sbin/mysqld[0x74f996]
/usr/sbin/mysqld(_ZN2ib5fatalD1Ev+0x66)[0x1086196]
/usr/sbin/mysqld(_Z20buf_page_io_completeP10buf_page_tb+0x2e5)[0x10c2115]
/usr/sbin/mysqld(_Z13buf_read_pageRK9page_id_tRK11page_size_t+0x55a)[0x10f209a]
/usr/sbin/mysqld(_Z16buf_page_get_genRK9page_id_tRK11page_size_tmP11buf_block_tmPKcmP5mtr_tb+0x4e5)[0x10c3915]
/usr/sbin/mysqld(_Z31trx_rseg_get_n_undo_tablespacesPm+0x14f)[0x106473f]
/usr/sbin/mysqld[0x102bc18]
/usr/sbin/mysqld(_Z34innobase_start_or_create_for_mysqlv+0x2e0e)[0x102ff6e]
/usr/sbin/mysqld[0xef683d]
/usr/sbin/mysqld(_Z24ha_initialize_handlertonP13st_plugin_int+0x4f)[0x7cc69f]
/usr/sbin/mysqld[0xc888c5]
/usr/sbin/mysqld(_Z40plugin_register_builtin_and_init_core_sePiPPc+0x1e5)[0xc8bde5]
/usr/sbin/mysqld[0x771770]
/usr/sbin/mysqld(_Z11mysqld_mainiPPc+0x795)[0x772e75]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xe7)[0x7f13eca5cb97]
/usr/sbin/mysqld(_start+0x2a)[0x76921a]
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
2020-04-13T14:02:29.762243Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2020-04-13T14:02:29.763643Z 0 [Note] /usr/sbin/mysqld (mysqld 5.7.29-0ubuntu0.18.04.1) starting as process 1172 ...
2020-04-13T14:02:29.766954Z 0 [Note] InnoDB: PUNCH HOLE support available
2020-04-13T14:02:29.766968Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2020-04-13T14:02:29.766972Z 0 [Note] InnoDB: Uses event mutexes
2020-04-13T14:02:29.766975Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2020-04-13T14:02:29.766978Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2020-04-13T14:02:29.766981Z 0 [Note] InnoDB: Using Linux native AIO
2020-04-13T14:02:29.767173Z 0 [Note] InnoDB: Number of pools: 1
2020-04-13T14:02:29.767265Z 0 [Note] InnoDB: Using CPU crc32 instructions
2020-04-13T14:02:29.768563Z 0 [Note] InnoDB: Initializing buffer pool, total size = 1G, instances = 8, chunk size = 128M
2020-04-13T14:02:29.826545Z 0 [Note] InnoDB: Completed initialization of buffer pool
2020-04-13T14:02:29.838644Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2020-04-13T14:02:29.849950Z 0 [ERROR] InnoDB: Database page corruption on disk or a failed file read of page [page id: space=0, page number=5]. You may have to recover from a backup.
2020-04-13T14:02:29.849971Z 0 [Note] InnoDB: Page dump in ascii and hex (16384 bytes):
len 16384; hex e92d6d1700000005000000000000000000000001275854f6000700000000000000000000000000000000001f2100000000000000000200f20000000000000006fffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff$
InnoDB: End of page dump
2020-04-13T14:02:29.901921Z 0 [Note] InnoDB: Uncompressed page, stored checksum in field1 3912068375, calculated checksums for field1: crc32 3912068375/814294125, innodb 1896780861, none 3735928559, stored checksum in field2 1946050728, calculated checksums for field2: crc32 3912068375/814294125, innodb 2062665854, $
InnoDB: Page may be a transaction system page
2020-04-13T14:02:29.901938Z 0 [Note] InnoDB: It is also possible that your operating system has corrupted its own file cache and rebooting your computer removes the error. If the corrupt page is an index page. You can also try to fix the corruption by dumping, dropping, and reimporting the corrupt table. You can use$
2020-04-13T14:02:29.901943Z 0 [ERROR] [FATAL] InnoDB: Aborting because of a corrupt database page in the system tablespace. Or, there was a failure in tagging the tablespace as corrupt.
2020-04-13 14:02:29 0x7ff267cd2740 InnoDB: Assertion failure in thread 140679100311360 in file ut0ut.cc line 918
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
14:02:29 UTC - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.
key_buffer_size=16777216
read_buffer_size=131072
max_used_connections=0
max_threads=151
thread_count=0
connection_count=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 76388 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
Edit with MySQL settings:
[mysqld_safe]
socket = /var/run/mysqld/mysqld.sock
nice = 0
[mysqld]
user = mysql
pid-file = /var/run/mysqld/mysqld.pid
socket = /var/run/mysqld/mysqld.sock
port = 3306
basedir = /usr
datadir = /var/lib/mysql
tmpdir = /tmp
lc-messages-dir = /usr/share/mysql
skip-external-locking
bind-address = 127.0.0.1
key_buffer_size = 16M
max_allowed_packet = 16M
thread_stack = 192K
thread_cache_size = 8
myisam-recover-options = BACKUP
query_cache_limit = 1M
query_cache_size = 16M
log_error = /var/log/mysql/error.log
slow_query_log = 1
long_query_time = 1
slow_query_log_file = /var/log/mysql/slow-query.log
expire_logs_days = 10
max_binlog_size = 100M
innodb_buffer_pool_size=1G
2nd Edit: free -h
total used free shared buff/cache available
Mem: 3.9G 1.7G 668M 44M 1.5G 1.8G
Swap: 979M 325M 654M
iostat -xm 5 3
Linux 4.15.0-96-generic (100-065-025-010) 2020-04-16 _x86_64_ (4 CPU)
avg-cpu: %user %nice %system %iowait %steal %idle
2.28 0.01 0.61 0.06 0.00 97.05
Device r/s w/s rMB/s wMB/s rrqm/s wrqm/s %rrqm %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm %util
sda 1.19 6.34 0.04 0.09 0.10 4.75 8.01 42.82 1.08 0.68 0.01 30.96 15.18 0.34 0.26
dm-0 1.16 10.49 0.04 0.10 0.00 0.00 0.00 0.00 1.43 0.60 0.01 31.25 10.00 0.22 0.25
dm-1 0.13 0.60 0.00 0.00 0.00 0.00 0.00 0.00 0.89 206.89 0.12 4.08 4.00 0.08 0.01
avg-cpu: %user %nice %system %iowait %steal %idle
1.15 0.00 0.10 0.00 0.00 98.75
Device r/s w/s rMB/s wMB/s rrqm/s wrqm/s %rrqm %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm %util
sda 0.00 0.40 0.00 0.05 0.00 11.40 0.00 96.61 0.00 0.00 0.00 0.00 118.00 0.00 0.00
dm-0 0.00 11.80 0.00 0.05 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 4.00 0.00 0.00
dm-1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
avg-cpu: %user %nice %system %iowait %steal %idle
0.85 0.00 0.15 0.05 0.00 98.95
Device r/s w/s rMB/s wMB/s rrqm/s wrqm/s %rrqm %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm %util
sda 0.00 2.00 0.00 0.04 0.00 4.20 0.00 67.74 0.00 0.40 0.00 0.00 18.00 0.40 0.08
dm-0 0.00 6.20 0.00 0.04 0.00 0.00 0.00 0.00 0.00 0.13 0.00 0.00 5.81 0.13 0.08
dm-1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
