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

Question

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?

Answer 1

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.

Answer 2

Same scenario here. I have been unable to find a definition of Lock_time in the slow queries log, but this post provides a definition consistent with the situation:

the “lock time” logged in the slow query log only counts time for table-level locks that are taken at the MySQL top level, not InnoDB locks taken at the storage-engine level.

I found the actual lock time using innodb_lock_monitor (as the same post suggests) and innotop. There is a post from one of the innotop contributors explaining how to do that.