# Replication lag in 5.5 after buffer pool fills up **URL:** \ **Category:** Other MySQL® Questions\ **Created:** [June 5, 2012, 10:36am UTC](https://forums.percona.com/t/replication-lag-in-5-5-after-buffer-pool-fills-up/1819 "2012-06-05T10:36:07Z")\ **Posts on this page:** 3\ **Page:** 1
**Author:** ![jlintz](https://avatars.discourse-cdn.com/v4/letter/j/779978/32.png) [@jlintz](https://forums.percona.com/u/jlintz)\ **Post date:** [June 5, 2012, 10:36am UTC](https://forums.percona.com/t/replication-lag-in-5-5-after-buffer-pool-fills-up/1819/1 "2012-06-05T10:36:07Z")
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 ---
**Author:** ![federated\_life](https://avatars.discourse-cdn.com/v4/letter/f/57b2e6/32.png) [@federated\_life](https://forums.percona.com/u/federated_life)\ **Post date:** [June 6, 2012, 12:45pm UTC](https://forums.percona.com/t/replication-lag-in-5-5-after-buffer-pool-fills-up/1819/2 "2012-06-06T12:45:21Z")
if your not too concerned with a crash, innodb\_flush\_log\_at\_trx\_commit = 0 , for the lag on the replica’s state: sleeping History list length 8 would indicate, to me at least, that your buffer pool isn’t ‘filled up’ and flushing. also if you have your io capacity set to 3000, did you try O\_DSYNC? ( assuming your on a san but maybe you have ssds ). ---
**Author:** ![sterin](https://avatars.discourse-cdn.com/v4/letter/s/3ab097/32.png) [@sterin](https://forums.percona.com/u/sterin)\ **Post date:** [June 13, 2012, 8:06am UTC](https://forums.percona.com/t/replication-lag-in-5-5-after-buffer-pool-fills-up/1819/3 "2012-06-13T08:06:59Z")
federated\_life wrote on Wed, 06 June 2012 20:15 > [@](#): > > if your not too concerned with a crash, innodb\_flush\_log\_at\_trx\_commit = 0 , for the lag on the replica’s Since he is already running innodb\_flush\_log\_at\_trx\_commit = 2 I don’t think that is going to make any direct difference. Especially since the modification rate is so low as 105 writes/second. But here are the questions: 1. What about overall memory usage on the machine? Is the OS possibly starting to swap and start use up IO, but you have only been looking at the MySQL status and only associated the problem with the buffer pool filling up? 1. What kind of storage solution do you have? How much does it actually handle? 1. Biggest change in 5.5 related to this is probably the native support for AIO on Linux. Have you tried as a test to switch back to InnoDB’s emulated AIO with innodb\_use\_native\_aio = 0 ? (although I think it’s a long shot)