Hi,
Recently we’ve completed an upgrade to Percona 5.5.21 and after running fine for a few weeks, our slaves started lagging behind. We noticed this occurred right when the buffer pool filled up on the slaves. After bouncing one of the slaves and clearing the buffer pool, the replication caught up right away. We did not experience this problem on 5.1 on the same hardware configuration. The insert rate is very low, around 70/sec. There was a huge jump in spin rounds once the buffer pool filled up. Below is a copy of the my.cnf from a server and an output of SHOW INNODB STATUS from a slave that is falling behind.
[mysqld]
datadir=/data/mysql
expire_logs_days = 15
innodb_adaptive_flushing = 0
innodb_buffer_pool_size = 53G
innodb_data_file_path = ibdata1:100M:autoextend
innodb_doublewrite = 1
innodb_file_per_table = 1
innodb_flush_log_at_trx_commit = 2
innodb_flush_method = O_DIRECT
innodb_io_capacity = 3000
innodb_log_buffer_size = 4M
innodb_log_file_size = 512M
innodb_log_files_in_group = 3
innodb_max_dirty_pages_pct = 80
innodb_read_ahead = none
innodb_read_io_threads = 24
innodb_support_xa = 0
innodb_thread_concurrency = 16
innodb_use_sys_malloc = 1
innodb_write_io_threads = 12
key_buffer_size = 64M
log-error = /var/log/mysqld.log
log-queries-not-using-indexes
log-slow-queries = /data/mysql/mysql-slow.log
log_bin = /data/mysql/binlog/mysql-bin.log
log_slave_updates = 1
long_query_time = 2
max_binlog_size = 250M
max_connections = 4096
max_heap_table_size = 64M
query_cache_limit = 2M
query_cache_size = 64M
read_buffer_size = 2M
read_rnd_buffer_size = 8M
relay-log-index = /data/mysql/relay-logs/db-relay-bin.index
relay-log = /data/mysql/relay-logs/db-relay-bin
relay_log_space_limit = 25G
replicate-same-server-id = 0
server-id = 11129
skip-name-resolve
skip-slave-start
socket = /var/lib/mysql/mysql.sock
table_cache = 2048
thread_cache_size = 32
tmp_table_size = 64M
tmpdir = /data/mysql/tmp
user = mysql
lc-messages-dir = /usr/share/mysql/english/
mysql> SHOW ENGINE INNODB STATUS\G
*************************** 1. row ***************************
Type: InnoDB
Name:
Status:
120605 15:57:07 INNODB MONITOR OUTPUT
Per second averages calculated from the last 8 seconds
BACKGROUND THREAD
srv_master_thread loops: 2289882 1_second, 2289881 sleeps, 228966 10_second, 241 background, 241 flush
srv_master_thread log flush and writes: 2311034
SEMAPHORES
OS WAIT ARRAY INFO: reservation count 613934, signal count 566935
Mutex spin waits 4387304, rounds 7999861, OS waits 150111
RW-shared spins 233448, rounds 6922705, OS waits 230420
RW-excl spins 0, rounds 7033695, OS waits 231218
Spin rounds per wait: 1.82 mutex, 29.65 RW-shared, 7033695.00 RW-excl
FILE I/O
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (read thread)
I/O thread 5 state: waiting for completed aio requests (read thread)
I/O thread 6 state: waiting for completed aio requests (read thread)
I/O thread 7 state: waiting for completed aio requests (read thread)
I/O thread 8 state: waiting for completed aio requests (read thread)
I/O thread 9 state: waiting for completed aio requests (read thread)
I/O thread 10 state: waiting for completed aio requests (read thread)
I/O thread 11 state: waiting for completed aio requests (read thread)
I/O thread 12 state: waiting for completed aio requests (read thread)
I/O thread 13 state: waiting for completed aio requests (read thread)
I/O thread 14 state: waiting for completed aio requests (read thread)
I/O thread 15 state: waiting for completed aio requests (read thread)
I/O thread 16 state: waiting for completed aio requests (read thread)
I/O thread 17 state: waiting for completed aio requests (read thread)
I/O thread 18 state: waiting for completed aio requests (read thread)
I/O thread 19 state: waiting for completed aio requests (read thread)
I/O thread 20 state: waiting for completed aio requests (read thread)
I/O thread 21 state: waiting for completed aio requests (read thread)
I/O thread 22 state: waiting for completed aio requests (read thread)
I/O thread 23 state: waiting for completed aio requests (read thread)
I/O thread 24 state: waiting for completed aio requests (read thread)
I/O thread 25 state: waiting for completed aio requests (read thread)
I/O thread 26 state: waiting for completed aio requests (write thread)
I/O thread 27 state: waiting for completed aio requests (write thread)
I/O thread 28 state: waiting for completed aio requests (write thread)
I/O thread 29 state: waiting for completed aio requests (write thread)
I/O thread 30 state: waiting for completed aio requests (write thread)
I/O thread 31 state: waiting for completed aio requests (write thread)
I/O thread 32 state: waiting for completed aio requests (write thread)
I/O thread 33 state: waiting for completed aio requests (write thread)
I/O thread 34 state: waiting for completed aio requests (write thread)
I/O thread 35 state: waiting for completed aio requests (write thread)
I/O thread 36 state: waiting for completed aio requests (write thread)
I/O thread 37 state: waiting for completed aio requests (write thread)
Pending normal aio reads: 0 [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0] ,
ibuf aio reads: 0, log i/o’s: 0, sync i/o’s: 0
Pending flushes (fsync) log: 0; buffer pool: 0
1714541 OS file reads, 224305112 OS file writes, 12307842 OS fsyncs
2.62 reads/s, 16384 avg bytes/read, 105.86 writes/s, 8.37 fsyncs/s
INSERT BUFFER AND ADAPTIVE HASH INDEX
Ibuf: size 1, free list len 0, seg size 2, 0 merges
merged operations:
insert 0, delete mark 0, delete 0
discarded operations:
insert 0, delete mark 0, delete 0
Hash table size 112623829, node heap has 1 buffer(s)
0.00 hash searches/s, 39.12 non-hash searches/s
LOG
Log sequence number 1015113642854
Log flushed up to 1015113642854
Last checkpoint at 1015113625347
Max checkpoint age 1302939833
Checkpoint age target 1262222964
Modified age 17507
Checkpoint age 17507
0 pending log writes, 0 pending chkp writes
116560569 log i/o’s done, 38.62 log i/o’s/second
BUFFER POOL AND MEMORY
Total memory allocated 58464403456; in additional pool allocated 0
Internal hash tables (constant factor + variable factor)
Adaptive hash index 901011232 (900990632 + 20600)
Page hash 56312744 (buffer pool 0 only)
Dictionary cache 225319932 (225249296 + 70636)
File system 87512 (82672 + 4840)
Lock system 146585976 (146585224 + 752)
Recovery system 0 (0 + 0)
Dictionary memory allocated 70636
Buffer pool size 3473407
Buffer pool size, bytes 56908300288
Free buffers 0
Database pages 3473406
Old database pages 1282189
Modified db pages 137
Pending reads 0
Pending writes: LRU 112, flush list 0, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 1714385, created 1988761, written 105847991
2.10 reads/s, 0.70 creates/s, 52.59 writes/s
Buffer pool hit rate 992 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 3473406, unzip_LRU len: 0
I/O sum[4087]:cur[0], unzip sum[0]:cur[0]
ROW OPERATIONS
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
—OLDEST VIEW—
Normal read view
Read view low limit trx n:o 6F812800
Read view up limit trx id 6F812800
Read view low limit trx id 6F812800
Read view individually stored trx ids:
Main thread process no. 24458, id 1509325120, state: sleeping
Number of rows inserted 113611681, updated 0, deleted 0, read 0
37.12 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
TRANSACTIONS
Trx id counter 7646BBA2
Purge done for trx’s n:o < 0 undo n:o < 0
History list length 8
LIST OF TRANSACTIONS FOR EACH SESSION:
—TRANSACTION 0, not started
MySQL thread id 27122, OS thread handle 0x5d1ee940, query id 227343485 localhost root
SHOW ENGINE INNODB STATUS
—TRANSACTION 7646BBA1, ACTIVE 6 sec inserting
mysql tables in use 1, locked 1
1 lock struct(s), heap size 376, 0 row lock(s)
MySQL thread id 4, OS thread handle 0x5d270940, query id
END OF INNODB MONITOR OUTPUT
1 row in set (1.80 sec)
One possibility discussed was looking at the multiple buffer pool option in 5.5 but given we did not experience this in 5.1, I’m curious if there’s something obvious to explain why we see such a performance degradation when the buffer pool fills up on 5.5. Thanks