MySQL Bugs: #47813: Abnormal/large Time values in slow query log

Bug #47813	Abnormal/large Time values in slow query log
Submitted:	4 Oct 2009 16:36	Modified:	13 Dec 2009 12:03
Reporter:	Dan McGee	Email Updates:
Status:	Not a Bug	Impact on me:	None
Category:	MySQL Server: Logging	Severity:	S3 (Non-critical)
Version:	5.1.38 source	OS:	Linux (2.6.26-2-xen-amd64)
Assigned to:		CPU Architecture:	Any
Tags:	slow query log

Description:
It looks like the changes in http://bugs.mysql.com/bug.php?id=35396 didn't fully fix the weird times showing up in slow query logs. I am still seeing huge values show up:

Count: 1 Time=18446744073709.55s (18446744073709s) Lock=0.00s (0s) Rows=0.0 (0), archweb-pubu01[archweb-pubu01]@localhost
SELECT `repos`.`id`, `repos`.`name` FROM `repos` WHERE `repos`.`id` = N ORDER BY `repos`.`name` ASC

I saw upwards of 30 of these this morning. I can provide more examples if necessary, but I did notice this happens on both MyISAM and InnoDB tables, so it doesn't seem to be restricted to one storage backend or the other.

More resources and a possible fix just from Googling, I have no idea if this is actually correct. :)
https://bugs.launchpad.net/percona-patches/+bug/316988
http://bazaar.launchpad.net/~percona-dev/percona-patches/5.0.75/revision/26

More system information:
dan@gudrun ~
$ uname -a
Linux gudrun.archlinux.org 2.6.26-2-xen-amd64 #1 SMP Thu Aug 20 00:36:34 UTC 2009 x86_64 Intel(R) Xeon(TM) CPU 2.80GHz GenuineIntel GNU/Linux

dan@gudrun ~
$ mysqld --version
mysqld Ver 5.1.38-log for unknown-linux-gnu on x86_64 (Source distribution)

gudrun is an Arch Linux install running as a Xen instance on a Debian install. It has 2 CPUs available for use of the 4 hardware CPUs.

How to repeat:
Not sure what the best case is. It seems like running some fast queries on a multicore machine where the thread is likely to move from one CPU to another could trigger this. In addition, running on Xen might contribute to the problem?

Do you run ntd in that virtual machine? Is it possible that time was adjusted while these queries were running?

ntpd runs in the dom0. Note that this is ntpd and not ntpdate, so it should ensure that the clock never moves backwards (it will do clock skewing but not clock setting). There is no ntpd running in the domU instances; they rely on the Xen host for their clock settings.

I say this not being a Xen expert; I'd be interested to hear from another MySQL user or developer with their DB running inside a Xen instance.

no it's certainly doesnot look like BUG#35396 . In that bug offset was 18446744073709551614 - in hex it's FFFFFFFFFFFFFFFE, - obviously it's just negative number -1  in the unsigned variable.

But here - offset is 18446744073709 - I dont think it's negative number. It looks like just timer returns wrong/random value.

Dan, Could you propose any steps to reproduce it?

We've since upgraded our Xen domU kernel and aren't seeing this anymore- I'm guessing there was a bug at the kernel level where the system call was in fact returning values going backwards.

The current kernel is now this:
Linux gudrun.archlinux.org 2.6.31-ARCH #1 SMP PREEMPT Tue Oct 6 13:42:55 CEST 2009 x86_64 Intel(R) Xeon(TM) CPU 2.80GHz GenuineIntel GNU/Linux

This can probably be closed as being a bug not in MySQL.

Thank you Dan, I am  closing it then.