Slow query log to file now displays queries with microsecond precission

--long-query-time is now given in seconds with microseconds as decimals
--min_examined_row_limit added for slow query log
long_query_time user variable is now double with 6 decimals
Added functions to get time in microseconds
Added faster time() functions for system that has gethrtime()  (Solaris)
We now do less time() calls.
Added field->in_read_set() and field->in_write_set() for easier field manipulation by handlers
set_var.cc and my_getopt() can now handle DOUBLE variables.
All time() calls changed to my_time()
my_time() now does retry's if time() call fails.
Added debug function for stopping in mysql_admin_table() when tables are locked
Some trivial function and struct variable renames to avoid merge errors.
Fixed compiler warnings
Initialization of some time variables on windows moved to my_init() 


include/my_getopt.h:
  Added support for double arguments
include/my_sys.h:
  Fixed wrong type to packfrm()
  Added new my_time functions
include/mysql/plugin.h:
  Added support for DOUBLE
libmysql/CMakeLists.txt:
  Added new time functions
libmysql/Makefile.shared:
  Added new time functions
mysql-test/r/variables.result:
  Testing of long_query_time
mysql-test/t/variables.test:
  Testing of long_query_time
mysys/charset.c:
  Fixed compiler warnings
mysys/default_modify.c:
  Fixed compiler warnings
mysys/hash.c:
  Fixed compiler warnings
mysys/mf_getdate.c:
  Use my_time()
mysys/mf_iocache2.c:
  Fixed compiler warnings
mysys/mf_pack.c:
  Fixed compiler warnings
mysys/mf_path.c:
  Fixed compiler warnings
mysys/my_append.c:
  Fixed compiler warnings
mysys/my_compress.c:
  Fixed compiler warnings
mysys/my_copy.c:
  Fixed compiler warnings
mysys/my_gethwaddr.c:
  Fixed compiler warnings
mysys/my_getopt.c:
  Added support for double arguments
mysys/my_getsystime.c:
  Added functions to get time in microseconds.
  Added faster time() functions for system that has gethrtime()  (Solaris)
  Moved windows initialization code to my_init()
mysys/my_init.c:
  Added initializing of variables needed for windows time functions
mysys/my_static.c:
  Added variables needed for windows time functions
mysys/my_static.h:
  Added variables needed for windows time functions
mysys/my_thr_init.c:
  Added THR_LOCK_time, used for faster my_time()
mysys/mysys_priv.h:
  Added THR_LOCK_time, used for faster my_time()
mysys/thr_alarm.c:
  time() -> my_time()
sql/event_data_objects.cc:
  end_time() -> set_current_time()
sql/event_queue.cc:
  end_time() -> set_current_time()
sql/event_scheduler.cc:
  Fixed compiler warnings
sql/field.h:
  Added field->in_read_set() and field->in_write_set() for easier field manipulation by handlers
sql/item.h:
  Added decimal to Item_float(double)
sql/item_cmpfunc.h:
  Added decimal to Item_float(double)
sql/item_timefunc.cc:
  time() -> my_time()
sql/item_xmlfunc.cc:
  Fixed compiler warning
sql/lock.cc:
  lock_time() -> set_time_after_lock()
sql/log.cc:
  Timing in slow query log to file is now done in microseconds
  Changed some while() loops to for() loops.
  Fixed indentation
  time() -> my_time()
sql/log.h:
  Slow query logging is now done based on microseconds
sql/log_event.cc:
  time() -> my_time()
  Fixed arguments to new Item_float()
sql/mysql_priv.h:
  Fixed compiler warnings
  Added opt_log_slow_slave_statements
sql/mysqld.cc:
  Added --log_slow_slave_statements and --min_examined_row_limit
  --long-query-time now takes a double argument with microsecond resolution
  Don't write shutdown message when using --help
  Removed not needed \n
  Thread create time and connect time is now done in microseconds
  time() -> my_time()
  Avoid some time() calls
sql/net_serv.cc:
  Fixed compiler warnings
sql/parse_file.cc:
  time() -> my_time()
sql/set_var.cc:
  Added support for DOUBLE variables
  Added support for variables that are given in seconds with microsecond resolution
sql/set_var.h:
  Added support for variables that are given in seconds with microsecond resolution
sql/slave.cc:
  Allow logging of slave queries to slow query log if 'opt_log_slow_slave_statements' is given
  time() -> my_time()
sql/sql_cache.h:
  Fixed compiler warning()
sql/sql_class.cc:
  Initialize new THD variables
sql/sql_class.h:
  long_query_time is now in microseconds
  Added min_examined_row_limit
  Reordered some THD elements for higher efficency
  Added timers in microseconds (connect_utime, thr_create_utime, start_utime and utime_after_lock)
  Start of query is now recorded both in seconds and in microseconds.
  Following renames was made for more clarity and avoid merge problems from earlier versions:
  connect_time -> connect_utime
  thr_create_time -> thr_create_utime
  end_time()  -> set_current_time()
  lock_time() -> set_time_after_lock()
  
  Added THD::start_utime, which is start of query in microseconds from some arbitary time
  Added function THD::current_utime()
  
  Removed safe_time() as retry's are handled in my_time()
sql/sql_connect.cc:
  User resources are now using microsecond resolution
sql/sql_insert.cc:
  end_time() -> set_current_time()
sql-common/client.c:
  time() -> my_time()
sql/sql_parse.cc:
  Testing if we should print to slow_query_log() is now done with microsecond precission.
  If min_examined_row_limit is given, only log queries to slow query log that has examined more rows than this.
sql/sql_select.cc:
  Simplify code now that Item_float() takes decimals as argument
sql/sql_show.cc:
  time() -> my_time()
  Added support for SYS_DOUBLE
sql/sql_table.cc:
  Added debug function for stopping in mysql_admin_table() when tables are locked
sql/structs.h:
  intime -> reset_utime

1 files changed, 54 insertions, 47 deletions

diff --git a/sql/log.cc b/sql/log.cc
index 0bf77d68410..207c248c9e8 100644
--- a/sql/log.cc
+++ b/sql/log.cc
@@ -524,8 +524,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)
@@ -545,13 +545,12 @@ 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 variables */
   TABLE *table= slow_log.table;
   CHARSET_INFO *client_cs= thd->variables.character_set_client;
-
   DBUG_ENTER("log_slow");
 
   /* below should never happen */
@@ -582,6 +581,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
@@ -694,12 +695,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);
 }
 
@@ -774,10 +775,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;
@@ -904,28 +905,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
@@ -933,10 +933,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();
@@ -947,17 +947,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)
@@ -967,10 +972,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();
@@ -995,7 +1000,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)
@@ -1017,8 +1022,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 : "", "] @ ",
@@ -1033,6 +1036,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(current_time, user_host_buff,
@@ -2165,8 +2169,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
@@ -2184,8 +2188,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;
@@ -2198,6 +2202,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;
 
@@ -2228,10 +2233,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;
@@ -3872,9 +3879,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);
 }
 
 
@@ -3902,7 +3909,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);
     }
@@ -4499,7 +4506,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;