Bug#36574298 Background histogram update warnings flood error log

Several users have experienced the error log being flooded with warnings
from background histogram updates. One reported case from a customer saw
as many as 300 000 messages per hour.

The offending warning concerned the failure to acquire metadata locks on
a table. There is a 10-second cooldown on background histogram updates
for any given table. Therefore the above flooding of the error log
should only occur under special circumstances, for example with DDL
operations on a large number of tables. Nevertheless, flooding the error
log with messages from background histogram updates is not helpful for
the user.

This patch throttles messages written to the error log from the
background histogram update operation. The rate is set to at most one
message per minute. This rate should suffice for the user to identify
potential problems with background histogram updates.

With this patch we downgrade all error events that happen during the
background histogram update from priority level error to priority level
warning. The reasoning is twofold: 1) A failure to update statistics is
generally ignorable, so a warning is more suitable than an error, and 2)
throttling of messages in the error log only works out-of-the-box for
error events that have a priority level lower than error.

Change-Id: I62d6cd7acf2d0851605eec362de72e57356ef832

Author: Tobias Christiani

mysql-test/r/histogram_background_error_throttling.result

@@ -0,0 +1,23 @@
+#
+# Bug#36574298: Background histogram update warnings flood error log
+#
+CREATE TABLE t1 (x INT);
+ANALYZE TABLE t1 UPDATE HISTOGRAM ON x AUTO UPDATE;
+Table	Op	Msg_type	Msg_text
+test.t1	histogram	status	Histogram statistics created for column 'x'.
+INSERT INTO t1 VALUES (1), (2), (3);
+CREATE TABLE t2 (x INT);
+ANALYZE TABLE t2 UPDATE HISTOGRAM ON x AUTO UPDATE;
+Table	Op	Msg_type	Msg_text
+test.t2	histogram	status	Histogram statistics created for column 'x'.
+INSERT INTO t2 VALUES (1), (2), (3);
+DO SLEEP(1);
+FLUSH ERROR LOGS;
+# With throttling of background histogram update warnings we should only
+# see a single warning in the error log even though we have raised
+# multiple ER_BACKGROUND_HISTOGRAM_UPDATE warnings.
+SELECT COUNT(*) AS should_be_one FROM performance_schema.error_log WHERE ERROR_CODE = 'MY-015116';
+should_be_one
+1
+DROP TABLE t1;
+DROP TABLE t2;

mysql-test/suite/sys_vars/r/log_error_suppression_list_basic.result

@@ -67,11 +67,11 @@ Level	Code	Message
 Warning	3735	log_error_suppression_list: Could not add suppression rule for code "10001". Rule-set may be full, or code may not correspond to an error-log message.
 Error	1231	Variable 'log_error_suppression_list' can't be set to the value of '10000 10001'
 SET @@global.log_error_suppression_list= CONCAT(REPEAT("10000,", 2), "11111");
+SET @@global.log_error_suppression_list= CONCAT(REPEAT("ER_PARSER_TRACE,",507),"ER_PARSER_TRACE");
 SET @@global.log_error_suppression_list= CONCAT(REPEAT("ER_PARSER_TRACE,",508),"ER_PARSER_TRACE");
-SET @@global.log_error_suppression_list= CONCAT(REPEAT("ER_PARSER_TRACE,",509),"ER_PARSER_TRACE");
 ERROR 42000: Variable 'log_error_suppression_list' can't be set to the value of 'ER_PARSER_TRACE,ER_PARSER_TRACE,ER_PARSER_TRACE,ER_PARSER_TRACE,ER_PARSER_TRACE,ER_PARSER_TRACE,ER_PARSER_TRACE,ER_PARSER_TRACE,ER_PARSER_TRACE,ER_PARSER_TRACE,ER_PARSER_TRACE,ER_PARSER_TRACE,ER_PARSE'
+SET @@global.log_error_suppression_list= CONCAT(REPEAT("10000,", 507), "11111");
 SET @@global.log_error_suppression_list= CONCAT(REPEAT("10000,", 508), "11111");
-SET @@global.log_error_suppression_list= CONCAT(REPEAT("10000,", 509), "11111");
 ERROR 42000: Variable 'log_error_suppression_list' can't be set to the value of '10000,10000,10000,10000,10000,10000,10000,10000,10000,10000,10000,10000,10000,10000,10000,10000,10000,10000,10000,10000,10000,10000,10000,10000,10000,10000,10000,10000,10000,10000,10000,10000,10000,10'
 SET @@global.log_error_suppression_list='10000.123';
 ERROR 42000: Variable 'log_error_suppression_list' can't be set to the value of '10000.123'

mysql-test/suite/sys_vars/t/log_error_suppression_list_basic.test

@@ -66,15 +66,16 @@ SHOW WARNINGS;
 SET @@global.log_error_suppression_list="10000 10001";
 SHOW WARNINGS;
 
-# too many items
+# The statements below verify that we can have at most 512 rules in the log error suppression list.
+# This count includes the rules specified in log_builtins_filter_set_defaults().
 SET @@global.log_error_suppression_list= CONCAT(REPEAT("10000,", 2), "11111");
-# 508 repeated + 1 tail + 2 automatic rules == 511 total
+# 507 repeated + 1 tail + 4 automatic rules == 512 total. This is OK.
+SET @@global.log_error_suppression_list= CONCAT(REPEAT("ER_PARSER_TRACE,",507),"ER_PARSER_TRACE");
+--error ER_WRONG_VALUE_FOR_VAR
 SET @@global.log_error_suppression_list= CONCAT(REPEAT("ER_PARSER_TRACE,",508),"ER_PARSER_TRACE");
+SET @@global.log_error_suppression_list= CONCAT(REPEAT("10000,", 507), "11111");
 --error ER_WRONG_VALUE_FOR_VAR
-SET @@global.log_error_suppression_list= CONCAT(REPEAT("ER_PARSER_TRACE,",509),"ER_PARSER_TRACE");
 SET @@global.log_error_suppression_list= CONCAT(REPEAT("10000,", 508), "11111");
---error ER_WRONG_VALUE_FOR_VAR
-SET @@global.log_error_suppression_list= CONCAT(REPEAT("10000,", 509), "11111");
 
 # Bug#28145616: PARSER ACCEPTS GARBAGE VALUES IF PREFIXED BY VALID ERROR CODES
 --error ER_WRONG_VALUE_FOR_VAR

mysql-test/t/histogram_background_error_throttling-master.opt

@@ -0,0 +1,2 @@
+--loose-debug='+d,background_histogram_update_errors'
+--force-restart

mysql-test/t/histogram_background_error_throttling.test

@@ -0,0 +1,44 @@
+--source include/have_debug.inc
+
+-- echo #
+-- echo # Bug#36574298: Background histogram update warnings flood error log
+-- echo #
+
+# Note: this test is in a separate file because we want to use
+# the loose-debug='+d,background_histogram_update_errors' startup option
+# to trigger multiple errors during histogram updates from the background thread.
+# If we instead use "SET GLOBAL DEBUG = ..." we run seem to run into some
+# flakiness in terms of when this setting is picked up by the background thread.
+
+# Create two tables with automatic histograms and insert values to trigger
+# automatic updates from the background thread. This will raise multiple
+# ER_BACKGROUND_HISTOGRAM_UPDATE warnings due to the
+# loose-debug='+d,background_histogram_update_errors' startup option.
+CREATE TABLE t1 (x INT);
+ANALYZE TABLE t1 UPDATE HISTOGRAM ON x AUTO UPDATE;
+INSERT INTO t1 VALUES (1), (2), (3);
+
+CREATE TABLE t2 (x INT);
+ANALYZE TABLE t2 UPDATE HISTOGRAM ON x AUTO UPDATE;
+INSERT INTO t2 VALUES (1), (2), (3);
+
+# Wait for a background histogram update error to show up in the error log.
+let $wait_condition = SELECT COUNT(*) > 0 FROM performance_schema.error_log WHERE ERROR_CODE = 'MY-015116';
+let $wait_timeout = 15;
+--source include/wait_condition.inc
+
+# The wait_condition only waits for at least one error to show up.
+# We give the system an additional second to synchronize and flush the error logs.
+# This should ensure that all of the error messages have been written to the log.
+# It would be preferable to use DEBUG_SYNC for this, but it does not seem straightforward
+# to get it to work with a background thread.
+DO SLEEP(1);
+FLUSH ERROR LOGS;
+
+--echo # With throttling of background histogram update warnings we should only
+--echo # see a single warning in the error log even though we have raised
+--echo # multiple ER_BACKGROUND_HISTOGRAM_UPDATE warnings.
+SELECT COUNT(*) AS should_be_one FROM performance_schema.error_log WHERE ERROR_CODE = 'MY-015116';
+
+DROP TABLE t1;
+DROP TABLE t2;

sql/histograms/histogram.cc

@@ -1713,15 +1713,21 @@ static void cleanup_session_context(THD *thd) {
 
 /**
   Custom error handling for histogram updates from the background thread.
-  Downgrades MDL timeout errors to warnings.
+  Downgrades all errors to warnings. This is done for two reasons:
+
+  1) Because errors during background histogram updates are mostly ignorable,
+     i.e., it is not critical that the user does something if histogram
+     statistics fail to be updated.
+
+  2) We wish to throttle error log entries from background histogram updates,
+     and this is currently only supported for a priority level of warnings.
 */
 class Background_error_handler : public Internal_error_handler {
  public:
-  bool handle_condition(THD *, uint sql_errno, const char *,
+  bool handle_condition(THD *, uint, const char *,
                         Sql_condition::enum_severity_level *level,
                         const char *) override {
-    if (sql_errno == ER_LOCK_WAIT_TIMEOUT &&
-        *level == Sql_condition::SL_ERROR) {
+    if (*level == Sql_condition::SL_ERROR) {
       *level = Sql_condition::SL_WARNING;
     }
     return false;
@@ -1757,7 +1763,6 @@ bool auto_update_table_histograms_from_background_thread(
     thd->mdl_context.release_transactional_locks();
     write_diagnostics_area_to_error_log(thd, db_name, table_name);
     cleanup_session_context(thd);
-    DEBUG_SYNC(thd, "background_histogram_update_done");
   });
 
   // It is crucial that we release objects from the dictionary cache _before_
@@ -1776,6 +1781,20 @@ bool auto_update_table_histograms_from_background_thread(
   auto error_handler_guard =
       create_scope_guard([&]() { thd->pop_internal_handler(); });
 
+  // Simulate multiple errors to test error log throttling. We should only see
+  // the first error.
+  DBUG_EXECUTE_IF("background_histogram_update_errors", {
+    my_error(ER_LOCK_WAIT_TIMEOUT, MYF(0));
+    my_error(ER_UNABLE_TO_BUILD_HISTOGRAM, MYF(0), "field", "schema", "table");
+    my_error(ER_UNABLE_TO_UPDATE_COLUMN_STATISTICS, MYF(0), "field", "schema",
+             "table");
+    my_error(ER_LOCK_WAIT_TIMEOUT, MYF(0));
+    my_error(ER_UNABLE_TO_BUILD_HISTOGRAM, MYF(0), "field", "schema", "table");
+    my_error(ER_UNABLE_TO_UPDATE_COLUMN_STATISTICS, MYF(0), "field", "schema",
+             "table");
+    return true;
+  });
+
   // Lock the table metadata so we can check whether the table has any
   // automatically updated histograms. We get the column names from the table
   // definition in order to avoid opening the table until we know that it will

sql/server_component/log_builtins_filter.cc

@@ -92,6 +92,10 @@
 
 static bool filter_inited = false;
 static ulong filter_rule_uuid = 0;
+// The number of built-in rules in the log_filter_builtin_rules ruleset. This
+// counter should be incremented for each built-in rule we add in
+// log_builtins_filter_set_defaults().
+static uint32 builtin_count = 0;
 
 log_filter_ruleset *log_filter_builtin_rules = nullptr;
 log_filter_tag rule_tag_builtin = {"log_filter_builtin", nullptr};
@@ -289,11 +293,12 @@ static void log_builtins_filter_ruleset_free(log_filter_ruleset **ruleset) {
 }
 
 /**
-  Defaults for when the configuration engine isn't loaded;
-  aim for 5.7 compatibility.
+  Defaults for when the configuration engine isn't loaded; aim for 5.7
+  compatibility.
 */
 static void log_builtins_filter_set_defaults(log_filter_ruleset *ruleset) {
   log_filter_rule *r;
+  builtin_count = 0;
 
   assert(ruleset != nullptr);
 
@@ -308,6 +313,7 @@ static void log_builtins_filter_set_defaults(log_filter_ruleset *ruleset) {
   r->verb = LOG_FILTER_RETURN;
 
   ruleset->count++;
+  builtin_count++;
 
   // sys_var: log_error_verbosity
   r = log_builtins_filter_rule_init(ruleset);
@@ -318,6 +324,7 @@ static void log_builtins_filter_set_defaults(log_filter_ruleset *ruleset) {
   r->verb = LOG_FILTER_DROP;
 
   ruleset->count++;
+  builtin_count++;
 
   // example: remove all source-line log items
   // these are not desirable by default, only while debugging.
@@ -328,6 +335,29 @@ static void log_builtins_filter_set_defaults(log_filter_ruleset *ruleset) {
   // aux optional
 
   ruleset->count++;
+  builtin_count++;
+
+  // Throttle background histogram update errors.
+
+  // Initialize a new rule.
+  r = log_builtins_filter_rule_init(ruleset);
+
+  // Condition/comparator: equal.
+  r->cond = LOG_FILTER_COND_EQ;
+
+  // Match information: MySQL error code.
+  log_item_set(&r->match, LOG_ITEM_SQL_ERRCODE)->data_integer =
+      ER_BACKGROUND_HISTOGRAM_UPDATE;
+
+  // Action/verb: throttle (rate-limit).
+  r->verb = LOG_FILTER_THROTTLE;
+
+  // Auxiliary information: maximum number of messages per minute.
+  log_item_set(&r->aux, LOG_ITEM_GEN_INTEGER)->data_integer = 1;
+
+  // Rule complete, be counted.
+  ruleset->count++;
+  builtin_count++;
 }
 
 /**
@@ -970,15 +1000,15 @@ int log_builtins_filter_parse_suppression_list(char *list, bool update) {
     }
 
     /*
-      During check-phase, make sure the requested number of error-codes
-      (and therefore, the requested number of DROP rules) will fit into
-      the built-in rule-set.  Reserve one rule for --log-error-verbosity
-      and one for our "ERROR and SYSTEM always pass" shortcut.
-      Without this check, we'd still catch the (attempted) overflow during
-      assignment, but if we do it during the check phase, we protect the
+      During check-phase, make sure the requested number of error-codes (and
+      therefore, the requested number of DROP rules) will fit into the built-in
+      rule-set. Without this check, we'd still catch the (attempted) overflow
+      during assignment, but if we do it during the check phase, we protect the
       integrity of both the current rule-set and the variable's value.
     */
-    else if (++list_len >= (log_filter_builtin_rules->alloc - 2))
+    else if (uint32_t max_user_rules_in_list =
+                 log_filter_builtin_rules->alloc - builtin_count;
+             ++list_len > max_user_rules_in_list)
       goto fail;
 
     start = end;