Bug #53496 Use Lock_time in slow query log output for InnoDB row lock wait time
Submitted: 7 May 2010 15:51 Modified: 11 Jan 2011 2:01
Reporter: Mark Callaghan Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB Plugin storage engine Severity:S4 (Feature request)
Version:5.1 OS:Any
Assigned to: Jimmy Yang CPU Architecture:Any
Tags: innodb, log, query, slow

[7 May 2010 15:51] Mark Callaghan
Description:
Lock_time in the slow query log is MyISAM-centric. It appears to be used by lock tables and lock tables is rarely done by InnoDB applications.

I want InnoDB row lock wait time per statement to be reported there.

How to repeat:
enable the slow query log

Suggested fix:
srv_suspend_mysql_thread() is called by row_mysql_handle_errors() when the error is DB_LOCK_WAIT. It is easy to time the wait. We just need to get the cumulative wait time up to MySQL.
[7 May 2010 15:59] Valeriy Kravchuk
Thank you for the feature request.
[13 Aug 2010 7:28] Jimmy Yang
We already counting the lock wait time in srv_suspend_mysql_thread(), however, it is not set to THD or trx specific counters (used for srv_n_lock_max_wait_time). 

Now adding a new variable in THD, so we can record the lock wait time by InnoDB storage engine:

# Time: 100813  0:14:38
# User@Host: root[root] @ localhost []
# Query_time: 27.948538  Lock_time: 0.000358 Storage_Lock_time: 26.028251 Rows_sent: 0  Rows_examined: 1
SET timestamp=1281683678;
update t1 set a = 10 where a = 10;
[13 Aug 2010 8:31] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/115646

3154 Jimmy Yang	2010-08-13
      This is the draft change for bug #53496, and open for any comments since
      it involves MySQL code. We added a new reporting variable "Storage_lock_time"
      for lock time wait used by InnoDB. This could impact the slow log output
      format. We could also wrap InnoDB lock wait into the existing "Lock_time",
      in that case, we just need to update thd->utime_after_lock with additional
      lock wait from InnoDB.
[16 Aug 2010 11:24] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/115766

3156 Jimmy Yang	2010-08-16
      Fix bug #53496 Use Lock_time in slow query log output for InnoDB row
      lock wait time. Including the InnoDB lock time in the exiting "Lock_time"
      output.
[25 Aug 2010 9:24] Bugs System
Pushed into mysql-5.5 5.5.6-m3 (revid:alik@ibmvm-20100825092002-2yvkb3iwu43ycpnm) (version source revid:alik@ibmvm-20100825092002-2yvkb3iwu43ycpnm) (merge vers: 5.5.6-m3) (pib:20)
[30 Aug 2010 8:32] Bugs System
Pushed into mysql-trunk 5.6.1-m4 (revid:alik@sun.com-20100830082732-n2eyijnv86exc5ci) (version source revid:alik@sun.com-20100830082732-n2eyijnv86exc5ci) (merge vers: 5.6.1-m4) (pib:21)
[30 Aug 2010 8:36] Bugs System
Pushed into mysql-next-mr (revid:alik@sun.com-20100830082745-n6sh01wlwh3itasv) (version source revid:alik@sun.com-20100830082745-n6sh01wlwh3itasv) (pib:21)
[14 Sep 2010 17:55] John Russell
How exactly is the slow query log output changed by this patch?
[15 Sep 2010 16:31] Jimmy Yang
John, in the final version, instead of adding a new Storage_Lock_time field, we added the InnoDB lock time to the existing "Lock_time" field:

# Time: 100813  0:14:38
# User@Host: root[root] @ localhost []
# Query_time: 27.948538  Lock_time: 25.432158 Rows_sent: 0 

So output format is the same as before, except now the "Lock_time" would have larger value since it includes the lock wait time in InnoDB. This is exactly the original request from Mark
[11 Jan 2011 1:56] John Russell
Added to 5.5.6 change log:

The Lock_time field in the slow query log now reports a larger value,
including the time for InnoDB lock waits at the statement level.