本文是對mysql在刪除表時i/o錯誤原因分析，首先要先觀察問題現象然后做出相關的問題調查，可以得出結論：主線程獲取ibuf的（space，page）的過程與刪除操作執行的過程并沒有鎖保證互斥，只有async i/o完成之后的merge操作與刪除操作才有互斥。全部的解釋本文有詳細的介紹。apache php mysql
begin!
問題現象
最近使用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>,?type=0,?mode=<optimized>,?page_id=...,?page_size=...,?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>)?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</optimized></optimized></optimized>
很明顯這是后臺線程在做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>)?at?mysql-5.7.22/storage/innobase/include/ut0mutex.ic:105 #5??exit?(this=<optimized>)?at?mysql-5.7.22/storage/innobase/include/ib0mutex.h:690 #6??exit?(this=<optimized>)?at?mysql-5.7.22/storage/innobase/include/ib0mutex.h:961 #7??buf_flush_yield?(bpage=<optimized>,?buf_pool=<optimized>)?at?mysql-5.7.22/storage/innobase/buf/buf0lru.cc:405 #8??buf_flush_try_yield?(processed=<optimized>,?bpage=<optimized>,?buf_pool=<optimized>)?at?mysql-5.7.22/storage/innobase/buf/buf0lru.cc:449 #9??buf_flush_or_remove_pages?(trx=<optimized>,?flush=<optimized>,?observer=<optimized>,?id=<optimized>,?buf_pool=<optimized>)?at?mysql-5.7.22/storage/innobase/buf/buf0lru.cc:632 #10?buf_flush_dirty_pages?(buf_pool=<optimized>,?id=<optimized>,?observer=<optimized>,?flush=<optimized>,?trx=<optimized>)?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>,?nonatomic=<optimized>,?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>,?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,?tables=tables@entry=0x7f9d7c00dfe0,?if_exists=<optimized>,?drop_temporary=<optimized>)?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</optimized></optimized></optimized></optimized></optimized></optimized></optimized></optimized></optimized></optimized></optimized></optimized></optimized></optimized></optimized></optimized></optimized></optimized></optimized></optimized></optimized></optimized></optimized>
解決辦法
為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，分配時讀取系統表空間保存的值，然后加一，具有唯一性）。
end：對于知識點我就介紹到這里了，寫的有點快，可能有不足之處，還望多多交流指正，希望能幫到大家。
相關文章：
相關視頻：
