Re: Unexpected RAM usage on MySQL
Posted by: Matteo Tassinari
Date: March 18, 2019 03:38AM

> So all InnoDB ops in RAN needs innodb_buffer_pool_size=8GB, plus somefor growth.

I tried setting it to 8 GB, let's see if the server holds up.

> What do the mysql log and syslog say when that db size query crashes the server?

MySQL log says really nothing useful:

2019-03-18 07:30:17 28697 mysqld_safe Number of processes running now: 0
2019-03-18 07:30:17 28697 mysqld_safe mysqld restarted
2019-03-18  7:30:17 140120010852160 [Note] /opt/lampp/sbin/mysqld (mysqld 10.1.36-MariaDB) starting as process 15756 ...
2019-03-18  7:30:18 140120010852160 [Note] InnoDB: Using mutexes to ref count buffer pool pages
2019-03-18  7:30:18 140120010852160 [Note] InnoDB: The InnoDB memory heap is disabled
2019-03-18  7:30:18 140120010852160 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-03-18  7:30:18 140120010852160 [Note] InnoDB: GCC builtin __sync_synchronize() is used for memory barrier
2019-03-18  7:30:18 140120010852160 [Note] InnoDB: Compressed tables use zlib 1.2.8
2019-03-18  7:30:18 140120010852160 [Note] InnoDB: Using SSE crc32 instructions
2019-03-18  7:30:18 140120010852160 [Note] InnoDB: Initializing buffer pool, size = 2.0G
2019-03-18  7:30:18 140120010852160 [Note] InnoDB: Completed initialization of buffer pool
2019-03-18  7:30:18 140120010852160 [Note] InnoDB: Highest supported file format is Barracuda.
2019-03-18  7:30:18 140120010852160 [Note] InnoDB: The log sequence number 205611208804 in ibdata file do not match the log sequence number 205622170923 in the ib_logfiles!
2019-03-18  7:30:34 140120010852160 [Note] InnoDB: Processed 1001 .ibd/.isl files
2019-03-18  7:30:50 140120010852160 [Note] InnoDB: Processed 2167 .ibd/.isl files
2019-03-18  7:31:06 140120010852160 [Note] InnoDB: Processed 3212 .ibd/.isl files
2019-03-18  7:31:22 140120010852160 [Note] InnoDB: Processed 4312 .ibd/.isl files
2019-03-18  7:31:38 140120010852160 [Note] InnoDB: Processed 5423 .ibd/.isl files
2019-03-18  7:31:54 140120010852160 [Note] InnoDB: Processed 6479 .ibd/.isl files
2019-03-18  7:32:10 140120010852160 [Note] InnoDB: Processed 7601 .ibd/.isl files
2019-03-18  7:32:26 140120010852160 [Note] InnoDB: Processed 8734 .ibd/.isl files
2019-03-18  7:32:42 140120010852160 [Note] InnoDB: Processed 10032 .ibd/.isl files
2019-03-18  7:32:58 140120010852160 [Note] InnoDB: Processed 11561 .ibd/.isl files
2019-03-18  7:33:14 140120010852160 [Note] InnoDB: Processed 13002 .ibd/.isl files
2019-03-18  7:33:30 140120010852160 [Note] InnoDB: Processed 14487 .ibd/.isl files
2019-03-18  7:33:46 140120010852160 [Note] InnoDB: Processed 16137 .ibd/.isl files
2019-03-18  7:34:02 140120010852160 [Note] InnoDB: Processed 17666 .ibd/.isl files
2019-03-18  7:34:18 140120010852160 [Note] InnoDB: Processed 19294 .ibd/.isl files
2019-03-18  7:34:34 140120010852160 [Note] InnoDB: Processed 20790 .ibd/.isl files
2019-03-18  7:34:50 140120010852160 [Note] InnoDB: Processed 22341 .ibd/.isl files
2019-03-18  7:35:06 140120010852160 [Note] InnoDB: Processed 23672 .ibd/.isl files
2019-03-18  7:35:22 140120010852160 [Note] InnoDB: Processed 25036 .ibd/.isl files
2019-03-18  7:35:38 140120010852160 [Note] InnoDB: Processed 26356 .ibd/.isl files
2019-03-18  7:35:54 140120010852160 [Note] InnoDB: Processed 27907 .ibd/.isl files
2019-03-18  7:36:10 140120010852160 [Note] InnoDB: Processed 29249 .ibd/.isl files
2019-03-18  7:36:26 140120010852160 [Note] InnoDB: Processed 30580 .ibd/.isl files
2019-03-18  7:36:42 140120010852160 [Note] InnoDB: Processed 31713 .ibd/.isl files
2019-03-18  7:36:58 140120010852160 [Note] InnoDB: Processed 32879 .ibd/.isl files
2019-03-18  7:37:14 140120010852160 [Note] InnoDB: Processed 33990 .ibd/.isl files
2019-03-18  7:37:30 140120010852160 [Note] InnoDB: Processed 35068 .ibd/.isl files
2019-03-18  7:37:46 140120010852160 [Note] InnoDB: Processed 36146 .ibd/.isl files
2019-03-18  7:38:02 140120010852160 [Note] InnoDB: Processed 37158 .ibd/.isl files
2019-03-18  7:38:18 140120010852160 [Note] InnoDB: Processed 38148 .ibd/.isl files
2019-03-18  7:38:34 140120010852160 [Note] InnoDB: Processed 39171 .ibd/.isl files
2019-03-18  7:38:50 140120010852160 [Note] InnoDB: Processed 40381 .ibd/.isl files
2019-03-18  7:39:06 140120010852160 [Note] InnoDB: Processed 42042 .ibd/.isl files
2019-03-18  7:39:22 140120010852160 [Note] InnoDB: Processed 43824 .ibd/.isl files
2019-03-18  7:39:38 140120010852160 [Note] InnoDB: Processed 45694 .ibd/.isl files
2019-03-18  7:39:54 140120010852160 [Note] InnoDB: Processed 47058 .ibd/.isl files
2019-03-18  7:40:10 140120010852160 [Note] InnoDB: Processed 48378 .ibd/.isl files
2019-03-18  7:40:26 140120010852160 [Note] InnoDB: Processed 49918 .ibd/.isl files
2019-03-18  7:40:42 140120010852160 [Note] InnoDB: Processed 51249 .ibd/.isl files
2019-03-18  7:40:58 140120010852160 [Note] InnoDB: Processed 52305 .ibd/.isl files
2019-03-18  7:41:14 140120010852160 [Note] InnoDB: Processed 53328 .ibd/.isl files
2019-03-18  7:41:26 140120010852160 [Note] InnoDB: Restoring possible half-written data pages from the doublewrite buffer...
2019-03-18  7:41:27 140120010852160 [Note] InnoDB: Read redo log up to LSN=205622171136
2019-03-18  7:51:22 140120010852160 [Note] InnoDB: 128 rollback segment(s) are active.
2019-03-18  7:51:22 140120010852160 [Note] InnoDB: Waiting for purge to start
2019-03-18  7:51:22 140120010852160 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.39-83.1 started; log sequence number 205622170923
2019-03-18  7:51:22 140117159159552 [Note] InnoDB: Dumping buffer pool(s) not yet started
2019-03-18  7:51:22 140120010852160 [Note] Plugin 'FEEDBACK' is disabled.
2019-03-18  7:51:22 140120010852160 [Note] Recovering after a crash using tc.log
2019-03-18  7:51:22 140120010852160 [Note] Starting crash recovery...
2019-03-18  7:51:22 140120010852160 [Note] Crash recovery finished.

and here is the logs in /var/log/messages:

Mar 18 07:30:14 asp1 kernel: mysqld invoked oom-killer: gfp_mask=0xd0, order=0, oom_score_adj=-750
Mar 18 07:30:14 asp1 kernel: mysqld cpuset=/ mems_allowed=0
Mar 18 07:30:14 asp1 kernel: CPU: 1 PID: 29398 Comm: mysqld Kdump: loaded Not tainted 3.10.0-862.11.6.el7.x86_64 #1
Mar 18 07:30:14 asp1 kernel: Hardware name: Xen HVM domU, BIOS 4.7.5-1.21 08/13/2018
Mar 18 07:30:14 asp1 kernel: Call Trace:
Mar 18 07:30:14 asp1 kernel: [<ffffffff851135d4>] dump_stack+0x19/0x1b
Mar 18 07:30:14 asp1 kernel: [<ffffffff8510e79f>] dump_header+0x90/0x229
Mar 18 07:30:14 asp1 kernel: [<ffffffff84b9a7b6>] ? find_lock_task_mm+0x56/0xc0
Mar 18 07:30:14 asp1 kernel: [<ffffffff84b9ac64>] oom_kill_process+0x254/0x3d0
Mar 18 07:30:14 asp1 kernel: [<ffffffff84c133c6>] mem_cgroup_oom_synchronize+0x546/0x570
Mar 18 07:30:14 asp1 kernel: [<ffffffff84c12840>] ? mem_cgroup_charge_common+0xc0/0xc0
Mar 18 07:30:14 asp1 kernel: [<ffffffff84b9b4f4>] pagefault_out_of_memory+0x14/0x90
Mar 18 07:30:14 asp1 kernel: [<ffffffff8510c941>] mm_fault_error+0x6a/0x157
Mar 18 07:30:14 asp1 kernel: [<ffffffff85120856>] __do_page_fault+0x496/0x4f0
Mar 18 07:30:14 asp1 kernel: [<ffffffff851208e5>] do_page_fault+0x35/0x90
Mar 18 07:30:14 asp1 kernel: [<ffffffff8511c758>] page_fault+0x28/0x30
Mar 18 07:30:14 asp1 kernel: Task in /system.slice/agews-mysql.service killed as a result of limit of /system.slice/agews-mysql.service
Mar 18 07:30:14 asp1 kernel: memory: usage 14673840kB, limit 14680064kB, failcnt 72672282
Mar 18 07:30:14 asp1 kernel: memory+swap: usage 28031240kB, limit 9007199254740988kB, failcnt 0
Mar 18 07:30:14 asp1 kernel: kmem: usage 0kB, limit 9007199254740988kB, failcnt 0
Mar 18 07:30:14 asp1 kernel: Memory cgroup stats for /system.slice/agews-mysql.service: cache:7688KB rss:14671312KB rss_huge:108544KB mapped_file:132KB swap:13357400KB inactive_anon:1598772KB active_anon:13072540KB inactive_file:6728KB active_file:268KB unevictable:0KB
Mar 18 07:30:14 asp1 kernel: [ pid ]   uid  tgid total_vm      rss nr_ptes swapents oom_score_adj name
Mar 18 07:30:14 asp1 kernel: [28695]     0 28695    28892        1      11      126          -750 agews
Mar 18 07:30:14 asp1 kernel: [28697]     0 28697    28328        3      11       94          -750 mysqld_safe
Mar 18 07:30:14 asp1 kernel: [27538]   996 27538  7925184  3668461   14774  3339256          -750 mysqld
Mar 18 07:30:14 asp1 kernel: Memory cgroup out of memory: Kill process 11884 (mysqld) score 206 or sacrifice child
Mar 18 07:30:14 asp1 kernel: Killed process 27538 (mysqld) total-vm:31700736kB, anon-rss:14673844kB, file-rss:0kB, shmem-rss:0kB

> How much RAM is the app using? Other processes?

As of now, apache is using a little less than 350 MB and mysql is at about 8 GB.

Also, the Percona Monitoring and Management client is using about 50 MB or RAM, and that's pretty much it, no other relevant processes in terms of RAM usage.

> Would be helpful to take show variables and show global status readings again after a longer and more typical use period and with the new innodb_buffer_pool_size.

That might be a problem, as the app services are set to a nightly restart exactly to try to reclaim some memory ...

Options: ReplyQuote




Sorry, you can't reply to this topic. It has been closed.

Content reproduced on this site is the property of the respective copyright holders. It is not reviewed in advance by Oracle and does not necessarily represent the opinion of Oracle or any other party.