run->cleanup的順序在后臺(tái)跑著。跑完后察看日志發(fā)現(xiàn)一個(gè)問(wèn)題,MySQL服務(wù)的錯(cuò)..."/>
您好,登錄后才能下訂單哦!
問(wèn)題現(xiàn)象
最近使用sysbench測(cè)試MySQL,由于測(cè)試時(shí)間較長(zhǎng),寫(xiě)了一個(gè)腳本按prepare->run->cleanup的順序在后臺(tái)跑著。跑完后察看日志發(fā)現(xiàn)一個(gè)問(wèn)題,MySQL服務(wù)的錯(cuò)誤日志中出現(xiàn)多條類似以下信息的報(bào)錯(cuò):
[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。
看起來(lái)是I/O出現(xiàn)了錯(cuò)誤,但MySQL進(jìn)程并未崩潰,sysbench客戶端也沒(méi)有報(bào)錯(cuò)。
發(fā)現(xiàn)問(wèn)題過(guò)程
根據(jù)報(bào)錯(cuò)的時(shí)間記錄以及腳本輸出的各個(gè)階段的時(shí)間點(diǎn)對(duì)比,確定了當(dāng)時(shí)腳本正在執(zhí)行的命令為:
sysbench --tables=100 --table-size=4000000 --threads=50 --mysql-db=sbtest --time=300 oltp_delete cleanup
重新手動(dòng)執(zhí)行一遍這個(gè)用例,卻沒(méi)有再出現(xiàn)同樣的情況。但是用腳本執(zhí)行卻依然能夠發(fā)現(xiàn)這個(gè)錯(cuò)誤信息。初步懷疑是run和cleanup之間不能間隔太久才會(huì)觸發(fā)這個(gè)問(wèn)題。由于執(zhí)行一遍100G數(shù)據(jù)量的時(shí)間較長(zhǎng),重現(xiàn)代價(jià)較大,先嘗試縮減用例數(shù)據(jù)量。將—table-size=4000000修改為2000000,此時(shí)執(zhí)行腳本,又不會(huì)觸發(fā)這個(gè)問(wèn)題了,最后將—table-size=3000000可以穩(wěn)定觸發(fā)又能減少部分重現(xiàn)時(shí)間。為了確認(rèn)是否間隔太長(zhǎng)會(huì)導(dǎo)致不能復(fù)現(xiàn),修改腳本在run和cleanup兩個(gè)階段之間sleep 10秒,果然不會(huì)觸發(fā)這個(gè)錯(cuò)誤信息。修改為sleep 5秒則還能觸發(fā),不過(guò)報(bào)錯(cuò)條數(shù)已有所減少。
問(wèn)題調(diào)查
察看對(duì)應(yīng)版本mysql5.7.22的代碼,發(fā)現(xiàn)這個(gè)報(bào)錯(cuò)只有一個(gè)位置:fil0fil.cc文件的第5578行fil_io()函數(shù)內(nèi)。 直接使用gdb調(diào)試,在這個(gè)位置加上斷點(diǎn),并執(zhí)行可復(fù)現(xiàn)的腳本,得到以下堆棧:
(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
很明顯這是后臺(tái)線程在做insert buffer merge操作。此時(shí)發(fā)現(xiàn)space->stop_new_ops為true,也就是要處理的頁(yè)面所屬的space正在被刪除。為什么會(huì)去操作正在被刪除的space呢?這需要調(diào)查下insert buffer功能、insert buffer merge的流程以及刪除表的流程。
insert buffer背景知識(shí)
insert buffer是一種特殊的數(shù)據(jù)結(jié)構(gòu)(B+ tree),當(dāng)輔助索引頁(yè)面不在緩沖池中時(shí),它會(huì)將更改緩存起來(lái),稍后在頁(yè)面被其他讀取操作加載到緩沖池中時(shí)合并。MySQL最初引進(jìn)這個(gè)功能的時(shí)候只能緩存insert操作,所以叫做insert buffer,現(xiàn)在這些操作可以是 INSERT, UPDATE, or DELETE(DML),所以改叫做change buffer了(本文依然以insert buffer描述),但源碼中依然以ibuf作為標(biāo)識(shí)。這個(gè)功能把若干對(duì)同一頁(yè)面的更新緩存起來(lái),合并為一次性更新操作,減少了IO,并轉(zhuǎn)化隨機(jī)IO為順序IO,這樣可以避免隨機(jī)IO帶來(lái)性能損耗,提高數(shù)據(jù)庫(kù)的寫(xiě)性能。
相關(guān)insert buffer merge邏輯
當(dāng)buffer page讀入buffer pool時(shí),就會(huì)進(jìn)行insert buffer merge。主要有幾個(gè)場(chǎng)景會(huì)出現(xiàn)merge過(guò)程:
我們這次的問(wèn)題很明顯屬于第二種情況。innodb主線程(svr_master_thread)會(huì)每隔一秒主動(dòng)進(jìn)行一次insert buffer的merge操作。先判斷過(guò)去1s之內(nèi)服務(wù)器是否發(fā)生過(guò)活動(dòng)(插入元組到頁(yè)面、undo表上的行操作等),如果發(fā)生過(guò),則merge的最大頁(yè)面數(shù)為innodb_io_capacity設(shè)定的5%。如果沒(méi)有則merge的最大頁(yè)面數(shù)為innodb_io_capacity設(shè)定的值。
innodb主線程(svr_master_thread)merge的主流程如下:
相關(guān)刪除表的邏輯
問(wèn)題結(jié)論
情況很明確了,主線程獲取ibuf的(space,page)的過(guò)程與刪除操作執(zhí)行的過(guò)程并沒(méi)有鎖保證互斥,只有async I/O完成之后的merge操作與刪除操作才有互斥。如果后臺(tái)線程開(kāi)始ibuf merge并已經(jīng)執(zhí)行過(guò)了第2步的檢測(cè),但還沒(méi)有執(zhí)行到第3步檢測(cè),此時(shí)用戶線程開(kāi)始做刪除表的操作,并設(shè)置好stop_new_ops標(biāo)記但還沒(méi)有執(zhí)行到第5步刪除表空間緩存,就會(huì)出現(xiàn)這個(gè)錯(cuò)誤信息。兩線程的交互如下圖所示:
不出意外的話,在打中斷點(diǎn)時(shí)必然有線程在執(zhí)行對(duì)應(yīng)表的刪除操作。果然我們可以發(fā)現(xiàn)如下堆棧:
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新增一個(gè)參數(shù)ignore_missing_space。表示忽略正在刪除的space,默認(rèn)為false,當(dāng)ibuf_merge_pages調(diào)用的時(shí)候置為true。在fil_io報(bào)錯(cuò)處額外判斷該參數(shù)是否為true,是則不報(bào)錯(cuò),繼續(xù)其他流程。
或者直接在buf_read_ibuf_merge_pages調(diào)用buf_read_page_low時(shí)傳入IORequest::IGNORE_MISSING參數(shù)。
具體代碼參考MariaDB commit:8edbb1117a9e1fd81fbd08b8f1d06c72efe38f44
影響版本
察看相關(guān)信息,這個(gè)問(wèn)題是修改Bug#19710564時(shí)刪除表空間版本引入的。
優(yōu)化建議
可優(yōu)化一下性能:在buf_read_ibuf_merge_pages中記錄下出錯(cuò)的space id,循環(huán)的時(shí)候判斷下一個(gè)page的space id,如果space id是相同的,直接刪除對(duì)應(yīng)ibuf的記錄(當(dāng)前分配的最大space id記錄在系統(tǒng)表空間,space id占4個(gè)字節(jié),低于0xFFFFFFF0UL,分配時(shí)讀取系統(tǒng)表空間保存的值,然后加一,具有唯一性)。
總結(jié)
以上就是這篇文章的全部?jī)?nèi)容了,希望本文的內(nèi)容對(duì)大家的學(xué)習(xí)或者工作具有一定的參考學(xué)習(xí)價(jià)值,如果有疑問(wèn)大家可以留言交流,謝謝大家對(duì)億速云的支持。
免責(zé)聲明:本站發(fā)布的內(nèi)容(圖片、視頻和文字)以原創(chuàng)、轉(zhuǎn)載和分享為主,文章觀點(diǎn)不代表本網(wǎng)站立場(chǎng),如果涉及侵權(quán)請(qǐng)聯(lián)系站長(zhǎng)郵箱:is@yisu.com進(jìn)行舉報(bào),并提供相關(guān)證據(jù),一經(jīng)查實(shí),將立刻刪除涉嫌侵權(quán)內(nèi)容。