From abf4b3fa6aab3dac2d532361b237ccbf6a1e633d Mon Sep 17 00:00:00 2001 From: Rohit Kalhans Date: Tue, 10 Jul 2012 18:24:11 +0530 Subject: [PATCH] BUG#11759333: SBR LOGGING WARNING MESSAGES FOR PRIMARY KEY UPDATES WITH A LIMIT OF 1 Problem: The unsafety warning for statements such as update...limit1 where pk=1 are thrown when binlog-format = STATEMENT,despite of the fact that such statements are actually safe. this leads to filling up of the disk space with false warnings. Solution: This is not a complete fix for the problem, but prevents the disks from getting filled up. This should therefore be regarded as a workaround. In the future this should be overriden by server general suppress/filtering framework. It should also be noted that another worklog is supposed to defeat this case's artificial unsafety. We use a warning suppression mechanism to detect warning flood, enable the suppression, and disable this when the average warnings/second has reduced to acceptable limits. Activation: The supression for LIMIT unsafe statements are activated when the last 50 warnings were logged in less than 50 seconds. Supression: Once activated this supression will prevent the individual warnings to be logged in the error log, but print the warning for every 50 warnings with the note: "The last warning was repeated N times in last S seconds" Noteworthy is the fact that this supression works only on the error logs and the warnings seen by the clients will remain as it is (i.e. one warning/ unsafe statement) Deactivation: The supression will be deactivated once the average # of warnings/sec have gone down to the acceptable limits. --- sql/sql_class.cc | 144 +++++++++++++++++++++++++++++++++++++++++++++-- 1 file changed, 139 insertions(+), 5 deletions(-) diff --git a/sql/sql_class.cc b/sql/sql_class.cc index 7e93157c69e..c118030e7b4 100644 --- a/sql/sql_class.cc +++ b/sql/sql_class.cc @@ -4806,6 +4806,140 @@ show_query_type(THD::enum_binlog_query_type qtype) } #endif +/* + Constants required for the limit unsafe warnings suppression +*/ +//seconds after which the limit unsafe warnings suppression will be activated +#define LIMIT_UNSAFE_WARNING_ACTIVATION_TIMEOUT 50 +//number of limit unsafe warnings after which the suppression will be activated +#define LIMIT_UNSAFE_WARNING_ACTIVATION_THRESHOLD_COUNT 50 + +static struct timeval limit_unsafe_suppression_start_time; +static struct timezone limit_unsafe_suppression_start_time_zone; +static bool unsafe_warning_suppression_is_activated= false; +static int limit_unsafe_warning_count= 0; + +/** + Auxiliary function to reset the limit unsafety warning suppression. +*/ +static void reset_binlog_unsafe_suppression() +{ + DBUG_ENTER("reset_binlog_unsafe_suppression"); + unsafe_warning_suppression_is_activated= false; + limit_unsafe_warning_count= 0; + gettimeofday(&limit_unsafe_suppression_start_time, + &limit_unsafe_suppression_start_time_zone); + DBUG_VOID_RETURN; +} + +/** + Auxiliary function to print warning in the error log. +*/ +static void print_unsafe_warning_to_log(int unsafe_type, char* buf, + char* query) +{ + DBUG_ENTER("print_unsafe_warning_in_log"); + sprintf(buf, ER(ER_BINLOG_UNSAFE_STATEMENT), + ER(LEX::binlog_stmt_unsafe_errcode[unsafe_type])); + sql_print_warning(ER(ER_MESSAGE_AND_STATEMENT), buf, query); + DBUG_VOID_RETURN; +} + +/** + Auxiliary function to check if the warning for limit unsafety should be + thrown or suppressed. Details of the implementation can be found in the + comments inline. + SYNOPSIS: + @params + buf - buffer to hold the warning message text + unsafe_type - The type of unsafety. + query - The actual query statement. + + TODO: Remove this function and implement a general service for all warnings + that would prevent flooding the error log. +*/ +static void do_unsafe_limit_checkout(char* buf, int unsafe_type, char* query) +{ + struct timeval now; + struct timezone tz_now; + DBUG_ENTER("do_unsafe_limit_checkout"); + DBUG_ASSERT(unsafe_type == LEX::BINLOG_STMT_UNSAFE_LIMIT); + limit_unsafe_warning_count++; + /* + INITIALIZING: + If this is the first time this function is called with log warning + enabled, the monitoring the unsafe warnings should start. + */ + if (limit_unsafe_suppression_start_time.tv_sec == 0) + { + gettimeofday(&limit_unsafe_suppression_start_time, + &limit_unsafe_suppression_start_time_zone); + print_unsafe_warning_to_log(unsafe_type, buf, query); + } + else + { + if (!unsafe_warning_suppression_is_activated) + print_unsafe_warning_to_log(unsafe_type, buf, query); + + if (limit_unsafe_warning_count >= + LIMIT_UNSAFE_WARNING_ACTIVATION_THRESHOLD_COUNT) + { + gettimeofday (&now, &tz_now); + if (!unsafe_warning_suppression_is_activated) + { + /* + ACTIVATION: + We got LIMIT_UNSAFE_WARNING_ACTIVATION_THRESHOLD_COUNT warnings in + less than LIMIT_UNSAFE_WARNING_ACTIVATION_TIMEOUT we activate the + suppression. + */ + if ((now.tv_sec-limit_unsafe_suppression_start_time.tv_sec) <= + LIMIT_UNSAFE_WARNING_ACTIVATION_TIMEOUT) + { + unsafe_warning_suppression_is_activated= true; + DBUG_PRINT("info",("A warning flood has been detected and the limit \ +unsafety warning suppression has been activated.")); + } + else + { + /* + there is no flooding till now, therefore we restart the monitoring + */ + gettimeofday(&limit_unsafe_suppression_start_time, + &limit_unsafe_suppression_start_time_zone); + limit_unsafe_warning_count= 0; + } + } + else + { + /* + Print the suppression note and the unsafe warning. + */ + sql_print_information("The following warning was suppressed %d times \ +during the last %d seconds in the error log", + limit_unsafe_warning_count, + (int) + (now.tv_sec - + limit_unsafe_suppression_start_time.tv_sec)); + print_unsafe_warning_to_log(unsafe_type, buf, query); + /* + DEACTIVATION: We got LIMIT_UNSAFE_WARNING_ACTIVATION_THRESHOLD_COUNT + warnings in more than LIMIT_UNSAFE_WARNING_ACTIVATION_TIMEOUT, the + suppression should be deactivated. + */ + if ((now.tv_sec - limit_unsafe_suppression_start_time.tv_sec) > + LIMIT_UNSAFE_WARNING_ACTIVATION_TIMEOUT) + { + reset_binlog_unsafe_suppression(); + DBUG_PRINT("info",("The limit unsafety warning supression has been \ +deactivated")); + } + } + limit_unsafe_warning_count= 0; + } + } + DBUG_VOID_RETURN; +} /** Auxiliary method used by @c binlog_query() to raise warnings. @@ -4815,6 +4949,7 @@ show_query_type(THD::enum_binlog_query_type qtype) */ void THD::issue_unsafe_warnings() { + char buf[MYSQL_ERRMSG_SIZE * 2]; DBUG_ENTER("issue_unsafe_warnings"); /* Ensure that binlog_unsafe_warning_flags is big enough to hold all @@ -4840,17 +4975,16 @@ void THD::issue_unsafe_warnings() ER(LEX::binlog_stmt_unsafe_errcode[unsafe_type])); if (global_system_variables.log_warnings) { - char buf[MYSQL_ERRMSG_SIZE * 2]; - sprintf(buf, ER(ER_BINLOG_UNSAFE_STATEMENT), - ER(LEX::binlog_stmt_unsafe_errcode[unsafe_type])); - sql_print_warning(ER(ER_MESSAGE_AND_STATEMENT), buf, query()); + if (unsafe_type == LEX::BINLOG_STMT_UNSAFE_LIMIT) + do_unsafe_limit_checkout( buf, unsafe_type, query()); + else //cases other than LIMIT unsafety + print_unsafe_warning_to_log(unsafe_type, buf, query()); } } } DBUG_VOID_RETURN; } - /** Log the current query.