並行複製從庫發生自動重啟分析 背景 半同步複製從庫在晚上凌晨2點半發生自動重啟，另一個非同步複製從庫在第二天凌晨3點也發生了自動重啟。 分析 版本mysql 5.7.16 mysql show variables like '%slave_para%'; + + + | Variable_name | ...
並行複製從庫發生自動重啟分析
背景
半同步複製從庫在晚上凌晨2點半發生自動重啟，另一個非同步複製從庫在第二天凌晨3點也發生了自動重啟。
分析
版本mysql 5.7.16
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- 兩個發生自動重啟的從庫日誌中都出現了ibuf record inserted to page x:x ，通過查看space_id發現都是對應的同一張表(xxx.xx)，疑是晚上的定時任務對這張表做了大事務的操作。從庫的並行複製只有對併發提交的事務才會進行並行應用，對一個大事務，只有一個線程進行應用。
分析在從庫發生自動重啟的時間段里發現，產生了大事務
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
xxxx.xxxxw565330
DELETExxxx.xxxx23595
DELETExxxx.xxxxail24156
DELETExxxx.xxxx18475
INSERTxxxx.xxxxw_his576265
INSERTxxxx.xxxx_his23829
INSERTxxxx.xxxxail_his24539
INSERTxxxx.xxxxhis18709
6.向看源碼的朋友請教了下，得到了MySQL自動重啟的Stack Trace
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測試
主庫模擬一個大事務，看從庫是否有異常出現
環境
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;從庫出現大量類似生產環境中的日誌，但沒有模擬出從庫自動重啟的情況
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。但沒有復現出從庫發生自動重啟的情況。
建議：
- 儘量減少大事務的執行，拆分為小事務
- 從庫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
