Re: Unexpected RAM usage on MySQL
Posted by: Matteo Tassinari
Date: March 15, 2019 02:08AM

> Need to see what the mysql error log says about that.

Nothing too useful, this is what reported at last restart:

2019-03-15 02:23:57 6048 mysqld_safe Number of processes running now: 0
2019-03-15 02:23:57 6048 mysqld_safe mysqld restarted
2019-03-15 2:23:58 139856503813952 [Note] /opt/lampp/sbin/mysqld (mysqld 10.1.36-MariaDB) starting as process 31231 ...
2019-03-15 2:23:58 139856503813952 [Note] InnoDB: Using mutexes to ref count buffer pool pages
2019-03-15 2:23:58 139856503813952 [Note] InnoDB: The InnoDB memory heap is disabled
2019-03-15 2:23:58 139856503813952 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-03-15 2:23:58 139856503813952 [Note] InnoDB: GCC builtin __sync_synchronize() is used for memory barrier
2019-03-15 2:23:58 139856503813952 [Note] InnoDB: Compressed tables use zlib 1.2.8
2019-03-15 2:23:58 139856503813952 [Note] InnoDB: Using SSE crc32 instructions
2019-03-15 2:23:58 139856503813952 [Note] InnoDB: Initializing buffer pool, size = 2.0G
2019-03-15 2:23:58 139856503813952 [Note] InnoDB: Completed initialization of buffer pool
2019-03-15 2:23:58 139856503813952 [Note] InnoDB: Highest supported file format is Barracuda.
2019-03-15 2:23:58 139856503813952 [Note] InnoDB: The log sequence number 205554549039 in ibdata file do not match the log sequence number 205578603650 in the ib_logfiles!
2019-03-15 2:24:14 139856503813952 [Note] InnoDB: Processed 1848 .ibd/.isl files
2019-03-15 2:24:30 139856503813952 [Note] InnoDB: Processed 3773 .ibd/.isl files
2019-03-15 2:24:46 139856503813952 [Note] InnoDB: Processed 6171 .ibd/.isl files
2019-03-15 2:25:02 139856503813952 [Note] InnoDB: Processed 8635 .ibd/.isl files
2019-03-15 2:25:18 139856503813952 [Note] InnoDB: Processed 10780 .ibd/.isl files
2019-03-15 2:25:34 139856503813952 [Note] InnoDB: Processed 12639 .ibd/.isl files
2019-03-15 2:25:50 139856503813952 [Note] InnoDB: Processed 14355 .ibd/.isl files
2019-03-15 2:26:06 139856503813952 [Note] InnoDB: Processed 16225 .ibd/.isl files
2019-03-15 2:26:22 139856503813952 [Note] InnoDB: Processed 17974 .ibd/.isl files
2019-03-15 2:26:38 139856503813952 [Note] InnoDB: Processed 19954 .ibd/.isl files
2019-03-15 2:26:54 139856503813952 [Note] InnoDB: Processed 21780 .ibd/.isl files
2019-03-15 2:27:10 139856503813952 [Note] InnoDB: Processed 24222 .ibd/.isl files
2019-03-15 2:27:26 139856503813952 [Note] InnoDB: Processed 26752 .ibd/.isl files
2019-03-15 2:27:42 139856503813952 [Note] InnoDB: Processed 29040 .ibd/.isl files
2019-03-15 2:27:58 139856503813952 [Note] InnoDB: Processed 31438 .ibd/.isl files
2019-03-15 2:28:14 139856503813952 [Note] InnoDB: Processed 33660 .ibd/.isl files
2019-03-15 2:28:30 139856503813952 [Note] InnoDB: Processed 35827 .ibd/.isl files
2019-03-15 2:28:46 139856503813952 [Note] InnoDB: Processed 37950 .ibd/.isl files
2019-03-15 2:29:02 139856503813952 [Note] InnoDB: Processed 40073 .ibd/.isl files
2019-03-15 2:29:18 139856503813952 [Note] InnoDB: Processed 42295 .ibd/.isl files
2019-03-15 2:29:34 139856503813952 [Note] InnoDB: Processed 44858 .ibd/.isl files
2019-03-15 2:29:50 139856503813952 [Note] InnoDB: Processed 47619 .ibd/.isl files
2019-03-15 2:30:06 139856503813952 [Note] InnoDB: Processed 50127 .ibd/.isl files
2019-03-15 2:30:22 139856503813952 [Note] InnoDB: Processed 52382 .ibd/.isl files
2019-03-15 2:30:35 139856503813952 [Note] InnoDB: Restoring possible half-written data pages from the doublewrite buffer...
2019-03-15 2:30:36 139856503813952 [Note] InnoDB: Read redo log up to LSN=205578604032
2019-03-15 2:33:17 139856503813952 [Note] InnoDB: 128 rollback segment(s) are active.
2019-03-15 2:33:17 139856503813952 [Note] InnoDB: Waiting for purge to start
2019-03-15 2:33:17 139856503813952 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.39-83.1 started; log sequence number 205578603650
2019-03-15 2:33:17 139853446502144 [Note] InnoDB: Dumping buffer pool(s) not yet started
2019-03-15 2:33:17 139856503813952 [Note] Plugin 'FEEDBACK' is disabled.
2019-03-15 2:33:17 139856503813952 [Note] Recovering after a crash using tc.log
2019-03-15 2:33:17 139856503813952 [Note] Starting crash recovery...
2019-03-15 2:33:17 139856503813952 [Note] Crash recovery finished.
2019-03-15 2:33:17 139856503813952 [Note] Server socket created on IP: '::'.
2019-03-15 2:33:17 139856503813952 [Note] /opt/lampp/sbin/mysqld: ready for connections.
Version: '10.1.36-MariaDB' socket: '/opt/agews64/data/mysql/mysql.sock' port: 3306 Source distribution

I also checked /var/log/messages, which says that mysqld was oom-killed:

Mar 15 02:23:53 asp1 kernel: node_exporter invoked oom-killer: gfp_mask=0x201da, order=0, oom_score_adj=0
Mar 15 02:23:53 asp1 kernel: node_exporter cpuset=/ mems_allowed=0
Mar 15 02:23:53 asp1 kernel: CPU: 0 PID: 18058 Comm: node_exporter Kdump: loaded Not tainted 3.10.0-862.11.6.el7.x86_64 #1
Mar 15 02:23:53 asp1 kernel: Hardware name: Xen HVM domU, BIOS 4.7.5-1.21 08/13/2018
Mar 15 02:23:53 asp1 kernel: Call Trace:
Mar 15 02:23:53 asp1 kernel: [<ffffffff851135d4>] dump_stack+0x19/0x1b
Mar 15 02:23:53 asp1 kernel: [<ffffffff8510e79f>] dump_header+0x90/0x229
Mar 15 02:23:53 asp1 kernel: [<ffffffff84afa952>] ? ktime_get_ts64+0x52/0xf0
Mar 15 02:23:53 asp1 kernel: [<ffffffff84b513ef>] ? delayacct_end+0x8f/0xb0
Mar 15 02:23:53 asp1 kernel: [<ffffffff84b9ac64>] oom_kill_process+0x254/0x3d0
Mar 15 02:23:53 asp1 kernel: [<ffffffff84b9a70d>] ? oom_unkillable_task+0xcd/0x120
Mar 15 02:23:53 asp1 kernel: [<ffffffff84b9a7b6>] ? find_lock_task_mm+0x56/0xc0
Mar 15 02:23:53 asp1 kernel: [<ffffffff84b9b4a6>] out_of_memory+0x4b6/0x4f0
Mar 15 02:23:53 asp1 kernel: [<ffffffff8510f2a3>] __alloc_pages_slowpath+0x5d6/0x724
Mar 15 02:23:53 asp1 kernel: [<ffffffff84ba17f5>] __alloc_pages_nodemask+0x405/0x420
Mar 15 02:23:53 asp1 kernel: [<ffffffff84bebf98>] alloc_pages_current+0x98/0x110
Mar 15 02:23:53 asp1 kernel: [<ffffffff84b97057>] __page_cache_alloc+0x97/0xb0
Mar 15 02:23:53 asp1 kernel: [<ffffffff84b99758>] filemap_fault+0x298/0x490
Mar 15 02:23:53 asp1 kernel: [<ffffffffc057be66>] ext4_filemap_fault+0x36/0x50 [ext4]
Mar 15 02:23:53 asp1 kernel: [<ffffffff84bc352a>] __do_fault.isra.58+0x8a/0x100
Mar 15 02:23:53 asp1 kernel: [<ffffffff84bc3adc>] do_read_fault.isra.60+0x4c/0x1b0
Mar 15 02:23:53 asp1 kernel: [<ffffffff84c35a20>] ? core_sys_select+0x220/0x2e0
Mar 15 02:23:53 asp1 kernel: [<ffffffff84bc8484>] handle_pte_fault+0x2f4/0xd10
Mar 15 02:23:53 asp1 kernel: [<ffffffff84bcae3d>] handle_mm_fault+0x39d/0x9b0
Mar 15 02:23:53 asp1 kernel: [<ffffffff85120557>] __do_page_fault+0x197/0x4f0
Mar 15 02:23:53 asp1 kernel: [<ffffffff851208e5>] do_page_fault+0x35/0x90
Mar 15 02:23:53 asp1 kernel: [<ffffffff8511c758>] page_fault+0x28/0x30
Mar 15 02:23:53 asp1 kernel: Mem-Info:
Mar 15 02:23:53 asp1 kernel: active_anon:3446850 inactive_anon:436571 isolated_anon:0#012 active_file:52 inactive_file:62 isolated_file:33#012 unevictable:0 dirty:0 writeback:1 unstable:0#012 slab_reclaimable:81428 slab_unreclaimable:15828#012 mapped:733 shmem:874 pagetables:18051 bounce:0#012 free:33080 free_pcp:232 free_cma:0
Mar 15 02:23:53 asp1 kernel: Node 0 DMA free:15904kB min:64kB low:80kB high:96kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15988kB managed:15904kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes
Mar 15 02:23:53 asp1 kernel: lowmem_reserve[]: 0 3598 15861 15861
Mar 15 02:23:53 asp1 kernel: Node 0 DMA32 free:64328kB min:15316kB low:19144kB high:22972kB active_anon:2894768kB inactive_anon:606832kB active_file:240kB inactive_file:144kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:3915776kB managed:3685344kB mlocked:0kB dirty:0kB writeback:0kB mapped:2892kB shmem:2956kB slab_reclaimable:90376kB slab_unreclaimable:6264kB kernel_stack:560kB pagetables:16992kB unstable:0kB bounce:0kB free_pcp:120kB local_pcp:120kB free_cma:0kB writeback_tmp:0kB pages_scanned:4806 all_unreclaimable? yes
Mar 15 02:23:54 asp1 kernel: lowmem_reserve[]: 0 0 12262 12262
Mar 15 02:23:54 asp1 kernel: Node 0 Normal free:52088kB min:52196kB low:65244kB high:78292kB active_anon:10892632kB inactive_anon:1139452kB active_file:0kB inactive_file:104kB unevictable:0kB isolated(anon):0kB isolated(file):132kB present:12840960kB managed:12560512kB mlocked:0kB dirty:0kB writeback:4kB mapped:40kB shmem:540kB slab_reclaimable:235336kB slab_unreclaimable:57048kB kernel_stack:2992kB pagetables:55212kB unstable:0kB bounce:0kB free_pcp:808kB local_pcp:120kB free_cma:0kB writeback_tmp:0kB pages_scanned:877 all_unreclaimable? yes
Mar 15 02:23:54 asp1 kernel: lowmem_reserve[]: 0 0 0 0
Mar 15 02:23:54 asp1 kernel: 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
Mar 15 02:23:54 asp1 kernel: Node 0 DMA32: 777*4kB (UEM) 491*8kB (UE) 347*16kB (UEM) 489*32kB (UEM) 168*64kB (UEM) 42*128kB (E) 34*256kB (UEM) 14*512kB (UEM) 4*1024kB (UE) 0*2048kB 0*4096kB = 64332kB
Mar 15 02:23:54 asp1 kernel: Node 0 Normal: 651*4kB (EM) 535*8kB (UEM) 399*16kB (UEM) 232*32kB (EM) 120*64kB (UEM) 52*128kB (EM) 23*256kB (UEM) 14*512kB (UEM) 4*1024kB (EM) 0*2048kB 0*4096kB = 52180kB
Mar 15 02:23:54 asp1 kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
Mar 15 02:23:54 asp1 kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
Mar 15 02:23:54 asp1 kernel: 4371 total pagecache pages
Mar 15 02:23:54 asp1 kernel: 3444 pages in swap cache
Mar 15 02:23:54 asp1 kernel: Swap cache stats: add 2265240510, delete 2265218928, find 1253147153/1434818329
Mar 15 02:23:54 asp1 kernel: Free swap = 0kB
Mar 15 02:23:54 asp1 kernel: Total swap = 14679344kB
Mar 15 02:23:54 asp1 kernel: 4193181 pages RAM
Mar 15 02:23:54 asp1 kernel: 0 pages HighMem/MovableOnly
Mar 15 02:23:54 asp1 kernel: 127741 pages reserved
Mar 15 02:23:54 asp1 kernel: [ pid ] uid tgid total_vm rss nr_ptes swapents oom_score_adj name
Mar 15 02:23:54 asp1 kernel: [ 352] 0 352 9867 86 24 83 0 systemd-journal
Mar 15 02:23:54 asp1 kernel: [ 544] 0 544 6801 22 19 276 0 systemd-logind
Mar 15 02:23:54 asp1 kernel: [ 545] 81 545 14577 9 33 194 -900 dbus-daemon
Mar 15 02:23:54 asp1 kernel: [ 555] 0 555 5381 31 15 38 0 irqbalance
Mar 15 02:23:54 asp1 kernel: [ 557] 70 557 15039 1 34 115 0 avahi-daemon
Mar 15 02:23:54 asp1 kernel: [ 580] 0 580 27522 2 11 32 0 agetty
Mar 15 02:23:54 asp1 kernel: [ 581] 0 581 24273 1 53 171 0 login
Mar 15 02:23:54 asp1 kernel: [ 590] 70 590 15007 0 31 99 0 avahi-daemon
Mar 15 02:23:54 asp1 kernel: [ 911] 0 911 28203 16 60 241 -1000 sshd
Mar 15 02:23:54 asp1 kernel: [ 983] 0 983 3152 199 11 107 0 xe-daemon
Mar 15 02:23:54 asp1 kernel: [25075] 0 25075 28858 2 12 104 0 bash
Mar 15 02:23:54 asp1 kernel: [20041] 0 20041 2517 7 10 26 0 nimbus
Mar 15 02:23:54 asp1 kernel: [20043] 0 20043 21704 23 11 133 0 controller
Mar 15 02:23:54 asp1 kernel: [20100] 0 20100 3848 13 12 74 0 hdb
Mar 15 02:23:54 asp1 kernel: [20111] 0 20111 21529 25 13 70 0 spooler
Mar 15 02:23:54 asp1 kernel: [20236] 0 20236 4557 46 13 61 0 processes
Mar 15 02:23:54 asp1 kernel: [12829] 0 12829 22983 191 48 4804 0 miniserv.pl
Mar 15 02:23:54 asp1 kernel: [12854] 0 12854 51957 9 40 169 0 gssproxy
Mar 15 02:23:54 asp1 kernel: [21681] 0 21681 170154 219 136 2371 0 rsyslogd
Mar 15 02:23:54 asp1 kernel: [26181] 0 26181 22386 8 42 251 0 master
Mar 15 02:23:54 asp1 kernel: [26183] 89 26183 22456 12 46 256 0 qmgr
Mar 15 02:23:54 asp1 kernel: [26208] 0 26208 15511 12 30 147 -1000 auditd
Mar 15 02:23:54 asp1 kernel: [26393] 0 26393 6476 2 18 50 0 atd
Mar 15 02:23:54 asp1 kernel: [15502] 89 15502 22415 18 45 235 0 tlsmgr
Mar 15 02:23:54 asp1 kernel: [ 9210] 0 9210 4636 41 12 95 0 cdm
Mar 15 02:23:54 asp1 kernel: [ 6925] 0 6925 10724 1 26 69 0 lvmetad
Mar 15 02:23:54 asp1 kernel: [ 4658] 0 4658 11124 1 24 111 -1000 systemd-udevd
Mar 15 02:23:54 asp1 kernel: [ 946] 999 946 153089 36 61 853 0 polkitd
Mar 15 02:23:54 asp1 kernel: [ 962] 0 962 143480 123 95 2669 0 tuned
Mar 15 02:23:54 asp1 kernel: [18056] 0 18056 28825 1 13 50 0 sh
Mar 15 02:23:54 asp1 kernel: [18057] 0 18057 15557 4145 27 1195 0 node_exporter
Mar 15 02:23:54 asp1 kernel: [18095] 0 18095 28825 1 13 52 0 sh
Mar 15 02:23:54 asp1 kernel: [18096] 0 18096 10991 4708 26 1565 0 mysqld_exporter
Mar 15 02:23:54 asp1 kernel: [18133] 0 18133 28825 0 13 49 0 sh
Mar 15 02:23:54 asp1 kernel: [18134] 0 18134 8303 1828 20 555 0 percona-qan-age
Mar 15 02:23:54 asp1 kernel: [ 6046] 0 6046 28892 1 11 124 0 agews
Mar 15 02:23:54 asp1 kernel: [ 6048] 0 6048 28328 2 12 94 0 mysqld_safe
Mar 15 02:23:54 asp1 kernel: [17501] 0 17501 169139 28 155 20648 0 httpd
Mar 15 02:23:54 asp1 kernel: [17506] 996 17506 169805 1210 152 21177 0 httpd
Mar 15 02:23:54 asp1 kernel: [17507] 996 17507 169246 914 151 20819 0 httpd
Mar 15 02:23:54 asp1 kernel: [17508] 996 17508 169322 821 149 20890 0 httpd
Mar 15 02:23:54 asp1 kernel: [17509] 996 17509 169758 1624 150 20719 0 httpd
Mar 15 02:23:54 asp1 kernel: [17602] 996 17602 169246 872 149 20784 0 httpd
Mar 15 02:23:55 asp1 kernel: [18161] 0 18161 31571 20 18 134 0 crond
Mar 15 02:23:55 asp1 kernel: [18656] 996 18656 7996241 3842050 15057 3367018 0 mysqld
Mar 15 02:23:55 asp1 kernel: [21395] 0 21395 45075 6 44 223 0 crond
Mar 15 02:23:55 asp1 kernel: [21398] 996 21398 28294 1 11 44 0 sh
Mar 15 02:23:55 asp1 kernel: [21401] 996 21401 28294 2 12 45 0 cron
Mar 15 02:23:55 asp1 kernel: [21605] 996 21605 28360 2 11 116 0 agews
Mar 15 02:23:55 asp1 kernel: [21638] 996 21638 119791 1479 118 26286 0 php
Mar 15 02:23:55 asp1 kernel: [22785] 89 22785 22438 18 45 234 0 pickup
Mar 15 02:23:55 asp1 kernel: [28413] 0 28413 45075 8 44 221 0 crond
Mar 15 02:23:55 asp1 kernel: [28416] 996 28416 28294 1 12 44 0 sh
Mar 15 02:23:55 asp1 kernel: [28418] 996 28418 28294 0 12 44 0 cron
Mar 15 02:23:55 asp1 kernel: [28625] 996 28625 28360 0 12 116 0 agews
Mar 15 02:23:55 asp1 kernel: [28658] 996 28658 116655 1817 108 23076 0 php
Mar 15 02:23:55 asp1 kernel: [30781] 0 30781 45075 124 44 105 0 crond
Mar 15 02:23:55 asp1 kernel: [30782] 996 30782 28294 39 11 5 0 sh
Mar 15 02:23:55 asp1 kernel: [30783] 996 30783 28360 106 10 12 0 agews
Mar 15 02:23:55 asp1 kernel: [30816] 996 30816 113807 18773 105 3609 0 php
Mar 15 02:23:55 asp1 kernel: [31081] 996 31081 169139 67 137 20607 0 httpd
Mar 15 02:23:55 asp1 kernel: [31158] 0 31158 1090 7 7 11 0 sleep
Mar 15 02:23:55 asp1 kernel: [31169] 0 31169 23016 770 47 4247 0 /usr/libexec/we
Mar 15 02:23:55 asp1 kernel: [31173] 0 31173 169139 175 135 20498 0 httpd
Mar 15 02:23:55 asp1 kernel: Out of memory: Kill process 18656 (mysqld) score 933 or sacrifice child
Mar 15 02:23:55 asp1 kernel: Killed process 18656 (mysqld) total-vm:31984964kB, anon-rss:15368200kB, file-rss:0kB, shmem-rss:0kB

> > What I can say about the server being overloaded, is that it currently hosts
> > a multitenant application in which each database is copied, under a different
> > name, for each different customer.
>
> Still missing something big ...
>
>
> PID   USER  PR NI VIRT  RES   SHR  S %CPU %MEM
> TIME+   COMMAND
> 21542 mysql 20 0  28.9g 14.5g 1980 S 0.0  93.5
> 2:20.33 mysqld
>
>
> MySQL claiming 29G of virtual mem whilst asleep,
> yikes, and I've not been able to find what is
> doing that. Just a hunch, did you try turning off
> performance_schema?

The performance schema is currently on 'cause I hoped it would give some insight on the root cause of this restart, but please notice that the report above comes from a moment when the application was in use, not asleep.

Also, about the performance schema, after activating it I didn't notice a worsening of the server's conditions, it doesn't seem to have too much a negative impact.

> > we do not use the Aria storage engine
>
> Then innodb_buffer_pool_size should be 70-75% of RAM available to MySQL.

Yes, I know the rule, however isn't it for a server which hosts the database server only? This server has also apache on it.

Also, considering the crashes I am getting while giving the InnoDB buffer pool only 2 GB out of 16, I would imagine the conditions would be worse should I give it more than that, am I wrong?

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.