背景
半同步復制從庫在晚上凌晨2點半發生異常crash，另一個異步復制從庫在第二天凌晨3點也發生了異常crash。
版本
mysql 5.7.16
redhat 6.8
mysql> show variables like '%slave_para%';
+------------------------+---------------+
| Variable_name | Value |
+------------------------+---------------+
| slave_parallel_type | LOGICAL_CLOCK |
| slave_parallel_workers | 16 |
+------------------------+---------------+
分析
-
mysqld服務在以mysqld_safe守護進程啟動的情況下，在發生mysqld異常情況（比如OOM）會自動拉起mysqld服務，但已確認兩個從庫實例messages中無與OOM相關的日志。
-
從監控中發現，兩個從庫與Seconds_Behind_Master沒有很高的異常上升。
-
參數slave_pending_jobs_size_max 在多線程復制時，在隊列中Pending的事件所占用的最大內存，默認為16M，如果內存富余，或者延遲較大時，可以適當調大;注意這個值要比主庫的max_allowed_packet大。
參考官方文檔：slave_pending_jobs_size_max -
兩個發生異常crash的從庫日志中都出現了ibuf record inserted to page x:x ，通過查看space_id發現都是對應的同一張表(a_xxx.join_acct_flow)，疑是晚上的定時任務對這張表做了大事務的操作。從庫的並行復制只有對並發提交的事務才會進行並行應用，對一個大事務，只有一個線程進行應用。
-
分析在從庫發生異常crash的時間段里發現，產生了大事務
mysqlbinlog -v -v --base64-output=decode-rows
--start-datetime='2018-04-03 02:47:22' --stop-datetime='2018-04-03 02:48:26' /data/mysql/mysql-bin.003446 | awk
'/###/{if($0~/UPDATE|INSERT|DELETE/)count[$2""$NF]++}END{for(i in
count)print i,"\t",count[i]}' | column -t | sort -k3nr | more
DELETE`a_xxx`.`xxx_acct_flow` 565330
DELETE`a_xxx`.`xxx_bfj_flow` 23595
DELETE`a_xxx`.`xxx_loan_detail` 24156
DELETE`a_xxx`.`xxx_pay_log` 18475
INSERT`a_xxx`.`xxx_acct_flow_his` 576265
INSERT`a_xxx`.`xxx_bfj_flow_his` 23829
INSERT`a_xxx`.`xxx_loan_detail_his` 24539
INSERT`a_xxx`.`xxx_pay_log_his` 18709
- 向看源碼的朋友請教了下，得到了MySQL異常crash的Stack Trace
獲取內存地址放入/tmp/err.log 中
[0xf1dff5]
[0x79d3b4]
[0x358c00f7e0]
[0x358bc325e5]
[0x358bc33dc5]
[0x1159d65]
[0x115e8b3]
[0x102b4d1]
[0x102f531]
[0x1033b29]
[0x11a59a1]
[0x1200afb]
[0x110db48]
[0x358c007aa1]
[0x358bce8aad]
nm -D -n /usr/local/mysql/bin/mysqld>/tmp/mysqld.sym
resolve_stack_dump -s /tmp/mysqld.sym -n /tmp/err.log |c++filt | less
0xf1dff5 my_print_stacktrace + 53
0x79d3b4 handle_fatal_signal + 1188
0x358c00f7e0 _end + -1978652160
0x358bc325e5 _end + -1982703611
0x358bc33dc5 _end + -1982697499
0x1159d65 ut_dbg_assertion_failed(char const*, char const*, unsigned long) + 170
0x115e8b3 ib::fatal::~fatal() + 179
0x102b4d1 ibuf_print(_IO_FILE*) + 881
0x102f531 ibuf_update_free_bits_low(buf_block_t const*, unsigned long, mtr_t*) + 3905
0x1033b29 ibuf_merge_or_delete_for_page(buf_block_t*, page_id_t const&, page_size_t const*, unsigned long) + 2825
0x11a59a1 buf_page_io_complete(buf_page_t*, bool) + 1249
0x1200afb fil_aio_wait(unsigned long) + 347
0x110db48 io_handler_thread + 200
0x358c007aa1 _end + -1978684223
0x358bce8aad _end + -1981956915
- 可見，在mysqld發生異常crash時的內部函數是ibuf_update_free_bits_low，ibuf_merge_or_delete_for_page（在做change buffer的merge操作
- 貌似是由於主實例執行了delete大事務，從實例多線程進行apply（change buffer merge）出現的問題導致mysqld發生crash?
測試
主庫模擬一個大事務，看從庫是否有異常出現
環境
centos 7.4
mysql5.7.19
從庫並行復制線程 8
從庫slave_pending_jobs_size_max 設置比主庫 max_allowed_packet大
主庫
mysql> desc sbtest1;
+-----+-----------+-----+-----+------+----------------+
| id | int(11) | NO | PRI | NULL | auto_increment |
| k | int(11) | NO | MUL | 0 | |
| c | char(120) | NO | | | |
| pad | char(60) | NO | | | |
| id3 | int(11) | YES | | NULL | |
| id5 | int(11) | YES | | NULL | |
+-----+-----------+-----+-----+------+----------------+
select count(*) from sbtest1;
mysql> show variables like 'max_allowed_packet%';
+--------------------+----------+
| max_allowed_packet | 16777216 | 16M
+--------------------+----------+
從庫
mysql> show variables like '%slave_para%';
+------------------------+---------------+
| Variable_name | Value |
+------------------------+---------------+
| slave_parallel_type | LOGICAL_CLOCK |
| slave_parallel_workers | 8 |
+------------------------+---------------+
mysql> show variables like '%slave_pending_jobs%';
+-----------------------------+----------+
| Variable_name | Value |
+-----------------------------+----------+
| slave_pending_jobs_size_max | 67108864 | 64M
+-----------------------------+----------+
主庫執行
UPDATE sbtest1 SET c=REPEAT(UUID(),2) where id<100000;
從庫出現大量類似生產環境中的日志，但沒有模擬出從庫異常crash的情況
Note] Multi-threaded slave: Coordinator has waited 208341 times hitting slave_pending_jobs_size_max; current event size = 8044
Note] Multi-threaded slave: Coordinator has waited 208351 times hitting slave_pending_jobs_size_max; current event size = 8044
Note] Multi-threaded slave: Coordinator has waited 208361 times hitting slave_pending_jobs_size_max; current event size = 8044
Note] Multi-threaded slave: Coordinator has waited 208371 times hitting slave_pending_jobs_size_max; current event size = 8044
Note] Multi-threaded slave: Coordinator has waited 208381 times hitting slave_pending_jobs_size_max; current event
結論
從庫開啟並行復制，主庫執行大事務，從庫日志會出現大量中 Coordinator has waited。但沒有復現出從庫發生異常crash的情況。
建議：
- 盡量減少大事務的執行，拆分為小事務
- 從庫slave_pending_jobs_size_max 變量設置比主庫max_allowed_packet大些
- 可設置binlog_rows_query_log_events = 1（可以動態開啟），DDL,DML會以語句形式在binlog中記錄，方便分析binlog
- crash問題后續可以多保留一些日志，再次復現時好分析些
- 已給官方提了bug了，鏈接地址為 http://bugs.mysql.com/90342