Mysql – Galera / InnoDB: how can “thesqldump: Couldn’t execute ‘FLUSH TABLES WITH READ LOCK’: Lock wait timeout exceeded” happen

galerainnodbmariadbmysqldump

Galera 3 node cluster with MariaDB 5.5

error

mysqldump: Couldn't execute 'FLUSH TABLES WITH READ LOCK': Lock wait timeout exceeded; try restarting transaction (1205)

backup command

mysqldump --max_allowed_packet=1G -u root -pdbpassword --opt --flush-logs --single-transaction  --all-databases | bzcat -zc > /var/lib/mysql/backup/fullbackup`date +%Y%m%d-%H%M%S`.sql.bz2

I found only XtraBackup Failing with Lock wait timeout exceeded from Percona Discussion group

The most likely explanation for this is that you have a long-running
statement (even a SELECT).

innobackupex uses FLUSH TABLES WITH READ LOCK to ensure exclusive
access to the non-transactional tables before it backs them up. But
FTWRL requires that there be no statements running, and it will wait
until any current statements complete. If you have a SELECT that is
running for 100 seconds for example, then FTWRL may give up before it
succeeds. And therefore innobackupex won't be able to complete
backing up the non-transactional tables (e.g. mysql.*).

The workaround if you are invoking innobackupex yourself is to use the
–no-lock option on the command-line. But as far as I know, this is not possible when innobackupex is invoked as an SST method by PXC.

Only mysql db is MyISAM / no customer databases.

> SELECT * FROM INFORMATION_SCHEMA.TABLES   WHERE engine = 'MyISAM';
+---------------+--------------+---------------------------+------------+--------+---------+------------+------------+----------------+-------------+--------------------+--------------+-----------+----------------+---------------------+---------------------+---------------------+-------------------+----------+----------------+---------------------------------------------------+
| TABLE_CATALOG | TABLE_SCHEMA | TABLE_NAME                | TABLE_TYPE | ENGINE | VERSION | ROW_FORMAT | TABLE_ROWS | AVG_ROW_LENGTH | DATA_LENGTH | MAX_DATA_LENGTH    | INDEX_LENGTH | DATA_FREE | AUTO_INCREMENT | CREATE_TIME         | UPDATE_TIME         | CHECK_TIME          | TABLE_COLLATION   | CHECKSUM | CREATE_OPTIONS | TABLE_COMMENT                                     |
+---------------+--------------+---------------------------+------------+--------+---------+------------+------------+----------------+-------------+--------------------+--------------+-----------+----------------+---------------------+---------------------+---------------------+-------------------+----------+----------------+---------------------------------------------------+
| def           | mysql        | columns_priv              | BASE TABLE | MyISAM |      10 | Fixed      |          0 |              0 |           0 | 227994731135631359 |         4096 |         0 |           NULL | 2016-04-06 17:50:04 | 2017-04-27 17:09:29 | NULL                | utf8_bin          |     NULL |                | Column privileges                                 |
| def           | mysql        | db                        | BASE TABLE | MyISAM |      10 | Fixed      |        422 |            440 |      186560 | 123848989752688639 |        58368 |       880 |           NULL | 2016-04-06 17:50:04 | 2017-05-03 00:16:26 | 2016-04-06 17:50:04 | utf8_bin          |     NULL |                | Database privileges                               |
| def           | mysql        | event                     | BASE TABLE | MyISAM |      10 | Dynamic    |          0 |              0 |           0 |    281474976710655 |         2048 |         0 |           NULL | 2016-04-06 17:50:04 | 2017-04-27 17:09:29 | NULL                | utf8_general_ci   |     NULL |                | Events                                            |
| def           | mysql        | func                      | BASE TABLE | MyISAM |      10 | Fixed      |          0 |              0 |           0 | 162974011515469823 |         1024 |         0 |           NULL | 2016-04-06 17:50:04 | 2017-04-27 17:09:29 | NULL                | utf8_bin          |     NULL |                | User defined functions                            |
| def           | mysql        | help_category             | BASE TABLE | MyISAM |      10 | Dynamic    |         39 |             28 |        1092 |    281474976710655 |         3072 |         0 |           NULL | 2016-04-06 17:50:04 | 2017-04-27 17:09:29 | NULL                | utf8_general_ci   |     NULL |                | help categories                                   |
| def           | mysql        | help_keyword              | BASE TABLE | MyISAM |      10 | Fixed      |        464 |            197 |       91408 |  55450570411999231 |        16384 |         0 |           NULL | 2016-04-06 17:50:04 | 2017-04-27 17:09:29 | NULL                | utf8_general_ci   |     NULL |                | help keywords                                     |
| def           | mysql        | help_relation             | BASE TABLE | MyISAM |      10 | Fixed      |       1028 |              9 |        9252 |   2533274790395903 |        19456 |         0 |           NULL | 2016-04-06 17:50:04 | 2017-04-27 17:09:29 | NULL                | utf8_general_ci   |     NULL |                | keyword-topic relation                            |
| def           | mysql        | help_topic                | BASE TABLE | MyISAM |      10 | Dynamic    |        508 |            886 |      450388 |    281474976710655 |        20480 |         0 |           NULL | 2016-04-06 17:50:04 | 2017-04-27 17:09:29 | NULL                | utf8_general_ci   |     NULL |                | help topics                                       |
| def           | mysql        | host                      | BASE TABLE | MyISAM |      10 | Fixed      |          0 |              0 |           0 | 110056715893866495 |         2048 |         0 |           NULL | 2016-04-06 17:50:04 | 2017-04-27 17:09:29 | NULL                | utf8_bin          |     NULL |                | Host privileges;  Merged with database privileges |
| def           | mysql        | ndb_binlog_index          | BASE TABLE | MyISAM |      10 | Dynamic    |          0 |              0 |           0 |    281474976710655 |         1024 |         0 |           NULL | 2016-04-06 17:50:04 | 2017-04-27 17:09:29 | NULL                | latin1_swedish_ci |     NULL |                |                                                   |
| def           | mysql        | plugin                    | BASE TABLE | MyISAM |      10 | Dynamic    |          1 |             32 |          32 |    281474976710655 |         2048 |         0 |           NULL | 2016-04-06 17:50:04 | 2017-04-27 17:09:29 | NULL                | utf8_general_ci   |     NULL |                | MySQL plugins                                     |
| def           | mysql        | proc                      | BASE TABLE | MyISAM |      10 | Dynamic    |          3 |           1208 |        3624 |    281474976710655 |         4096 |         0 |           NULL | 2016-04-06 17:50:04 | 2017-04-27 17:09:29 | NULL                | utf8_general_ci   |     NULL |                | Stored Procedures                                 |
| def           | mysql        | procs_priv                | BASE TABLE | MyISAM |      10 | Fixed      |          0 |              0 |           0 | 239253730204057599 |         4096 |         0 |           NULL | 2016-04-06 17:50:04 | 2017-04-27 17:09:29 | NULL                | utf8_bin          |     NULL |                | Procedure privileges                              |
| def           | mysql        | proxies_priv              | BASE TABLE | MyISAM |      10 | Fixed      |          1 |            693 |        1386 | 195062158860484607 |         5120 |       693 |           NULL | 2016-04-06 17:50:04 | 2017-04-27 17:09:29 | 2016-04-06 17:50:04 | utf8_bin          |     NULL |                | User proxy privileges                             |
| def           | mysql        | servers                   | BASE TABLE | MyISAM |      10 | Fixed      |          0 |              0 |           0 | 433752939111120895 |         1024 |         0 |           NULL | 2016-04-06 17:50:04 | 2017-04-27 17:09:29 | NULL                | utf8_general_ci   |     NULL |                | MySQL Foreign Servers table                       |
| def           | mysql        | tables_priv               | BASE TABLE | MyISAM |      10 | Fixed      |          0 |              0 |           0 | 239535205180768255 |         4096 |         0 |           NULL | 2016-04-06 17:50:04 | 2017-04-27 17:09:29 | NULL                | utf8_bin          |     NULL |                | Table privileges                                  |
| def           | mysql        | time_zone                 | BASE TABLE | MyISAM |      10 | Fixed      |          0 |              0 |           0 |   1970324836974591 |         1024 |         0 |              1 | 2016-04-06 17:50:04 | 2017-04-27 17:09:29 | NULL                | utf8_general_ci   |     NULL |                | Time zones                                        |
| def           | mysql        | time_zone_leap_second     | BASE TABLE | MyISAM |      10 | Fixed      |          0 |              0 |           0 |   3659174697238527 |         1024 |         0 |           NULL | 2016-04-06 17:50:04 | 2017-04-27 17:09:29 | NULL                | utf8_general_ci   |     NULL |                | Leap seconds information for time zones           |
| def           | mysql        | time_zone_name            | BASE TABLE | MyISAM |      10 | Fixed      |          0 |              0 |           0 |  55450570411999231 |         1024 |         0 |           NULL | 2016-04-06 17:50:04 | 2017-04-27 17:09:29 | NULL                | utf8_general_ci   |     NULL |                | Time zone names                                   |
| def           | mysql        | time_zone_transition      | BASE TABLE | MyISAM |      10 | Fixed      |          0 |              0 |           0 |   4785074604081151 |         1024 |         0 |           NULL | 2016-04-06 17:50:04 | 2017-04-27 17:09:29 | NULL                | utf8_general_ci   |     NULL |                | Time zone transitions                             |
| def           | mysql        | time_zone_transition_type | BASE TABLE | MyISAM |      10 | Fixed      |          0 |              0 |           0 |  10696049115004927 |         1024 |         0 |           NULL | 2016-04-06 17:50:04 | 2017-04-27 17:09:29 | NULL                | utf8_general_ci   |     NULL |                | Time zone transition types                        |
| def           | mysql        | user                      | BASE TABLE | MyISAM |      10 | Dynamic    |        424 |            120 |       51132 |    281474976710655 |        17408 |       240 |           NULL | 2016-04-06 17:50:04 | 2017-05-03 00:16:26 | NULL                | utf8_bin          |     NULL |                | Users and global privileges                       |
+---------------+--------------+---------------------------+------------+--------+---------+------------+------------+----------------+-------------+--------------------+--------------+-----------+----------------+---------------------+---------------------+---------------------+-------------------+----------+----------------+---------------------------------------------------+
22 rows in set, 3 warnings (21.77 sec)

why mysqldump uses FLUSH TABLES WITH READ LOCK? Howto debug this error?

Best Answer

For mysqldump, FLUSH TABLES WITH READ LOCK is only issue with --master-data, or --flush-logs together with --single-transaction.

To debug, simply turn on general query log (general_log=1) and you should see the corresponding line where MySQL executes this statement.

Related Solutions

Mysql – Lock wait timeout exceeded on insert despite low lock_time in the slow query log

The query times are wall time from start to finish. The lock times are times spent actually locking affected tables. If you run

select sleep(60);

You'll see a slow query entry with a query time of 60 seconds and no lock time.

50 seconds is a standard lock wait time out setting. Run

show variables like 'innodb_lock_wait_timeout';

I'll bet it's 50. The queries in your OP are likely showing a query time of this b/c of the time out setting. They're probably sitting there not really doing anything waiting for some other query to finish until they're effectively killed. If they're hitting that limit it should be easy to just run show processlist; to see what's going on. You'll likely see many threads in a Locked state (i.e. doing nothing but waiting) where there's one thread "doing something".

Are your truncated "insert" statement ultimately doing some kind of expensive subselect from other tables?

Is your application explicitly locking tables and not letting go?

Edit: Queries hitting a lock wait timeout does not mean they are holding on to a lock for that limit but rather they got tired of waiting for someone else to give it up and let them have a go.

show engine innodb status\G

Can also give you insight to what is locked at the moment and who is holding them. Although the output can be a bit cryptic at first glance it can give some pointers.

Mysql – Amazon RDS MySQL 5.5 Innodb Lock wait timeout exceeded

Since you are running MySQL 5.5, have you considering tuning InnoDB for better performance?

There are several variables that have been added to the MySQL 5.1 InnoDB Plugin that are now native to MySQL 5.5. They usually help increase hyperthreading and take advantage of more IOPS if the environment can handled it. In your case, you should be able to.

I have spun RDS models before (See my post : Local database vs Amazon RDS) and can tell you that RDS is not very helpful in tuning InnoDB. You will have to take the bull by the horns on this one.

When you spun up the RDS instance, you probably used the default DB Parameter Group

You should be able to create a new DB Parameter Group for yourself. When you get to this, set the following:

innodb_read_io_threads : Highest allowed is 64. In RDS, highest allowed is 16. Default is 4.
innodb_write_io_threads : Highest allowed is 64. In RDS, highest allowed is 16. Default is 4.
innodb_thread_concurrency : Default is already 0. Never set this value to any other number.

I suggest these because they are default in RDS for innodb_read_io_threads and innodb_write_io_threads are just too low. In addition, your SHOW ENGINE INNODB STATUS\G

--------
FILE I/O
--------
I/O thread 0 state: waiting for i/o request (insert buffer thread)
I/O thread 1 state: waiting for i/o request (log thread)
I/O thread 2 state: waiting for i/o request (read thread)
I/O thread 3 state: waiting for i/o request (read thread)
I/O thread 4 state: waiting for i/o request (read thread)
I/O thread 5 state: waiting for i/o request (read thread)
I/O thread 6 state: waiting for i/o request (write thread)
I/O thread 7 state: waiting for i/o request (write thread)
I/O thread 8 state: waiting for i/o request (write thread)
I/O thread 9 state: waiting for i/o request (write thread)

only shows the default of 4 for each class of io threads.

Here is the Bad News: To implement config changes, once you create your own DB Parameter Group, you must export the data from the old RDS instance, create a new instance using your new DB Parameter Group, and reload. In more detail...

Create a Custom DB Parameter Group (call it MySettings)
Download RDS CLI and setup a config file with your AWS Credentials
Execute the following : ./rds-modify-db-parameter-group MySettings --parameters "name=innodb_read_io_threads,value=16,method=immediate"
Modify using DB Parameter Option List MySettings
Restart the MySQL RDS Instance

I hope this helps !!!

Best Answer

Related Solutions

Mysql – Lock wait timeout exceeded on insert despite low lock_time in the slow query log

Mysql – Amazon RDS MySQL 5.5 Innodb Lock wait timeout exceeded

Related Question