diff options
Diffstat (limited to 'sql/log.cc')
| -rw-r--r-- | sql/log.cc | 480 |
1 files changed, 346 insertions, 134 deletions
diff --git a/sql/log.cc b/sql/log.cc index 550285026b2..bb18d08f4db 100644 --- a/sql/log.cc +++ b/sql/log.cc @@ -52,8 +52,6 @@ LOGGER logger; MYSQL_BIN_LOG mysql_bin_log; ulong sync_binlog_counter= 0; -static Muted_query_log_event invisible_commit; - static bool test_if_number(const char *str, long *res, bool allow_wildcards); static int binlog_init(void *p); @@ -73,23 +71,28 @@ static int binlog_prepare(handlerton *hton, THD *thd, bool all); */ class Silence_log_table_errors : public Internal_error_handler { + char m_message[MYSQL_ERRMSG_SIZE]; public: Silence_log_table_errors() - {} + { + m_message[0]= '\0'; + } virtual ~Silence_log_table_errors() {} virtual bool handle_error(uint sql_errno, const char *message, MYSQL_ERROR::enum_warning_level level, THD *thd); + const char *message() const { return m_message; } }; bool Silence_log_table_errors::handle_error(uint /* sql_errno */, - const char * /* message */, + const char *message_arg, MYSQL_ERROR::enum_warning_level /* level */, THD * /* thd */) { + strmake(m_message, message_arg, sizeof(m_message)-1); return TRUE; } @@ -150,7 +153,7 @@ private: class binlog_trx_data { public: binlog_trx_data() - : m_pending(0), before_stmt_pos(MY_OFF_T_UNDEF) + : at_least_one_stmt(0), m_pending(0), before_stmt_pos(MY_OFF_T_UNDEF) { trans_log.end_of_file= max_binlog_cache_size; } @@ -183,6 +186,16 @@ public: reinit_io_cache(&trans_log, WRITE_CACHE, pos, 0, 0); if (pos < before_stmt_pos) before_stmt_pos= MY_OFF_T_UNDEF; + + /* + The only valid positions that can be truncated to are at the + beginning of a statement. We are relying on this fact to be able + to set the at_least_one_stmt flag correctly. In other word, if + we are truncating to the beginning of the transaction cache, + there will be no statements in the cache, otherwhise, we will + have at least one statement in the transaction cache. + */ + at_least_one_stmt= (pos > 0); } /* @@ -208,6 +221,12 @@ public: IO_CACHE trans_log; // The transaction cache + /** + Boolean that is true if there is at least one statement in the + transaction cache. + */ + bool at_least_one_stmt; + private: /* Pending binrows event. This event is the event where the rows are @@ -413,6 +432,7 @@ bool Log_to_csv_event_handler:: A positive return value in store() means truncation. Still logging a message in the log in this case. */ + table->field[5]->flags|= FIELDFLAG_HEX_ESCAPE; if (table->field[5]->store(sql_text, sql_text_len, client_cs) < 0) goto err; @@ -436,8 +456,9 @@ bool Log_to_csv_event_handler:: result= FALSE; err: - if (result) - sql_print_error("Failed to write to mysql.general_log"); + if (result && !thd->killed) + sql_print_error("Failed to write to mysql.general_log: %s", + error_handler.message()); if (need_rnd_end) { @@ -495,11 +516,13 @@ bool Log_to_csv_event_handler:: bool result= TRUE; bool need_close= FALSE; bool need_rnd_end= FALSE; + Silence_log_table_errors error_handler; Open_tables_state open_tables_backup; CHARSET_INFO *client_cs= thd->variables.character_set_client; bool save_time_zone_used; DBUG_ENTER("Log_to_csv_event_handler::log_slow"); + thd->push_internal_handler(& error_handler); /* CSV uses TIME_to_timestamp() internally if table needs to be repaired which will set thd->time_zone_used @@ -629,8 +652,11 @@ bool Log_to_csv_event_handler:: result= FALSE; err: - if (result) - sql_print_error("Failed to write to mysql.slow_log"); + thd->pop_internal_handler(); + + if (result && !thd->killed) + sql_print_error("Failed to write to mysql.slow_log: %s", + error_handler.message()); if (need_rnd_end) { @@ -994,7 +1020,7 @@ bool LOGGER::general_log_write(THD *thd, enum enum_server_command command, current_time= my_time(0); while (*current_handler) - error+= (*current_handler++)-> + error|= (*current_handler++)-> log_general(thd, current_time, user_host_buff, user_host_len, id, command_name[(uint) command].str, @@ -1362,26 +1388,20 @@ binlog_end_trans(THD *thd, binlog_trx_data *trx_data, inside a stored function. */ thd->binlog_flush_pending_rows_event(TRUE); + + error= mysql_bin_log.write(thd, &trx_data->trans_log, end_ev); + trx_data->reset(); + /* - We write the transaction cache to the binary log if either we're - committing the entire transaction, or if we are doing an - autocommit outside a transaction. - */ - if (all || !(thd->options & (OPTION_BEGIN | OPTION_NOT_AUTOCOMMIT))) + We need to step the table map version after writing the + transaction cache to disk. + */ + mysql_bin_log.update_table_map_version(); + statistic_increment(binlog_cache_use, &LOCK_status); + if (trans_log->disk_writes != 0) { - error= mysql_bin_log.write(thd, &trx_data->trans_log, end_ev); - trx_data->reset(); - /* - We need to step the table map version after writing the - transaction cache to disk. - */ - mysql_bin_log.update_table_map_version(); - statistic_increment(binlog_cache_use, &LOCK_status); - if (trans_log->disk_writes != 0) - { - statistic_increment(binlog_cache_disk_use, &LOCK_status); - trans_log->disk_writes= 0; - } + statistic_increment(binlog_cache_disk_use, &LOCK_status); + trans_log->disk_writes= 0; } } else @@ -1420,6 +1440,8 @@ static int binlog_prepare(handlerton *hton, THD *thd, bool all) return 0; } +#define YESNO(X) ((X) ? "yes" : "no") + /** This function is called once after each statement. @@ -1428,10 +1450,8 @@ static int binlog_prepare(handlerton *hton, THD *thd, bool all) @param hton The binlog handlerton. @param thd The client thread that executes the transaction. - @param all true if this is the last statement before a COMMIT - statement; false if either this is a statement in a - transaction but not the last, or if this is a statement - not inside a BEGIN block and autocommit is on. + @param all This is @c true if this is a real transaction commit, and + @false otherwise. @see handlerton::commit */ @@ -1447,26 +1467,86 @@ static int binlog_commit(handlerton *hton, THD *thd, bool all) trx_data->reset(); DBUG_RETURN(0); } + /* - Write commit event if at least one of the following holds: - - the user sends an explicit COMMIT; or - - the autocommit flag is on, and we are not inside a BEGIN. - However, if the user has not sent an explicit COMMIT, and we are - either inside a BEGIN or run with autocommit off, then this is not - the end of a transaction and we should not write a commit event. + Decision table for committing a transaction. The top part, the + *conditions* represent different cases that can occur, and hte + bottom part, the *actions*, represent what should be done in that + particular case. + + Real transaction 'all' was true + + Statement in cache There were at least one statement in the + transaction cache + + In transaction We are inside a transaction + + Stmt modified non-trans The statement being committed modified a + non-transactional table + + All modified non-trans Some statement before this one in the + transaction modified a non-transactional + table + + + ============================= = = = = = = = = = = = = = = = = + Real transaction N N N N N N N N N N N N N N N N + Statement in cache N N N N N N N N Y Y Y Y Y Y Y Y + In transaction N N N N Y Y Y Y N N N N Y Y Y Y + Stmt modified non-trans N N Y Y N N Y Y N N Y Y N N Y Y + All modified non-trans N Y N Y N Y N Y N Y N Y N Y N Y + + Action: (C)ommit/(A)ccumulate C C - C A C - C - - - - A A - A + ============================= = = = = = = = = = = = = = = = = + + + ============================= = = = = = = = = = = = = = = = = + Real transaction Y Y Y Y Y Y Y Y Y Y Y Y Y Y Y Y + Statement in cache N N N N N N N N Y Y Y Y Y Y Y Y + In transaction N N N N Y Y Y Y N N N N Y Y Y Y + Stmt modified non-trans N N Y Y N N Y Y N N Y Y N N Y Y + All modified non-trans N Y N Y N Y N Y N Y N Y N Y N Y + + (C)ommit/(A)ccumulate/(-) - - - - C C - C - - - - C C - C + ============================= = = = = = = = = = = = = = = = = + + In other words, we commit the transaction if and only if both of + the following are true: + - We are not in a transaction and committing a statement + + - We are in a transaction and one (or more) of the following are + true: + + - A full transaction is committed + + OR + + - A non-transactional statement is committed and there is + no statement cached + + Otherwise, we accumulate the statement */ - if (all || !(thd->options & (OPTION_NOT_AUTOCOMMIT | OPTION_BEGIN))) + ulonglong const in_transaction= + thd->options & (OPTION_NOT_AUTOCOMMIT | OPTION_BEGIN); + DBUG_PRINT("debug", + ("all: %d, empty: %s, in_transaction: %s, all.modified_non_trans_table: %s, stmt.modified_non_trans_table: %s", + all, + YESNO(trx_data->empty()), + YESNO(in_transaction), + YESNO(thd->transaction.all.modified_non_trans_table), + YESNO(thd->transaction.stmt.modified_non_trans_table))); + if (in_transaction && + (all || + (!trx_data->at_least_one_stmt && + thd->transaction.stmt.modified_non_trans_table)) || + !in_transaction && !all) { Query_log_event qev(thd, STRING_WITH_LEN("COMMIT"), TRUE, FALSE); qev.error_code= 0; // see comment in MYSQL_LOG::write(THD, IO_CACHE) int error= binlog_end_trans(thd, trx_data, &qev, all); DBUG_RETURN(error); } - else - { - int error= binlog_end_trans(thd, trx_data, &invisible_commit, all); - DBUG_RETURN(error); - } + DBUG_RETURN(0); } /** @@ -1479,10 +1559,8 @@ static int binlog_commit(handlerton *hton, THD *thd, bool all) @param hton The binlog handlerton. @param thd The client thread that executes the transaction. - @param all true if this is the last statement before a COMMIT - statement; false if either this is a statement in a - transaction but not the last, or if this is a statement - not inside a BEGIN block and autocommit is on. + @param all This is @c true if this is a real transaction rollback, and + @false otherwise. @see handlerton::rollback */ @@ -1498,21 +1576,36 @@ static int binlog_rollback(handlerton *hton, THD *thd, bool all) DBUG_RETURN(0); } - /* - Update the binary log with a BEGIN/ROLLBACK block if we have - cached some queries and we updated some non-transactional - table. Such cases should be rare (updating a - non-transactional table inside a transaction...) - */ - if (unlikely(thd->transaction.all.modified_non_trans_table || - (thd->options & OPTION_KEEP_LOG))) + DBUG_PRINT("debug", ("all: %s, all.modified_non_trans_table: %s, stmt.modified_non_trans_table: %s", + YESNO(all), + YESNO(thd->transaction.all.modified_non_trans_table), + YESNO(thd->transaction.stmt.modified_non_trans_table))); + if (all && thd->transaction.all.modified_non_trans_table || + !all && thd->transaction.stmt.modified_non_trans_table || + (thd->options & OPTION_KEEP_LOG)) { + /* + We write the transaction cache with a rollback last if we have + modified any non-transactional table. We do this even if we are + committing a single statement that has modified a + non-transactional table since it can have modified a + transactional table in that statement as well, which needs to be + rolled back on the slave. + */ Query_log_event qev(thd, STRING_WITH_LEN("ROLLBACK"), TRUE, FALSE); qev.error_code= 0; // see comment in MYSQL_LOG::write(THD, IO_CACHE) error= binlog_end_trans(thd, trx_data, &qev, all); } - else + else if (all && !thd->transaction.all.modified_non_trans_table || + !all && !thd->transaction.stmt.modified_non_trans_table) + { + /* + If we have modified only transactional tables, we can truncate + the transaction cache without writing anything to the binary + log. + */ error= binlog_end_trans(thd, trx_data, 0, all); + } DBUG_RETURN(error); } @@ -2739,14 +2832,62 @@ bool MYSQL_BIN_LOG::reset_logs(THD* thd) for (;;) { - my_delete_allow_opened(linfo.log_file_name, MYF(MY_WME)); + if ((error= my_delete_allow_opened(linfo.log_file_name, MYF(0))) != 0) + { + if (my_errno == ENOENT) + { + push_warning_printf(current_thd, MYSQL_ERROR::WARN_LEVEL_WARN, + ER_LOG_PURGE_NO_FILE, ER(ER_LOG_PURGE_NO_FILE), + linfo.log_file_name); + sql_print_information("Failed to delete file '%s'", + linfo.log_file_name); + my_errno= 0; + error= 0; + } + else + { + push_warning_printf(current_thd, MYSQL_ERROR::WARN_LEVEL_ERROR, + ER_BINLOG_PURGE_FATAL_ERR, + "a problem with deleting %s; " + "consider examining correspondence " + "of your binlog index file " + "to the actual binlog files", + linfo.log_file_name); + error= 1; + goto err; + } + } if (find_next_log(&linfo, 0)) break; } /* Start logging with a new file */ close(LOG_CLOSE_INDEX); - my_delete_allow_opened(index_file_name, MYF(MY_WME)); // Reset (open will update) + if ((error= my_delete_allow_opened(index_file_name, MYF(0)))) // Reset (open will update) + { + if (my_errno == ENOENT) + { + push_warning_printf(current_thd, MYSQL_ERROR::WARN_LEVEL_WARN, + ER_LOG_PURGE_NO_FILE, ER(ER_LOG_PURGE_NO_FILE), + index_file_name); + sql_print_information("Failed to delete file '%s'", + index_file_name); + my_errno= 0; + error= 0; + } + else + { + push_warning_printf(current_thd, MYSQL_ERROR::WARN_LEVEL_ERROR, + ER_BINLOG_PURGE_FATAL_ERR, + "a problem with deleting %s; " + "consider examining correspondence " + "of your binlog index file " + "to the actual binlog files", + index_file_name); + error= 1; + goto err; + } + } if (!thd->slave_thread) need_start_event=1; if (!open_index_file(index_file_name, 0)) @@ -2906,6 +3047,9 @@ int MYSQL_BIN_LOG::update_log_index(LOG_INFO* log_info, bool need_update_threads 0 ok @retval LOG_INFO_EOF to_log not found + LOG_INFO_EMFILE too many files opened + LOG_INFO_FATAL if any other than ENOENT error from + my_stat() or my_delete() */ int MYSQL_BIN_LOG::purge_logs(const char *to_log, @@ -2935,44 +3079,84 @@ int MYSQL_BIN_LOG::purge_logs(const char *to_log, while ((strcmp(to_log,log_info.log_file_name) || (exit_loop=included)) && !log_in_use(log_info.log_file_name)) { - ulong file_size= 0; - if (decrease_log_space) //stat the file we want to delete + MY_STAT s; + if (!my_stat(log_info.log_file_name, &s, MYF(0))) { - MY_STAT s; - - /* - If we could not stat, we can't know the amount - of space that deletion will free. In most cases, - deletion won't work either, so it's not a problem. - */ - if (my_stat(log_info.log_file_name,&s,MYF(0))) - file_size= s.st_size; - else - sql_print_information("Failed to execute my_stat on file '%s'", + if (my_errno == ENOENT) + { + /* + It's not fatal if we can't stat a log file that does not exist; + If we could not stat, we won't delete. + */ + push_warning_printf(current_thd, MYSQL_ERROR::WARN_LEVEL_WARN, + ER_LOG_PURGE_NO_FILE, ER(ER_LOG_PURGE_NO_FILE), + log_info.log_file_name); + sql_print_information("Failed to execute my_stat on file '%s'", log_info.log_file_name); + my_errno= 0; + } + else + { + /* + Other than ENOENT are fatal + */ + push_warning_printf(current_thd, MYSQL_ERROR::WARN_LEVEL_ERROR, + ER_BINLOG_PURGE_FATAL_ERR, + "a problem with getting info on being purged %s; " + "consider examining correspondence " + "of your binlog index file " + "to the actual binlog files", + log_info.log_file_name); + error= LOG_INFO_FATAL; + goto err; + } } - /* - It's not fatal if we can't delete a log file ; - if we could delete it, take its size into account - */ - DBUG_PRINT("info",("purging %s",log_info.log_file_name)); - if (!my_delete(log_info.log_file_name, MYF(0)) && decrease_log_space) - *decrease_log_space-= file_size; - - ha_binlog_index_purge_file(current_thd, log_info.log_file_name); - if (current_thd->is_slave_error) { - DBUG_PRINT("info",("slave error: %d", current_thd->is_slave_error)); - if (my_errno == EMFILE) { - DBUG_PRINT("info",("my_errno: %d, set ret = LOG_INFO_EMFILE", my_errno)); - ret = LOG_INFO_EMFILE; - break; + else + { + DBUG_PRINT("info",("purging %s",log_info.log_file_name)); + if (!my_delete(log_info.log_file_name, MYF(0))) + { + if (decrease_log_space) + *decrease_log_space-= s.st_size; + } + else + { + if (my_errno == ENOENT) + { + push_warning_printf(current_thd, MYSQL_ERROR::WARN_LEVEL_WARN, + ER_LOG_PURGE_NO_FILE, ER(ER_LOG_PURGE_NO_FILE), + log_info.log_file_name); + sql_print_information("Failed to delete file '%s'", + log_info.log_file_name); + my_errno= 0; + } + else + { + push_warning_printf(current_thd, MYSQL_ERROR::WARN_LEVEL_ERROR, + ER_BINLOG_PURGE_FATAL_ERR, + "a problem with deleting %s; " + "consider examining correspondence " + "of your binlog index file " + "to the actual binlog files", + log_info.log_file_name); + if (my_errno == EMFILE) + { + DBUG_PRINT("info", + ("my_errno: %d, set ret = LOG_INFO_EMFILE", my_errno)); + error= LOG_INFO_EMFILE; + } + error= LOG_INFO_FATAL; + goto err; + } } } + ha_binlog_index_purge_file(current_thd, log_info.log_file_name); + if (find_next_log(&log_info, 0) || exit_loop) break; } - + /* If we get killed -9 here, the sysadmin would have to edit the log index file after restart - otherwise, this should be safe @@ -3003,6 +3187,8 @@ err: 0 ok @retval LOG_INFO_PURGE_NO_ROTATE Binary file that can't be rotated + LOG_INFO_FATAL if any other than ENOENT error from + my_stat() or my_delete() */ int MYSQL_BIN_LOG::purge_logs_before_date(time_t purge_time) @@ -3026,14 +3212,67 @@ int MYSQL_BIN_LOG::purge_logs_before_date(time_t purge_time) while (strcmp(log_file_name, log_info.log_file_name) && !log_in_use(log_info.log_file_name)) { - /* It's not fatal even if we can't delete a log file */ - if (!my_stat(log_info.log_file_name, &stat_area, MYF(0)) || - stat_area.st_mtime >= purge_time) - break; - my_delete(log_info.log_file_name, MYF(0)); - - ha_binlog_index_purge_file(current_thd, log_info.log_file_name); - + if (!my_stat(log_info.log_file_name, &stat_area, MYF(0))) + { + if (my_errno == ENOENT) + { + /* + It's not fatal if we can't stat a log file that does not exist. + */ + push_warning_printf(current_thd, MYSQL_ERROR::WARN_LEVEL_WARN, + ER_LOG_PURGE_NO_FILE, ER(ER_LOG_PURGE_NO_FILE), + log_info.log_file_name); + sql_print_information("Failed to execute my_stat on file '%s'", + log_info.log_file_name); + my_errno= 0; + } + else + { + /* + Other than ENOENT are fatal + */ + push_warning_printf(current_thd, MYSQL_ERROR::WARN_LEVEL_ERROR, + ER_BINLOG_PURGE_FATAL_ERR, + "a problem with getting info on being purged %s; " + "consider examining correspondence " + "of your binlog index file " + "to the actual binlog files", + log_info.log_file_name); + error= LOG_INFO_FATAL; + goto err; + } + } + else + { + if (stat_area.st_mtime >= purge_time) + break; + if (my_delete(log_info.log_file_name, MYF(0))) + { + if (my_errno == ENOENT) + { + /* It's not fatal even if we can't delete a log file */ + push_warning_printf(current_thd, MYSQL_ERROR::WARN_LEVEL_WARN, + ER_LOG_PURGE_NO_FILE, ER(ER_LOG_PURGE_NO_FILE), + log_info.log_file_name); + sql_print_information("Failed to delete file '%s'", + log_info.log_file_name); + my_errno= 0; + } + else + { + push_warning_printf(current_thd, MYSQL_ERROR::WARN_LEVEL_ERROR, + ER_BINLOG_PURGE_FATAL_ERR, + "a problem with deleting %s; " + "consider examining correspondence " + "of your binlog index file " + "to the actual binlog files", + log_info.log_file_name); + error= LOG_INFO_FATAL; + goto err; + } + } + ha_binlog_index_purge_file(current_thd, log_info.log_file_name); + } if (find_next_log(&log_info, 0)) break; } @@ -3377,6 +3616,16 @@ THD::binlog_start_trans_and_stmt() if (options & (OPTION_NOT_AUTOCOMMIT | OPTION_BEGIN)) trans_register_ha(this, TRUE, binlog_hton); trans_register_ha(this, FALSE, binlog_hton); + /* + Mark statement transaction as read/write. We never start + a binary log transaction and keep it read-only, + therefore it's best to mark the transaction read/write just + at the same time we start it. + Not necessary to mark the normal transaction read/write + since the statement-level flag will be propagated automatically + inside ha_commit_trans. + */ + ha_data[binlog_hton->slot].ha_info[0].set_trx_read_write(); } DBUG_VOID_RETURN; } @@ -3397,35 +3646,6 @@ void THD::binlog_set_stmt_begin() { trx_data->before_stmt_pos= pos; } -int THD::binlog_flush_transaction_cache() -{ - DBUG_ENTER("binlog_flush_transaction_cache"); - binlog_trx_data *trx_data= (binlog_trx_data*) - thd_get_ha_data(this, binlog_hton); - DBUG_PRINT("enter", ("trx_data=0x%lu", (ulong) trx_data)); - if (trx_data) - DBUG_PRINT("enter", ("trx_data->before_stmt_pos=%lu", - (ulong) trx_data->before_stmt_pos)); - - /* - Write the transaction cache to the binary log. We don't flush and - sync the log file since we don't know if more will be written to - it. If the caller want the log file sync:ed, the caller has to do - it. - - The transaction data is only reset upon a successful write of the - cache to the binary log. - */ - - if (trx_data && likely(mysql_bin_log.is_open())) { - if (int error= mysql_bin_log.write_cache(&trx_data->trans_log, true, true)) - DBUG_RETURN(error); - trx_data->reset(); - } - - DBUG_RETURN(0); -} - /* Write a table map to the binary log. @@ -4432,15 +4652,7 @@ static void print_buffer_to_nt_eventlog(enum loglevel level, char *buff, return an error (e.g. logging to the log tables) */ -#ifdef EMBEDDED_LIBRARY -int vprint_msg_to_log(enum loglevel level __attribute__((unused)), - const char *format __attribute__((unused)), - va_list argsi __attribute__((unused))) -{ - DBUG_ENTER("vprint_msg_to_log"); - DBUG_RETURN(0); -} -#else /*!EMBEDDED_LIBRARY*/ +#ifndef EMBEDDED_LIBRARY static void print_buffer_to_file(enum loglevel level, const char *buffer) { time_t skr; |