MySQL中I/O出現錯誤問題原因及解決方案(附最佳化建議)

php是最好的语言
發布: 2018-07-30 16:44:26
原創
6581 人瀏覽過

本文是對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 out>, type=0, mode=<optimized out>, 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 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過程:

  1. 當頁面被讀入緩衝池時,讀取完成後先進行ibuf的merge,然後頁面才可用;

  2. merge操作作為後台任務執行。 innodb_io_capacity參數可設定InnoDB後台任務每次merge程序的頁面數上限;

  3. 在崩潰復原期間,當索引頁被讀入緩衝池時,將執行對應頁的insert buffer merge;

  4. insert buffer具有持久性,系統崩潰不會導致它失效。重新啟動後,insert buffer merge操作將恢復正常;

  5. 伺服器關閉時可使用—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的主流程如下:

  1. 主執行緒從ibuf樹的葉子節點讀取頁號和space號,並記錄到一個二元數組中(未加鎖);

  2. 主執行緒對二元組中space進行偵測是否在表空間快取中,如不在,說明已經刪除了,刪除對應ibuf的記錄;

  3. 主執行緒判斷是否對一個正在刪除的space進行非同步讀取操作,如果是,報錯,並刪除對應ibuf的記錄,轉到過程2繼續下一個陣列元素的判斷;

  4. 如果一切判断正常,主线程发出async io请求,async读取需要被merge的索引页面;

  5. I/O handler 线程,在接受到完成的async I/O之后,进行merge操作;

  6. 进行merge的时候调用fil_space_acquire对space->n_pending_ops进行自增。避免删除操作并发;

  7. 执行完毕后调用fil_space_release对space->n_pending_ops进行自减。

相关删除表的逻辑

  1. 对fil_system->mutex加锁,设置sp->stop_new_ops = true,标记space正在删除,不允许对它进行新操作,然后对fil_system->mutex解锁;

  2. 对fil_system->mutex加锁,检测space->n_pending_ops,对fil_system->mutex解锁。如果检测到大于0,意味着还有依赖的操作未完成,睡眠20ms后重试;

  3. 对fil_system->mutex加锁,检测space->n_pending_flushes和(*node)->n_pending ,对fil_system->mutex解锁。如果检测到大于0,意味着还有依赖的I/O未完成,睡眠20ms后重试;

  4. 此时认为已经没有冲突的操作了,刷出所有脏页面或删除所有给定的表空间的页面;

  5. 从表空间缓存删除指定space的记录;

  6. 删除对应数据文件。

问题结论

情况很明确了,主线程获取ibuf的(space,page)的过程与删除操作执行的过程并没有锁保证互斥,只有async I/O完成之后的merge操作与删除操作才有互斥。如果后台线程开始ibuf merge并已经执行过了第2步的检测,但还没有执行到第3步检测,此时用户线程开始做删除表的操作,并设置好stop_new_ops标记但还没有执行到第5步删除表空间缓存,就会出现这个错误信息。两线程的交互如下图所示:

MySQL中I/O出現錯誤問題原因及解決方案(附最佳化建議)

不出意外的话,在打中断点时必然有线程在执行对应表的删除操作。果然我们可以发现如下堆栈:

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>, id=<optimized out>, observer=<optimized out>, flush=<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, tables=tables@entry=0x7f9d7c00dfe0, 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,分配时读取系统表空间保存的值,然后加一,具有唯一性)。

end:对于知识点我就介绍到这里了,写的有点快,可能有不足之处,还望多多交流指正,希望能帮到大家。

相关文章:

mysql1064错误原因及解决办法

MySQL常见问题及解决方案

相关视频:

AJAX跨域解决方案:JSONP视频教程

以上是MySQL中I/O出現錯誤問題原因及解決方案(附最佳化建議)的詳細內容。更多資訊請關注PHP中文網其他相關文章!

來源:php.cn
本網站聲明
本文內容由網友自願投稿,版權歸原作者所有。本站不承擔相應的法律責任。如發現涉嫌抄襲或侵權的內容,請聯絡admin@php.cn
最新問題
熱門教學
更多>
最新下載
更多>
網站特效
網站源碼
網站素材
前端模板
關於我們 免責聲明 Sitemap
PHP中文網:公益線上PHP培訓,幫助PHP學習者快速成長!