MySQL Bugs: #9579: slow log gives wrong times

Bug #9579	slow log gives wrong times
Submitted:	2 Apr 2005 7:52	Modified:	3 Oct 2007 1:27
Reporter:	Ian Webber	Email Updates:
Status:	Can't repeat	Impact on me:	None
Category:	MySQL Server	Severity:	S3 (Non-critical)
Version:	4.0.23a	OS:	Linux (suse 9.0)
Assigned to:	Geert Vanderkelen	CPU Architecture:	Any

Description:
the slow log is giving impossible query times like 4294967293 seconds
It only seems to happen at times like xx:59:xx

# Time: 050331 14:59:56
# Query_time: 4294967293  Lock_time: 0  Rows_sent: 9317  Rows_examined: 
18634

# Time: 050401 14:59:59
# Query_time: 4294967295  Lock_time: 0  Rows_sent: 167356  Rows_examined: 334712

How to repeat:
run lots of queries at 14:59

Hi Andrey,

I could not repeat this on both 4.0.23a and 4.1.10a, using SuSE 9.2 here.

# Time: 050407 15:59:23
# User@Host: geert[geert] @ localhost []
# Query_time: 8  Lock_time: 0  Rows_sent: 1  Rows_examined: 394032

# Time: 050407 15:59:23
# User@Host: geert[geert] @ localhost []
# Query_time: 8  Lock_time: 0  Rows_sent: 1  Rows_examined: 394032

I don't have a SuSE 9.0. Any way you could repeat this using 4.1.11?
4294967295 is an interesting number though.

Regards,

Unfortunately I cant use 4.1, but I get a few of these every day. Almost always the time is x:59:59, or if not, very close to it. 

# Time: 050406 18:00:00
# Query_time: 4294967295  Lock_time: 0  Rows_sent: 1  Rows_examined: 19049
# Time: 050407  9:59:59
# Query_time: 4294967295  Lock_time: 0  Rows_sent: 1  Rows_examined: 19049
# Query_time: 4294967295  Lock_time: 0  Rows_sent: 2  Rows_examined: 19049
# Time: 050407 22:59:59
# Query_time: 4294967295  Lock_time: 0  Rows_sent: 1  Rows_examined: 0

I have checked three other servers running the same site, but with 64 bit and Suse 9.2 and this problem never happens, so it must be related to 32 bit, or Suse 9.0 or both

Hi Ian,

Sorry, got your name wrong there :)
Are these official binaries or you compiled it on SuSE 9.0 yourself? Is that gcc 3.3.3?

self compiled with gcc 3.3.1
CFLAGS="-O3 -march=pentiumpro" CXX=gcc CXXFLAGS="-O3 -march=pentiumpro 
-felide-constructors -fno-exceptions -fno-rtti" 
./configure --prefix=/usr/local/mysql --enable-assembler --with-mysqld-ldflags=-all-static --disable-shared --with-extra-charset=complex --with-mysqld-user=mysql

Hi Ian,

You are adjusting your clock every hour, are you?
Otherwise, it could be something todo with the time.h issues.. Like how it defines the storage of the number of seconds since 1970. This would be an example why the official MySQL binary  could be better.

Regards,

Geert

yes, we adjust the clock every hour. I will change it to once a day and see if that makes a difference. However we also adjust the clock once an hour on the Suse 9.2 64 bit servers and never get the error. But yes, I agree with you that it more likely to be a bug in Suse 9.0 than in MySQL. Thanks for your help

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

Status was incorrect.

I am seeing the same thing on CentOS 3.5 (Redhat ES lookalike) except that the times are not as consistent.  This is a shared-hosting server running Plesk inside a Virtuozzo VPS.  Here is a snippet of the current log:

grep -B2 'Query_time: 4294967295' plesk-7-5-shared-2-slow.log | egrep 'Time|Query_time: 4294967295' | tail -40
# Query_time: 4294967295  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
# Time: 060321 10:09:32
# Query_time: 4294967295  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
# Query_time: 4294967295  Lock_time: 1  Rows_sent: 2  Rows_examined: 68
# Time: 060321 10:16:48
# Query_time: 4294967295  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
# Time: 060321 10:17:35
# Query_time: 4294967295  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
# Time: 060321 10:18:02
# Query_time: 4294967295  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
# Time: 060321 10:29:38
# Query_time: 4294967295  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
# Query_time: 4294967295  Lock_time: 0  Rows_sent: 1  Rows_examined: 0
# Time: 060321 10:39:18
# Query_time: 4294967295  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
# Query_time: 4294967295  Lock_time: 0  Rows_sent: 473  Rows_examined: 946
# Query_time: 4294967295  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
# Time: 060321 10:49:02
# Query_time: 4294967295  Lock_time: 0  Rows_sent: 1  Rows_examined: 0
# Time: 060321 10:49:43
# Query_time: 4294967295  Lock_time: 0  Rows_sent: 1  Rows_examined: 0
# Query_time: 4294967295  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
# Time: 060321 10:52:04
# Query_time: 4294967295  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
# Query_time: 4294967295  Lock_time: 0  Rows_sent: 47  Rows_examined: 94
# Time: 060321 11:10:43
# Query_time: 4294967295  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
# Time: 060321 11:12:47
# Query_time: 4294967295  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
# Time: 060321 11:33:59
# Query_time: 4294967295  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
# Time: 060321 11:41:45
# Query_time: 4294967295  Lock_time: 0  Rows_sent: 0  Rows_examined: 7
# Query_time: 4294967295  Lock_time: 0  Rows_sent: 0  Rows_examined: 8
# Time: 060321 11:47:52
# Query_time: 4294967295  Lock_time: 0  Rows_sent: 1  Rows_examined: 1
# Time: 060321 12:05:05
# Query_time: 4294967295  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
# Time: 060321 12:21:22
# Query_time: 4294967295  Lock_time: 0  Rows_sent: 0  Rows_examined: 0

Forgot to mention; the server version (as per mysql -V) is:
mysql  Ver 11.18 Distrib 3.23.58, for redhat-linux-gnu (i386)

Hello,

the log of one of my mysql server is full of such weird time :
# Time: 060525  4:02:14
# Query_time: 4294967295  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
# Time: 060525  4:02:58
# Query_time: 4294967295  Lock_time: 0  Rows_sent: 1  Rows_examined: 0
# Time: 060525  4:04:19
# Query_time: 4294967294  Lock_time: 0  Rows_sent: 1  Rows_examined: 0
# Time: 060525  4:04:27
# Query_time: 4294967294  Lock_time: 0  Rows_sent: 1  Rows_examined: 0
# Time: 060525  4:04:35
# Query_time: 4294967294  Lock_time: 0  Rows_sent: 1  Rows_examined: 0

it goes on all day, i even have 0 time slow queries like :
# Time: 060525  6:25:39
# Query_time: 0  Lock_time: 1  Rows_sent: 0  Rows_examined: 0

It has started right after install.

mysql -V : 
mysql  Ver 14.7 Distrib 4.1.19, for pc-linux-gnu (i686) using readline 4.3

mysqladmin ver :
mysqladmin  Ver 8.41 Distrib 4.1.19, for pc-linux-gnu on i686
Copyright (C) 2000 MySQL AB & MySQL Finland AB & TCX DataKonsult AB
This software comes with ABSOLUTELY NO WARRANTY. This is free software,
and you are welcome to modify and redistribute it under the GPL license

Server version          4.1.19-standard-log
Protocol version        10
Connection              Localhost via UNIX socket
UNIX socket             /usr/mysql/data/mysql.sock
Uptime:                 7 days 8 hours 40 min 4 sec

Threads: 9  Questions: 252384653  Slow queries: 50629  Opens: 138462  Flush tables: 1  Open tables: 700  Queries per second avg: 396.829

i have 4 servers running mysql (same version or 4.1.14) and this one is the only one with this problem (it can happen once in a while on another server when the time is set but never all day like this).

This server is a Dual Core AMD Opteron(tm) Processor 180 2,4Ghz running Linux 2.4.32 with grsec.
It is the only Opteron dual core i have and all the others use the same OS and the same my.cnf.

This server does not swap and is not overly busy :
             total       used       free     shared    buffers     cached
Mem:       2059928    2009936      49992          0      80472    1447960
-/+ buffers/cache:     481504    1578424
Swap:       522104          0     522104

12:24pm  up 7 days,  8:51,  1 user,  load average: 0.16, 0.19, 0.17

I run clockspeed (on all my servers) to keep the time ok.

i am willing to give more info if necessary because this problem prevents me from analyzing my log which is annoying !

Thank you for your time.

Kevin

Hi Ian, Kevin, Bob,

Bug is to long open and I would like to find a way to reproduce. I have been trying some tricks already, but can't come up with something which actually show these wrong results.
It's probably going to be hard to reproduce, but is this happening on a certain query.. ?

Thanks,

Geert

Hi Geert,

thank you for your message. This problem happens with all kind of queries which do not do the same thing on other servers so i dont think it comes from the queries themselves.
I really think it must have something to do with the opteron as, in my case, other servers with the same installation (os, soft and queries) but different processors (pentium) do not have this problem.
I don't know what else to add to help, maybe if you can rent a opteron server at ovh.com ! Unfortunately i cannot let you use mine for now although i could do some tests if needed.

KEvin

the original problem I reported was solved by running nph less frequently

We are getting exactly the same problem:

# Time: 070117 14:02:53
# User@Host: quantel[quantel] @ Quentmodel19203 [xxx.xxx.xxx.xxx]
# Query_time: 4294967295  Lock_time: 0  Rows_sent: 1  Rows_examined: 7

we are running 4.1.12a-win32 on Windows 2K

Some interesting things about this weird number:
4294967295 is the largest odd number of sides for which a regular polygon can be constructed using a compass and straightedge. This construction is possible only if the number is a product of distinct Fermat primes (3, 5, 17, 257 or 65537).
ie (2+1)*(2^2+1)*(2^4+1)*(2^16+1)

The fact that this centres around powers of 2 seems a bit too convenient. Is the count slipping a bit somewhere?

Sorry got a bit distracted by google ;)

The big number is 2^32-1 looks like a signed int been cast to an unsigned int?

As I mentioned earlier, this error more or less disappeared when we ran nph less frequently. So I suppose it is caused by nph setting the clock back and how the OS and MySQL handles this. Or as David points out - a signed int being cast to an
unsigned int

I can't repeat the behavior reported, running my own test during 16 hours
now on FC 6.0.

This error can be reproduced by adjusting the system clock.
When the system clock is adjusted backwards, queries that lasted shorter than the amount of time the clock was set back appear in the slow query log having a very large value. Apparently the signed number is treated as an unsigned number, making it pass the check for a slow query and making it printed as a very large number.

The error is in sql_parse.cpp line 2206, the ulong cast is wrong.

if ((ulong) (thd->start_time - thd->time_after_lock) >

and in mysqld/log.cpp line 1988

                      (ulong) (current_time - query_start_arg),

This has been fixed in bug #35396 for 5.0.78, 5.1.32, 6.0.10 (not 4.x)