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:
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

[4 Oct 2009 16:36] Dan McGee
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. :)

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?
[4 Oct 2009 18:02] Valeriy Kravchuk
Do you run ntd in that virtual machine? Is it possible that time was adjusted while these queries were running?
[4 Oct 2009 18:28] Dan McGee
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.
[3 Dec 2009 13:21] Alexey Kishkin
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?
[6 Dec 2009 19:13] Dan McGee
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.
[13 Dec 2009 12:03] Alexey Kishkin
Thank you Dan, I am  closing it then.