1

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?

2 Answers 2

2

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.

2
  • > The lock times are times spent actually locking affected tables Is this true? My understanding is that it is time spent by the query waiting for a lock to be freed.
    – AndreiM
    Jun 28, 2012 at 11:51
  • >They're probably sitting there not really doing anything waiting for some other query to finish until they're effectively killed What i don't understand is why this doesn't count as 'Lock_wait'. They are waiting, but not for a lock?
    – AndreiM
    Jun 28, 2012 at 11:53
1

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.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge that you have read and understand our privacy policy and code of conduct.

Not the answer you're looking for? Browse other questions tagged or ask your own question.