From: Andrei Elkin Date: March 27 2011 6:16pm Subject: bzr commit into mysql-trunk branch (andrei.elkin:3311) Bug#11748510 List-Archive: http://lists.mysql.com/commits/133957 X-Bug: 11748510 Message-Id: <201103271816.p2RIGb0h013123@mysql1000.dsl.inet.fi> MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="===============1043074703==" --===============1043074703== MIME-Version: 1.0 Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: 7bit Content-Disposition: inline #At file:///home/andrei/MySQL/BZR/2a-23May/FIXES/bug11748510_36524_less_drama/ based on revid:magne.mahre@stripped 3311 Andrei Elkin 2011-03-27 bug#11748510 incident of deadlock on slave is overdramatized In cases of temporary errors in replication event execution (deadlock, timeout) the error log gained an overreacting error message whereas just a warning would be fine. Fixed with checking of the temporary status of the error inside Slave_reporting_capability::report() to demote the error to the warning level if needed. The warning gets converted into the error whenever number of successive attempts to re-apply the event(s) gets equal to @@global.slave_trans_retries. @ mysql-test/extra/rpl_tests/rpl_deadlock.test regression test for bug#11748510 is added. @ mysql-test/suite/rpl/r/rpl_deadlock_innodb.result results get updated. @ sql/rpl_reporting.cc implementing error to warning demotion and refining stderr report func:s invocation with prior checking of global_system_variables.log_warnings. @ sql/rpl_slave.cc has_temporary_error() is extended with a new argument and a new rule to return 0 if there has been the fatal error flag raised. A minor refinement is done to not regard an error as temporary in case there is no retry. @ sql/rpl_slave.h providing has_temporary_error() interface for rpl_reporting.cc. modified: mysql-test/extra/rpl_tests/rpl_deadlock.test mysql-test/suite/rpl/r/rpl_deadlock_innodb.result sql/rpl_reporting.cc sql/rpl_slave.cc sql/rpl_slave.h === modified file 'mysql-test/extra/rpl_tests/rpl_deadlock.test' --- a/mysql-test/extra/rpl_tests/rpl_deadlock.test 2010-12-19 17:07:28 +0000 +++ b/mysql-test/extra/rpl_tests/rpl_deadlock.test 2011-03-27 18:16:32 +0000 @@ -123,6 +123,57 @@ SELECT * FROM t3; source include/check_slave_is_running.inc; --echo +# +# bug#11748510/36524 incident of deadlock on slave is overdramatized +# +# Observe that the slave stopped when the number of transation retries +# exceeds @@global.slave_transaction_retries +# +connection master; + +--echo *** Test the deadlock warning to be escalated into the error *** + +delete from t1; +delete from t2; +delete from t3; + +sync_slave_with_master; + +# make sure slave's unilateral row gone as well +delete from t1; +delete from t2; +delete from t3; + +# the first attempt to run a deadlock scenario of p 1) leads to the error +set @save.slave_transaction_retries= @@global.slave_transaction_retries; +set @@global.slave_transaction_retries= 0; +source include/stop_slave.inc; + +connection master; + +BEGIN; +INSERT INTO t1 VALUES (1); +# We make a long transaction here +INSERT INTO t2 VALUES (2), (2), (2), (2), (2), (2), (2), (2), (2), (2); +INSERT INTO t3 VALUES (3); +COMMIT; + +connection slave; +BEGIN; +SELECT count(*) as zero FROM t1 FOR UPDATE; + +start slave; + +--echo *** Now the slave must be stopped due to timeout *** + +let $slave_sql_errno= 1205; # ER_LOCK_TIMEOUT +let $show_slave_sql_error= 0; +source include/wait_for_slave_sql_error.inc; + +rollback; + +set @@global.slave_transaction_retries= @save.slave_transaction_retries; +source include/start_slave.inc; # Clean up --echo *** Clean up *** connection master; === modified file 'mysql-test/suite/rpl/r/rpl_deadlock_innodb.result' --- a/mysql-test/suite/rpl/r/rpl_deadlock_innodb.result 2010-12-19 17:22:30 +0000 +++ b/mysql-test/suite/rpl/r/rpl_deadlock_innodb.result 2011-03-27 18:16:32 +0000 @@ -103,6 +103,31 @@ a 3 include/check_slave_is_running.inc +*** Test the deadlock warning to be escalated into the error *** +delete from t1; +delete from t2; +delete from t3; +delete from t1; +delete from t2; +delete from t3; +set @save.slave_transaction_retries= @@global.slave_transaction_retries; +set @@global.slave_transaction_retries= 0; +include/stop_slave.inc +BEGIN; +INSERT INTO t1 VALUES (1); +INSERT INTO t2 VALUES (2), (2), (2), (2), (2), (2), (2), (2), (2), (2); +INSERT INTO t3 VALUES (3); +COMMIT; +BEGIN; +SELECT count(*) as zero FROM t1 FOR UPDATE; +zero +0 +start slave; +*** Now the slave must be stopped due to timeout *** +include/wait_for_slave_sql_error.inc [errno=1205] +rollback; +set @@global.slave_transaction_retries= @save.slave_transaction_retries; +include/start_slave.inc *** Clean up *** DROP TABLE t1,t2,t3; SET global max_relay_log_size= @my_max_relay_log_size; === modified file 'sql/rpl_reporting.cc' --- a/sql/rpl_reporting.cc 2010-08-05 17:45:25 +0000 +++ b/sql/rpl_reporting.cc 2011-03-27 18:16:32 +0000 @@ -17,6 +17,7 @@ #include "rpl_reporting.h" #include "log.h" // sql_print_error, sql_print_warning, // sql_print_information +#include "rpl_slave.h" Slave_reporting_capability::Slave_reporting_capability(char const *thread_name) : m_thread_name(thread_name) @@ -29,11 +30,17 @@ void Slave_reporting_capability::report(loglevel level, int err_code, const char *msg, ...) const { +#if !defined(EMBEDDED_LIBRARY) + THD *thd= current_thd; void (*report_function)(const char *, ...); char buff[MAX_SLAVE_ERRMSG]; char *pbuff= buff; uint pbuffsize= sizeof(buff); va_list args; + + if (level == ERROR_LEVEL && has_temporary_error(thd, err_code)) + level= WARNING_LEVEL; + va_start(args, msg); mysql_mutex_lock(&err_lock); @@ -51,10 +58,12 @@ Slave_reporting_capability::report(logle report_function= sql_print_error; break; case WARNING_LEVEL: - report_function= sql_print_warning; + report_function= global_system_variables.log_warnings? + sql_print_warning : NULL; break; case INFORMATION_LEVEL: - report_function= sql_print_information; + report_function= global_system_variables.log_warnings? + sql_print_information : NULL; break; default: DBUG_ASSERT(0); // should not come here @@ -71,6 +80,7 @@ Slave_reporting_capability::report(logle m_thread_name, pbuff, (pbuff[0] && *(strend(pbuff)-1) == '.') ? "" : ",", err_code); +#endif } Slave_reporting_capability::~Slave_reporting_capability() === modified file 'sql/rpl_slave.cc' --- a/sql/rpl_slave.cc 2011-03-17 13:20:36 +0000 +++ b/sql/rpl_slave.cc 2011-03-27 18:16:32 +0000 @@ -2514,15 +2514,23 @@ static ulong read_event(MYSQL* mysql, Ma DBUG_RETURN(len - 1); } -/* - Check if the current error is of temporary nature of not. +/** + Check if the current error is of temporary nature or not. Some errors are temporary in nature, such as ER_LOCK_DEADLOCK and ER_LOCK_WAIT_TIMEOUT. Ndb also signals that the error is temporary by pushing a warning with the error code ER_GET_TEMPORARY_ERRMSG, if the originating error is temporary. + + @param thd a THD instance, typically of the slave SQL thread's. + @error_arg the error code for assessment. + defaults to zero which makes the function check the top + of the reported errors stack. + + @return 1 as the positive and 0 as the negative verdict */ -static int has_temporary_error(THD *thd) +int has_temporary_error(THD *thd, uint error_arg) { + uint error; DBUG_ENTER("has_temporary_error"); DBUG_EXECUTE_IF("all_errors_are_temporary_errors", @@ -2533,20 +2541,25 @@ static int has_temporary_error(THD *thd) }); /* - If there is no message in THD, we can't say if it's a temporary + The state of the slave thread can't be regarded as + experiencing a temporary failure in cases of @c is_slave_error was set TRUE, + or if there is no message in THD, we can't say if it's a temporary error or not. This is currently the case for Incident_log_event, - which sets no message. Return FALSE. + which sets no message. */ - if (!thd->is_error()) + if (thd->is_fatal_error || !thd->is_error()) DBUG_RETURN(0); + error= (error_arg == 0)? thd->stmt_da->sql_errno() : error_arg; + /* Temporary error codes: currently, InnoDB deadlock detected by InnoDB or lock - wait timeout (innodb_lock_wait_timeout exceeded + wait timeout (innodb_lock_wait_timeout exceeded). + Notice, the temporary error requires slave_trans_retries != 0) */ - if (thd->stmt_da->sql_errno() == ER_LOCK_DEADLOCK || - thd->stmt_da->sql_errno() == ER_LOCK_WAIT_TIMEOUT) + if (slave_trans_retries && + (error == ER_LOCK_DEADLOCK || error == ER_LOCK_WAIT_TIMEOUT)) DBUG_RETURN(1); #ifdef HAVE_NDB_BINLOG @@ -3007,10 +3020,13 @@ static int exec_relay_log_event(THD* thd } } else - sql_print_error("Slave SQL thread retried transaction %lu time(s) " - "in vain, giving up. Consider raising the value of " - "the slave_transaction_retries variable.", - slave_trans_retries); + { + thd->is_fatal_error= 1; + rli->report(ERROR_LEVEL, thd->stmt_da->sql_errno(), + "Slave SQL thread retried transaction %lu time(s) " + "in vain, giving up. Consider raising the value of " + "the slave_transaction_retries variable.", rli->trans_retries); + } } else if ((exec_res && !temp_err) || (opt_using_transactions && === modified file 'sql/rpl_slave.h' --- a/sql/rpl_slave.h 2011-02-16 17:13:30 +0000 +++ b/sql/rpl_slave.h 2011-03-27 18:16:32 +0000 @@ -213,6 +213,7 @@ void set_slave_thread_options(THD* thd); void set_slave_thread_default_charset(THD *thd, Relay_log_info const *rli); int apply_event_and_update_pos(Log_event* ev, THD* thd, Relay_log_info* rli); int rotate_relay_log(Master_info* mi); +int has_temporary_error(THD *thd, uint err= 0); pthread_handler_t handle_slave_io(void *arg); pthread_handler_t handle_slave_sql(void *arg); --===============1043074703== MIME-Version: 1.0 Content-Type: text/bzr-bundle; charset="us-ascii"; name="bzr/andrei.elkin@stripped" Content-Transfer-Encoding: 7bit Content-Disposition: inline # Bazaar merge directive format 2 (Bazaar 0.90) # revision_id: andrei.elkin@stripped # target_branch: file:///home/andrei/MySQL/BZR/2a-23May/FIXES\ # /bug11748510_36524_less_drama/ # testament_sha1: 1b6a727cf0c9b480ac878164489bdd872ecf195b # timestamp: 2011-03-27 21:16:37 +0300 # base_revision_id: magne.mahre@stripped\ # y6p1m9y730lssgf7 # # Begin bundle IyBCYXphYXIgcmV2aXNpb24gYnVuZGxlIHY0CiMKQlpoOTFBWSZTWd3pfxgAByd/gFUQEAB/9/// /+//qr////5gEEdvd3rfd9vW93ZMq7sabaFoO3uOXKo+2XWr73j1rC3ta203OuuostN3u4CSRNAA VPJ6R6aJtUeEKfqNT1AZNGI2kyNNDEAyDJAEYgTSniE9NJiPJBoADQAGgAAA1MTU01TyjTZIDQaa aaNABgjIAGEDIGQCREQIaSejRPSnptDKYhhTTCaGgMgDQABoNpImhTyMhoRkyTSD1Bp6j1MRkAwI AA0NNMJIgJoJoJmo00mSnsjRT8SmnigAek9IAAB5JepF2sJZGvRi9Du1+TYx7u2XM03v0v/yJ+dj 4wfM4axhx7dx7qN7/07z24ShXF/Nm+NYbfAaJz4ZrptBXyFtdb2rMWt24vNaVtdd6hTfylingibP F1a9e5GTjzBDORqGRnkSVqAhX0VkcQKYSOdLjbQMuqRuDNtS0etupBFUhN0BC/y3rG6Pw5CH/bIv eXO1V6KWiFle4QL9mCLUj0MS1sHuxdLJ8YnVUcCqTt9YXCBiL7I+WdZns208q3o2o7qG22222CNO TIm1+6Dj58dpQzYUu6dtFgzkiaaBrwBRSIgrTEZMWkqAPJSCo5Cc5zXksEaOfWt8VL7ILp799lbB 4NW368e845+A4OLQbwauZSSRsk4NdmJjeLxnQSbSf39yqM9hQYmgso2UT09eXJy2OeQfH/0WnTnT iRrDgUgrS1RneEcWnwJa+g4QMNdLzHumHfk/JlKHjM0zS0lyIBCSylHA0ASE0vtpgMQooMw5kkoz 3LCOtS4yvpntvrclzeBZdrwgXvox4eg28GXNzuy7WA0OTyuGxG3CFjNUqRIajGUoqs5R3EJGFpXo ljWNm2YTui7UmpcLh37NVb8cc2XINFSKS3nxhZ3957DxgxgxhtjJ6vC7YIf37c55Dh0w0pnbTAdp m4s97btrlvaft9gzPFr5OzKWFKVndXMQRzIWQYlaUGMouk56hUwLd7KVgxvOPDv3RdkkURkP75/e LtsiIndlEvy9SCTyOAZg3GkR51LFvpqF1DNzVq7xOrUnBYAqxQn0sLaPFrdu1j/Xw/X5m+A7nC9/ di/vEGeFa9Y0iNkFBj7GFai9mZeu7gwgq0dfG4iPonNis3K8T12CRl31HqnW/iOHeJV6/SZq4p1p Uxbx5+tBxYUFcfWpkymEtNFLcb+Fh5P4zrbGk+6YMDNrcSPUb0k4GjDUTrxzTUWwiwzDDEUdOPYi eVEa6va+C49KJBNjj29GWZC0sLmhahhztENWqsKhKaiJXYtCqSgosNZeqWJlU0ghWklrpEMVCIYq iaEUtKQJihBRKK4kn5y4rGOCippSUY0vUbilSpyuMTZ6LL6wZzVgqrKqMSlt6AeN0dI7DJgoeUaM K3sKCcQUOO823QkppAyZYZLp9y6si1+B5WQ4oOVc8m9YxVaoXtDztkxUgD03pyBC9+rFg3ATips3 Y9ket81YUSa6IE1wlsjIEFvUye1EOcM4rzOjk2FBU6tpNJVqYwXHnxEZbb83fM6wRigN9dmIgGjY 0fhiKJQ+KyUSDdl0xua5abONq8d6qWbBxxxIcsJcCrF9zDS7q5JXcdK0A4BAt71cMJfaowW6eE6T Udh1tdQ4RpljYMmmrSHxbpOYMllBSYUdMzY1E0YFViJVeKAnCxeVJq8v1HG6dn8v+4rWVJO3RbaG RFfbwzO51y9HzWi7l3JoqS0W/DZlmEZSizuudQjHj0sCN0NsZ8YWkUYq4CUshlMTW6JmKYZzhu30 hULQ+62V6MKulrKbmIMIiwX6qZTqEgTMK/x0GfgHHTJHbWEdUHi2hOlRRZF81QWstxCkWGW0csNq btNhwXWUGiCmls5MB1FgUctYRTAMS6sXo2OQvUy0Vi4cQxWMXjYbemV8V5zm+gzQSSlqkxTLDByF 9TmAmhywvucN2K3CQmdVYQOLQ4TQTyLJesxFgkaxPafwHnQOc8cwLjhQ33ItVbLKFotLVXaAvAPU FglHFszfkqGwohm3XECxHwUc8DvV5mMUqZ8OBlrRPTtjffTIlOVkVBYQy7i6kxzZLq6lsWdZKPVf nYr04QGiEo9FwSYY2DBEuZxze0HctDbduc5iprqWOrFrsb8YXVjN2kpmQcSpBlRehlExMDXVSrVY MWzrHGGg5ecGO13LHP5+C3LPPF118z9OWzbjOUxoInF3qc7KAoCeU4pQQ7W77jbKQpPSTlb5AXwU 34/f2Zc7mP1PymR+DeHvurraxRz/YyYlIMw9O1i0ngW26eItf4PzXEeJwErm09ZueHTDGxyikSiB F+UOjyI5vGgqOWMR7QNS6aVWkoCfnv+HwE3p8ZwnkGZMDMN3kBif4AIDEYxMGMJzxXU/agbk7gro QErPIdcgmGgYasKqdGeAeGKJMfMISFMVjVD/wXfQYsMbAwNbqouYlvLyA6NGBYnyY1iwCRkfQcsT yNpeb8qlSoF8ZkEGw2ivO2GFwsR8yxvKraWE9WaMMNArCpiMWKvgsfZ2+yhq7sKd59obH1nYI6Wu R/CS1AUkYUR0QiEPyEAfB6fouQUtuGxiGjD2XCJob62aeB8vx1CdFNDDkEl9Syhmo6AfSUVgon+Y 8hV9p9S8UDyjjWW+cq8x6Ovw6jCQKXX6icSM+Akyzmh17IDXqNF5jMgnA5BWefGI1hYo1dH5bAID LkbuBvhhUOtFeBIeMFmvznQJkW+k0IwU2zms5BkLpCq0LbxFwUgoY92DxORUnaAe3Mq9BrbJEqs2 /OBYyuwvsAqgyBXCT4fD7PPqOZ6KsuGo7TGA5PXdJiQgcR9h+CRCNRZxRjUD1gjewVSKrV17XTjb lgfMJJvvzCLmoLi1ZyYuOF5QjuaTfcd5lyvnErV6Ck9ReyTMdOG5TWRXnOWumJ75SV4mdSLi+WI2 Q0lSFBJQgVQU0YALduJyTNLVKtcnHBefoEt6qT9glBz7lTOB2WdKLuDMQA4ocDyzRrtykuorTjEa pJilQahLVDuFhIkXmEeK4YGI0J1zKGe+jXKMLBHhrEUmFOY5s/4sCmMFj6muuzFKIB30xoUAMJ0i s6EoY8ufSHrPJsG4SSOEZaiIt27oKcmh0TLz1sqarazexQyCuaSJNjQiQaz+vDAvxuo9EMJDCIJg dFqC7DrGNcvQ8cuj0wy0+qbIlMCBoIEhvIFy3ovRyKODGZk6e4RgA8mBHfQNN4BSDm4uz3LwKhov TrHu9BZpZd58UkboZOJB5UGc+Q1b3xzNHXjrbVkqqBtATtoYABSDQLJVJr+ymxAPRJPDkNe40LBL 74HDO3lbqueqKiUmhwQECaCiDpkc06tqrXCwUy0UVG/hRFvSXeFe2Q62kSIYztmQrdfr3QgzzK30 xFo40IK6be574wKtVFYVS0wClIIJglXndkBkL5LUiPNouw2LE91pgxg2hj2gHgNa7/ItpUmcy6jx 9JwUBzwLHDcbTHx7Jnw8fNq4ewyA17jc+gsS9edGTpQ0aBVTNa2dSyKSi0jLZ5iQUsobNtG0uLFx YdhOERBA0nMrzGNYkuyZ0j9xIaouBdCm7Bdqy4Lq6Djb7JYRKwTKOcQWQ3mqbjIQetgaPxord5Wi fimMddDDVxW5XLTsXJArorpHAHJLvyUSyN1KcxHTu+95gDXsGwjRILqe3eA4rckI9fNQDjTkweqU El0iiX6OzM0QLTYjlsx2NiNqa4bYxsaSTK1Tx7/etR2rUbyAT9O+UeqeBiCzpjEwU4Y2ge8npO4A 4aqcwX9ziyS+yFwL1e9gbCoVasvM5Rdw5ujZgdbMASu4ECuUzTGYxGgMQIzwYKVQ2ysxvQwG5yeH ReBHgrYa2OxphF6wabIBQma4O315UhNgjKZa80WC1bokQksqIlyYFgLbHdSayad9K8swBP2EUNqR wAK6ulPgVi5VrherWF2O4ppnghJdh1EHWPIq3Gg0GlraECpXFj0Om0tEjUpVQJ49+zaslErla9TF M4p3gsUzVymYvXZcZiVde4g3Ig9UZWDmEZSJHNZkdvbAVAMReKpyKM+mxQqmEyRCSZJeWBKQi2LQ nExE6R5wT0BEwHFMFtFoPYVB0YK4tKFxWsms5OawPCZplC8EoteLbTaZnTSUNpsY2Ey1WEyjofBG 9K3MuWEzOnU4aFJwSVjiTOVI3mgIXMXYiOdhUJEqCRlTN1XpExgE/LXWa9zXakzLR0syznewYank wIY+AkVA7gUAsSICUU0zbv+t/GpyXFGKvKHP5dtEbsaZwRgrNi1LuqWc56Lr9z0MCrorEy2zePit 2ey9AruFnBOhPj27cFs1VXeU1kCwliuK2K2qXsZc4JYmUlRCTMHGlpGDXzTOBvgmqNDa4poDaRu7 lp1lEgoC4LRUKruTEWGLcFgyjAOfEAqrhNpUKeXYTupPb09aLaVbSTOWfDIs2Ra04TOwPTc7IDiR aS15/O7eEluKiJh4q8L8TQFjjaCB5eLYvQ1EOyJVKS2OjwDOYm2QEScD3BgxyMC8iQlp53CJbmIX D7baVgeffmXaPIyybIhlbndSi8pFKRwtT4FyqRFDbkWoLYwRASig5J+QbLhmnTX54F3EVDGCmjnb RH24l82BbY6CgtC2MV6SlcMYxQPkZGzUoaFK2wwN4t7xiIiIiIiIuOpQdtWpfwprahbOwg48WoBa G01Goio3K5YEiSxAmPDGAuMpV5QVqLzr7vtsallCW/uPlZAVcaIR3qyULePZfhXfrbgN5KKqnI4N 0EfhV2HoJXl5UXgIcjCLPNMgxBPfKjUIrCgYJbEdhX2CTyVMKdYdRYexERDBUQ0Ors/sfF/XJW1Q JHsNHBnUXa1rmlZToXHVQLJc8WyhjYGiDLo0FQqWVCZD0JywKzc0BgTYiCDLlbY6UugTMUR4Qca4 2x3yoEwOB2GEuhAAIMAKi1oicbNJ9khZ5GM4yC1SacjBY9kGLxvL0E0RvU3EvJPctpnWtMWDhiBb Cg1gOu4lyajMTtrSTPbK8D3fhKjtfVZa2udA/i61ktC6WQPdzbiS3jo1Y1FeUtRyoLYyeC6R6pmg 3z7Q0HcOArmtLdsFDSd0zzFs41k79KUy6fMWZ53ILQWvIyOQr7oz//9VFHrF3JFOFCQ3el/GAA== --===============1043074703==--