MySQL Bugs: #53191: Lock_time in slow log is negative when logging stored routines

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

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 .

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.

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

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.

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();

this is a new bug in 5.1.45 and higher.
looks like an improper fix for bug #47905

@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.

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().

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

See also bug#52704

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().

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().

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)

Pushed into mysql-next-mr (revid:alik@sun.com-20100615150216-cubqoyn1fj9b6a2p) (version source revid:alik@ibmvm-20100610103252-to5miyvcox8lnmgx) (pib:16)

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.

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)

Noted in 5.1.49 changelog.

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)

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)

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)

Already documented in the 5.1.49 changelog; no new changelog entries required. setting back to Closed state.