MySQL Slow Query Log - Interpretationsfrage

[daemotron]

Moin allerseits,

hab mich eben ein bisschen über die Zeitangaben in meinem Slow Query Log gewundert. Leider geht aus der MySQL-Dokumentation dazu nicht hervor, in welchen Zeiteinheiten da gemessen wird. Hier mal ein Auszug (bei long_query_time = 2):

Code: Select all

~ $ mysqldumpslow -t 1 /var/log/mysql/mysql.slow

Reading mysql slow query log from /var/log/mysql/mysql.slow

Count: 10  Time=4294967295.00s (-1s)  Lock=0.00s (0s)  Rows=0.0 (0), web1002[web1002]@[127.0.0.1]
  UPDATE pages
  SET
  SYS_LASTCHANGED='S'
  WHERE
  uid=N

Kann mir jemand verraten, wie ich die Angaben unter Time zu verstehen habe? Ich bekomme das einfach nicht zur Deckung mit den Laufzeitangaben des Programms, das die betreffende Query absetzt. da habe ich Laufzeiten im Bereich von ca. 350 - 500 Millisekunden...

[outofbound]

http://lists.mysql.com/mysql/203443

http://www.planetmysql.org/entries/1943

Gruss,

Out

[daemotron]

Hallo Out,

den ersten Link hatte ich auch schon gefunden. In der Tat wird dort das selbe Phänomen beschrieben, aber eine Erklärung gibt's auch da nicht. mysqlsla werde ich mir definitiv mal anschauen, aber es kann IMHO nicht an mysqldumpslow liegen - wenn ich mir die Logdatei "roh" anschaue, finde ich dort dieselben merkwürdigen Angaben.

Gruss,
Jesco

[Roger Wilco]

Das Phänomen tritt auf, wenn die Zeit auf dem System nicht konsistent verläuft. Du hast vermutlich einen NTP-Client laufen, der die Zeit korrigiert. Wenn der Slow-Query dann gestartet wird, eine Weile läuft, währenddessen der NTP-Client die Zeit neu stellt und diese zufällig zurückgestellt wird (z. B. weil die Uhr auf dem System zu schnell läuft), hast du eine negative Zeitdifferenz zwischen Start und Ende der Abfrage.