Bug #53191 Lock_time in slow log is negative when logging stored routines
Submitted: 27 Apr 2010 9:10 Modified: 14 Oct 2010 14:50
Reporter: Bingxi Wu Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Logging Severity:S1 (Critical)
Version:5.1.45, 5.1.46 OS:Any (linux, windows)
Assigned to: Kristofer Pettersson CPU Architecture:Any
Tags: Lock_time, regression

[27 Apr 2010 9:10] Bingxi Wu
Description:
High load courrency.The slow log is fly-by-night.
PS
# Query_time: 5.819929  Lock_time: 18446744073709.167969 Rows_sent: 39  Rows_examined: 38

How to repeat:
MySQL-5.1.45 Enterprise pro use innodb-plugin

High load courrency ,call one procedure .
[27 Apr 2010 9:53] Sveta Smirnova
Thank you for the report.

What wrong with slow log? If you mean large value - it is not negative yet, negative would be 18446744073709551614 See also bug #47813 where user had same problem because OS bug.
[28 Apr 2010 1:39] Bingxi Wu
This problem don't same it .

I have test MySQL-5.1.41 enperprise pro is ok.
But MySQL-5.1.45 enterprise pro and MySQL-5.1.46 all have the problem,

ps:
grep "Lock_time" mysql.slow |more
# Query_time: 0.016731  Lock_time: 18446744073707.460938 Rows_sent: 29  Rows_examined: 29
# Query_time: 0.000495  Lock_time: 18446744073707.265625 Rows_sent: 32  Rows_examined: 32
# Query_time: 0.042690  Lock_time: 18446744073707.457031 Rows_sent: 28  Rows_examined: 28
# Query_time: 0.002490  Lock_time: 18446744073707.523438 Rows_sent: 28  Rows_examined: 28
# Query_time: 0.096617  Lock_time: 18446744073707.539062 Rows_sent: 27  Rows_examined: 27
# Query_time: 0.009849  Lock_time: 18446744073707.472656 Rows_sent: 28  Rows_examined: 28
# Query_time: 0.008154  Lock_time: 18446744073707.523438 Rows_sent: 31  Rows_examined: 31
# Query_time: 0.000486  Lock_time: 18446744073707.492188 Rows_sent: 31  Rows_examined: 31
# Query_time: 0.000418  Lock_time: 18446744073707.468750 Rows_sent: 27  Rows_examined: 27
# Query_time: 0.027803  Lock_time: 18446744073707.503906 Rows_sent: 30  Rows_examined: 30
# Query_time: 0.000499  Lock_time: 18446744073707.449219 Rows_sent: 27  Rows_examined: 27
# Query_time: 0.004242  Lock_time: 18446744073707.324219 Rows_sent: 29  Rows_examined: 29
# Query_time: 0.000464  Lock_time: 18446744073707.468750 Rows_sent: 30  Rows_examined: 30
# Query_time: 0.000905  Lock_time: 18446744073707.488281 Rows_sent: 32  Rows_examined: 32
# Query_time: 0.022654  Lock_time: 18446744073707.429688 Rows_sent: 26  Rows_examined: 26
# Query_time: 0.000372  Lock_time: 18446744073707.507812 Rows_sent: 27  Rows_examined: 27
# Query_time: 0.002586  Lock_time: 18446744073707.484375 Rows_sent: 32  Rows_examined: 32
# Query_time: 0.000372  Lock_time: 18446744073707.496094 Rows_sent: 30  Rows_examined: 30
# Query_time: 0.000415  Lock_time: 18446744073707.144531 Rows_sent: 32  Rows_examined: 32
# Query_time: 0.000599  Lock_time: 18446744073707.425781 Rows_sent: 30  Rows_examined: 30
# Query_time: 0.028144  Lock_time: 18446744073706.691406 Rows_sent: 29  Rows_examined: 29
# Query_time: 0.042909  Lock_time: 18446744073707.117188 Rows_sent: 24  Rows_examined: 24
# Query_time: 0.009144  Lock_time: 18446744073707.539062 Rows_sent: 20  Rows_examined: 20
# Query_time: 0.001542  Lock_time: 18446744073707.527344 Rows_sent: 32  Rows_examined: 32
# Query_time: 0.000546  Lock_time: 18446744073707.453125 Rows_sent: 31  Rows_examined: 31
# Query_time: 0.000347  Lock_time: 18446744073707.527344 Rows_sent: 30  Rows_examined: 30
# Query_time: 0.000952  Lock_time: 18446744073707.242188 Rows_sent: 32  Rows_examined: 32
# Query_time: 0.001274  Lock_time: 18446744073707.394531 Rows_sent: 31  Rows_examined: 31
# Query_time: 0.000547  Lock_time: 18446744073707.097656 Rows_sent: 30  Rows_examined: 30

system:
Red Hat Enterprise Linux Server release 5.5 (Tikanga)
kernel:2.6.18-194.el5

MySQL:
mysql-enterprise-gpl-5.1.45-linux-x86_64-glibc23.tar.gz
[28 Apr 2010 6:37] Sveta Smirnova
Thank you for the feedback.

But what is the exact problem? Please send us some queries and output of SHOW CREATE TABLE for underlying tables so we can try to repeat it at our side.
[13 May 2010 7:01] MySQL Verification Team
To repeat:

Start server with --log-slow-queries=slow.log --long-query-time=1

In connection 1:

delimiter $
drop table if exists t1$
create table t1(a int)engine=myisam$
drop procedure if exists p1$
create procedure p1()
begin
  insert into t1 values (1);
  select count(*) from t1 where a=1;
  update t1 set a=a*2;
end $
delimiter ;

connection 2:
lock table t1 write;

connection 1:
call p1();

connection 2: (after few seconds...)
unlock tables;

Check slow log:

# User@Host: [root] @  [127.0.0.1]
# Query_time: 0.000000  Lock_time: 18446744073700.176000 Rows_sent: 1  Rows_examined: 2
use test;
SET timestamp=1273733720;
call p1();
[13 May 2010 7:10] MySQL Verification Team
this is a new bug in 5.1.45 and higher.
looks like an improper fix for bug #47905
[24 May 2010 13:23] Kristofer Pettersson
@sinisa I know the feeling. ;-)

To avoid negative numbers we need to store the start_utime variable too. For each statement we get these measurements:
   ----- start_utime
 l    .
 o    .
 c   lock tables
 k    .
 t    .
   ----- utime_after_lock
 q    .
 u    .
 e   query execution
 r    .
 y    .
 t    .
    ------ end_query_time = current_time

lockt= utime_after_lock - start_utime
queryt= current_time - utime_after_lock

Both lockt and queryt are set in dispatch_command() and sp_head::execute() using THD::set_time().

If we accept that lockt for a CALL-statement only includes minimal name locking and pre-locking then we can simply extend the patch for bug#47905 by also saving start_utime the same way we save utime_after_lock.
[25 May 2010 12:39] 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/109166

3369 Kristofer Pettersson	2010-05-25
      Bug#53191 Lock_time in slow log is negative when logging stored routines
      
      Logging slow stored procedures caused the slow log to write 
      very large lock times. The lock times was a result of a 
      negative number being cast to an unsigned integer.
      The reason the lock time appeard negative was because 
      one of the measurements points was reset after execution
      causing it to change order with the start time of the 
      statement.
      
      This bug is related to bug 47905 which in turn was 
      introduced because of a joint fix for 12480,12481,12482 and 11587.
      
      The fix is to only reset the start_time before any statement
      execution in a SP while not resetting start_utime or
      utime_after_lock which are used for measuring the 
      performance of the SP. Start_time is used to set the
      timestamp on the replication event which controlls how
      the slave interprets time functions like NOW().
[25 May 2010 15:34] 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/109204

3370 Kristofer Pettersson	2010-05-25
      Bug#53191 Lock_time in slow log is negative when logging stored routines
      
      Added test case
[7 Jun 2010 13:23] Kristofer Pettersson
See also bug#52704
[7 Jun 2010 18:55] 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/110393

3369 Kristofer Pettersson	2010-06-07
      Bug#53191 Lock_time in slow log is negative when logging stored routines
      
      Logging slow stored procedures caused the slow log to write 
      very large lock times. The lock times was a result of a 
      negative number being cast to an unsigned integer.
      The reason the lock time appeard negative was because 
      one of the measurements points was reset after execution
      causing it to change order with the start time of the 
      statement.
            
      This bug is related to bug 47905 which in turn was 
      introduced because of a joint fix for 12480,12481,12482 and 11587.
       
      The fix is to only reset the start_time before any statement
      execution in a SP while not resetting start_utime or
      utime_after_lock which are used for measuring the 
      performance of the SP. Start_time is used to set the
      timestamp on the replication event which controlls how
      the slave interprets time functions like NOW().
[8 Jun 2010 8:58] 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/110438

3419 Kristofer Pettersson	2010-06-08
      Bug#53191 Lock_time in slow log is negative when logging stored routines
      
      Logging slow stored procedures caused the slow log to write 
      very large lock times. The lock times was a result of a 
      negative number being cast to an unsigned integer.
      The reason the lock time appeard negative was because 
      one of the measurements points was reset after execution
      causing it to change order with the start time of the 
      statement.
            
      This bug is related to bug 47905 which in turn was 
      introduced because of a joint fix for 12480,12481,12482 and 11587.
      
      The fix is to only reset the start_time before any statement
      execution in a SP while not resetting start_utime or
      utime_after_lock which are used for measuring the 
      performance of the SP. Start_time is used to set the
      timestamp on the replication event which controlls how
      the slave interprets time functions like NOW().
[17 Jun 2010 6:13] Bugs System
Pushed into 5.5.5-m3 (revid:alexey.kopytov@sun.com-20100615145247-8bj0vmuqlotbqsn9) (version source revid:kristofer.pettersson@sun.com-20100608101707-z33wabk9jz31g79k) (merge vers: 5.5.5-m3) (pib:16)
[17 Jun 2010 6:17] Bugs System
Pushed into mysql-next-mr (revid:alik@sun.com-20100615150216-cubqoyn1fj9b6a2p) (version source revid:alik@ibmvm-20100610103252-to5miyvcox8lnmgx) (pib:16)
[12 Jul 2010 17:29] Paul DuBois
Noted in 5.5.5 changelog.

The Lock_time value in the slow query log was negative for stored
routines. 

Setting report to Need Merge pending further pushes.
[19 Jul 2010 14:36] Bugs System
Pushed into 5.1.49 (revid:build@mysql.com-20100719143034-omcma40sblwmay3x) (version source revid:kristofer.pettersson@sun.com-20100608085819-qpoyx9ken46bc64m) (merge vers: 5.1.48) (pib:16)
[19 Jul 2010 19:39] Paul DuBois
Noted in 5.1.49 changelog.
[14 Oct 2010 8:34] Bugs System
Pushed into mysql-5.1-telco-7.0 5.1.51-ndb-7.0.20 (revid:martin.skold@mysql.com-20101014082627-jrmy9xbfbtrebw3c) (version source revid:vasil.dimov@oracle.com-20100531152341-x2d4hma644icamh1) (merge vers: 5.5.5-m3) (pib:21)
[14 Oct 2010 8:49] Bugs System
Pushed into mysql-5.1-telco-6.3 5.1.51-ndb-6.3.39 (revid:martin.skold@mysql.com-20101014083757-5qo48b86d69zjvzj) (version source revid:vasil.dimov@oracle.com-20100531152341-x2d4hma644icamh1) (merge vers: 5.5.5-m3) (pib:21)
[14 Oct 2010 9:04] Bugs System
Pushed into mysql-5.1-telco-6.2 5.1.51-ndb-6.2.19 (revid:martin.skold@mysql.com-20101014084420-y54ecj85j5we27oa) (version source revid:vasil.dimov@oracle.com-20100531152341-x2d4hma644icamh1) (merge vers: 5.5.5-m3) (pib:21)
[14 Oct 2010 14:50] Jon Stephens
Already documented in the 5.1.49 changelog; no new changelog entries required. setting back to Closed state.