MySQL: Replication is paused with both threads running, System Lock in ProcessList

MySQLreplication

I have just set up Master Slave replication from a MariaDB EC2 instance to a MySQL RDS instance.

What can I do?

The Seconds_Behind_Master are increasing, never decreasing.

Slave_IO_State  Waiting for master to send event
Master_Host MY-HOST-IP^^^
Master_User slave
Master_Port 3306
Connect_Retry   60
Master_Log_File mysql-bin.000001
Read_Master_Log_Pos 100980741
Relay_Log_File  relaylog.000051
Relay_Log_Pos   642918
Relay_Master_Log_File   mysql-bin.000001
Slave_IO_Running    Yes
Slave_SQL_Running   Yes
Replicate_Do_DB 
Replicate_Ignore_DB 
Replicate_Do_Table  
Replicate_Ignore_Table  mysql.plugin, innodb_memcache.cache_policies, mysql.rds_sysinfo, mysql.rds_replication_status, mysql.rds_history, innodb_memcache.config_options
Replicate_Wild_Do_Table 
Replicate_Wild_Ignore_Table 
Last_Errno  0
Last_Error  
Skip_Counter    0
Exec_Master_Log_Pos 59472980
Relay_Log_Space 43275177
Until_Condition None
Until_Log_File  
Until_Log_Pos   0
Master_SSL_Allowed  No
Master_SSL_CA_File  
Master_SSL_CA_Path  
Master_SSL_Cert 
Master_SSL_Cipher   
Master_SSL_Key  
Seconds_Behind_Master   11515

On issuing SHOW PROCESSLIST:

2
rdsadmin
localhost:45313
mysql
Sleep
7
NULL

1068173
root
86.108.98.236:58747
NULL
Sleep
671
NULL

1068174
system user
NULL
Connect
672
Waiting for master to send event
NULL

1068175
system user
NULL
Connect
11643
System lock
NULL

1068190
root
IP-COMES-HERE^^^:46621
NULL
Query
0
init

You can see a SYSTEM LOCK.

The master sees the slave, and it was working previously.

SHOW ENGINE INNODB STATUS shows:

=====================================
2015-06-01 18:28:41 2b7f6b841700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 8 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 78727 srv_active, 0 srv_shutdown, 10037 srv_idle
srv_master_thread log flush and writes: 88762
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 38816
OS WAIT ARRAY INFO: signal count 40463
Mutex spin waits 99825, rounds 246233, OS waits 4479
RW-shared spins 13615, rounds 397880, OS waits 13032
RW-excl spins 341, rounds 642345, OS waits 21206
Spin rounds per wait: 2.47 mutex, 29.22 RW-shared, 1883.71 RW-excl
------------------------
LATEST FOREIGN KEY ERROR
------------------------
2015-06-01 10:43:38 2b7f6b986700  Cannot drop table `developer_dev`.`app`
because it is referenced by `market_dev_2`.`offer`
------------
TRANSACTIONS
------------
Trx id counter 2593136
Purge done for trx's n:o < 2593135 undo n:o < 0 state: running but idle
History list length 3137
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 1068194, OS thread handle 0x2b7f6b841700, query id 4801324 IP HERE root init
SHOW ENGINE INNODB STATUS
---TRANSACTION 2591367, not started
MySQL thread id 1068174, OS thread handle 0x2b7f6b535700, query id 0 Waiting for master to send event
---TRANSACTION 2581507, not started
MySQL thread id 1068173, OS thread handle 0x2b7f6abd0700, query id 4788653 86.108.98.236 root cleaning up
---TRANSACTION 2592991, not started
MySQL thread id 2, OS thread handle 0x2b7f6a3d2700, query id 4801176 localhost 127.0.0.1 rdsadmin cleaning up
---TRANSACTION 2593135, ACTIVE (PREPARED) 0 sec flushing log
7 lock struct(s), heap size 1184, 3 row lock(s), undo log entries 2
MySQL thread id 1068175, OS thread handle 0x2b7f6b2ab700, query id 4801320 System lock
--------
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 (write thread)
I/O thread 7 state: waiting for completed aio requests (write thread)
I/O thread 8 state: waiting for completed aio requests (write thread)
I/O thread 9 state: waiting for completed aio requests (write thread)
Pending normal aio reads: 0 [0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0] ,
ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 1; buffer pool: 0
992 OS file reads, 2680197 OS file writes, 1725299 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 6.50 writes/s, 6.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 5449511, node heap has 1866 buffer(s)
18.37 hash searches/s, 7.75 non-hash searches/s
---
LOG
---
Log sequence number 2542366583
Log flushed up to   2542365001
Pages flushed up to 2534173043
Last checkpoint at  2534173043
1 pending log writes, 0 pending chkp writes
662171 log i/o's done, 6.50 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 2818179072; in additional pool allocated 0
Dictionary memory allocated 208221
Buffer pool size   168064
Free buffers       77382
Database pages     88816
Old database pages 32621
Modified db pages  1686
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 104, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 889, created 87927, written 1554696
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 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: 88816, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
----------------------
INDIVIDUAL BUFFER POOL INFO
----------------------
---BUFFER POOL 0
Buffer pool size   21008
Free buffers       9962
Database pages     10813
Old database pages 3971
Modified db pages  180
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 150, created 10663, written 320364
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 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: 10813, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 1
Buffer pool size   21008
Free buffers       9595
Database pages     11180
Old database pages 4106
Modified db pages  187
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 73, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 58, created 11122, written 60499
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 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: 11180, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 2
Buffer pool size   21008
Free buffers       9930
Database pages     10845
Old database pages 3983
Modified db pages  64
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 54, created 10791, written 33280
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 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: 10845, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 3
Buffer pool size   21008
Free buffers       9641
Database pages     11132
Old database pages 4089
Modified db pages  328
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 126, created 11006, written 271895
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 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: 11132, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 4
Buffer pool size   21008
Free buffers       9429
Database pages     11345
Old database pages 4167
Modified db pages  224
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 3, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 133, created 11212, written 303361
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 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: 11345, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 5
Buffer pool size   21008
Free buffers       9540
Database pages     11235
Old database pages 4127
Modified db pages  194
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 12, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 127, created 11108, written 189494
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 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: 11235, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 6
Buffer pool size   21008
Free buffers       9455
Database pages     11319
Old database pages 4158
Modified db pages  244
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 16, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 130, created 11189, written 193531
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 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: 11319, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 7
Buffer pool size   21008
Free buffers       9830
Database pages     10947
Old database pages 4020
Modified db pages  265
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 111, created 10836, written 182272
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 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: 10947, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Main thread process no. 19950, id 47826225891072, state: sleeping
Number of rows inserted 11878528, updated 844596, deleted 8, read 732065066
3.37 inserts/s, 9.62 updates/s, 0.00 deletes/s, 9.62 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

MySQL version is 5.6.22

Best Answer

AWS may be throttling the IOs of the RDS Instance. You should check the IO level of your RDS instance.

Related Solutions

Mysql – innodb_flush_method=O_DIRECT vs O_DSYNC performance impact on ext3 with LVM disk partition

Back on January 21, 2009, Peter Zaitsev stated the following on mysqlperformanceblog.com

As the call for action – I would surely like someone to see if EXT3 can be fixed in this regard as it is by far the most common file system for Linux. It is also worth to investigate if something can be done on MySQL side – may be opening binlog with O_DSYNC flag if sync_binlog=1 instead of using fsync will help ? Or may be binlog pre-allocation would be good solution.

As of yet, I know of no one having touched this issue. O_DSYNC as a default is not an appealing prospect but does accommodate faster writes that are not really verified. That why there is so much hype around O_DIRECT.

I can tell you do not have the InnoDB Plugin installed. With the InnoDB Plugin, several variables should exist.

You should upgrade InnoDB in one of two ways:

Upgrade to MySQL 5.5 (All InnoDB Plugin enhancements are part of MySQL 5.5)
Upgrade the InnoDB Plugin

Once you have done so, you can enhance InnoDB to

access more CPUs and Cores
increase read and write I/O threads
scale the I/O capacity (this is especially needed for different storage media)

Here are my past posts on the settings you can change for this:

Sep 12, 2011 : Possible to make MySQL use more than one core?
Sep 20, 2011 : Multi cores and MySQL Performance
Apr 26, 2012 : Is the CPU performance relevant for a database server?
Mar 16, 2012 : Using multiple cores for single MySQL queries on Debian

Mysql – How to debug a db memory-leak causing thesql to go before it’s own limits

...even surpassing it's theorically maximum possible allocation.

[OK] Maximum possible memory usage: 7.3G (46% of installed RAM)

There is not actually a way to calculate maximum possible memory usage for MySQL, because there is no cap on the memory it can request from the system.

The calculation done by mysqltuner.pl is only an estimate, based on a formula that doesn't take into account all possible variables, because if all possible variables were taken into account, the answer would always be "infinite." It's unfortunate that it's labeled this way.

Here is my theory on what's contributing to your excessive memory usage:

thread_cache_size       = 128

Given that your max_connections is set to 200, the value of 128 for thread_cache_size seems far too high. Here's what makes me think this might be contributing to your problem:

When a thread is no longer needed, the memory allocated to it is released and returned to the system unless the thread goes back into the thread cache. In that case, the memory remains allocated.

^{http://dev.mysql.com/doc/refman/5.6/en/memory-use.html}

If your workload causes even an occasional client thread to require a large amount of memory, those threads may be holding onto that memory, then going back to the pool and sitting around, continuing to hold on to memory they don't technically "need" any more, on the premise that holding on to the memory is less costly than releasing it if you're likely to need it again.

I think it's worth a try to do the following, after first making a note of how much memory MySQL is using at the moment.

Note how many threads are currently cached:

mysql> show status like 'Threads_cached';
+----------------+-------+
| Variable_name  | Value |
+----------------+-------+
| Threads_cached | 9     |
+----------------+-------+
1 row in set (0.00 sec)

Next, disable the thread cache.

mysql> SET GLOBAL thread_cache_size = 0;

This disables the thread cache, but the cached threads will stay in the pool until they're used one more time. Disconnect from the server, then reconnect and repeat.

mysql> show status like 'Threads_cached';

Continue disconnecting, reconnecting, and checking until the counter reaches 0.

Then, see how much memory MySQL is holding.

You may see a decrease, possibly significant, and then again you may not. I tested this on one of my systems, which had 9 threads in the cache. Once those threads had all been cleared out of the cache, the total memory held by MySQL did decrease... not by much, but it does illustrate that threads in the cache do release at least some memory when they are destroyed.

If you see a significant decrease, you may have found your problem. If you don't, then there's one more thing that needs to happen, and how quickly it can happen depends on your environment.

If the theory holds that the other threads -- the ones currently servicing active client connections -- have significant memory allocated to them, either because of recent work in their current client session or because of work requiring a lot of memory that was done by another connection prior to them languishing in the pool, then you won't see all of the potential reduction in memory consumption until those threads are allowed to die and be destroyed. Presumably your application doesn't hold them forever, but how long it will take to know for sure whether there's a difference will depend on whether you have the option of cycling your application (dropping and reconnecting the client threads) or if you'll have to just wait for them to be dropped and reconnected over time on their own.

But... it seems like a worthwhile test. You should not see a substantial performance penalty by setting thread_cache_size to 0. Fortunately, thread_cache_size is a dynamic variable, so you can freely change it with the server running.

Best Answer

Related Solutions

Mysql – innodb_flush_method=O_DIRECT vs O_DSYNC performance impact on ext3 with LVM disk partition

Mysql – How to debug a db memory-leak causing thesql to go before it’s own limits

Related Question