Bug #59861 why does log_slow_statement call thd_proc_info twice?
Submitted: 1 Feb 2011 1:50 Modified: 7 Mar 2011 23:18
Reporter: Mark Callaghan Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Logging Severity:S3 (Non-critical)
Version:5.1, 5.5, trunk OS:Any
Assigned to: Jon Olav Hauglid CPU Architecture:Any
Tags: log, query, slow
Triage: Triaged: D4 (Minor)

[1 Feb 2011 1:50] Mark Callaghan
Description:
Why does log_slow_statement use this twice? Once should be enough.
     thd_proc_info(thd, "logging slow query");

------

void log_slow_statement(THD *thd)
{
  DBUG_ENTER("log_slow_statement");

  /*
    The following should never be true with our current code base,
    but better to keep this here so we don't accidently try to log a
    statement in a trigger or stored function
  */
  if (unlikely(thd->in_sub_stmt))
    DBUG_VOID_RETURN;                           // Don't set time for sub stmt

  /*
    Do not log administrative statements unless the appropriate option is
    set.
  */
  if (thd->enable_slow_log)
  {
    ulonglong end_utime_of_query= thd->current_utime();
    thd_proc_info(thd, "logging slow query");

    if (((thd->server_status & SERVER_QUERY_WAS_SLOW) ||
         ((thd->server_status &
           (SERVER_QUERY_NO_INDEX_USED | SERVER_QUERY_NO_GOOD_INDEX_USED)) &&
          opt_log_queries_not_using_indexes &&
           !(sql_command_flags[thd->lex->sql_command] & CF_STATUS_COMMAND))) &&
        thd->examined_row_count >= thd->variables.min_examined_row_limit)
    {
      thd_proc_info(thd, "logging slow query");
      thd->status_var.long_query_count++;
      slow_log_print(thd, thd->query(), thd->query_length(), 
                     end_utime_of_query);
    }
  }
  DBUG_VOID_RETURN;
}

How to repeat:
read the source in sql/sql_parse.cc

Suggested fix:
remove one of the calls
[1 Feb 2011 5:02] Valeriy Kravchuk
Verified by code review.
[3 Feb 2011 9:03] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/130303

3300 Jon Olav Hauglid	2011-02-03
      Bug #59861 why does log_slow_statement call thd_proc_info twice?
      
      This patch removes an extraneous
        thd_proc_info(thd, "logging slow query")
      call from low_slow_statement(). The removed call was from
      before it was decided to actually log the query to the slow log.
      
      No test case added.
[3 Feb 2011 9:13] Magne Mæhre
Ok to push
[7 Feb 2011 11:49] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/130557

3603 Jon Olav Hauglid	2011-02-07
      Bug #59861 why does log_slow_statement call thd_proc_info twice?
      
      This patch removes an extraneous
        thd_proc_info(thd, "logging slow query")
      call from low_slow_statement(). The removed call was from
      before it was decided to actually log the query to the slow log.
      
      No test case added.
[7 Feb 2011 11:50] Bugs System
Pushed into mysql-trunk 5.6.2 (revid:jon.hauglid@oracle.com-20110207114918-m0a336hi7wav0wmt) (version source revid:jon.hauglid@oracle.com-20110207114918-m0a336hi7wav0wmt) (merge vers: 5.6.2) (pib:24)
[7 Mar 2011 23:18] Paul Dubois
Code cleanup. No user impact. No changelog entry needed.
[7 Mar 2011 23:20] Paul Dubois
CHANGESET - http://lists.mysql.com/commits/130557
[29 Oct 2011 10:14] Shane Bester
Seems thd->current_utime() is called prematurely also. I've noted that in a new internal bug report.