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: | |
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
[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.