Cause Analysis and Solution of I/O Error When Deleting MySQL Table

Problem phenomenon

I recently used sysbench to test MySQL. Since the test took a long time, I wrote a script that ran in the background in the order of prepare->run->cleanup. After the run, I checked the log and found a problem. There were multiple errors similar to the following 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.

It looks like an I/O error, but the MySQL process did not crash and the sysbench client did not report an error.

Problem Discovery Process

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

I manually executed the test 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 this problem is triggered by the short interval between run and cleanup. Because it takes a long time to execute 100G of data and the repetition cost is large, try to reduce the amount of use case data first. Change --table-size=4000000 to 2000000. When executing the script, this problem will not be triggered. Finally, change --table-size=3000000 to stabilize the trigger and reduce some reproduction time. In order to confirm whether the long interval caused the problem to not be reproduced, the script was modified to sleep for 10 seconds between the run and cleanup stages. Sure enough, this error message was not triggered. If you change it to sleep for 5 seconds, it can still be triggered, but the number of errors reported has been reduced.

Problem Investigation

Looking at the code of the corresponding version of mysql5.7.22, I found that this error occurs in only one location: in the fil_io() function on line 5578 of the fil0fil.cc file. Use gdb debugging directly, add a breakpoint at this location, and execute a 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

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

Background knowledge of insert buffer

The insert buffer is a special data structure (B+ tree) that caches changes when the auxiliary index page is not in the buffer pool and merges it later 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 still describes it as insert buffer), but ibuf is still used as the identifier in the source code. This feature caches several updates to the same page and merges them into a one-time update operation, reducing IO and converting random IO into sequential IO. This can avoid performance loss caused by random IO and improve database write performance.

Related insert buffer merge logic

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

• When a page is read into the buffer pool, the ibuf is merged after the reading is completed, 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 crash recovery, when an index page is read into the buffer pool, an insert buffer merge of the corresponding page is performed;
• The insert buffer is persistent and a system crash will not cause it to become invalid. After restart, the insert buffer merge operation will return to normal;
• You can use --innodb-fast-shutdown=0 to force a full merge of ibufs when the server is shut down.

Our problem this time clearly belongs to the second case. The innodb main thread (svr_master_thread) will actively perform a merge operation on the insert buffer every second. First, determine whether there has been any activity on the server within the past second (such as inserting tuples into pages, row operations on undo tables, etc.). If so, the maximum number of pages to merge 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 them into a binary array (unlocked);
• The main thread checks whether the space in the tuple is in the table space cache. If not, it means it has been deleted, and deletes 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, and the process goes to process 2 to continue the judgment of the next array element.
• If everything is normal, the main thread sends an async io request, and async reads the index page that needs to be merged;
• The I/O handler thread performs a merge operation after receiving the completed async I/O.
• When performing a merge, call fil_space_acquire to increment space->n_pending_ops. Avoid concurrent deletion operations;
• After execution is completed, fil_space_release is called to decrement space->n_pending_ops.
  

Logic for deleting related tables

• Lock fil_system->mutex, set sp->stop_new_ops = true, mark space as being deleted, and disallow new operations on it, then unlock fil_system->mutex;
• Lock fil_system->mutex, check space->n_pending_ops, and unlock fil_system->mutex. If the detected value is greater than 0, it means that there are still dependent operations that have not been completed. Retry after sleeping for 20ms.
• Lock fil_system->mutex, check space->n_pending_flushes and (*node)->n_pending, and unlock fil_system->mutex. If the detection value is greater than 0, it means that there are still dependent I/Os that have not been completed, and the system will try again after sleeping for 20ms.
• At this point, it is assumed that there are no conflicting operations, and all dirty pages are flushed or all pages of the given tablespace are deleted;
• Delete the records of the specified space from the table space cache;
• Delete the corresponding data file.

Conclusion

The situation is very clear. There is no lock to ensure mutual exclusion between the main thread's process of obtaining ibuf's (space, page) and the process of executing the deletion operation. Only the merge operation and the deletion operation after the async I/O is completed are mutually exclusive. If the background thread starts ibuf merge and has executed step 2 detection but has not yet executed step 3 detection, and the user thread starts to delete the table and sets the stop_new_ops flag but has not yet executed step 5 to delete the tablespace cache, this error message will appear. The interaction between the two threads is shown in the following figure:

If nothing unexpected happens, there must be a thread executing the deletion operation of the corresponding table when the breakpoint is hit. Sure enough, we can find the following stack:

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

Solution

Add a new parameter ignore_missing_space for buf_read_ibuf_merge_pages, buf_read_page_low, and fil_io. Indicates ignoring the space being deleted. The default value is false and it is set to true when ibuf_merge_pages is called. In the fil_io error reporting area, it is additionally determined whether the parameter is true. If it is true, no error is reported and other processes continue.

Or directly pass in the IORequest::IGNORE_MISSING parameter when buf_read_ibuf_merge_pages calls buf_read_page_low.

For specific code, refer to MariaDB commit: 8edbb1117a9e1fd81fbd08b8f1d06c72efe38f44

Affected versions

Check the relevant information. This problem was introduced when deleting the tablespace version when modifying Bug#19710564.

• Introduced in MySQL Community Server 5.7.6, not fixed in version 5.7.22, fixed in version 8.0.0.
• MariaDB Server 10.2 is affected. MariaDB Server 10.2.9, 10.3.2 has been fixed

Optimization suggestions

The performance can be optimized as follows: record the erroneous space id in buf_read_ibuf_merge_pages, determine the space id of the next page during the loop, and if the space id is the same, directly delete the corresponding ibuf record (the currently allocated maximum space id is recorded in the system tablespace, the space id occupies 4 bytes, which is lower than 0xFFFFFFF0UL. When allocating, read the value saved in the system tablespace, then add one to make it unique).

Summarize

The above is the full content of this article. I hope that the content of this article will have certain reference learning value for your study or work. If you have any questions, you can leave a message to communicate. Thank you for your support for 123WORDPRESS.COM.