#At file:///home/kgeorge/mysql/work/B35396-5.0-bugteam/ based on revid:davi.arnaut@stripped
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.
Bug #35396: print meaningful note instead of unsigned negative number
when the system time has been adjusted back during the query execution
=== modified file 'sql/log.cc'
--- a/sql/log.cc 2008-12-11 11:06:50 +0000
+++ b/sql/log.cc 2009-01-26 13:00:00 +0000
@@ -2336,11 +2336,25 @@ bool MYSQL_LOG::write(THD *thd,const cha
+ /* use the buffer to hold 2 string representations of ulonglong */
+ char *lock_time= buff + 39, *query_time= buff;
+ /* System time may be reset to a lower value while the query is running. */
+ if (current_time >= query_start_arg)
+ sprintf(query_time, "%lu", (ulong) (current_time - query_start_arg));
+ query_time= (char *) "undef";
+ /* System time may be reset to a lower value while the lock is held. */
+ if (thd->time_after_lock >= query_start_arg)
+ sprintf(lock_time, "%lu", (ulong) (current_time - query_start_arg));
+ lock_time= (char *) "undef";
/* For slow query log */
- "# Query_time: %lu Lock_time: %lu Rows_sent: %lu Rows_examined: %lu\n",
- (ulong) (current_time - query_start_arg),
- (ulong) (thd->time_after_lock - query_start_arg),
+ "# Query_time: %.40s Lock_time: %.40s Rows_sent: %lu Rows_examined: %lu\n",
(ulong) thd->examined_row_count) == (uint) -1)