問題背景

在5.6.29和5.7.11版本之前，當binlog格式設置成mixed時，創建event事件中包含sysdate函數時，會導致復制中斷。

與此bug相關：https://bugs.mysql.com/bug.php?id=71859

場景重現

測試版本：mysql 5.6.23重現方法：分別設置statement、mixed、row格式執行以下語句，mixed格式時會導致復制中斷，其他兩種格式不會造成復制中斷。

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;

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

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

• Row模式

set global binlog_format=row;

復制正常，主從有差異

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

• mixed模式

set global binlog_format=mixed;

關閉延遲

mixed模式下產生的binlog日志

正常的statement 和row 模式

從這些截圖可知，在mixed模式下創建event時，在同一個事務內即產生了DDL statement，也產生了額外寫入mysql.event表的row事件。

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

mixed模式下遇到非復制安全函數會轉換成row模式。例如：sysdate()返回實際執行時間而非調用時間與now函數有差異。

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時函數調用，定位為何產生了row事件。查看源碼中有哪些create_event函數

[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觀察以下兩個函數調用情況

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();}

運行stap -v event.stp，在另一個mysql終端執行創建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]

基本可知函數調用順序 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()是非安全函數，所以調用了set_current_stmt_binlog_format_row_if_mixed()。

問題應該出在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; }

從上述代碼可以看出，此函數判斷binlog格式是mixed時則調用set_current_stmt_binlog_format_row，

修復補丁中，在create_event 和update_event 函數中，在調用Event_db_repository::create_event前設置binlog格式為statement，再執行Event_db_repository::create_event時就不會產生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;

完整補丁見：git log -p 112899f406d2f1f838a180669781a8973ef3e343

結論

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

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

3. 在主從環境下創建event_scheduler，slave默認是禁用狀態SLAVESIDE_DISABLED。應考慮主從切換后，原主從的event_scheduler狀態，避免產生意外行為，比如 new slave 寫入數據。

總結

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

如果覺得生活随笔網站內容還不錯，歡迎將生活随笔推薦給好友。