MySQL刪除表時I/O錯誤的原因分析與解決
問題現象
最近使用sysbench測試MySQL，由於測試時間較長，寫了一個指令碼按prepare->run->cleanup的順序在後臺跑著。跑完後察看日誌發現一個問題，MySQL服務的錯誤日誌中出現多條類似以下資訊的報錯：
[ERROR] InnoDB: Trying to do I/O to a tablespace which does not exist. I/O type: read,page: [page id: space=32,page number=57890],I/O length: 16384 bytes。
看起來是I/O出現了錯誤，但MySQL程序並未崩潰，sysbench客戶端也沒有報錯。
發現問題過程
根據報錯的時間記錄以及指令碼輸出的各個階段的時間點對比，確定了當時指令碼正在執行的命令為：
sysbench --tables=100 --table-size=4000000 --threads=50 --mysql-db=sbtest --time=300 oltp_delete cleanup
重新手動執行一遍這個用例，卻沒有再出現同樣的情況。但是用指令碼執行卻依然能夠發現這個錯誤資訊。初步懷疑是run和cleanup之間不能間隔太久才會觸發這個問題。由於執行一遍100G資料量的時間較長，重現代價較大，先嚐試縮減用例資料量。將—table-size=4000000修改為2000000，此時執行指令碼，又不會觸發這個問題了，最後將—table-size=3000000可以穩定觸發又能減少部分重現時間。為了確認是否間隔太長會導致不能復現，修改指令碼在run和cleanup兩個階段之間sleep 10秒，果然不會觸發這個錯誤資訊。修改為sleep 5秒則還能觸發，不過報錯條數已有所減少。
問題調查
察看對應版本mysql5.7.22的程式碼，發現這個報錯只有一個位置：fil0fil.cc檔案的第5578行fil_io()函式內。 直接使用gdb除錯，在這個位置加上斷點，並執行可復現的指令碼，得到以下堆疊：
(gdb) bt #0 fil_io (type=...,sync=sync@entry=false,page_id=...,page_size=...,byte_offset=byte_offset@entry=0,len=16384,buf=0x7f9ead544000,message=message@entry=0x7f9ea8ce9c78) at mysql-5.7.22/storage/innobase/fil/fil0fil.cc:5580 #1 0x00000000010f99fa in buf_read_page_low (err=0x7f9ddaffc72c,sync=<optimized out>,type=0,mode=<optimized out>,unzip=true) at mysql-5.7.22/storage/innobase/buf/buf0rea.cc:195 #2 0x00000000010fc5fa in buf_read_ibuf_merge_pages (sync=sync@entry=false,space_ids=space_ids@entry=0x7f9ddaffc7e0,page_nos=page_nos@entry=0x7f9ddaffc7a0,n_stored=2) at mysql-5.7.22/storage/innobase/buf/buf0rea.cc:834 #3 0x0000000000f3a86c in ibuf_merge_pages (n_pages=n_pages@entry=0x7f9ddaffce30,sync=sync@entry=false) at mysql-5.7.22/storage/innobase/ibuf/ibuf0ibuf.cc:2552 #4 0x0000000000f3a94a in ibuf_merge (sync=false,sync=false,n_pages=0x7f9ddaffce30) at mysql-5.7.22/storage/innobase/ibuf/ibuf0ibuf.cc:2656 #5 ibuf_merge_in_background (full=full@entry=false) at mysql-5.7.22/storage/innobase/ibuf/ibuf0ibuf.cc:2721 #6 0x000000000102bcf4 in srv_master_do_active_tasks () at mysql-5.7.22/storage/innobase/srv/srv0srv.cc:2132 #7 srv_master_thread (arg=<optimized out>) at mysql-5.7.22/storage/innobase/srv/srv0srv.cc:2383 #8 0x00007fa003eeddc5 in start_thread () from /lib64/libpthread.so.0 #9 0x00007fa002aab74d in clone () from /lib64/libc.so.6
很明顯這是後臺執行緒在做insert buffer merge操作。此時發現space->stop_new_ops為true，也就是要處理的頁面所屬的space正在被刪除。為什麼會去操作正在被刪除的space呢？這需要調查下insert buffer功能、insert buffer merge的流程以及刪除表的流程。
insert buffer背景知識
insert buffer是一種特殊的資料結構（B+ tree），當輔助索引頁面不在緩衝池中時，它會將更改快取起來，稍後在頁面被其他讀取操作載入到緩衝池中時合併。MySQL最初引進這個功能的時候只能快取insert操作，所以叫做insert buffer，現在這些操作可以是 INSERT,UPDATE,or DELETE(DML)，所以改叫做change buffer了（本文依然以insert buffer描述），但原始碼中依然以ibuf作為標識。這個功能把若干對同一頁面的更新快取起來，合併為一次性更新操作，減少了IO，並轉化隨機IO為順序IO,這樣可以避免隨機IO帶來效能損耗，提高資料庫的寫效能。
相關insert buffer merge邏輯
當buffer page讀入buffer pool時，就會進行insert buffer merge。主要有幾個場景會出現merge過程：
- 當頁面被讀入緩衝池時，讀取完成後先進行ibuf的merge，然後頁面才可用；
- merge操作作為後臺任務執行。 innodb_io_capacity引數可設定InnoDB後臺任務每次merge過程的頁面數上限；
- 在崩潰恢復期間，當索引頁被讀入緩衝池時，將執行對應頁的insert buffer merge；
- insert buffer具有永續性，系統崩潰不會導致它失效。重啟後，insert buffer merge操作將恢復正常；
- 伺服器關閉時可使用—innodb-fast-shutdown = 0強制進行ibuf的完全合併。
我們這次的問題很明顯屬於第二種情況。innodb主執行緒(svr_master_thread）會每隔一秒主動進行一次insert buffer的merge操作。先判斷過去1s之內伺服器是否發生過活動（插入元組到頁面、undo表上的行操作等），如果發生過，則merge的最大頁面數為innodb_io_capacity設定的5%。如果沒有則merge的最大頁面數為innodb_io_capacity設定的值。
innodb主執行緒(svr_master_thread）merge的主流程如下：
- 主執行緒從ibuf樹的葉子節點讀取頁號和space號，並記錄到一個二元陣列中（未加鎖）；
- 主執行緒對二元組中space進行檢測是否在表空間快取中，如不在，說明已經被刪除了，刪除對應ibuf的記錄；
- 主執行緒判斷是否對一個正在刪除的space進行非同步讀取操作，如果是，報錯，並刪除對應ibuf的記錄，轉到過程2繼續下一個陣列元素的判斷；
- 如果一切判斷正常，主執行緒發出async io請求，async讀取需要被merge的索引頁面；
- I/O handler 執行緒，在接受到完成的async I/O之後，進行merge操作；
- 進行merge的時候呼叫fil_space_acquire對space->n_pending_ops進行自增。避免刪除操作併發；
- 執行完畢後呼叫fil_space_release對space->n_pending_ops進行自減。
相關刪除表的邏輯
- 對fil_system->mutex加鎖，設定sp->stop_new_ops = true，標記space正在刪除，不允許對它進行新操作，然後對fil_system->mutex解鎖；
- 對fil_system->mutex加鎖，檢測space->n_pending_ops，對fil_system->mutex解鎖。如果檢測到大於0，意味著還有依賴的操作未完成，睡眠20ms後重試；
- 對fil_system->mutex加鎖，檢測space->n_pending_flushes和(*node)->n_pending ，對fil_system->mutex解鎖。如果檢測到大於0，意味著還有依賴的I/O未完成，睡眠20ms後重試；
- 此時認為已經沒有衝突的操作了，刷出所有髒頁面或刪除所有給定的表空間的頁面；
- 從表空間快取刪除指定space的記錄；
- 刪除對應資料檔案。
問題結論
情況很明確了，主執行緒獲取ibuf的（space，page）的過程與刪除操作執行的過程並沒有鎖保證互斥，只有async I/O完成之後的merge操作與刪除操作才有互斥。如果後臺執行緒開始ibuf merge並已經執行過了第2步的檢測，但還沒有執行到第3步檢測，此時使用者執行緒開始做刪除表的操作，並設定好stop_new_ops標記但還沒有執行到第5步刪除表空間快取，就會出現這個錯誤資訊。兩執行緒的互動如下圖所示：
不出意外的話，在打中斷點時必然有執行緒在執行對應表的刪除操作。果然我們可以發現如下堆疊：
Thread 118 (Thread 0x7f9de0111700 (LWP 5234)): #0 0x00007fa003ef1e8e in pthread_cond_broadcast@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 #1 0x0000000000f82f41 in broadcast (this=0xd452ef8) at mysql-5.7.22/storage/innobase/os/os0event.cc:184 #2 set (this=0xd452ef8) at mysql-5.7.22/storage/innobase/os/os0event.cc:75 #3 os_event_set (event=0xd452ef8) at mysql-5.7.22/storage/innobase/os/os0event.cc:483 #4 0x00000000010ec8a4 in signal (this=<optimized out>) at mysql-5.7.22/storage/innobase/include/ut0mutex.ic:105 #5 exit (this=<optimized out>) at mysql-5.7.22/storage/innobase/include/ib0mutex.h:690 #6 exit (this=<optimized out>) at mysql-5.7.22/storage/innobase/include/ib0mutex.h:961 #7 buf_flush_yield (bpage=<optimized out>,buf_pool=<optimized out>) at mysql-5.7.22/storage/innobase/buf/buf0lru.cc:405 #8 buf_flush_try_yield (processed=<optimized out>,bpage=<optimized out>,buf_pool=<optimized out>) at mysql-5.7.22/storage/innobase/buf/buf0lru.cc:449 #9 buf_flush_or_remove_pages (trx=<optimized out>,flush=<optimized out>,observer=<optimized out>,id=<optimized out>,buf_pool=<optimized out>) at mysql-5.7.22/storage/innobase/buf/buf0lru.cc:632 #10 buf_flush_dirty_pages (buf_pool=<optimized out>,trx=<optimized out>) at mysql-5.7.22/storage/innobase/buf/buf0lru.cc:693 #11 0x00000000010f6de7 in buf_LRU_remove_pages (trx=0x0,buf_remove=BUF_REMOVE_FLUSH_NO_WRITE,id=55,buf_pool=0x31e55e8) at mysql-5.7.22/storage/innobase/buf/buf0lru.cc:893 #12 buf_LRU_flush_or_remove_pages (id=id@entry=55,buf_remove=buf_remove@entry=BUF_REMOVE_FLUSH_NO_WRITE,trx=trx@entry=0x0) at mysql-5.7.22/storage/innobase/buf/buf0lru.cc:951 #13 0x000000000114e488 in fil_delete_tablespace (id=id@entry=55,buf_remove=buf_remove@entry=BUF_REMOVE_FLUSH_NO_WRITE) at mysql-5.7.22/storage/innobase/fil/fil0fil.cc:2800 #14 0x0000000000fe77bd in row_drop_single_table_tablespace (trx=0x0,is_encrypted=false,is_temp=false,filepath=0x7f9d7c209f38 "./sbtest/sbtest25.ibd",tablename=0x7f9d7c209dc8 "sbtest/sbtest25",space_id=55) at mysql-5.7.22/storage/innobase/row/row0mysql.cc:4189 #15 row_drop_table_for_mysql (name=name@entry=0x7f9de010e020 "sbtest/sbtest25",trx=trx@entry=0x7f9ff9515750,drop_db=<optimized out>,nonatomic=<optimized out>,nonatomic@entry=true,handler=handler@entry=0x0) at mysql-5.7.22/storage/innobase/row/row0mysql.cc:4741 #16 0x0000000000f092f3 in ha_innobase::delete_table (this=<optimized out>,name=0x7f9de010f5e0 "./sbtest/sbtest25") at mysql-5.7.22/storage/innobase/handler/ha_innodb.cc:12539 #17 0x0000000000801a30 in ha_delete_table (thd=thd@entry=0x7f9d7c1f6910,table_type=table_type@entry=0x2ebd100,path=path@entry=0x7f9de010f5e0 "./sbtest/sbtest25",db=db@entry=0x7f9d7c00e560 "sbtest",alias=0x7f9d7c00df98 "sbtest25",generate_warning=generate_warning@entry=true) at mysql-5.7.22/sql/handler.cc:2586 #18 0x0000000000d0a6af in mysql_rm_table_no_locks (thd=thd@entry=0x7f9d7c1f6910,tables=tables@entry=0x7f9d7c00dfe0,if_exists=true,drop_temporary=false,drop_view=drop_view@entry=false,dont_log_query=dont_log_query@entry=false) at mysql-5.7.22/sql/sql_table.cc:2546 #19 0x0000000000d0ba58 in mysql_rm_table (thd=thd@entry=0x7f9d7c1f6910,if_exists=<optimized out>,drop_temporary=<optimized out>) at mysql-5.7.22/sql/sql_table.cc:2196 #20 0x0000000000c9d90b in mysql_execute_command (thd=thd@entry=0x7f9d7c1f6910,first_level=first_level@entry=true) at mysql-5.7.22/sql/sql_parse.cc:3589 #21 0x0000000000ca1edd in mysql_parse (thd=thd@entry=0x7f9d7c1f6910,parser_state=parser_state@entry=0x7f9de01107a0) at mysql-5.7.22/sql/sql_parse.cc:5582 #22 0x0000000000ca2a20 in dispatch_command (thd=thd@entry=0x7f9d7c1f6910,com_data=com_data@entry=0x7f9de0110e00,command=COM_QUERY) at mysql-5.7.22/sql/sql_parse.cc:1458 #23 0x0000000000ca4377 in do_command (thd=thd@entry=0x7f9d7c1f6910) at mysql-5.7.22/sql/sql_parse.cc:999 #24 0x0000000000d5ed00 in handle_connection (arg=arg@entry=0x10b8e910) at mysql-5.7.22/sql/conn_handler/connection_handler_per_thread.cc:300 #25 0x0000000001223d74 in pfs_spawn_thread (arg=0x10c48f40) at mysql-5.7.22/storage/perfschema/pfs.cc:2190 #26 0x00007fa003eeddc5 in start_thread () from /lib64/libpthread.so.0 #27 0x00007fa002aab74d in clone () from /lib64/libc.so.6
解決辦法
為buf_read_ibuf_merge_pages、buf_read_page_low、fil_io新增一個引數ignore_missing_space。表示忽略正在刪除的space，預設為false，當ibuf_merge_pages呼叫的時候置為true。在fil_io報錯處額外判斷該引數是否為true，是則不報錯，繼續其他流程。
或者直接在buf_read_ibuf_merge_pages呼叫buf_read_page_low時傳入IORequest::IGNORE_MISSING引數。
具體程式碼參考MariaDB commit：8edbb1117a9e1fd81fbd08b8f1d06c72efe38f44
影響版本
察看相關資訊，這個問題是修改Bug#19710564時刪除表空間版本引入的。
- MySQL Community Server 5.7.6引入，版本5.7.22尚未修復，版本8.0.0已修復。
- MariaDB Server 10.2受影響。MariaDB Server 10.2.9,10.3.2已修復
優化建議
可優化一下效能：在buf_read_ibuf_merge_pages中記錄下出錯的space id，迴圈的時候判斷下一個page的space id，如果space id是相同的，直接刪除對應ibuf的記錄（當前分配的最大space id記錄在系統表空間，space id佔4個位元組，低於0xFFFFFFF0UL，分配時讀取系統表空間儲存的值，然後加一，具有唯一性）。
總結
以上就是這篇文章的全部內容了，希望本文的內容對大家的學習或者工作具有一定的參考學習價值，如果有疑問大家可以留言交流，謝謝大家對我們的支援。