diff options
Diffstat (limited to 'sql/log.cc')
| -rw-r--r-- | sql/log.cc | 101 |
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; |