[MDEV-31386] InnoDB: Failing assertion: page_type == i_s_page_type[page_type].type_value Created: 2023-06-01  Updated: 2023-08-01  Resolved: 2023-07-03

Status: Closed
Project: MariaDB Server
Component/s: Information Schema, Storage Engine - InnoDB
Affects Version/s: 10.9
Fix Version/s: 10.6.15, 10.9.8, 10.10.6, 10.11.5, 11.0.3, 11.1.2, 11.2.1

Type: Bug Priority: Blocker
Reporter: Elena Stepanova Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: regression, rr-profile

Attachments: File MDEV-31386.cc     File MDEV-31386.yy    
Issue Links:
Problem/Incident
is caused by MDEV-29911 InnoDB recovery and mariadb-backup --... Closed
Relates
relates to MDEV-31816 buf_LRU_free_page() does not preserve... Closed

 Description   

Note: I don't have information whether it's happening on other versions, so I'm keeping only "10.9" in affected/fix fields. Please adjust based on the results of the analysis.

10.9 44c9008ba65686abf1c82c9166255a8c52d61f74

#2  0x00005633fe41635d in ut_dbg_assertion_failed (expr=0x5633ff5f1ec0 "page_type == i_s_page_type[page_type].type_value", file=0x5633ff5f0900 "/data/MDEV-31386/10.9/storage/innobase/handler/i_s.cc", 
    line=4038) at /data/MDEV-31386/10.9/storage/innobase/ut/ut0dbg.cc:60
#3  0x00005633fe017d5d in i_s_innodb_set_page_type (page_info=0x6260000a6e48, frame=0x640000634000 " Ac") at /data/MDEV-31386/10.9/storage/innobase/handler/i_s.cc:4038
#4  0x00005633fe018356 in i_s_innodb_buffer_page_get_info (bpage=0x640000465d70, pos=115, page_info=0x6260000a6e48) at /data/MDEV-31386/10.9/storage/innobase/handler/i_s.cc:4112
#5  0x00005633fe0187d5 in i_s_innodb_buffer_page_fill (thd=0x62b000230218, tables=0x6290007dacf0) at /data/MDEV-31386/10.9/storage/innobase/handler/i_s.cc:4176
#6  0x00005633fd0ebf0f in get_schema_tables_result (join=0x629000864640, executed_place=PROCESSED_BY_JOIN_EXEC) at /data/MDEV-31386/10.9/sql/sql_show.cc:8924
#7  0x00005633fcfc91c6 in JOIN::exec_inner (this=0x629000864640) at /data/MDEV-31386/10.9/sql/sql_select.cc:4806
#8  0x00005633fcfc71b2 in JOIN::exec (this=0x629000864640) at /data/MDEV-31386/10.9/sql/sql_select.cc:4627
#9  0x00005633fcfcac0e in mysql_select (thd=0x62b000230218, tables=0x6290007dacf0, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2684619520, 
    result=0x629000864610, unit=0x62b000234440, select_lex=0x6290007da5c8) at /data/MDEV-31386/10.9/sql/sql_select.cc:5107
#10 0x00005633fcf9fe11 in handle_select (thd=0x62b000230218, lex=0x62b000234368, result=0x629000864610, setup_tables_done_option=0) at /data/MDEV-31386/10.9/sql/sql_select.cc:584
#11 0x00005633fcee1070 in execute_sqlcom_select (thd=0x62b000230218, all_tables=0x6290007dacf0) at /data/MDEV-31386/10.9/sql/sql_parse.cc:6278
#12 0x00005633fcecfda1 in mysql_execute_command (thd=0x62b000230218, is_called_from_prepared_stmt=false) at /data/MDEV-31386/10.9/sql/sql_parse.cc:3948
#13 0x00005633fceeae1b in mysql_parse (thd=0x62b000230218, 
    rawbuf=0x6290007da238 "SELECT /* TID 1-10 QNO 1-4 */ t1.* FROM `information_schema`.`INNODB_BUFFER_PAGE` t1 LEFT JOIN (SELECT /* `information_schema`.`INNODB_SYS_TABLESPACES` */ t11.`FS_BLOCK_SIZE` AS fld1, COUNT(*) AS cnt "..., length=399, parser_state=0x34427f52a920) at /data/MDEV-31386/10.9/sql/sql_parse.cc:8043
#14 0x00005633fcec33c8 in dispatch_command (command=COM_QUERY, thd=0x62b000230218, 
    packet=0x6290007d0219 "SELECT /* TID 1-10 QNO 1-4 */ t1.* FROM `information_schema`.`INNODB_BUFFER_PAGE` t1 LEFT JOIN (SELECT /* `information_schema`.`INNODB_SYS_TABLESPACES` */ t11.`FS_BLOCK_SIZE` AS fld1, COUNT(*) AS cnt "..., packet_length=400, blocking=true) at /data/MDEV-31386/10.9/sql/sql_parse.cc:1894
#15 0x00005633fcec0926 in do_command (thd=0x62b000230218, blocking=true) at /data/MDEV-31386/10.9/sql/sql_parse.cc:1407
#16 0x00005633fd30c57e in do_handle_one_connection (connect=0x60800002c3b8, put_in_cache=true) at /data/MDEV-31386/10.9/sql/sql_connect.cc:1416
#17 0x00005633fd30bf0b in handle_one_connection (arg=0x60800002c3b8) at /data/MDEV-31386/10.9/sql/sql_connect.cc:1318
#18 0x00007ffd791cd609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#19 0x0000147ed2b90133 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95



 Comments   
Comment by Marko Mäkelä [ 2023-06-02 ]

The FIL_PAGE_TYPE of the page on which the assertion fails is 1. That is an invalid value. However, buf_page_t::state() for the block descriptor is FREED, that is, it might not actually be a valid page and the check should perhaps not be evaluated. The block had been freed here:

10.9 44c9008ba65686abf1c82c9166255a8c52d61f74

#2  0x00005633fe0ebea9 in buf_page_t::set_freed (this=..., prev_state=..., 
    count=...) at /data/MDEV-31386/10.9/storage/innobase/include/buf0buf.h:737
#3  0x00005633fe0d41c4 in recv_recover_page (block=..., mtr=..., recs=..., 
    space=..., init=...)
    at /data/MDEV-31386/10.9/storage/innobase/log/log0recv.cc:3328
#4  0x00005633fe0d5c42 in IORequest::fake_read_complete (this=..., offset=...)
    at /data/MDEV-31386/10.9/storage/innobase/log/log0recv.cc:3467
#5  0x00005633fe16955b in fake_io_callback (c=...)
    at /data/MDEV-31386/10.9/storage/innobase/os/os0file.cc:3434

Deeper analysis will be needed to understand whether the assertion should be simply skipped after buf_page_t::set_freed(), or this is a sign of actual data corruption.

Comment by Marko Mäkelä [ 2023-06-05 ]

The only log record that was applied for the page was FREE_PAGE. Because the contents of freed page frames do not matter, the page frame was never initialized. In all other cases (there had been an INIT_PAGE record, or the page was read from the file system), the buffer page contents should be valid.

In this special case, we could actually avoid invoking the recovery altogether, to save some memory. Even if innodb_immediate_scrub_data_uncompressed had been set (it was at the default value OFF here) or the data file used sparse files with page_compressed, recovery could theoretically duplicate the logic of buf_page_t::flush() and avoid allocating a buffer block.

I think that we should simply fix i_s_innodb_buffer_page_get_info() so that it will ignore the contents of freed blocks.

Comment by Marko Mäkelä [ 2023-06-05 ]

I tried to come up with a simple test to reproduce this bug, but failed. Here is one attempt; I also tested a kill+restart after DROP INDEX:

--source include/have_innodb.inc
--source include/have_sequence.inc
set global innodb_file_per_table=0;
create table t engine=innodb select * from seq_1_to_1000000;
drop table t;
--source include/kill_mysqld.inc
--source include/start_mysqld.inc
SELECT COUNT(*) FROM INFORMATION_SCHEMA.INNODB_BUFFER_PAGE;

elenst, can you please test the following fix?

diff --git a/storage/innobase/handler/i_s.cc b/storage/innobase/handler/i_s.cc
index 3cb51f5e15d..b00308d7e51 100644
--- a/storage/innobase/handler/i_s.cc
+++ b/storage/innobase/handler/i_s.cc
@@ -3882,7 +3882,7 @@ i_s_innodb_buffer_page_get_info(
 
 	page_info->state = bpage->state();
 
-	if (page_info->state < buf_page_t::FREED) {
+	if (page_info->state < buf_page_t::UNFIXED) {
 		page_info->page_type = I_S_PAGE_TYPE_UNKNOWN;
 		page_info->compressed_only = false;
 	} else {

Comment by Elena Stepanova [ 2023-06-05 ]

There have been not nearly enough occurrences of the failure in my tests to come up with any statistics and thus to make a conclusion that the problem was solved if the failure doesn't occur in N attempts.
As usual in such cases, the only reliable solution is that mleich extends his tests to make them hit the problem based on marko 's analysis of (possible) circumstances which lead to it, runs sufficient amount of targeted tests on the unfixed code to establish the statistical baseline, and then runs them on the fixed code.

Comment by Marko Mäkelä [ 2023-06-07 ]

I have some ideas for reproducing this bug in the 10.9 branch:

  1. Kill the server soon after the completion of an operation that would free lots of pages:
    • DROP INDEX
    • BEGIN; INSERT many_rows; ROLLBACK;
    • DROP TABLE of a table that had been created in the system tablespace
  2. Remove any ib_buffer_pool file.
  3. Start up with innodb_force_recovery=2 and possibly a larger innodb_buffer_pool_size than the one that was used in the killed server. The idea is to avoid the eviction of any buf_page_t::FREED pages after recovery.
  4. As soon as possible after startup, execute a query that accesses all rows of INFORMATION_SCHEMA.INNODB_BUFFER_PAGE.
Comment by Matthias Leich [ 2023-06-07 ]

No replay of the assert even though I tried many variants and executed many tests
- the ideas by Marko
  - new RQG test
  - derivates of existing RQG tests 
- Elena's test and her version of RQG
Hence I will give up for now.
The following checks were added to my version of RQG
1. Run a SELECT * FROM `information_schema`.`INNODB_BUFFER_PAGE`
    direct after starting a DB server + check if that SQL fails.
2. If checking tables after some intentional crash followed by some restart
    than do no more omit tables within the information_schema.

Comment by Matthias Leich [ 2023-06-09 ]

I have some replay test. 6 replays on 130 repetitions of the test.
origin/10.9 878a86f2764289e6679065b334fef8ca56786948 2023-06-07T14:32:46+03:00
Hence ~ 1000 repetitions of that test without any replay of the problem on some source tree with fix ensure that either

  • the problem is really fixed
    or
  • the fix has reduced the likelihood to show up drastic.
Comment by Matthias Leich [ 2023-06-14 ]

No replay on origin/10.9 878a86f2764289e6679065b334fef8ca56786948 2023-06-07T14:32:46+03:00 + the patch from above.

Comment by Marko Mäkelä [ 2023-07-03 ]

As part of fixing this, I removed the test innodb.innodb_defragment_fill_factor, because it would depend on information on freed pages being available in information_schema.innodb_buffer_page. The feature that the test is related to was removed in MDEV-30545.

Generated at Thu Feb 08 10:23:29 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.