Causes and solutions of I/O errors in MySQL (with optimization suggestions)-Mysql Tutorial-php.cn

This article is an analysis of the causes of I/O errors when MySQL deletes tables. First, we must observe the problem phenomenon and then investigate related issues. We can draw the conclusion: the process of the main thread obtaining ibuf (space, page) is different from There is no lock to guarantee mutual exclusion during the execution of the delete operation. Only the merge operation and the delete operation after the async I/O is completed are mutually exclusive. All explanations are described in detail in this article. apache php mysql

begin!

Problem phenomenon

Recently used sysbench to test MySQL, due to The test took a long time, so I wrote a script to run in the background in the order of prepare->run->cleanup. After running, I checked the log and found a problem. Multiple error reports similar to the following information appeared in the error log of the MySQL service:

[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。

Copy after login

It seems that an I/O error occurred, but the MySQL process did not crash. The sysbench client No error was reported on the terminal.

Process of discovering the problem

Based on the time record of the error and the comparison of the time points of each stage of the script output, it was determined that the command being executed by the script at that time was:

sysbench --tables=100 --table-size=4000000 --threads=50 --mysql-db=sbtest --time=300 oltp_delete cleanup

Copy after login

Manually executed this use case again, but the same situation did not occur again. However, this error message can still be found when executing the script. The initial suspicion is that the interval between run and cleanup cannot be too long to trigger this problem. Since it takes a long time to execute 100G of data once and the cost of reproducing is high, try to reduce the amount of use case data first. Modify -table-size=4000000 to 2000000. When the script is executed at this time, this problem will not be triggered. Finally, -table-size=3000000 can be stably triggered and reduce part of the recurrence time. In order to confirm whether the interval is too long, which will lead to non-recurrence, I modified the script to sleep for 10 seconds between the run and cleanup stages. As expected, this error message will not be triggered. If it is changed to sleep for 5 seconds, it can still be triggered, but the number of error reports has been reduced.

Problem Investigation

Looking at the code of the corresponding version mysql5.7.22, we found that this error is reported in only one location: in the fil_io() function on line 5578 of the fil0fil.cc file. Use gdb to debug directly, add a breakpoint at this location, and execute the reproducible script to get the following stack:

(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

Copy after login

Obviously this is a background thread doing the insert buffer merge operation. At this time, it is found that space->stop_new_ops is true, that is, the space to which the page to be processed belongs is being deleted. Why do you want to operate the space that is being deleted? This requires investigating the insert buffer function, insert buffer merge process, and table deletion process.

insert buffer background knowledge

insert buffer is a special data structure (B tree) that changes when the auxiliary index page is not in the buffer pool Cached and later merged when the page is loaded into the buffer pool by other read operations. When MySQL first introduced this feature, it could only cache insert operations, so it was called insert buffer. Now these operations can be INSERT, UPDATE, or DELETE (DML), so it is called change buffer (this article is still described as insert buffer), but the source code still uses ibuf as the identifier. This function caches several updates to the same page, merges them into one-time update operations, reduces IO, and converts random IO into sequential IO. This can avoid performance losses caused by random IO and improve the write performance of the database.

Related insert buffer merge logic

When the buffer page is read into the buffer pool, insert buffer merge will be performed. There are several main scenarios where the merge process will occur:

When the page is read into the buffer pool, after the reading is completed, the ibuf merge is performed first, and then the page is available;
The merge operation is performed as a background task. The innodb_io_capacity parameter can set the upper limit of the number of pages in each merge process of the InnoDB background task;
During the crash recovery period, when the index page is read into the buffer pool, the insert buffer of the corresponding page will be executed. merge;
insert buffer is persistent and system crash will not cause it to become invalid. After restarting, the insert buffer merge operation will return to normal;
When the server is shut down, you can use —innodb-fast-shutdown = 0 to force a complete merge of ibuf.

Our problem this time obviously belongs to the second situation. The main thread of innodb (svr_master_thread) will actively perform a merge operation of insert buffer every second. First determine whether there has been any activity on the server in the past 1s (inserting tuples into pages, undoing row operations on the table, etc.). If so, the maximum number of merged pages is 5% of the innodb_io_capacity setting. If not, the maximum number of pages to merge is the value set by innodb_io_capacity.

The main process of innodb main thread (svr_master_thread) merge is as follows:

The main thread reads the page number and space number from the leaf node of the ibuf tree, and records it to a In the binary array (unlocked);
The main thread checks whether the space in the binary array is in the table space cache. If it is not in the table space cache, it means it has been deleted. Delete the corresponding ibuf record;
The main thread determines whether to perform an asynchronous read operation on a space being deleted. If so, an error is reported and the corresponding ibuf record is deleted. Go to process 2 to continue. Judgment of an array element;
如果一切判断正常，主线程发出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进行自减。

问题结论

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

Causes and solutions of I/O errors in MySQL (with optimization suggestions)

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

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

Copy after login

解决办法

为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常见问题及解决方案