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
Triage: Triaged: D2 (Serious)

[18 Mar 2008 14:15] Guillaume Lefranc
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.
[18 Mar 2008 19:23] Sveta Smirnova
Thank you for the report.

Please provide your configuration file.
[18 Mar 2008 19:26] Sveta Smirnova
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
[25 Mar 2008 16:42] Guillaume Lefranc
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.
[22 Apr 2008 1:07] insoo kim
# 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
[7 Jul 2008 15:39] Guillaume Lefranc
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
[25 Sep 2008 9:58] Sveta Smirnova
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;
[26 Jan 2009 13:00] 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/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.
[29 Jan 2009 10:38] 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/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.
[29 Jan 2009 12:41] 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/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.
[3 Feb 2009 9:11] Bugs System
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)
[3 Feb 2009 9:41] Bugs System
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)
[4 Feb 2009 11:17] Bugs System
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)
[13 Feb 2009 20:21] Paul Dubois
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.
[17 Feb 2009 15:01] Bugs System
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)
[17 Feb 2009 16:48] Bugs System
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)
[17 Feb 2009 18:24] Bugs System
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)
[29 Jun 2009 5:36] Roel Van de Paar
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.
[27 Oct 2011 14:38] Yakov Beschasnov
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?
[1 Dec 2011 19:05] Sveta Smirnova
This is still repeatable with test case I used in version 5.1.61
[1 Dec 2011 20:01] Sveta Smirnova
Problem is not repeatable with version 5.5
[1 Dec 2011 20:37] Sveta Smirnova
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.