MySQL Bugs: #35396: Abnormal / impossible / large Query_time and Lock

Bug #35396	Abnormal / impossible / large Query_time and Lock_time values in slow query log
Submitted:	18 Mar 2008 14:15	Modified:	1 Dec 2011 20:37
Reporter:	Guillaume Lefranc	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Logging	Severity:	S3 (Non-critical)
Version:	5.0.50sp1a, 5.0 bzr	OS:	Any
Assigned to:	Georgi Kodinov	CPU Architecture:	Any
Tags:	slow query log

Description:
In the MySQL slow query log, I get this kind of lines logged:

# Query_time: 18446744073709551614  Lock_time: 0  Rows_sent: 2  Rows_examined: 2
SELECT c.* FROM c WHERE c.id=7269153 ORDER BY c.c_id DESC LIMIT 0,20;

This usually happens ~20 times a day, at different intervals and with completely different queries.
The Query Time values logged are either 18446744073709551614 or 18446744073709551615.

How to repeat:
Impossible to repeat practically, but I have this bug on every of my database instances.

Thank you for the report.

Please provide your configuration file.

Please also indicate accurate package you use (file name) and upgrade to current 5.0.51a or 5.0.56 and check if bug still exists if possible

package used is mysql-enterprise-gpl-5.0.50sp1a-linux-x86_64-icc-glibc23.tar.gz.
I'll try to upgrade but it will be difficult since I'm not an enterprise subscriber anymore.

# Time: 080422  7:04:00
# User@Host: WingBus[WingBus] @ wingbus.com [222.122.160.28]
# Query_time: 18446744073709551615  Lock_time: 0  Rows_sent: 1  Rows_examined: 0
SELECT t.*
 FROM TalkCategory t
 WHERE t.category_id = 2;

i have same bug, too.

Server version:         5.0.51a-log Source distribution

bug seems related to drifting clock and NTP.
I have a ntp server on my machine, and whenever the clock is reset negatively, the "negative query times" effect appears.

From my server logs:

syslog: Jul  6 22:18:15 db-70 ntpd[4881]: time reset -0.646330 s

mysql-slow.log:
# Query_time: 18446744073709551615  Lock_time: 0  Rows_sent: 2  Rows_examined: 2470
# Time: 080706 22:18:20

Thank you for the feedback.

Verified as described. Version 5.1 seems to be not affected.

To repeat.

$cat bug35396.test
select 1;

$cat bug35396-master.opt
--log-slow-queries --long-query-time=0

$./mtr --manual-gdb bug35396

In other window:

$gdb ....
...
(gdb) b log.cc:2253
Breakpoint 2 at 0x14c789: file log.cc, line 2253.
(gdb) c
Continuing.

Breakpoint 2, MYSQL_LOG::write (this=0x5d6ca0, thd=0x481e218, query=0x4846a28 "select 1", query_length=8, query_start_arg=1222336397) at log.cc:2253
2253          Security_context *sctx= thd->security_ctx;

!!!!!!
Change system time 1 min backward
!!!!!!
(gdb) c

$cat var/log/master-slow.log  
/users/ssmirnova/src/mysql-5.0/sql/mysqld, Version: 5.0.72-debug-log (Source distribution). started with:
Tcp port: 9306  Unix socket: /users/ssmirnova/src/mysql-5.0/mysql-test/var/tmp/master.sock
Time                 Id Command    Argument
# Time: 080925 13:52:30
# User@Host: root[root] @ localhost []
# Query_time: 4294967249  Lock_time: 0  Rows_sent: 1  Rows_examined: 0
use test;
select 1;

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/64025

2735 Georgi Kodinov	2009-01-26
      Bug #35396: Abnormal query times in slow query log
      
      If the system time is adjusted back during a query execution
      (resulting in the end time being earlier than the start time)
      the code that prints to the slow query log gets confused and 
      prints unsigned negative numbers.
      
      Fixed to check for such cases and print meaningful note instead 
      of unsigned negative numbers.
      No test case since this would involve changing the system time.

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/64433

2735 Georgi Kodinov	2009-01-29
      Bug #35396: Abnormal query times in slow query log
            
      If the system time is adjusted back during a query execution
      (resulting in the end time being earlier than the start time)
      the code that prints to the slow query log gets confused and 
      prints unsigned negative numbers.
            
      Fixed by not logging the statements that would have negative
      execution time due to time shifts.
      No test case since this would involve changing the system time.

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/64459

2735 Georgi Kodinov	2009-01-29
      Bug #35396: Abnormal query times in slow query log
                  
      If the system time is adjusted back during a query execution
      (resulting in the end time being earlier than the start time)
      the code that prints to the slow query log gets confused and 
      prints unsigned negative numbers.
                  
      Fixed by not logging the statements that would have negative
      execution time due to time shifts.
      No test case since this would involve changing the system time.

Pushed into 5.0.78 (revid:joro@sun.com-20090203090422-v91rh3gmx2ulhbu9) (version source revid:joro@sun.com-20090129124524-xtgvt43zwta7qgcy) (merge vers: 5.0.77) (pib:6)

Pushed into 5.1.32 (revid:joro@sun.com-20090203090549-gos3v4320vimrzg6) (version source revid:joro@sun.com-20090129124935-mfv4pddc8exvs3nz) (merge vers: 5.1.32) (pib:6)

Pushed into 6.0.10-alpha (revid:kostja@sun.com-20090204104420-mw1i2u9lum4bxjo6) (version source revid:davi.arnaut@sun.com-20090129184519-mgp2vr1rna9nk8li) (merge vers: 6.0.10-alpha) (pib:6)

Noted in 5.0.78, 5.1.32, 6.0.10 changelogs.

If the system time was adjusted backward during query execution, the
apparent execution time could be negative. But in some cases these 
queries would be written to the slow query log, with the negative
execution time written as a large unsigned number. Now statements
with apparent negative execution time are not written to the slow
query log.

Pushed into 5.1.32-ndb-6.3.23 (revid:tomas.ulin@sun.com-20090217131017-6u8qz1edkjfiobef) (version source revid:tomas.ulin@sun.com-20090203133556-9rclp06ol19bmzs4) (merge vers: 5.1.32-ndb-6.3.22) (pib:6)

Pushed into 5.1.32-ndb-6.4.3 (revid:tomas.ulin@sun.com-20090217134419-5ha6xg4dpedrbmau) (version source revid:tomas.ulin@sun.com-20090203133556-9rclp06ol19bmzs4) (merge vers: 5.1.32-ndb-6.3.22) (pib:6)

Pushed into 5.1.32-ndb-6.2.17 (revid:tomas.ulin@sun.com-20090217134216-5699eq74ws4oxa0j) (version source revid:tomas.ulin@sun.com-20090202111723-1zzwax187rtls913) (merge vers: 5.1.32-ndb-6.2.17) (pib:6)

Note that besides seeing large Query_time results, you may also notice large Lock_time results.

Also, automatic OS clock adjustments in Windows can be due to many different reasons, including automatic and/or incorrect NTP adjustments (check w32time), hardware issues (bios/bios battery/overclocking/oscillator crystal), software issues (virus/system load/rogue programs) etc.

Hi!

On the version 5.1.58 (FreeBSD), we have noticed a similar error:

# User@Host: partbile[partbile] @ fe105.hc.ru [89.111.177.201]
# Query_time: 18446744073708.605469  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
SET timestamp=1319436009;
set collation_connection='utf8_general_ci';

Time synchronization is performed continuously by means of ntpd. What do you think?

This is still repeatable with test case I used in version 5.1.61

Problem is not repeatable with version 5.5

As this bug was really fixed in 5.1.32 and re-occurs in current 5.1 versions I opened separate report: bug #63524 for tracking this, possibly new, problem. Please subscribe to new report.