From: Jon Olav Hauglid
Date: November 1 2011 8:48am
Subject: bzr push into mysql-trunk branch (jon.hauglid:3541 to 3542) Bug#13326965
List-Archive: http://lists.mysql.com/commits/141691
X-Bug: 13326965
Message-Id: <201111010848.pA18mIWe027908@acsmt357.oracle.com>
MIME-Version: 1.0
Content-Type: text/plain; charset="us-ascii"
Content-Transfer-Encoding: 7bit

 3542 Jon Olav Hauglid	2011-11-01
      Bug#13326965 THD->CURRENT_UTIME() CALLED WHEN NOT NEEDED IN
                   LOG_SLOW_STATEMENT()
      
      The problem was that thd->current_utime() was called before
      writing to the slow log even if no log entries ended up being
      written. This is unneccessary and potentially a performance
      problem (thd->current_utime() -> my_micro_time() -> 
      __gettimeofday()).
      
      This patch fixes the problem by not calling thd->current_utime()
      before it is known that a log entry will in fact be written.
      
      The patch doesn't contain a test case since it is hard to test
      for performance improvements in our test framework.

    modified:
      sql/log.cc
      sql/log.h
      sql/sql_parse.cc
 3541 Tor Didriksen	2011-11-01 [merge]
      empty merge 5.5 => trunk

=== modified file 'sql/log.cc'
--- a/sql/log.cc	2011-10-27 19:28:15 +0000
+++ b/sql/log.cc	2011-11-01 08:47:32 +0000
@@ -1015,15 +1015,13 @@ bool LOGGER::flush_general_log()
     thd                 THD of the query being logged
     query               The query being logged
     query_length        The length of the query string
-    current_utime       Current time in microseconds (from undefined start)
 
   RETURN
     FALSE   OK
     TRUE    error occured
 */
 
-bool LOGGER::slow_log_print(THD *thd, const char *query, uint query_length,
-                            ulonglong current_utime)
+bool LOGGER::slow_log_print(THD *thd, const char *query, uint query_length)
 
 {
   bool error= FALSE;
@@ -1032,7 +1030,7 @@ bool LOGGER::slow_log_print(THD *thd, co
   char user_host_buff[MAX_USER_HOST_SIZE + 1];
   Security_context *sctx= thd->security_ctx;
   uint user_host_len= 0;
-  ulonglong query_utime, lock_utime;
+  ulonglong query_utime, lock_utime, current_utime;
 
   DBUG_ASSERT(thd->enable_slow_log);
   /*
@@ -1062,6 +1060,7 @@ bool LOGGER::slow_log_print(THD *thd, co
                              sctx->ip ? sctx->ip : "", "]", NullS) -
                     user_host_buff);
 
+    current_utime= thd->current_utime();
     current_time= my_time_possible_from_micro(current_utime);
     if (thd->start_utime)
     {
@@ -2034,10 +2033,9 @@ int error_log_print(enum loglevel level,
 }
 
 
-bool slow_log_print(THD *thd, const char *query, uint query_length,
-                    ulonglong current_utime)
+bool slow_log_print(THD *thd, const char *query, uint query_length)
 {
-  return logger.slow_log_print(thd, query, query_length, current_utime);
+  return logger.slow_log_print(thd, query, query_length);
 }
 
 

=== modified file 'sql/log.h'
--- a/sql/log.h	2011-10-27 19:28:15 +0000
+++ b/sql/log.h	2011-11-01 08:47:32 +0000
@@ -418,8 +418,7 @@ public:
   void cleanup_end();
   bool error_log_print(enum loglevel level, const char *format,
                       va_list args);
-  bool slow_log_print(THD *thd, const char *query, uint query_length,
-                      ulonglong current_utime);
+  bool slow_log_print(THD *thd, const char *query, uint query_length);
   bool general_log_print(THD *thd,enum enum_server_command command,
                          const char *format, va_list args);
   bool general_log_write(THD *thd, enum enum_server_command command,
@@ -479,8 +478,7 @@ extern sql_print_message_func sql_print_
 int error_log_print(enum loglevel level, const char *format,
                     va_list args);
 
-bool slow_log_print(THD *thd, const char *query, uint query_length,
-                    ulonglong current_utime);
+bool slow_log_print(THD *thd, const char *query, uint query_length);
 
 bool general_log_print(THD *thd, enum enum_server_command command,
                        const char *format,...);

=== modified file 'sql/sql_parse.cc'
--- a/sql/sql_parse.cc	2011-10-27 19:28:15 +0000
+++ b/sql/sql_parse.cc	2011-11-01 08:47:32 +0000
@@ -1628,8 +1628,6 @@ void log_slow_statement(THD *thd)
   */
   if (thd->enable_slow_log)
   {
-    ulonglong end_utime_of_query= thd->current_utime();
-
     if (((thd->server_status & SERVER_QUERY_WAS_SLOW) ||
          ((thd->server_status &
            (SERVER_QUERY_NO_INDEX_USED | SERVER_QUERY_NO_GOOD_INDEX_USED)) &&
@@ -1642,11 +1640,9 @@ void log_slow_statement(THD *thd)
       if (thd->rewritten_query.length())
         slow_log_print(thd,
                        thd->rewritten_query.c_ptr_safe(),
-                       thd->rewritten_query.length(), 
-                       end_utime_of_query);
+                       thd->rewritten_query.length());
       else
-        slow_log_print(thd, thd->query(), thd->query_length(), 
-                       end_utime_of_query);
+        slow_log_print(thd, thd->query(), thd->query_length());
     }
   }
   DBUG_VOID_RETURN;

No bundle (reason: useless for push emails).