Shulou(Shulou.com)06/01 Report--

Problem phenomenon

Recently, I used sysbench to test MySQL. Due to the long testing time, I wrote a script to run in the background in the order of prepare- > run- > cleanup. After running, check the log and find a problem. There are several errors similar to the following information in the error log of 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 there is an error in iCandle O, but the MySQL process does not crash and the sysbench client does not report an error.

The process of finding problems

According to the time record of the error report and the comparison of the time points of each stage of the script output, it is determined that the command being executed by the script at that time is:

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

The use case is executed manually again, but the same situation does not occur again. But you can still find this error message with script execution. The initial suspicion is that the gap between run and cleanup should not be too long to trigger this problem. Because it takes a long time to execute 100G of data once, and the reproduction cost is high, try to reduce the amount of use case data first. Change the-table-size=4000000 to 2000000, execute the script at this time, and the problem will not be triggered. Finally, the-table-size=3000000 can be triggered stably and reduce part of the recurrence time. To confirm that the interval is too long to cause it to fail to reproduce, modifying the script to sleep for 10 seconds between run and cleanup does not trigger this error message. If you change it to sleep for 5 seconds, it can still trigger, but the number of errors has been reduced.

Problem investigation

Looking at the code for the corresponding version of mysql5.7.22, there is only one place for this error: in the fil_io () function on line 5578 of the fil0fil.cc file. Debug directly with gdb, 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=, type=0, mode=, 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=) 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

It is obvious that the background thread is doing the insert buffer merge operation. At this point, 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 manipulate the space that is being deleted? This requires an investigation of the insert buffer function, the process of insert buffer merge, and the process of deleting tables.

Background knowledge of insert buffer

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

Related insert buffer merge logic

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

When the page is read into the buffer pool, the merge of ibuf is performed after the reading is completed, and then the page is available; the merge operation is executed as a background task. The innodb_io_capacity parameter sets the upper limit on the number of pages per merge process of the InnoDB background task; during crash recovery, when the index page is read into the buffer pool, the insert buffer merge;insert buffer that will execute the corresponding page is persistent and the system crash will not cause it to fail. After restart, 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 full merge of ibuf.

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

The main flow of the 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 into a binary array (unlocked). The main thread detects whether the space in the binary is in the tablespace cache. If not, it has been deleted. Delete the record of the corresponding ibuf. The main thread judges whether to asynchronously read an space being deleted, if so, reports an error, deletes the record of the corresponding ibuf, and 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 the async reads the index page that needs to be merge; the Iasync O handler thread performs the merge operation after receiving the completed async Icano. When performing merge, call fil_space_acquire to augment space- > n_pending_ops. Avoid the concurrency of deletion operations; call fil_space_release after execution to subtract space- > n_pending_ops.

Related logic for deleting tables

Lock fil_system- > mutex, set sp- > stop_new_ops = true, mark space is being deleted, do not allow new operations on it, and then unlock fil_system- > mutex; lock fil_system- > mutex, detect space- > n_pending_ops, and unlock fil_system- > mutex. If a value greater than 0 is detected, it means that there are still dependent operations to be completed. Try again after sleeping 20ms. Lock fil_system- > mutex, detect space- > n_pending_flushes and (* node)-> n_pending, and unlock fil_system- > mutex. If a value greater than 0 is detected, it means that the dependent space O is not completed, and then try again after sleeping. If you think that there is no conflict, brush out all dirty pages or delete all pages in the given table space; delete the records of the specified space from the tablespace cache; delete the corresponding data files.

Problem conclusion

It is clear that there is no lock guarantee between the process of the main thread acquiring ibuf (space,page) and the process of performing the delete operation, and only the merge operation and the delete operation after the completion of the merge operation are mutually exclusive. This error message will occur if the background thread starts ibuf merge and has already performed the detection in step 2, but has not yet performed the detection in step 3, 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. The interaction between the two threads is shown in the following figure:

If nothing happens, there must be a thread performing the deletion 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=) at mysql-5.7.22/storage/innobase/include/ut0mutex.ic:105#5 exit (this=) at mysql-5.7.22/storage/innobase/include/ib0mutex.h:690#6 exit (this=) at mysql-5.7.22/storage/innobase/include/ib0mutex.h:961#7 buf_flush_yield (bpage= Buf_pool=) at mysql-5.7.22/storage/innobase/buf/buf0lru.cc:405#8 buf_flush_try_yield (processed=, bpage=, buf_pool=) at mysql-5.7.22/storage/innobase/buf/buf0lru.cc:449#9 buf_flush_or_remove_pages (trx=, flush=, observer=, id=, buf_pool=) at mysql-5.7.22/storage/innobase/buf/buf0lru.cc:632#10 buf_flush_dirty_pages (buf_pool=, id=, observer=, flush= Trx=) 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=, nonatomic=, 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= 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=, drop_temporary=) 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 parameter ignore_missing_space for buf_read_ibuf_merge_pages, buf_read_page_low and fil_io. This means that the space being deleted is ignored. It defaults to false and is set to true when ibuf_merge_pages is called. Determine whether the parameter is true where the fil_io error is reported. If so, do not report the error, and continue other processes.

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

For more information, please see MariaDB commit:8edbb1117a9e1fd81fbd08b8f1d06c72efe38f44.

Affect the version

Take a look at the relevant information, this problem was introduced when you modified Bug# 19710564 to delete the tablespace version.

MySQL Community Server 5.7.6 was introduced, version 5.7.22 has not been fixed, version 8.0.0 has been fixed. MariaDB Server 10.2 was affected. MariaDB Server 10.2.9, 10.3.2 fixed

Optimization suggestion

Can optimize the performance: record the error space id in buf_read_ibuf_merge_pages, determine the space id of the next page during the cycle, and delete the record of the corresponding ibuf directly if the space id is the same (the maximum space id record currently allocated is in the system tablespace, space id accounts for 4 bytes, which is lower than 0xFFFFFFF0UL, the value saved in the system tablespace is read during allocation, and then add one, which is unique).

Summary

The above is the whole content of this article, I hope that the content of this article has a certain reference and learning value for your study or work, if you have any questions, you can leave a message and exchange, thank you for your support.

Welcome to subscribe "Shulou Technology Information " to get latest news, interesting things and hot topics in the IT industry, and controls the hottest and latest Internet news, technology news and IT industry trends.