2

Every 4th day I run in to OOM problem.

[Sat Dec 27 12:20:21 2014] Out of memory: Kill process 3662 (mysqld) score 990 or sacrifice child
[Sat Dec 27 12:20:21 2014] Killed process 3662 (mysqld) total-vm:267580568kB, anon-rss:249094644kB, file-rss:0kB

When I check the mysql err log I get this. Then it gets restarted automatically, at the time of restart the load avg is 60.

InnoDB: Warning: a long semaphore wait:
--Thread 140212527941376 has waited at dict0dict.cc line 1027 for 248.00 seconds the semaphore:
Mutex at 0x17556e048 '&dict_sys->mutex', lock var 1
waiters flag 1
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending preads 0, pwrites 0

=====================================
2014-12-27 12:07:22 7f8677fff700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 17 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 398108 srv_active, 0 srv_shutdown, 91 srv_idle
srv_master_thread log flush and writes: 398198
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 5067811
--Thread 140215609943808 has waited at srv0srv.cc line 2605 for 210.00 seconds the semaphore:
X-lock on RW-latch at 0x1366220 '&dict_operation_lock'
a writer (thread id 140215473645312) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0undo.cc line 298
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-trusty-64bit/percona-server-5.6-5.6.21-70.1/storage/innobase/dict/dict0stats.cc line
2385
--Thread 140212556961536 has waited at dict0dict.cc line 1027 for 169.00 seconds the semaphore:
Mutex at 0x17556e048 '&dict_sys->mutex', lock var 1
waiters flag 1
--Thread 140212527941376 has waited at dict0dict.cc line 1027 for 269.00 seconds the semaphore:
Mutex at 0x17556e048 '&dict_sys->mutex', lock var 1
waiters flag 1
--Thread 140212532467456 has waited at dict0dict.cc line 1027 for 240.00 seconds the semaphore:
Mutex at 0x17556e048 '&dict_sys->mutex', lock var 1
waiters flag 1
--Thread 140215449335552 has waited at dict0dict.cc line 1027 for 58.000 seconds the semaphore:
Mutex at 0x17556e048 '&dict_sys->mutex', lock var 1
waiters flag 1
OS WAIT ARRAY INFO: signal count 1139329316
Mutex spin waits 275600240, rounds 166051177, OS waits 1327651
RW-shared spins 569536954, rounds 1645302082, OS waits 2312389
RW-excl spins 122854873, rounds 1740073086, OS waits 910606
Spin rounds per wait: 0.60 mutex, 2.89 RW-shared, 14.16 RW-excl
------------
TRANSACTIONS
------------
Trx id counter 1800673801
Purge done for trx's n:o < 1800671398 undo n:o < 0 state: running but idle
History list length 1002
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 3549436, OS thread handle 0x7f85c58a4700, query id 1264087983 ec2-175-41-139-224.ap-southeast-1.compute.amazonaws.com 175.41.139.224 readonly init
`
...
.....

RECORD LOCKS space id 2 page no 100 n bits 184 index "PRIMARY" of table "mysql"."innodb_index_stats" trx id 1800673786 lock_mode X
---Killed
141227 12:20:29 mysqld_safe Number of processes running now: 0
141227 12:20:29 mysqld_safe mysqld restarted

Below is my.cnf

[mysql]

# CLIENT #
port                           = 3306
socket                         = /dbvol/mysql/var/run/mysqld/mysqld.sock

[mysqld]

# GENERAL #
user                           = mysql
default-storage-engine         = InnoDB
socket                         = /dbvol/mysql/var/run/mysqld/mysqld.sock
pid-file                       = /dbvol/mysql/var/run/mysqld/mysqld.pid

# MyISAM #
key-buffer-size                = 1G
myisam-recover                 = FORCE,BACKUP

# SAFETY #
max-allowed-packet             = 512M
max-connect-errors             = 1000000

# DATA STORAGE #
datadir                        = /dbvol/mysql/lib/mysql/

# BINARY LOGGING #
binlog-format              = MIXED
log-bin                        = /dbvol/mysql/lib/mysql/mysql-bin
expire-logs-days               = 21
sync-binlog                    = 1

# REPLICATION #

read-only                      = 1
skip-slave-start               = 1
log-slave-updates              = 0
relay-log                      = /dbvol/mysql/lib/mysql/relay-bin
slave-net-timeout              = 60
sync-master-info               = 10000
#sync-relay-log                = 10000
sync-relay-log-info            = 10000
server-id                      = 21300

# CACHES AND LIMITS #
tmp-table-size                 = 32M
max-heap-table-size            = 32M
query-cache-type               = 1
query-cache-size               = 1024M
max-connections                = 1200
thread-cache-size              = 600
open-files-limit               = 65535
table-definition-cache         = 4096
table-open-cache-instances     = 16
table-open-cache               = 1500

# INNODB #
innodb-flush-method            = O_DIRECT
innodb-log-files-in-group      = 2
innodb-log-file-size           = 512M
innodb-flush-log-at-trx-commit = 1
innodb-file-per-table          = 1
innodb-buffer-pool-size        = 220G

# LOGGING #
log-error                      = /dbvol/mysql/log/mysql-error.log
log-queries-not-using-indexes  = 1
slow-query-log                 = 1
slow-query-log-file            = /dbvol/mysql/log/mysql-slow.log
long_query_time                = 5
slow_query_log_use_global_control = log_slow_rate_limit
log_slow_rate_limit = 100

Server Capacity:

CPU : 32
MEM : 240G
SSD: 3TB

Server version: 5.6.21-70.1-log Percona Server (GPL), Release 70.1, Revision 698

Any idea to fix this? Is my buffer_pool_size is too huge in my.cnf?

3

I would suggest that even though your innodb_buffer_pool_size is undoubtedly too large for the available memory (192GB would be the theoretical max "sane" value) your thread-cache-size is likely to be what's occasionally pushing you over the edge.

There's no rational justification for such a large value, particularly with max connections limited to 1200.

I will speculate that shrinking the buffer pool size may lengthen the interval between oom events, and you definitely need to do that... but reducing the thread cache size value may be necessary to eliminate oom events altogether.

Individual client threads can have essentially unbounded memory growth, depending on what's needed to execute any particular query. (That's why the memory usage calculation formulas you'll see that multiply by max connections are essentially worthless for calculating meaningful numbers -- they only give you the least-worst-case scenario).

With the thread cache at 600, you are leaving a door open for a hundreds of memory-intensive queries to leave behind a cached thread holding on to memory that may not be cleaned up for a long time, if ever. It's not technically a "leak," but it behaves similarly.

Decrease this variable below the point where the SHOW STATUS LIKE 'threads_created'; never reaches the point where it stops growing somewhat consistently during moderate to high traffic periods... unless you have an incredibly bursty demand for the number of concurrent connections, you only need a very small number of threads in the thread cache.

The only circumstance I recall where I needed this value to be larger was an application that, on start/restart, attempted to make 48 new client connections in parallel at easentially exactly the same time. (Yes, they had their reasons). Without some number of cached threads available, the server couldn't reliably establish this many new connections so quickly.

And that's what the thread cache does -- reduces the resource cost of new connections to the server, at the expense of maintaining the old ones.


Note, the query cache is also probably too large for good performance. It's essentially unrelated to the oom issue since it doesn't grow, but it's still excessive, since the qcache is a choke point for every query, and a larger cache takes more processing time to manage.

2

OMG 220G out of 240G ??? WAY TOO BIG !!!

Take a look at this Pictorial Representation of InnoDB from Percona CTO Vadim Tkachenko

InnoDB Architecture

Look at the Buffer Pool layout. You allocated 220G but it's all not available for data.

There is a setting called innodb_change_buffer_max_size. The default is 25. This means that 25% of the Buffer Pool is dedicated to applying changes to secondary indexes and pushing those changes into the Insert Buffer of the System Tablespace (ibdata1).

In reality, this would make 165G available for you to house data and index pages. In rare cases, if there is not enough room for data and index pages, it might overrun into the Insert Buffer. I have seen this problem occur in MySQL with much smaller Buffer Pools that are being inundated (or slammed) with heavy writes and lots of indexes. You are probably pushing data into the Buffer Pool faster than data and index pages are being written out (data churn). It's like pouring water into a sink whose drain is partly clogged. Eventually, the sink fills and spills water on the floor. In your particular case, you are spilling water on the floor every 4 days. Hence, your OOM.

You should probably add the following to help ease memory consumption and write I/O

# INNODB #

innodb-flush-method            = O_DIRECT
innodb-log-files-in-group      = 2
innodb-log-file-size           = 512M
innodb-flush-log-at-trx-commit = 1
innodb-file-per-table          = 1
innodb_buffer_pool_size        = 180G
innodb_buffer_pool_instances   = 16
innodb_read_io_threads         = 16
innodb_write_io_threads        = 64
innodb_log_buffer_size         = 256M

Give it a Try !!!

  • 1
    tried with Buffer_pool_size with 180G. I will update after a week. – Mannoj Dec 31 '14 at 15:33
  • 1
    OK. When it comes to the Buffer Pool, I usually try not to pass 75% of RAM for bare metal and 60% for VMs. – RolandoMySQLDBA Dec 31 '14 at 15:36
  • @mannoj Would you please give us the high level view of how this problem was corrected about 4 years ago. I suspect you remember the major event that helped resolve your dilemma at the time. If you are still using MySQL on 5.6 or greater, the following will help in your config. innodb_lru_scan_depth=100 # from 1024 to conserve CPU cycles. Thanks. – Wilson Hauck Jun 16 '18 at 22:41

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.