問題背景

在5.6.29和5.7.11版本之前，當(dāng)binlog格式設(shè)置成mixed時，創(chuàng)建event事件中包含sysdate函數(shù)時，會導(dǎo)致復(fù)制中斷。

與此bug相關(guān)：https://bugs.mysql.com/bug.php?id=71859

場景重現(xiàn)

測試版本：mysql 5.6.23重現(xiàn)方法：分別設(shè)置statement、mixed、row格式執(zhí)行以下語句，mixed格式時會導(dǎo)致復(fù)制中斷，其他兩種格式不會造成復(fù)制中斷。

DELIMITER $$DROP EVENT IF EXISTS `MIS_CUMULATIVE_REV_EVENT`$$CREATE EVENT IF NOT EXISTS `MIS_CUMULATIVE_REV_EVENT`ON SCHEDULE EVERY 3 second STARTS sysdate()ON COMPLETION PRESERVEDO BEGINDECLARE EXIT HANDLER FOR SQLEXCEPTIONSELECT CONCAT('SQL EXCEPTION - TERMINATING EVENT FOR STORED PROCEDURE CALL');END$$

• statement 模式

set global binlog_format=statement;

設(shè)置5s延遲觀察下starts字段時間，復(fù)制正常，主從有差異

slave2 [localhost] {msandbox} (test) > change master to MASTER_DELAY=5;

• Row模式

set global binlog_format=row;

復(fù)制正常，主從有差異

start字段同樣有差異，因為sysdate函數(shù)是sql實際執(zhí)行時間；如果是now函數(shù)，start字段時間會是一樣的。

• mixed模式

set global binlog_format=mixed;

關(guān)閉延遲

mixed模式下產(chǎn)生的binlog日志

正常的statement 和row 模式

從這些截圖可知，在mixed模式下創(chuàng)建event時，在同一個事務(wù)內(nèi)即產(chǎn)生了DDL statement，也產(chǎn)生了額外寫入mysql.event表的row事件。

對于DDL語句在任何binlog格式下，都會以statement格式記錄。

mixed模式下遇到非復(fù)制安全函數(shù)會轉(zhuǎn)換成row模式。例如：sysdate()返回實際執(zhí)行時間而非調(diào)用時間與now函數(shù)有差異。

mysql> SELECT NOW(), SLEEP(2), NOW();+---------------------+----------+---------------------+| NOW() | SLEEP(2) | NOW() |+---------------------+----------+---------------------+| 2006-04-12 13:47:36 | 0 | 2006-04-12 13:47:36 |+---------------------+----------+---------------------+mysql> SELECT SYSDATE(), SLEEP(2), SYSDATE();+---------------------+----------+---------------------+| SYSDATE() | SLEEP(2) | SYSDATE() |+---------------------+----------+---------------------+| 2006-04-12 13:47:44 | 0 | 2006-04-12 13:47:46 |+---------------------+----------+---------------------+

問題分析

利用systemtap觀察下，create event時函數(shù)調(diào)用，定位為何產(chǎn)生了row事件。查看源碼中有哪些create_event函數(shù)

[root@10-186-21-66 ~]# stap -L 'process("/usr/local/mysql/bin/mysqld").function("create_event")'process("/usr/local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld").function("create_event@/export/home/pb2/build/sb_0-14249461-1422537824.58/mysqlcom-pro-5.6.23/sql/event_db_repository.cc:660") $this:class Event_db_repository* const $thd:struct THD* $parse_data:struct Event_parse_data* $create_if_not:bool $event_already_exists:bool* $table:struct TABLE* $sp:struct sp_head* $saved_mode:sql_mode_t $mdl_savepoint:class MDL_savepointprocess("/usr/local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld").function("create_event@/export/home/pb2/build/sb_0-14249461-1422537824.58/mysqlcom-pro-5.6.23/sql/event_queue.cc:200") $this:class Event_queue* const $thd:struct THD* $new_element:struct Event_queue_element* $created:bool* $__FUNCTION__:char[] constprocess("/usr/local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld").function("create_event@/export/home/pb2/build/sb_0-14249461-1422537824.58/mysqlcom-pro-5.6.23/sql/events.cc:307") $thd:struct THD* $parse_data:struct Event_parse_data* $if_not_exists:bool

共有以下3處

第1處：

/** Create a new event. @param[in,out] thd THD @param[in] parse_data Event's data from parsing stage @param[in] if_not_exists Whether IF NOT EXISTS was specified In case there is an event with the same name (db) and IF NOT EXISTS is specified, an warning is put into the stack. @sa Events::drop_event for the notes about locking, pre-locking and Events DDL. @retval FALSE OK @retval TRUE Error (reported)*/boolEvents::create_event(THD *thd, Event_parse_data *parse_data, bool if_not_exists)

第2處：

/** Creates an event record in mysql.event table. Creates an event. Relies on mysql_event_fill_row which is shared with ::update_event. @pre All semantic checks must be performed outside. This function only creates a record on disk. @pre The thread handle has no open tables. @param[in,out] thd THD @param[in] parse_data Parsed event definition @param[in] create_if_not TRUE if IF NOT EXISTS clause was provided to CREATE EVENT statement @param[out] event_already_exists When method is completed successfully set to true if event already exists else set to false @retval FALSE success @retval TRUE error*/boolEvent_db_repository::create_event(THD *thd, Event_parse_data *parse_data, bool create_if_not, bool *event_already_exists)

第3處：

/** Adds an event to the queue. Compute the next execution time for an event, and if it is still active, add it to the queue. Otherwise delete it. The object is left intact in case of an error. Otherwise the queue container assumes ownership of it. @param[in] thd thread handle @param[in] new_element a new element to add to the queue @param[out] created set to TRUE if no error and the element is added to the queue, FALSE otherwise @retval TRUE an error occured. The value of created is undefined, the element was not deleted. @retval FALSE success*/boolEvent_queue::create_event(THD *thd, Event_queue_element *new_element, bool *created)

利用systemtap觀察以下兩個函數(shù)調(diào)用情況

probe process("/usr/local/mysql/bin/mysqld").function("create_event") { printf(">>>>>>create_event"); print_ubacktrace();}probe process("/usr/local/mysql/bin/mysqld").function("set_current_stmt_binlog_format_row") { printf("+++++set_current_stmt_binlog_format_row"); print_ubacktrace();}

運(yùn)行stap -v event.stp，在另一個mysql終端執(zhí)行創(chuàng)建event語句

>>>>>>create_event 0x7d36b1 : _ZN6Events12create_eventEP3THDP16Event_parse_datab+0x21/0x340 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x727984 : _Z21mysql_execute_commandP3THD+0x5804/0x6ce0 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x729178 : _Z11mysql_parseP3THDPcjP12Parser_state+0x318/0x420 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x72a4cb : _Z16dispatch_command19enum_server_commandP3THDPcj+0xbcb/0x28f0 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x72c2c7 : _Z10do_commandP3THD+0xd7/0x1c0 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x6f3ee6 : _Z24do_handle_one_connectionP3THD+0x116/0x1b0 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x6f3fc5 : handle_one_connection+0x45/0x60 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x9b22f6 : pfs_spawn_thread+0x126/0x140 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x7ff7b42859d1 [/lib64/libpthread-2.12.so+0x79d1/0x219000]>>>>>>create_event 0x8bae27 : _ZN19Event_db_repository12create_eventEP3THDP16Event_parse_databPb+0x17/0x2b0 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x7d377f : _ZN6Events12create_eventEP3THDP16Event_parse_datab+0xef/0x340 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x727984 : _Z21mysql_execute_commandP3THD+0x5804/0x6ce0 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x729178 : _Z11mysql_parseP3THDPcjP12Parser_state+0x318/0x420 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x72a4cb : _Z16dispatch_command19enum_server_commandP3THDPcj+0xbcb/0x28f0 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x72c2c7 : _Z10do_commandP3THD+0xd7/0x1c0 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x6f3ee6 : _Z24do_handle_one_connectionP3THD+0x116/0x1b0 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x6f3fc5 : handle_one_connection+0x45/0x60 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x9b22f6 : pfs_spawn_thread+0x126/0x140 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x7ff7b42859d1 [/lib64/libpthread-2.12.so+0x79d1/0x219000]+++++set_current_stmt_binlog_format_row 0x8e6556 : _ZN3THD21decide_logging_formatEP10TABLE_LIST+0x606/0xa60 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x6d4e68 : _Z11lock_tablesP3THDP10TABLE_LISTjj+0xe8/0x860 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x6de9d2 : _Z20open_and_lock_tablesP3THDP10TABLE_LISTbjP19Prelocking_strategy+0xa2/0xe0 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x8ba6a1 : _ZN19Event_db_repository16open_event_tableEP3THD13thr_lock_typePP5TABLE+0x101/0x1d0 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x8bae94 : _ZN19Event_db_repository12create_eventEP3THDP16Event_parse_databPb+0x84/0x2b0 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x7d377f : _ZN6Events12create_eventEP3THDP16Event_parse_datab+0xef/0x340 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x727984 : _Z21mysql_execute_commandP3THD+0x5804/0x6ce0 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x729178 : _Z11mysql_parseP3THDPcjP12Parser_state+0x318/0x420 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x72a4cb : _Z16dispatch_command19enum_server_commandP3THDPcj+0xbcb/0x28f0 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x72c2c7 : _Z10do_commandP3THD+0xd7/0x1c0 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x6f3ee6 : _Z24do_handle_one_connectionP3THD+0x116/0x1b0 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x6f3fc5 : handle_one_connection+0x45/0x60 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x9b22f6 : pfs_spawn_thread+0x126/0x140 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x7ff7b42859d1 [/lib64/libpthread-2.12.so+0x79d1/0x219000]>>>>>>create_event 0x8bc64e : _ZN11Event_queue12create_eventEP3THDP19Event_queue_elementPb+0x1e/0xe0 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x7d3916 : _ZN6Events12create_eventEP3THDP16Event_parse_datab+0x286/0x340 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x727984 : _Z21mysql_execute_commandP3THD+0x5804/0x6ce0 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x729178 : _Z11mysql_parseP3THDPcjP12Parser_state+0x318/0x420 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x72a4cb : _Z16dispatch_command19enum_server_commandP3THDPcj+0xbcb/0x28f0 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x72c2c7 : _Z10do_commandP3THD+0xd7/0x1c0 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x6f3ee6 : _Z24do_handle_one_connectionP3THD+0x116/0x1b0 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x6f3fc5 : handle_one_connection+0x45/0x60 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld] 0x9b22f6 : pfs_spawn_thread+0x126/0x140 [...local/mysql-advanced-5.6.23-linux-glibc2.5-x86_64/bin/mysqld]

基本可知函數(shù)調(diào)用順序 Event::create_event -> Event_db_repository::create_event -> decide_logging_format -> set_current_stmt_binlog_format_row_if_mixed -> Event_queue::create_event

binlog.cc decide_logging_format()

if (lex->is_stmt_unsafe() || lex->is_stmt_row_injection() || (flags_write_all_set & HA_BINLOG_STMT_CAPABLE) == 0) { /* log in row format! */ set_current_stmt_binlog_format_row_if_mixed(); }

因為sysdate()是非安全函數(shù)，所以調(diào)用了set_current_stmt_binlog_format_row_if_mixed()。

問題應(yīng)該出在set_current_stmt_binlog_format_row_if_mixed

[root@10-186-21-66 ~]# addr2line -e /usr/local/mysql/bin/mysqld 0x8e6556/export/home/pb2/build/sb_0-14249461-1422537824.58/mysqlcom-pro-5.6.23/sql/sql_class.h:3669

sql_class.h

inline void set_current_stmt_binlog_format_row_if_mixed() { DBUG_ENTER("set_current_stmt_binlog_format_row_if_mixed"); /* This should only be called from decide_logging_format. @todo Once we have ensured this, uncomment the following statement, remove the big comment below that, and remove the in_sub_stmt==0 condition from the following 'if'. */ /* DBUG_ASSERT(in_sub_stmt == 0); */ /* If in a stored/function trigger, the caller should already have done the change. We test in_sub_stmt to prevent introducing bugs where people wouldn't ensure that, and would switch to row-based mode in the middle of executing a stored function/trigger (which is too late, see also reset_current_stmt_binlog_format_row()); this condition will make their tests fail and so force them to propagate the lex->binlog_row_based_if_mixed upwards to the caller. */ if ((variables.binlog_format == BINLOG_FORMAT_MIXED) && (in_sub_stmt == 0)) set_current_stmt_binlog_format_row(); DBUG_VOID_RETURN; }省略部分代碼 inline void set_current_stmt_binlog_format_row() { DBUG_ENTER("set_current_stmt_binlog_format_row"); current_stmt_binlog_format= BINLOG_FORMAT_ROW; DBUG_VOID_RETURN; }

從上述代碼可以看出，此函數(shù)判斷binlog格式是mixed時則調(diào)用set_current_stmt_binlog_format_row，

修復(fù)補(bǔ)丁中，在create_event 和update_event 函數(shù)中，在調(diào)用Event_db_repository::create_event前設(shè)置binlog格式為statement，再執(zhí)行Event_db_repository::create_event時就不會產(chǎn)生row事件了。

@@ -308,6 +308,7 @@ Events::create_event(THD *thd, Event_parse_data *parse_data, { bool ret; bool save_binlog_row_based, event_already_exists;+ ulong save_binlog_format= thd->variables.binlog_format; DBUG_ENTER("Events::create_event"); if (check_if_system_tables_error())@@ -341,10 +342,15 @@ Events::create_event(THD *thd, Event_parse_data *parse_data, */ if ((save_binlog_row_based= thd->is_current_stmt_binlog_format_row())) thd->clear_current_stmt_binlog_format_row();+ thd->variables.binlog_format= BINLOG_FORMAT_STMT;+ if (lock_object_name(thd, MDL_key::EVENT, parse_data->dbname.str, parse_data->name.str))- DBUG_RETURN(TRUE);+ {+ ret= true;+ goto err;+ } /* On error conditions my_error() is called so no need to handle here */ if (!(ret= db_repository->create_event(thd, parse_data, if_not_exists,@@ -399,10 +405,12 @@ Events::create_event(THD *thd, Event_parse_data *parse_data, } } }+err: /* Restore the state of binlog format */ DBUG_ASSERT(!thd->is_current_stmt_binlog_format_row()); if (save_binlog_row_based) thd->set_current_stmt_binlog_format_row();+ thd->variables.binlog_format= save_binlog_format;

完整補(bǔ)丁見：git log -p 112899f406d2f1f838a180669781a8973ef3e343

結(jié)論

1. 升級到5.6.29版本或改用row模式

2. 如果event 的dml語句中出現(xiàn)類似sysdate()，在mixed模式下并不會造成數(shù)據(jù)不一致，會自動轉(zhuǎn)成row模式

3. 在主從環(huán)境下創(chuàng)建event_scheduler，slave默認(rèn)是禁用狀態(tài)SLAVESIDE_DISABLED。應(yīng)考慮主從切換后，原主從的event_scheduler狀態(tài)，避免產(chǎn)生意外行為，比如 new slave 寫入數(shù)據(jù)。

總結(jié)

以上是生活随笔為你收集整理的mysql function_MySQL里event_ scheduler导致复制中断的故障分析-爱可生的全部內(nèi)容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網(wǎng)站內(nèi)容還不錯，歡迎將生活随笔推薦給好友。