## 問題現象 研發同學執行下列語句序列 ~~~ stop slave; set global slave_parallel_workers=0; start slave; ~~~ 后程序 hang 住，不一會返回了2013 錯誤，即服務器連接異常中斷，檢查 mysqld error log, 發現在mysqld在將并行復制轉化為串行復制的過程中異常 crash，其中錯誤信息為： ~~~ [ERROR] Error reading slave worker configuration [ERROR] Error creating relay log info: Failed to initialize the worker info structure. ~~~ crash 堆棧為： ~~~ #0 0x000000395fc0c69c in pthread_kill () from /lib64/libpthread.so.0 #1 0x00000000006b2425 in handle_fatal_signal (sig=11) #2 <signal handler called> #3 remove_info (this=0x2b19b775b000) #4 Relay_log_info::mts_finalize_recovery #5 0x0000000000920ec3 in slave_start_workers #6 0x0000000000921c03 in handle_slave_sql #7 0x000000395fc07851 in start_thread () from /lib64/libpthread.so.0 #8 0x000000395f4e767d in clone () from /lib64/libc.so.6 ~~~ 結合源碼仔細分析上面的錯誤信息不難發現，在啟動 SQL 線程初始化 worker 信息的過程中失敗，從而引起了空指針異常。 ## 問題復現 一個簡單的 start slave 就能夠導致 mysqld crash？應該不會那么簡單，編寫 testcase，試圖在本地重現以上問題，測例如下： ~~~ --source include/master-slave.inc --source include/not_embedded.inc --source include/not_windows.inc --connection slave stop slave; set global slave_parallel_workers= 1; start slave; stop slave; set global slave_parallel_workers= 0; start slave; --source include/rpl_end.inc ~~~ 運行后果然沒有能夠重現問題，根據研發的同學反映在中斷之前有一段時間命令是 hang 住的，于是斷定 hang 問題與 crash 應該存在著聯系，以上測例并不能將問題重現，于是與求助研發同學進行聯調，在 hang 住的時候采集到了以下關鍵 pt-pmp 信息： ~~~ pthread_cond_wait,os_cond_wait(os0sync.cc:214),os_event_wait_low(os0sync.cc:610),lock_wait_suspend_thread(lock0wait.cc:323),row_mysql_handle_errors(row0mysql.cc:1040),row_search_for_mysql(row0sel.cc:5064),ha_innobase::index_read(ha_innodb.cc:7668),ha_innobase::index_first(ha_innodb.cc:8041),ha_innobase::rnd_next(ha_innodb.cc:8138),handler::ha_rnd_next(handler.cc:2812),Rpl_info_table_access::scan_info(rpl_info_table_access.cc:287),Rpl_info_table::do_check_info(rpl_info_table.cc:444),Rpl_info_factory::decide_repository(rpl_info_factory.cc:567),Rpl_info_factory::create_worker(rpl_info_factory.cc:419),Relay_log_info::mts_finalize_recovery(rpl_rli.cc:328),slave_start_workers(rpl_slave.cc:6294),handle_slave_sql(rpl_slave.cc:6523),pfs_spawn_thread(pfs.cc:1858),start_thread(libpthread.so.0),clone(libc.so.6) pthread_cond_wait,safe_cond_wait(thr_mutex.c:240),inline_mysql_cond_wait(mysql_thread.h:1151),start_slave_thread(rpl_slave.cc:1502),start_slave_threads(rpl_slave.cc:1587),start_slave(rpl_slave.cc:9485),start_slave(rpl_slave.cc:548),start_slave_cmd(rpl_slave.cc:690),mysql_execute_command(sql_parse.cc:3576),mysql_parse(sql_parse.cc:6958),dispatch_command(sql_parse.cc:1583),do_command(sql_parse.cc:1102),do_handle_one_connection(sql_connect.cc:1006),handle_one_connection(sql_connect.cc:922),pfs_spawn_thread(pfs.cc:1858),start_thread(libpthread.so.0),clone(libc.so.6) ~~~ 可以看到在 start slave 后，sql thread 讀取 slave_worker_info 初始化 worker 的過程中遇到了鎖等待問題，于是斷定 relay_log_info_repository=’table’，并且有其它的線程對 slave_worker_info中的記錄上了Ｘ鎖，但是是哪個線程確不是很清楚，因為只看到了一個線程在訪問 slave_worker_info 表，然后再一次在hang的時候執行了下列操作： ~~~ mysql> SELECT r.trx_id waiting_trx_id, r.trx_mysql_thread_id waiting_thread, left(r.trx_query,20) waiting_query, concat(concat(lw.lock_type, ' '), lw.lock_mode) waiting_for_lock, b.trx_id blocking_trx_id, b.trx_mysql_thread_id blocking_thread, left(b.trx_query,20) blocking_query, concat(concat(lb.lock_type, ' '), lb.lock_mode) blocking_lock FROM information_schema.innodb_lock_waits w INNER JOIN information_schema.innodb_trx b ON b.trx_id = w.blocking_trx_id INNER JOIN information_schema.innodb_trx r ON r.trx_id = w.requesting_trx_id INNER JOIN information_schema.innodb_locks lw ON lw.lock_trx_id = r.trx_id INNER JOIN information_schema.innodb_locks lb ON lb.lock_trx_id = b.trx_id\G *************************** 1. row *************************** waiting_trx_id: 1313 waiting_thread: 12 waiting_query: NULL waiting_for_lock: RECORD S blocking_trx_id: 1312 blocking_thread: 6 blocking_query: start slave blocking_lock: RECORD X 1 row in set (0.00 sec) mysql> show processlist; +----+-------------+-----------------+-------+---------+------+-----------------------------------------+------------------+ | Id | User | Host | db | Command | Time | State | Info | +----+-------------+-----------------+-------+---------+------+-----------------------------------------+------------------+ | 2 | root | localhost:57292 | test | Sleep | 16 | | | | 3 | root | localhost:57293 | test | Sleep | 16 | | | | 6 | root | localhost:57299 | test | Query | 15 | Waiting for slave thread to start | start slave | | 7 | root | localhost:57300 | test | Sleep | 16 | | | | 11 | system user | | NULL | Connect | 15 | Connecting to master | | | 12 | system user | | mysql | Connect | 15 | Waiting for the next event in relay log | | | 13 | root | localhost | test | Query | 0 | init | show processlist | +----+-------------+-----------------+-------+---------+------+-----------------------------------------+------------------+ 7 rows in set (0.00 sec) ~~~ 其中 information_schema.innodb_lock_waits，information_schema.innodb_locks，information_schema.innodb_trx 的信息可參考[官方文檔](http://dev.mysql.com/doc/refman/5.6/en/innodb-i_s-tables.html)。 從以上信息可以清楚地看到 start slave（blocking_thread: 6）獲取了 slave_worker_info 中行記錄的Ｘ鎖，而 sql thread 線程 (waiting_thread: 12) 在獲取 S 鎖失敗引起鎖等待，進而獲取信息失敗返回NULL, 進而造成了空指針引用，mysqld crash，此時 start slave 與 sql thread 的資源竟爭如下： * start slave thread 獲取 slave_work_info 記錄的 X 鎖，等待 sql thread 已啟動的信號量，然后繼續運行； * sql thread 被啟動后，需要根據 slave_worker_info 為進行初始化，因此等待獲取相關行的Ｓ鎖; 因此，start slave thread 與 sql thread 形成了死鎖，分析到了現在還有兩個疑問沒有解釋： * start slave 為什么會訪問 slave_worker_info 且一直持有鎖資源? * 為什么本地在測試的時候加上 relay_log_info_repository 的設置還是不能重現呢？ 繼續研究，打開general log 后，發現有許多的 set autocommit=0 的語句，于是感覺可能是 autocommit 的問題，修改后測例如下： ~~~ --source include/master-slave.inc --source include/not_embedded.inc --source include/not_windows.inc --connection slave stop slave; set global relay_log_info_repository='table'; set global master_info_repository='table'; set global slave_parallel_workers= 1; start slave; --sleep 1 stop slave; set autocommit=0; set global slave_parallel_workers= 0; start slave; --source include/rpl_end.inc ~~~ 運行后問題終于重現。。。 ## 問題原因 有了以上的分析過程，不難看出，在 1) autocommit=0 && 2) relay_log_info_repository=’table’ && 3) 并行復制切換到串行復制時，就會觸發此 bug, 原因有以下兩個： * start slave thread 在等待 sql thread 的過程中沒有釋放其占用的鎖資源； * sql thread 在初始化 worker 信息時沒有處理獲取信息失敗的情況。 回到上面的問題： * start slave 為什么會訪問 slave_worker_info 且一直持有鎖資源? 答：start slave 的過程中需要初始化 worker信息，執行 crash recovery 等一系列操作，對于已經執行的不再執行，對于沒有執行的繼續執行，詳情見`global_init_info`，`mts_recovery_groups`?等函數，在autocommit=0 的情況下，start slave thread 沒有commit 或者執行完之前是不會釋放鎖資源的。 * 為什么本地在測試的時候加上 relay_log_info_repository 的設置還是不能重現呢？ 答：本地在測試的時候，autocommit 默認值為1，因此不會重現。 在上鎖方面為什么會上寫鎖，可以參考：`Rpl_info_table::do_init_info`?函數； * 影響范圍 經官方驗證，5.6, 5.6.26, 5.6.28, 5.7.10 均存在此 bug。 ## 問題擴展 在排查問題的過程中發現 start slave 時會自動提交當前 session 之前已經操作的數據，然后開啟一個新的事務，所以在使用 start slave 時要注意這個問題！