Bug #31091 slow query log doesn't log lock time

• Submitted: 19 Sep 2007 5:18
• Modified: 29 Jan 2010 3:17
• Reporter: li david
• Status: No Feedback
• Category: MySQL Server: General
• Severity: S4 (Feature request)
• Version: 5.0.45
• OS: Linux (redhat as4 x86_64)
• CPU Architecture: Any

[19 Sep 2007 5:18] li david

Description:
mysql> set global long_query_time=2;
Query OK, 0 rows affected (0.00 sec)
mysql> use test;
Database changed
mysql> lock table sbtest_innodb read local;
Query OK, 0 rows affected (0.00 sec)

mysql> select count(*) from sbtest_innodb limit 50;
+----------+
| count(*) |
+----------+
| 50000000 | 
+----------+
1 row in set (3 min 20.91 sec)

mysql> unlock table;
Query OK, 0 rows affected (0.00 sec)

It can't record lock time in slow query log as the following:
# Time: 070918 11:23:18
# User@Host: root[root] @ localhost []
# Query_time: 201  Lock_time: 0  Rows_sent: 1  Rows_examined: 50000000
select count(*) from sbtest_innodb limit 50;
mysql> lock table sbtest_innodb write;
Query OK, 0 rows affected (0.00 sec)

mysql> select count(*) from sbtest_innodb limit 50;
+----------+
| count(*) |
+----------+
| 50000000 | 
+----------+
1 row in set (3 min 21.07 sec)

mysql> unlock tables;
Query OK, 0 rows affected (0.00 sec)
so can't it as the following:
# Time: 070918 11:30:30
# User@Host: root[root] @ localhost []
# Query_time: 201  Lock_time: 0  Rows_sent: 1  Rows_examined: 50000000
select count(*) from sbtest_innodb limit 50;

How to repeat:
mysql> set global long_query_time=2;
Query OK, 0 rows affected (0.00 sec)
mysql> use test;
Database changed
mysql> lock table sbtest_innodb read local;
Query OK, 0 rows affected (0.00 sec)

mysql> select count(*) from sbtest_innodb limit 50;
+----------+
| count(*) |
+----------+
| 50000000 | 
+----------+
1 row in set (3 min 20.91 sec)

mysql> unlock table;
Query OK, 0 rows affected (0.00 sec)

It can't record lock time in slow query log as the following:
# Time: 070918 11:23:18
# User@Host: root[root] @ localhost []
# Query_time: 201  Lock_time: 0  Rows_sent: 1  Rows_examined: 50000000
select count(*) from sbtest_innodb limit 50;
mysql> lock table sbtest_innodb write;
Query OK, 0 rows affected (0.00 sec)

mysql> select count(*) from sbtest_innodb limit 50;
+----------+
| count(*) |
+----------+
| 50000000 | 
+----------+
1 row in set (3 min 21.07 sec)

mysql> unlock tables;
Query OK, 0 rows affected (0.00 sec)
so can't it as the following:
# Time: 070918 11:30:30
# User@Host: root[root] @ localhost []
# Query_time: 201  Lock_time: 0  Rows_sent: 1  Rows_examined: 50000000
select count(*) from sbtest_innodb limit 50;

[24 Oct 2007 15:00] li david

pls give us an answer

[18 Apr 2008 22:45] Trent Lloyd

Hi Li,

I attempted to duplicate this and was not able to reproduce it (on 5.0.50sp1a)

# Query_time: 8  Lock_time: 8  Rows_sent: 4  Rows_examined: 4

Can you please check this still applies to you?

Regards,
Trent

[29 Dec 2009 0:00] Bugs System

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

[30 Jan 2010 0:00] Bugs System

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".