List:Commits« Previous MessageNext Message »
From:Davi Arnaut Date:January 28 2009 7:39pm
Subject:Re: bzr commit into mysql-5.0-bugteam branch (joro:2735) Bug#35396
View as plain text  
On 1/26/09 11:00 AM, Georgi Kodinov wrote:
> #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.

I also think we shouldn't log into slow log if the the elapsed time is 
negative as we can't possibly know if its within the slow log time 
window. Please fix the check in log_slow_statement.

> modified:
>    sql/log.cc
>
> per-file messages:
>    sql/log.cc
>      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
>       }
>       if (query_start_arg)
>       {
> +      /* 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));
> +      else
> +        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));
> +      else
> +        lock_time= (char *) "undef";
> +
>         /* For slow query log */
>         if (my_b_printf(&log_file,
> -                      "# 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",
> +                      query_time,
> +                      lock_time,
>                         (ulong) thd->sent_row_count,
>                         (ulong) thd->examined_row_count) == (uint) -1)
>           tmp_errno=errno;
>
>

OK to push with the aforementioned fix.

-- Davi
Thread
bzr commit into mysql-5.0-bugteam branch (joro:2735) Bug#35396Georgi Kodinov26 Jan
  • Re: bzr commit into mysql-5.0-bugteam branch (joro:2735) Bug#35396Davi Arnaut26 Jan
  • Re: bzr commit into mysql-5.0-bugteam branch (joro:2735) Bug#35396Davi Arnaut28 Jan