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

innodblockingMySQL

Our Java/Spring application reports occasional lock wait timeouts on single record INSERTs to a MySQL 5.5 InnoDB table. Here are a few slow query log records for some of the failed INSERTs.

# Query_time: 51.472333  Lock_time: 0.000090 Rows_sent: 0  Rows_examined: 0
SET timestamp=1340049365;
insert into Foo ( ...

# Query_time: 51.045967  Lock_time: 0.000131 Rows_sent: 0  Rows_examined: 0
SET timestamp=1340049476;
insert into Foo ( ...

# Query_time: 50.693427  Lock_time: 0.000128 Rows_sent: 0  Rows_examined: 0
SET timestamp=1340049561;
insert into Foo ( ...

Clearly the queries are hanging for a long time and seem to be hitting the exception right at around 50s, but the short lock time does not make sense to me. What can the queries be waiting for if not some lock? Would someone please shed some light onto this?

Best Answer

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.

Related Solutions

Mysql – Unexplained InnoDB timeouts

I know this is really late, but you really need to capture the output of SHOW ENGINE INNODB STATUS; during that query to see why it's waiting.

If it happens a lot during a specific time, it would be easy to just grab that output every x seconds and hope you capture it (or perhaps artificially generate the load).

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 – Unexplained InnoDB timeouts

Mysql – Amazon RDS MySQL 5.5 Innodb Lock wait timeout exceeded

Related Question