Merge bk-internal.mysql.com:/home/bk/mysql-5.1

into  mysql.com:/home/my/mysql-5.1

1 files changed, 54 insertions, 47 deletions

diff --git a/sql/log.cc b/sql/log.cc
index dbb664c9d18..c5c84cfb11f 100644
--- a/sql/log.cc
+++ b/sql/log.cc
@@ -455,8 +455,8 @@ err:
     user_host         the pointer to the string with user@host info
     user_host_len     length of the user_host string. this is computed once
                       and passed to all general log event handlers
-    query_time        Amount of time the query took to execute (in seconds)
-    lock_time         Amount of time the query was locked (in seconds)
+    query_time        Amount of time the query took to execute (in microseconds)
+    lock_time         Amount of time the query was locked (in microseconds)
     is_command        The flag, which determines, whether the sql_text is a
                       query or an administrator command (these are treated
                       differently by the old logging routines)
@@ -476,7 +476,7 @@ err:
 bool Log_to_csv_event_handler::
   log_slow(THD *thd, time_t current_time, time_t query_start_arg,
            const char *user_host, uint user_host_len,
-           longlong query_time, longlong lock_time, bool is_command,
+           ulonglong query_utime, ulonglong lock_utime, bool is_command,
            const char *sql_text, uint sql_text_len)
 {
   TABLE_LIST table_list;
@@ -491,7 +491,6 @@ bool Log_to_csv_event_handler::
   time_t save_user_time;
   bool save_time_zone_used;
   CHARSET_INFO *client_cs= thd->variables.character_set_client;
-
   DBUG_ENTER("Log_to_csv_event_handler::log_slow");
 
   bzero(& table_list, sizeof(TABLE_LIST));
@@ -540,6 +539,8 @@ bool Log_to_csv_event_handler::
 
   if (query_start_arg)
   {
+    longlong query_time= (longlong) (query_utime/1000000);
+    longlong lock_time=  (longlong) (lock_utime/1000000);
     /*
       A TIME field can not hold the full longlong range; query_time or
       lock_time may be truncated without warning here, if greater than
@@ -705,12 +706,12 @@ void Log_to_file_event_handler::init_pthread_objects()
 bool Log_to_file_event_handler::
   log_slow(THD *thd, time_t current_time, time_t query_start_arg,
            const char *user_host, uint user_host_len,
-           longlong query_time, longlong lock_time, bool is_command,
+           ulonglong query_utime, ulonglong lock_utime, bool is_command,
            const char *sql_text, uint sql_text_len)
 {
   return mysql_slow_log.write(thd, current_time, query_start_arg,
                               user_host, user_host_len,
-                              query_time, lock_time, is_command,
+                              query_utime, lock_utime, is_command,
                               sql_text, sql_text_len);
 }
 
@@ -785,10 +786,10 @@ bool LOGGER::error_log_print(enum loglevel level, const char *format,
                              va_list args)
 {
   bool error= FALSE;
-  Log_event_handler **current_handler= error_log_handler_list;
+  Log_event_handler **current_handler;
 
   /* currently we don't need locking here as there is no error_log table */
-  while (*current_handler)
+  for (current_handler= error_log_handler_list ; *current_handler ;)
     error= (*current_handler++)->log_error(level, format, args) || error;
 
   return error;
@@ -878,28 +879,27 @@ bool LOGGER::flush_logs(THD *thd)
   SYNOPSIS
     slow_log_print()
 
-    thd               THD of the query being logged
-    query             The query being logged
-    query_length      The length of the query string
-    query_start_arg   Query start timestamp
+    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
+    FALSE   OK
+    TRUE    error occured
 */
 
 bool LOGGER::slow_log_print(THD *thd, const char *query, uint query_length,
-                            time_t query_start_arg)
+                            ulonglong current_utime)
+
 {
   bool error= FALSE;
-  Log_event_handler **current_handler= slow_log_handler_list;
+  Log_event_handler **current_handler;
   bool is_command= FALSE;
   char user_host_buff[MAX_USER_HOST_SIZE];
-
-  time_t current_time;
   Security_context *sctx= thd->security_ctx;
   uint user_host_len= 0;
-  longlong query_time= 0, lock_time= 0;
+  ulonglong query_utime, lock_utime;
 
   /*
     Print the message to the buffer if we have slow log enabled
@@ -907,10 +907,10 @@ bool LOGGER::slow_log_print(THD *thd, const char *query, uint query_length,
 
   if (*slow_log_handler_list)
   {
-    current_time= time(NULL);
+    time_t current_time;
 
     /* do not log slow queries from replication threads */
-    if (thd->slave_thread)
+    if (thd->slave_thread && !opt_log_slow_slave_statements)
       return 0;
 
     lock_shared();
@@ -921,17 +921,22 @@ bool LOGGER::slow_log_print(THD *thd, const char *query, uint query_length,
     }
 
     /* fill in user_host value: the format is "%s[%s] @ %s [%s]" */
-    user_host_len= strxnmov(user_host_buff, MAX_USER_HOST_SIZE,
-                            sctx->priv_user ? sctx->priv_user : "", "[",
-                            sctx->user ? sctx->user : "", "] @ ",
-                            sctx->host ? sctx->host : "", " [",
-                            sctx->ip ? sctx->ip : "", "]", NullS) -
-      user_host_buff;
-
-    if (query_start_arg)
+    user_host_len= (strxnmov(user_host_buff, MAX_USER_HOST_SIZE,
+                             sctx->priv_user ? sctx->priv_user : "", "[",
+                             sctx->user ? sctx->user : "", "] @ ",
+                             sctx->host ? sctx->host : "", " [",
+                             sctx->ip ? sctx->ip : "", "]", NullS) -
+                    user_host_buff);
+
+    current_time= my_time_possible_from_micro(current_utime);
+    if (thd->start_utime)
+    {
+      query_utime= (current_utime - thd->start_utime);
+      lock_utime=  (thd->utime_after_lock - thd->start_utime);
+    }
+    else
     {
-      query_time= (longlong) (current_time - query_start_arg);
-      lock_time= (longlong) (thd->time_after_lock - query_start_arg);
+      query_utime= lock_utime= 0;
     }
 
     if (!query)
@@ -941,10 +946,10 @@ bool LOGGER::slow_log_print(THD *thd, const char *query, uint query_length,
       query_length= command_name[thd->command].length;
     }
 
-    while (*current_handler)
-      error= (*current_handler++)->log_slow(thd, current_time, query_start_arg,
+    for (current_handler= slow_log_handler_list; *current_handler ;)
+      error= (*current_handler++)->log_slow(thd, current_time, thd->start_time,
                                             user_host_buff, user_host_len,
-                                            query_time, lock_time, is_command,
+                                            query_utime, lock_utime, is_command,
                                             query, query_length) || error;
 
     unlock();
@@ -969,7 +974,7 @@ bool LOGGER::general_log_print(THD *thd, enum enum_server_command command,
     Security_context *sctx= thd->security_ctx;
     ulong id;
     uint message_buff_len= 0, user_host_len= 0;
-
+    time_t current_time;
     if (thd)
     {                                           /* Normal thread */
       if ((thd->options & OPTION_LOG_OFF)
@@ -991,8 +996,6 @@ bool LOGGER::general_log_print(THD *thd, enum enum_server_command command,
       unlock();
       return 0;
     }
-    time_t current_time= time(NULL);
-
     user_host_len= strxnmov(user_host_buff, MAX_USER_HOST_SIZE,
                             sctx->priv_user ? sctx->priv_user : "", "[",
                             sctx->user ? sctx->user : "", "] @ ",
@@ -1007,6 +1010,7 @@ bool LOGGER::general_log_print(THD *thd, enum enum_server_command command,
     else
       message_buff[0]= '\0';
 
+    current_time= my_time(0);
     while (*current_handler)
       error+= (*current_handler++)->
         log_general(thd, current_time, user_host_buff,
@@ -2022,8 +2026,8 @@ err:
     user_host         the pointer to the string with user@host info
     user_host_len     length of the user_host string. this is computed once
                       and passed to all general log event handlers
-    query_time        Amount of time the query took to execute (in seconds)
-    lock_time         Amount of time the query was locked (in seconds)
+    query_utime       Amount of time the query took to execute (in microseconds)
+    lock_utime        Amount of time the query was locked (in microseconds)
     is_command        The flag, which determines, whether the sql_text is a
                       query or an administrator command.
     sql_text          the very text of the query or administrator command
@@ -2041,8 +2045,8 @@ err:
 
 bool MYSQL_QUERY_LOG::write(THD *thd, time_t current_time,
                             time_t query_start_arg, const char *user_host,
-                            uint user_host_len, longlong query_time,
-                            longlong lock_time, bool is_command,
+                            uint user_host_len, ulonglong query_utime,
+                            ulonglong lock_utime, bool is_command,
                             const char *sql_text, uint sql_text_len)
 {
   bool error= 0;
@@ -2060,6 +2064,7 @@ bool MYSQL_QUERY_LOG::write(THD *thd, time_t current_time,
   {						// Safety agains reopen
     int tmp_errno= 0;
     char buff[80], *end;
+    char query_time_buff[22+7], lock_time_buff[22+7];
     uint buff_len;
     end= buff;
 
@@ -2090,10 +2095,12 @@ bool MYSQL_QUERY_LOG::write(THD *thd, time_t current_time,
         tmp_errno= errno;
     }
     /* For slow query log */
+    sprintf(query_time_buff, "%.6f", ulonglong2double(query_utime)/1000000.0);
+    sprintf(lock_time_buff,  "%.6f", ulonglong2double(lock_utime)/1000000.0);
     if (my_b_printf(&log_file,
-                    "# Query_time: %lu  Lock_time: %lu"
+                    "# Query_time: %s  Lock_time: %s"
                     " Rows_sent: %lu  Rows_examined: %lu\n",
-                    (ulong) query_time, (ulong) lock_time,
+                    query_time_buff, lock_time_buff,
                     (ulong) thd->sent_row_count,
                     (ulong) thd->examined_row_count) == (uint) -1)
       tmp_errno= errno;
@@ -3735,9 +3742,9 @@ int error_log_print(enum loglevel level, const char *format,
 
 
 bool slow_log_print(THD *thd, const char *query, uint query_length,
-                    time_t query_start_arg)
+                    ulonglong current_utime)
 {
-  return logger.slow_log_print(thd, query, query_length, query_start_arg);
+  return logger.slow_log_print(thd, query, query_length, current_utime);
 }
 
 
@@ -3765,7 +3772,7 @@ void MYSQL_BIN_LOG::rotate_and_purge(uint flags)
 #ifdef HAVE_REPLICATION
     if (expire_logs_days)
     {
-      time_t purge_time= time(0) - expire_logs_days*24*60*60;
+      time_t purge_time= my_time(0) - expire_logs_days*24*60*60;
       if (purge_time >= 0)
         purge_logs_before_date(purge_time);
     }
@@ -4362,7 +4369,7 @@ static void print_buffer_to_file(enum loglevel level, const char *buffer)
 
   VOID(pthread_mutex_lock(&LOCK_error_log));
 
-  skr=time(NULL);
+  skr= my_time(0);
   localtime_r(&skr, &tm_tmp);
   start=&tm_tmp;