Details
-
Bug
-
Status: Closed (View Workflow)
-
Critical
-
Resolution: Fixed
-
10.3.10, 10.2.19, 10.2(EOL), 10.3(EOL), 10.4(EOL), 10.5, 10.6
Description
origin/10.6 b0d38448a176dc990554c7dd5b184c3ebe64be8b 2021-08-19T16:35:44+05:30
|
|
|
Workflow:
|
1. Bootstrap + start DB server with
|
--mysqld=--innodb_undo_tablespaces=3 --mysqld=--innodb_undo_log_truncate=ON
|
in command line.
|
2. One sessions creates some initial data and disconnects.
|
3. Several sessions run for a few minutes concurrent DML on the tables created in 2.
|
and disconnect.
|
4. Dump data, shutdown of DB server
|
5. Restart of DB server
|
6. Run SHOW VARIABLES
|
|
|
Most frequent seen failure:
|
mysqld: /data/Server/10.6Z/storage/innobase/trx/trx0purge.cc:99: bool TrxUndoRsegsIterator::set_next(): Assertion `purge_sys.purge_queue.empty() || purge_sys.purge_queue.top() != m_rsegs' failed.
|
|
|
Less frequent seen
|
# 2021-08-20T12:44:32 [2934208] | 2021-08-20 12:44:26 5 [ERROR] InnoDB: PAGE_MAX_TRX_ID out of bounds: 8205, 4
|
# 2021-08-20T12:44:32 [2934208] | 2021-08-20 12:44:26 5 [ERROR] InnoDB: Apparent corruption in space 8 page 280 of index col_longtext_utf8_key of table test.table100_innodb_int_autoinc
|
...
|
mysqld: /data/Server/10.6Z/storage/innobase/trx/trx0sys.cc:62: static void ReadViewBase::check_trx_id_sanity(trx_id_t, const table_name_t&): Assertion `0' failed.
|
---------------
|
# 2021-08-20T12:34:35 [2762582] | 2021-08-20 12:33:47 16 [Note] InnoDB: trying to read page [page id: space=3, page number=102] in nonexisting or being-dropped tablespace
|
... many repetitions of the line above
|
# 2021-08-20T12:34:35 [2762582] | 2021-08-20 12:33:47 16 [ERROR] [FATAL] InnoDB: Unable to read page [page id: space=3, page number=102] into the buffer pool after 100. The most probable cause of this error may be that the table has been corrupted. See https://mariadb.com/kb/en/library/innodb-recovery-modes/
|
# 2021-08-20T12:34:35 [2762582] | 210820 12:33:47 [ERROR] mysqld got signal 6 ;
|
---------------
|
Workflow like above including
|
7. CHECK TABLE ...
|
# 2021-08-20T16:24:28 [936058] | [rr 990542 12500]2021-08-20 16:23:51 5 [Warning] InnoDB: A transaction id in a record of table `test`.`table100_innodb_int_autoinc` is newer than the system-wide maximum.
|
mysqld: /data/Server/10.6Z/storage/innobase/trx/trx0sys.cc:62: static void ReadViewBase::check_trx_id_sanity(trx_id_t, const table_name_t&): Assertion `0' failed.
|
-----------------
|
[ERROR] [FATAL] InnoDB: Trying to read 4096 bytes at 2097152 outside the bounds of the file: .//undo001
|
|
|
|
|
RQG
|
====
|
git clone https://github.com/mleich1/rqg --branch experimental RQG
|
|
|
perl rqg.pl \
|
--grammar=conf/engines/many_indexes.yy \
|
--gendata=conf/engines/many_indexes.zz \
|
--reporters=RestartConsistencyRR \
|
--mysqld=--loose-innodb_lock_schedule_algorithm=fcfs \
|
--mysqld=--loose-idle_write_transaction_timeout=0 \
|
--mysqld=--loose-idle_transaction_timeout=0 \
|
--mysqld=--loose-idle_readonly_transaction_timeout=0 \
|
--mysqld=--connect_timeout=60 \
|
--mysqld=--interactive_timeout=28800 \
|
--mysqld=--slave_net_timeout=60 \
|
--mysqld=--net_read_timeout=30 \
|
--mysqld=--net_write_timeout=60 \
|
--mysqld=--loose-table_lock_wait_timeout=50 \
|
--mysqld=--wait_timeout=28800 \
|
--mysqld=--lock-wait-timeout=86400 \
|
--mysqld=--innodb-lock-wait-timeout=50 \
|
--no-mask \
|
--queries=10000000 \
|
--seed=random \
|
--reporters=Backtrace \
|
--reporters=ErrorLog \
|
--reporters=Deadlock1 \
|
--validators=None \
|
--mysqld=--log_output=none \
|
--mysqld=--log_bin_trust_function_creators=1 \
|
--mysqld=--loose-debug_assert_on_not_freed_memory=0 \
|
--engine=InnoDB \
|
--restart_timeout=240 \
|
--mysqld=--plugin-load-add=file_key_management.so \
|
--mysqld=--loose-file-key-management-filename=$RQG_HOME/conf/mariadb/encryption_keys.txt \
|
--duration=150 \
|
--mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \
|
--mysqld=--innodb_stats_persistent=on \
|
--mysqld=--innodb_adaptive_hash_index=on \
|
--mysqld=--log-bin \
|
--mysqld=--sync-binlog=1 \
|
--mysqld=--loose-innodb_evict_tables_on_commit_debug=off \
|
--mysqld=--loose-max-statement-time=30 \
|
--threads=9 \
|
--mysqld=--innodb_use_native_aio=1 \
|
--mysqld=--innodb_undo_tablespaces=3 \
|
--mysqld=--innodb_undo_log_truncate=ON \
|
--mysqld=--innodb_page_size=16K \
|
--mysqld=--innodb-buffer-pool-size=8M \
|
--no_mask \
|
--workdir=<local settings>
|
--vardir=<local settings>
|
--mtr-build-thread=<local settings>
|
--basedir1=<local settings>
|
--script_debug=_nix_
|
|
|
Observations:
|
1. innodb-buffer-pool-size=8M seems to be extreme small for innodb_page_size=16K.
|
Raising innodb-buffer-pool-size to 32M does not let the failures disappear.
|
2. In case the server finally shut down was running under 'rr' than the problems
|
did never show up.
|
3. After setting innodb_undo_log_truncate=off the failures disappeared.
|
Attachments
Issue Links
- blocks
-
-
- Closed
-
- causes
-
-
- Closed
-
- includes
-
-
- Closed
-
- is caused by
-
-
- Closed
-
- relates to
-
-
- Stalled
-
-
-
- Open
-
-
-
- Closed
-
-
-
- Confirmed
-
-
-
- Closed
-
(4 relates to)
Activity
To get into crashes, I disabled some (for this purpose) uninteresting output (which was already disabled for other than 8KiB and 16KiB page size) and fixed some low-hanging fruit:
diff --git a/mysql-test/suite/innodb/t/undo_truncate.test b/mysql-test/suite/innodb/t/undo_truncate.test
|
index d2a4e287305..817de99d6fd 100644
|
--- a/mysql-test/suite/innodb/t/undo_truncate.test
|
+++ b/mysql-test/suite/innodb/t/undo_truncate.test
|
@@ -112,7 +112,7 @@ if ($size1 == $size2)
|
# This fails for innodb_page_size=64k, occasionally also for 32k.
|
if (`select @@innodb_page_size IN (8192,16384)`)
|
{
|
- echo Truncation did not happen: $size1;
|
+# echo Truncation did not happen: $size1;
|
}
|
}
|
|
diff --git a/storage/innobase/fsp/fsp0fsp.cc b/storage/innobase/fsp/fsp0fsp.cc
|
index 8477e74c5f1..a63643774b8 100644
|
--- a/storage/innobase/fsp/fsp0fsp.cc
|
+++ b/storage/innobase/fsp/fsp0fsp.cc
|
@@ -2179,13 +2179,14 @@ fseg_alloc_free_page_low(
|
return(NULL);
|
}
|
|
- if (space->size <= ret_page && !is_system_tablespace(space_id)) {
|
+ if (space->size <= ret_page && !is_predefined_tablespace(space_id)) {
|
/* It must be that we are extending a single-table
|
tablespace whose size is still < 64 pages */
|
|
if (ret_page >= FSP_EXTENT_SIZE) {
|
ib::error() << "Error (2): trying to extend"
|
- " a single-table tablespace " << space_id
|
+ " a single-table tablespace '"
|
+ << space->chain.start->name
|
<< " by single page(s) though the"
|
<< " space size " << space->size
|
<< ". Page no " << ret_page << "."; |
With this patch, I got a crash in the buf_flush_page_cleaner() thread:
|
10.6 106b16a5af7a8e29889e0ef8930bd2901a9ad00e |
innodb.undo_truncate '2,4k,innodb' w40 [ 4 fail ]
|
Test ended at 2021-09-17 13:21:19
|
|
|
CURRENT_TEST: innodb.undo_truncate
|
mysqltest: At line 56: query 'reap' failed: <Unknown> (2013): Lost connection to server during query
|
…
|
2021-09-17 13:21:17 0 [ERROR] [FATAL] InnoDB: Trying to write 4096 bytes at 7340032 outside the bounds of the file: .//undo002
|
…
|
It took a bit longer to get a failure on 10.5 with the above patch, but in the end it did fail in exactly the same way (only with a larger page size):
|
10.5 c430aa72abbdccb1ece7f0d65b49a6b48e7c5ba7 |
innodb.undo_truncate '2,8k,innodb' w11 [ 10 fail ]
|
Test ended at 2021-09-17 13:25:19
|
|
|
CURRENT_TEST: innodb.undo_truncate
|
mysqltest: At line 56: query 'reap' failed: 2013: Lost connection to MySQL server during query
|
…
|
2021-09-17 13:25:18 0 [ERROR] [FATAL] InnoDB: Trying to write 8192 bytes at 8388608 outside the bounds of the file: .//undo002
|
I expect any version starting with 10.2 to be affected, so I will test 10.2 next.
7×100 rounds of innodb.undo_truncate,4k with the above patch did not fail on 10.2, but I would still not claim that anything earlier than 10.5 is unaffected by this. Starting with 10.5, the refactored page cleaner (MDEV-23379, MDEV-23855 and follow-up fixes) allows more concurrency and thus possibly a better opportunity for this to fail. On the other hand, 10.5 also introduced MDEV-15528, which may affect undo tablespace truncation. In 10.3 and 10.4, there page flushing and redo logging and recovery logic should be similar to 10.2, so I will not test them yet.
So far, I have been unable to generate an rr replay trace for this. I have tried two variants, both on /dev/shm (so, MDEV-17380 will not disable neighbor flushing):
while nice ./mtr --rr=-h --parallel=auto --mysqld=--skip-innodb-flush-neighbors innodb.undo_truncate,4k{,,,,,,,,,,,,,,,,,,,,,,,,}; do :; done |
while nice ./mtr --rr=-h --parallel=auto innodb.undo_truncate,4k{,,,,,,,,,,,,,,,,,,,,,,,,}; do :; done |
Oh, and I am using RelWithDebInfo build all the time. Maybe a Debug or ASAN build would be more useful after all? But I do not remember getting the debug test to fail at all without rr. It is possible that I just did not wait long enough.
mleich, can you try to generate a trace? Anything from RQG is fine as well. I would assume that using innodb_page_size=4k is easiest.
Will try.
|
Btw I am trying to reproduce the bugs mentioned on top on actual 10.6.
|
And in the moment it looks a lot as if removing any DDL related to FOREIGN KEYs lets the problems disappear.
|
If the FOREIGN KEY trouble is MDEV-26554, that should be 10.6 specific. Maybe 10.5 with the above patch would be a better choice for the RQG approach?
With a debug build, reproducing a failure took considerably longer. I started a RelWithDebInfo build concurrently with the test, and around the time the build was finishing, I got this:
|
10.6 b740b2356d539a27f8a7a9e9b6455f31bc6c9196 |
innodb.undo_truncate '2,4k,innodb' w5 [ 69 fail ]
|
Test ended at 2021-09-20 09:34:18
|
|
|
CURRENT_TEST: innodb.undo_truncate
|
mysqltest: At line 19: query 'create table t1(keyc int primary key, c char(100)) engine = innodb' failed: <Unknown> (2013): Lost connection to server during query
|
|
|
The result from queries just before the failure was:
|
SET @save_frequency = @@GLOBAL.innodb_purge_rseg_truncate_frequency;
|
SET @save_truncate = @@GLOBAL.innodb_undo_log_truncate;
|
SET GLOBAL innodb_undo_log_truncate = 0;
|
SET GLOBAL innodb_purge_rseg_truncate_frequency = 1;
|
SET @trunc_start=
|
(SELECT variable_value FROM information_schema.global_status
|
WHERE variable_name = 'innodb_undo_truncations');
|
create table t1(keyc int primary key, c char(100)) engine = innodb;
|
|
|
|
|
Server [mysqld.1 - pid: 38082, winpid: 38082, exit: 256] failed during test run
|
Server log from this test:
|
----------SERVER LOG START-----------
|
mariadbd: /mariadb/10.6/storage/innobase/fsp/fsp0fsp.cc:2395: bool fsp_reserve_free_extents(uint32_t*, fil_space_t*, uint32_t, fsp_reserve_t, mtr_t*, uint32_t): Assertion `size == space->size_in_header' failed.
|
210920 9:34:10 [ERROR] mysqld got signal 6 ;
|
Interestingly, today, my patches from 2021-09-17 were not needed (there were no failures related to that). The RelWithDebInfo build with a patch to enable the assertion crashed as well at that same spot:
diff --git a/storage/innobase/fsp/fsp0fsp.cc b/storage/innobase/fsp/fsp0fsp.cc
|
index 8477e74c5f1..9f1888a1601 100644
|
--- a/storage/innobase/fsp/fsp0fsp.cc
|
+++ b/storage/innobase/fsp/fsp0fsp.cc
|
@@ -2392,7 +2392,7 @@ fsp_reserve_free_extents(
|
try_again:
|
uint32_t size = mach_read_from_4(FSP_HEADER_OFFSET + FSP_SIZE
|
+ header->frame);
|
- ut_ad(size == space->size_in_header);
|
+ ut_a(size == space->size_in_header);
|
|
if (size < extent_size && n_pages < extent_size / 2) {
|
/* Use different rules for small single-table tablespaces */ |
|
10.6 b740b2356d539a27f8a7a9e9b6455f31bc6c9196 RelWithDebInfo patched |
innodb.undo_truncate '2,4k,innodb' w16 [ 21 fail ]
|
Test ended at 2021-09-20 09:41:17
|
|
|
CURRENT_TEST: innodb.undo_truncate
|
mysqltest: At line 78: query 'drop table t1, t2' failed: <Unknown> (2013): Lost connection to server during query
|
…
|
fsp/fsp0fsp.cc:2467(fsp_reserve_free_extents(unsigned int*, fil_space_t*, unsigned int, fsp_reserve_t, mtr_t*, unsigned int))[0x561214507fb4]
|
trx/trx0undo.cc:378(trx_undo_seg_create(fil_space_t*, buf_block_t*, unsigned long*, dberr_t*, mtr_t*))[0x561214bb2c50]
|
trx/trx0undo.cc:1042(trx_undo_create(trx_t*, trx_rseg_t*, trx_undo_t**, dberr_t*, mtr_t*))[0x561214bb4f91]
|
trx/trx0undo.cc:1215(trx_undo_assign_low(trx_t*, trx_rseg_t*, trx_undo_t**, dberr_t*, mtr_t*))[0x561214bb58b4]
|
trx/trx0rec.cc:2065(trx_undo_report_row_operation(que_thr_t*, dict_index_t*, dtuple_t const*, upd_t const*, unsigned long, unsigned char const*, unsigned short const*, unsigned long*))[0x561214ba2721]
|
btr/btr0cur.cc:5384(btr_cur_del_mark_set_clust_rec(buf_block_t*, unsigned char*, dict_index_t*, unsigned short const*, que_thr_t*, dtuple_t const*, mtr_t*))[0x561214bd4e99]
|
row/row0upd.cc:2647(row_upd_clust_step(upd_node_t*, que_thr_t*))[0x561214b8ac8b]
|
row/row0upd.cc:2909(row_upd_step(que_thr_t*))[0x561214b8c5be]
|
que/que0que.cc:635(que_run_threads(que_thr_t*))[0x561214b47203]
|
que/que0que.cc:430(que_graph_free(que_fork_t*))[0x561214b473db]
|
dict/drop.cc:130(trx_t::drop_table_statistics(table_name_t const&))[0x561214c1f6c3]
|
This stack trace suggests that in 10.5 it may have taken longer for the test to fail, because MDEV-4750 had globally disabled innodb_stats_persistent in mtr and it has only been recently re-enabled in the 10.6 series, to get better testing of MDEV-25919.
I will try to tweak the test so that it wil fail more easily.
I noticed one possible race condition in the code: The call to os_file_truncate() in trx_purge_truncate_history() is being executed while we are not holding an exclusive latch on the undo tablespace header page where FSP_SIZE is being stored. Ensuring that we hold an exclusive page latch across that call seems to have fixed failures of the reduced test that I was running.
I will let the RelWithDebInfo test run for several thousand rounds with that race fixed, and with all the size_in_header assertions converted from ut_ad() to ut_a() so that we have more chances of crashing.
The joy was premature. It still fails (this time again in trx_t::drop_table_statistics()), but after a much longer time:
innodb.undo_truncate '2,32k,innodb' w8 [ 327 fail ]
|
Test ended at 2021-09-20 10:46:20
|
|
|
CURRENT_TEST: innodb.undo_truncate
|
mysqltest: At line 56: query 'drop table t1, t2' failed: <Unknown> (2013): Lost connection to server during query
|
…
|
2021-09-20 10:46:06 0 [Note] InnoDB: Truncated .//undo002
|
2021-09-20 10:46:07 0x7f0cf0316640 InnoDB: Assertion failure in file /mariadb/10.6/storage/innobase/fsp/fsp0fsp.cc line 2398
|
On a tentative fix, I initiated 44×1000 runs of innodb.undo_truncate_recover about an hour ago on the Debug build. It has not failed yet. I expect that run to finish in about 2 hours.
Concurrently with that, I just started the RelWithDebInfo build with a simpler variant of the test where the undo log truncation is constantly enabled. Within a couple of minutes got a new type of failure, again in trx_t::drop_table_statistics():
innodb.undo_trunc '2,4k,innodb' w42 [ 38 fail ]
|
Test ended at 2021-09-20 11:56:22
|
|
|
CURRENT_TEST: innodb.undo_trunc
|
mysqltest: At line 33: query 'drop table t1, t2' failed: <Unknown> (2013): Lost connection to server during query
|
…
|
#5 0x000055a27363614e in ut_dbg_assertion_failed (expr=expr@entry=0x55a27405bad8 "n < FSP_SEG_INODES_PER_PAGE(physical_size)", file=file@entry=0x55a27405b748 "/mariadb/10.6/storage/innobase/fsp/fsp0fsp.cc", line=line@entry=1443) at /mariadb/10.6/storage/innobase/ut/ut0dbg.cc:60
|
#6 0x000055a27364c231 in fsp_alloc_seg_inode (mtr=<optimized out>, iblock=<optimized out>, header=<optimized out>, space=<optimized out>) at /mariadb/10.6/storage/innobase/fsp/fsp0fsp.cc:1443
|
#7 fseg_create (space=<optimized out>, space@entry=0x55a276b61668, byte_offset=<optimized out>, byte_offset@entry=60, mtr=<optimized out>, mtr@entry=0x7fd229791a80, has_done_reservation=<optimized out>, has_done_reservation@entry=true, block=<optimized out>, block@entry=0x0) at /mariadb/10.6/storage/innobase/fsp/fsp0fsp.cc:1715
|
#8 0x000055a273cf5e40 in trx_undo_seg_create (space=0x55a276b61668, rseg_hdr=0x7fd229ac1800, id=0x7fd2297918c8, err=0x7fd229791a44, mtr=0x7fd229791a80) at /mariadb/10.6/storage/innobase/trx/trx0undo.cc:384
|
#9 0x000055a273cf8161 in trx_undo_create (trx=trx@entry=0x7fd22aa95230, rseg=rseg@entry=0x55a2745f39c0 <trx_sys+25472>, undo=undo@entry=0x7fd22aa961e0, err=err@entry=0x7fd229791a44, mtr=mtr@entry=0x7fd229791a80) at /mariadb/10.6/storage/innobase/trx/trx0undo.cc:1042
|
#10 0x000055a273cf8a84 in trx_undo_assign_low (trx=trx@entry=0x7fd22aa95230, rseg=rseg@entry=0x55a2745f39c0 <trx_sys+25472>, undo=undo@entry=0x7fd22aa961e0, err=err@entry=0x7fd229791a44, mtr=mtr@entry=0x7fd229791a80) at /mariadb/10.6/storage/innobase/trx/trx0undo.cc:1213
|
I think that I must add some more instrumentation to get a better idea where the remaining problem is.
For the record, my simplified version of innodb.undo_truncate did not fail after I disabled innodb_stats_persistent:
nice ./mtr --mysqld=--innodb-{purge-rseg-truncate-frequency,undo-log-truncate}=1 --mysqld=--innodb-stats-persistent=0 --parallel=auto --repeat=1000 innodb.undo_trunc,4k{,,,,,,,,,,,,,,,,,,,,,,,}
|
completed without any failures:
innodb.undo_trunc '2,4k,innodb' w5 [ 1000 pass ] 1074
|
--------------------------------------------------------------------------
|
The servers were restarted 0 times
|
Spent 53268.177 of 2676 seconds executing testcases
|
|
|
Completed: All 24000 tests were successful.
|
So, it looks like the extra undo log written for deleting the persistent statistics during DROP TABLE is really necessary for reproducing the remaining failures.
The repeated runs of the debug test innodb.undo_truncate_recover is almost â…” done and should complete in about one hour. There has been no failure so far.
I realized that I had initiated the innodb.undo_truncate_recover test for n×1000 instead of n×100 rounds. Each round was about 10 seconds. I finally interrupted it by shutting down the server processes while the test was running:
Only 45 of 96 completed.
|
--------------------------------------------------------------------------
|
The servers were restarted 45 times
|
Spent 636921.388 of 16817 seconds executing testcases
|
|
|
Failure: Failed 1/44335 tests, 100.00% were successful.
|
So, that test never failed with the latest improvements. I will still have to iron out the intermittent failures of the test innodb.undo_truncate.
I was wondering why I only see all-zero block descriptors and page frames in core dumps until I remembered MDEV-10814 and that I am not working with Debug builds. Once I disabled madvise() in CMakeCache.txt, the core dumps started to make more sense.
Finally, I think that I nailed it down:
2021-09-20 17:34:04 0 [Note] InnoDB: Truncating .//undo002
|
size 2: 832→640
|
CURRENT_TEST: innodb.undo_truncate
|
2021-09-20 17:34:05 0 [Note] InnoDB: Truncated .//undo002
|
read header 2
|
extend 1: 704
|
…
|
extend 1: 1216
|
read header 2
|
2021-09-20 17:34:05 0x7f5a2d0bc640 InnoDB: Assertion failure in file /mariadb/10.6/storage/innobase/fsp/fsp0fsp.cc line 2417
|
InnoDB: Failing assertion: size == space->size_in_header
|
Reading from FSP_SIZE in the page frame, we got size==832. But, space->size_in_header==640. The read header 2 output means that we read page 0 of tablespace 2 (the failing one in this core dump) from the data file.
While I did not add instrumentation for the page write yet, I am fairly sure that we were evicting page 0 of the undo tablespace before we had written it back to the file.
The recovery test would not be affected by this, because we do write redo log correctly, and because the page eviction&reload occurs very rarely in these tests.
I augmented my instrumentation a little and confirmed the hypothesis that a tablespace header with size change is being discarded:
size 1: 1216→640
|
CURRENT_TEST: innodb.undo_truncate
|
2021-09-20 18:13:48 0 [Note] InnoDB: Truncated .//undo001
|
read header 1: 1216
|
I tried adding another invocation loop of buf_flush_list_space() to trx_purge_truncate_history() after purge_sys.truncate.current->clear_stopping(), but it did not fix this. I suspect that the pages can be discarded in buf_flush_list_space() simply because trx_purge_truncate_history() is invoking fil_space_t::set_stopping(), and I even got proof of that in the form of an added assertion failing in trx_purge_truncate_history(). This remaining problem ought to be related to MDEV-23855 and related refactoring in 10.5.
Finally, I found a good place to insert an assertion:
#5 0x000055c0ad09e9c4 in ut_dbg_assertion_failed (expr=expr@entry=0x55c0adabe19a "bpage->id().space() > 2", file=file@entry=0x55c0adabe088 "/mariadb/10.6/storage/innobase/buf/buf0flu.cc", line=line@entry=1217) at /mariadb/10.6/storage/innobase/ut/ut0dbg.cc:60
|
#6 0x000055c0ad0a85e1 in buf_flush_discard_page (bpage=<optimized out>) at /mariadb/10.6/storage/innobase/buf/buf0flu.cc:1217
|
#7 0x000055c0ad79cdc2 in buf_do_flush_list_batch (lsn=64596728, max_n=2000) at /mariadb/10.6/storage/innobase/buf/buf0flu.cc:1441
|
#8 buf_flush_list (lsn=64596728, max_n=2000) at /mariadb/10.6/storage/innobase/buf/buf0flu.cc:1525
|
#9 buf_flush_list (max_n=2000, lsn=64596728) at /mariadb/10.6/storage/innobase/buf/buf0flu.cc:1505
|
#10 0x000055c0ad79d48f in buf_flush_page_cleaner () at /mariadb/10.6/storage/innobase/buf/buf0flu.cc:2298
|
At this time, truncation for this undo tablespace is blocked in another thread (waiting for buf_pool.mutex, which is held by the crashing buf_flush_page_cleaner thread):
#4 buf_flush_list_space (space=space@entry=0x55c0b039c5c8, n_flushed=n_flushed@entry=0x0) at /mariadb/10.6/storage/innobase/buf/buf0flu.cc:1553
|
#5 0x000055c0ad09bfed in trx_purge_truncate_history () at /mariadb/10.6/storage/innobase/trx/trx0purge.cc:772
|
This race condition definitely looks like something new since 10.5.7.
To fix this with respect to page 0, I believe that we should try something like this:
- Continue to hold exclusive latch on the page 0 of the being-truncated undo tablespace across mini-transaction commit and durable log write of modifying FSP_SIZE
- Acquire buf_pool.flush_list_mutex before acquiring fil_system.mutex, to clear the "being truncated" status of the tablespace
- Release the mutexes and the latch on page 0
In trx_purge_truncate_history() we must protect page 0 against being discarded not only by continuously holding the page latch (which is what I was testing yesterday), but also by holding buf_pool.flush_list_mutex. Once buf_do_flush_list_batch() has looked up a tablespace and determined that it is being discarded, it will discard all pages for that tablespace. Once we have durably written the shrinking of FSP_SIZE and the reinitialization of the undo tablespace to the log, it should be safe to discard any other page writes except the newly reinitialized pages (including page 0).
I added some more instrumentation to check this hypothesis, but did not add the buf_pool.flush_list_mutex acquisition, so that we would still get the crash. The relevant portion of the log is as follows:
2021-09-21 10:34:55 0 [Note] InnoDB: Truncating .//undo001
|
flush 1
|
flush 1 done
|
size 1: 1216→640
|
CURRENT_TEST: innodb.undo_trunc
|
read header 2: 640
|
extend 2: 704
|
extend 2: 768
|
discard 1:66
|
…
|
discard 1:57
|
2021-09-21 10:34:56 0 [Note] InnoDB: Truncated .//undo001
|
discard 1:56
|
…
|
discard 1:0
|
discard 1:6
|
discard 1:2
|
discard 1:5
|
discard 1:4
|
discard 1:3
|
extend 2: 832
|
extend 2: 896
|
extend 2: 960
|
extend 2: 1024
|
extend 2: 1088
|
extend 2: 1152
|
extend 2: 1216
|
read header 1: 1216
|
2021-09-21 10:34:56 0x7f10b92ba640 InnoDB: Assertion failure in file /mariadb/10.6/storage/innobase/fsp/fsp0fsp.cc line 2417
|
InnoDB: Failing assertion: size == space->size_in_header
|
According to this output, we wrote out all of the undo tablespace 1 before it was truncated. After truncation, we discarded several pages of it.
My above idea appears to be insufficient, because we do not want to lose the contents of any of the newly reinitialized pages (pages 0 to 66 in the log output).
In-place truncation of an undo tablespace differs from DROP TABLE or anything that would rebuild a table with a different tablespace identifier. For such cases, the correct action is to discard any dirty pages that belonged to a discarded tablespace.
A more accurate fix would be: As long as the "being truncated" flag is set on a tablespace, we must not discard any pages without writing them out, but instead let those pages remain in the buffer pool. The simplest way to achieve this might be to tweak the mini-transaction commit in trx_purge_truncate_history() so that it will only copy the log to the global buffer but not release any page latches. We would release the page latches (and add the blocks to the buf_pool.flush_list) after the file has been truncated in the file system.
After I implemented a new member function mtr_t::commit_shrink(fil_space_t&) that performs the steps like I envisioned above, 95×100 rounds of a variant of the innodb.undo_truncate test passed without problems, and no undo pages were discarded by buf_flush_discard_page().
Even though I did not repeat any crash in 10.2, I am now convinced that undo tablespace truncation may have caused corruption ever since MDEV-13564 was introduced in MariaDB 10.2.19 and 10.3.10. Before that, a separate log file for undo tablespace truncation was being used.
origin/bb-10.2-MDEV-26450 565c38c994a3584dff82eec6e2deccbc93e57555 2021-09-21T18:02:04+03:00
|
performed well in RQG testing (Usage of foreign keys disabled).
|
|
|
origin/bb-10.5-MDEV-26450 2755e86a53cd89729d0cb54424fe83074dccd8ab 2021-09-22T16:40:47+03:00
|
did not look bad but I hit twice the same assert.
|
sdp:/data/Results/1632322073/Marko/dev/shm/vardir/1632322073/164/1/rr
|
|
|
_RR_TRACE_DIR="." rr replay --mark-stdio mysqld-1 # Fate till SIGKILL
|
_RR_TRACE_DIR="." rr replay --mark-stdio
|
# Restart with success but crash during checks
|
# 2021-09-22T11:29:28 [74467] Verifying table: `test`.`t6`
|
# 2021-09-22T11:29:28 [74467] INFO: Reporter 'CrashRecovery1': Executing CHECK TABLE `test`.`t6` EXTENDED.
|
# 2021-09-22T11:29:28 [74467] INFO: Reporter 'CrashRecovery1': Executing ANALYZE TABLE `test`.`t6`.
|
# 2021-09-22T11:29:28 [74467] INFO: Reporter 'CrashRecovery1': Executing OPTIMIZE TABLE `test`.`t6`.
|
# 2021-09-22T11:30:21 [74467] ERROR: OPTIMIZE TABLE `test`.`t6` harvested 2013: Lost connection to MySQL server during query. Will return STATUS_RECOVERY_FAILURE later.
|
# 2021-09-22T11:30:21 [74467] | [rr 163758 39652]mysqld: /data/Server/bb-10.5-MDEV-26450/storage/innobase/row/row0sel.cc:2889: void row_sel_field_store_in_mysql_format_func(byte*, const mysql_row_templ_t*, const dict_index_t*, ulint, const byte*, ulint): Assertion `templ->mysql_col_len == len' failed.
|
|
|
(rr) bt
|
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
|
#1 0x00007f021bb89859 in __GI_abort () at abort.c:79
|
#2 0x00007f021bb89729 in __assert_fail_base (fmt=0x7f021bd1f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x56143ee6d3e0 "templ->mysql_col_len == len", file=0x56143ee6ac60 "/data/Server/bb-10.5-MDEV-26450/storage/innobase/row/row0sel.cc", line=2889, function=<optimized out>) at assert.c:92
|
#3 0x00007f021bb9af36 in __GI___assert_fail (assertion=0x56143ee6d3e0 "templ->mysql_col_len == len", file=0x56143ee6ac60 "/data/Server/bb-10.5-MDEV-26450/storage/innobase/row/row0sel.cc", line=2889, function=0x56143ee6cec0 "void row_sel_field_store_in_mysql_format_func(byte*, const mysql_row_templ_t*, const dict_index_t*, ulint, const byte*, ulint)") at assert.c:101
|
#4 0x000056143da0b56c in row_sel_field_store_in_mysql_format_func (dest=0x61a0001674ce "", templ=0x6190000ca910, index=0x617000051e08, field_no=0, data=0x7f020c5200ad "\200", len=4) at /data/Server/bb-10.5-MDEV-26450/storage/innobase/row/row0sel.cc:2889
|
#5 0x000056143da0c8c7 in row_sel_store_mysql_field (mysql_rec=0x61a0001674b8 "\375\n8888888888", prebuilt=0x62100009b188, rec=0x7f020c5200ad "\200", index=0x617000051e08, offsets=0x7f01e9f94b50, field_no=0, templ=0x6190000ca910) at /data/Server/bb-10.5-MDEV-26450/storage/innobase/row/row0sel.cc:3039
|
#6 0x000056143da0d5b7 in row_sel_store_mysql_rec (mysql_rec=0x61a0001674b8 "\375\n8888888888", prebuilt=0x62100009b188, rec=0x7f020c5200ad "\200", vrow=0x0, rec_clust=false, index=0x617000051e08, offsets=0x7f01e9f94b50) at /data/Server/bb-10.5-MDEV-26450/storage/innobase/row/row0sel.cc:3175
|
#7 0x000056143da1c8bd in row_search_mvcc (buf=0x61a0001674b8 "\375\n8888888888", mode=PAGE_CUR_G, prebuilt=0x62100009b188, match_mode=0, direction=0) at /data/Server/bb-10.5-MDEV-26450/storage/innobase/row/row0sel.cc:5553
|
#8 0x000056143d61c195 in ha_innobase::index_read (this=0x61d0001cdeb8, buf=0x61a0001674b8 "\375\n8888888888", key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY) at /data/Server/bb-10.5-MDEV-26450/storage/innobase/handler/ha_innodb.cc:8867
|
#9 0x000056143d61eb12 in ha_innobase::index_first (this=0x61d0001cdeb8, buf=0x61a0001674b8 "\375\n8888888888") at /data/Server/bb-10.5-MDEV-26450/storage/innobase/handler/ha_innodb.cc:9228
|
#10 0x000056143d61ed50 in ha_innobase::rnd_next (this=0x61d0001cdeb8, buf=0x61a0001674b8 "\375\n8888888888") at /data/Server/bb-10.5-MDEV-26450/storage/innobase/handler/ha_innodb.cc:9321
|
#11 0x000056143ccfa998 in handler::ha_rnd_next (this=0x61d0001cdeb8, buf=0x61a0001674b8 "\375\n8888888888") at /data/Server/bb-10.5-MDEV-26450/sql/handler.cc:3080
|
#12 0x000056143d10b870 in rr_sequential (info=0x7f01e9f95890) at /data/Server/bb-10.5-MDEV-26450/sql/records.cc:519
|
#13 0x000056143c3ee738 in READ_RECORD::read_record (this=0x7f01e9f95890) at /data/Server/bb-10.5-MDEV-26450/sql/records.h:80
|
#14 0x000056143c7fcc35 in copy_data_between_tables (thd=0x62b00009a218, from=0x6190000cc698, to=0x6190002ff898, create=..., ignore=false, order_num=0, order=0x0, copied=0x7f01e9f964f0, deleted=0x7f01e9f96510, keys_onoff=Alter_info::LEAVE_AS_IS, alter_ctx=0x7f01e9f978b0) at /data/Server/bb-10.5-MDEV-26450/sql/sql_table.cc:11463
|
#15 0x000056143c7f8491 in mysql_alter_table (thd=0x62b00009a218, new_db=0x56143e514640 <null_clex_str>, new_name=0x56143e514640 <null_clex_str>, create_info=0x7f01e9f98b90, table_list=0x62b0000a1368, alter_info=0x7f01e9f98a80, order_num=0, order=0x0, ignore=false, if_exists=false) at /data/Server/bb-10.5-MDEV-26450/sql/sql_table.cc:10873
|
#16 0x000056143c7fead3 in mysql_recreate_table (thd=0x62b00009a218, table_list=0x62b0000a1368, table_copy=false) at /data/Server/bb-10.5-MDEV-26450/sql/sql_table.cc:11696
|
#17 0x000056143c980167 in admin_recreate_table (thd=0x62b00009a218, table_list=0x62b0000a1368) at /data/Server/bb-10.5-MDEV-26450/sql/sql_admin.cc:61
|
#18 0x000056143c9874ed in mysql_admin_table (thd=0x62b00009a218, tables=0x62b0000a1368, check_opt=0x62b00009f480, operator_name=0x56143e6de6e0 "optimize", lock_type=TL_WRITE, org_open_for_modify=true, repair_table_use_frm=false, extra_open_options=0, prepare_func=0x0, operator_func=(int (handler::*)(class handler * const, class THD *, HA_CHECK_OPT *)) 0x56143cd05670 <handler::ha_optimize(THD*, st_ha_check_opt*)>, view_operator_func=0x0, is_cmd_replicated=true) at /data/Server/bb-10.5-MDEV-26450/sql/sql_admin.cc:1139
|
#19 0x000056143c989a9b in Sql_cmd_optimize_table::execute (this=0x62b0000a1a48, thd=0x62b00009a218) at /data/Server/bb-10.5-MDEV-26450/sql/sql_admin.cc:1502
|
#20 0x000056143c58c227 in mysql_execute_command (thd=0x62b00009a218) at /data/Server/bb-10.5-MDEV-26450/sql/sql_parse.cc:6056
|
#21 0x000056143c598764 in mysql_parse (thd=0x62b00009a218, rawbuf=0x62b0000a1238 "OPTIMIZE TABLE `test`.`t6`", length=26, parser_state=0x7f01e9f9acb0, is_com_multi=false, is_next_command=false) at /data/Server/bb-10.5-MDEV-26450/sql/sql_parse.cc:8100
|
#22 0x000056143c570816 in dispatch_command (command=COM_QUERY, thd=0x62b00009a218, packet=0x6290000dc219 "", packet_length=26, is_com_multi=false, is_next_command=false) at /data/Server/bb-10.5-MDEV-26450/sql/sql_parse.cc:1891
|
#23 0x000056143c56d8af in do_command (thd=0x62b00009a218) at /data/Server/bb-10.5-MDEV-26450/sql/sql_parse.cc:1370
|
#24 0x000056143c952e91 in do_handle_one_connection (connect=0x608000002b38, put_in_cache=true) at /data/Server/bb-10.5-MDEV-26450/sql/sql_connect.cc:1418
|
#25 0x000056143c9526af in handle_one_connection (arg=0x608000002b38) at /data/Server/bb-10.5-MDEV-26450/sql/sql_connect.cc:1312
|
#26 0x00007f021c0b3609 in start_thread (arg=<optimized out>) at pthread_create.c:477
|
#27 0x00007f021bc86293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
|
(rr)
|
I do not memorize to have hit this assert within this year.
|
mleich, thank you. I believe that the prominent FOREIGN KEY problem MDEV-26554 is limited to the 10.6 series only.
I have now updated the bb-10.6-MDEV-26450 branch with the bb-10.5-MDEV-26450 that you tested. Those branches will also include a fix of MDEV-26445.
The 10.5 failure feels a lot like a mismatch between t6.frm and the InnoDB data dictionary. I checked when the server was killed before the restarted server failed:
ssh sdp
|
rr replay /data/Results/1632322073/Marko/dev/shm/vardir/1632322073/164/1/rr/mysqld-1
|
continue
|
watch -l log_sys.flushed_to_disk_lsn._M_i
|
reverse-continue
|
backtrace
|
watch -l log_sys.lsn._M_i
|
reverse-continue
|
backtrace
|
…
|
The last durable log write was not for a DDL operation, but something else:
…
|
UPDATE t3 SET col1 = 1 ORDER BY col1 DESC LIMIT 2 /* E_R Thread2 QNO 10359 CON_ID 127 */; |
COMMIT /* E_R Thread2 QNO 10360 CON_ID 127 */; |
At the time of the last durable InnoDB log write, there is no DDL ongoing. But, after that, we find the smoking gun:
break ha_innobase::commit_inplace_alter_table
|
continue
|
backtrace
|
|
bb-10.5-MDEV-26450 2755e86a53cd89729d0cb54424fe83074dccd8ab |
#0 ha_innobase::commit_inplace_alter_table (this=0x61d0008a48b8, altered_table=0x7f6d1e37f990, ha_alter_info=0x7f6d1e37f2b0, commit=true)
|
at /data/Server/bb-10.5-MDEV-26450/storage/innobase/handler/handler0alter.cc:10907
|
#1 0x000055c34481ba04 in handler::ha_commit_inplace_alter_table (this=0x61d0008a48b8, altered_table=0x7f6d1e37f990, ha_alter_info=0x7f6d1e37f2b0, commit=true)
|
at /data/Server/bb-10.5-MDEV-26450/sql/handler.cc:4874
|
#2 0x000055c3442fa924 in mysql_inplace_alter_table (thd=0x62b0000fc218, table_list=0x62b000103418, table=0x619000518198, altered_table=0x7f6d1e37f990, ha_alter_info=0x7f6d1e37f2b0,
|
target_mdl_request=0x7f6d1e37f390, alter_ctx=0x7f6d1e3803f0) at /data/Server/bb-10.5-MDEV-26450/sql/sql_table.cc:8164
|
#3 0x000055c34430c3dd in mysql_alter_table (thd=0x62b0000fc218, new_db=0x62b000100a78, new_name=0x62b000100e98, create_info=0x7f6d1e381760, table_list=0x62b000103418, alter_info=0x7f6d1e381650, order_num=0,
|
order=0x0, ignore=false, if_exists=false) at /data/Server/bb-10.5-MDEV-26450/sql/sql_table.cc:10730
|
#4 0x000055c3444804e5 in Sql_cmd_alter_table::execute (this=0x62b000103c70, thd=0x62b0000fc218) at /data/Server/bb-10.5-MDEV-26450/sql/sql_alter.cc:539
|
#5 0x000055c3440a1227 in mysql_execute_command (thd=0x62b0000fc218) at /data/Server/bb-10.5-MDEV-26450/sql/sql_parse.cc:6056
|
#6 0x000055c3440ad764 in mysql_parse (thd=0x62b0000fc218,
|
rawbuf=0x62b000103238 "ALTER TABLE t6 MODIFY COLUMN col1 INT AFTER col_string, LOCK = EXCLUSIVE, ALGORITHM = NOCOPY /* E_R Thread2 QNO 10361 CON_ID 127 */", length=132, parser_state=0x7f6d1e382cb0,
|
is_com_multi=false, is_next_command=false) at /data/Server/bb-10.5-MDEV-26450/sql/sql_parse.cc:8100
|
This looks simply like the lack of MDEV-17567 Atomic DDL. That this DDL operation was not durably committed inside InnoDB before the server was killed could be enough information for us. We actually do get this far right before the server is killed:
(rr) backtrace
|
#0 0x000055c34520dda8 in commit_try_norebuild (ha_alter_info=0x7f6d1e37f2b0, ctx=0x62b000105a28, altered_table=0x7f6d1e37f990, old_table=0x619000518198, trx=0x7f6d436dbdc8, table_name=0x61b0000c854d "t6")
|
at /data/Server/bb-10.5-MDEV-26450/storage/innobase/handler/handler0alter.cc:10346
|
#1 0x000055c3451e7664 in ha_innobase::commit_inplace_alter_table (this=0x61d0008a48b8, altered_table=0x7f6d1e37f990, ha_alter_info=0x7f6d1e37f2b0, commit=true)
|
at /data/Server/bb-10.5-MDEV-26450/storage/innobase/handler/handler0alter.cc:11109
|
#2 0x000055c34481ba04 in handler::ha_commit_inplace_alter_table (this=0x61d0008a48b8, altered_table=0x7f6d1e37f990, ha_alter_info=0x7f6d1e37f2b0, commit=true)
|
at /data/Server/bb-10.5-MDEV-26450/sql/handler.cc:4874
|
#3 0x000055c3442fa924 in mysql_inplace_alter_table (thd=0x62b0000fc218, table_list=0x62b000103418, table=0x619000518198, altered_table=0x7f6d1e37f990, ha_alter_info=0x7f6d1e37f2b0,
|
target_mdl_request=0x7f6d1e37f390, alter_ctx=0x7f6d1e3803f0) at /data/Server/bb-10.5-MDEV-26450/sql/sql_table.cc:8164
|
#4 0x000055c34430c3dd in mysql_alter_table (thd=0x62b0000fc218, new_db=0x62b000100a78, new_name=0x62b000100e98, create_info=0x7f6d1e381760, table_list=0x62b000103418, alter_info=0x7f6d1e381650, order_num=0,
|
order=0x0, ignore=false, if_exists=false) at /data/Server/bb-10.5-MDEV-26450/sql/sql_table.cc:10730
|
#5 0x000055c3444804e5 in Sql_cmd_alter_table::execute (this=0x62b000103c70, thd=0x62b0000fc218) at /data/Server/bb-10.5-MDEV-26450/sql/sql_alter.cc:539
|
#6 0x000055c3440a1227 in mysql_execute_command (thd=0x62b0000fc218) at /data/Server/bb-10.5-MDEV-26450/sql/sql_parse.cc:6056
|
#7 0x000055c3440ad764 in mysql_parse (thd=0x62b0000fc218,
|
rawbuf=0x62b000103238 "ALTER TABLE t6 MODIFY COLUMN col1 INT AFTER col_string, LOCK = EXCLUSIVE, ALGORITHM = NOCOPY /* E_R Thread2 QNO 10361 CON_ID 127 */", length=132, parser_state=0x7f6d1e382cb0,
|
is_com_multi=false, is_next_command=false) at /data/Server/bb-10.5-MDEV-26450/sql/sql_parse.cc:8100
|
…
|
(rr) finish
|
Run till exit from #0 0x000055c34520dda8 in commit_try_norebuild (ha_alter_info=0x7f6d1e37f2b0, ctx=0x62b000105a28, altered_table=0x7f6d1e37f990, old_table=0x619000518198, trx=0x7f6d436dbdc8,
|
table_name=0x61b0000c854d "t6") at /data/Server/bb-10.5-MDEV-26450/storage/innobase/handler/handler0alter.cc:10346
|
0x000055c3451e7664 in ha_innobase::commit_inplace_alter_table (this=0x61d0008a48b8, altered_table=0x7f6d1e37f990, ha_alter_info=0x7f6d1e37f2b0, commit=true)
|
at /data/Server/bb-10.5-MDEV-26450/storage/innobase/handler/handler0alter.cc:11109
|
11109 fail = commit_try_norebuild(
|
Value returned is $28 = false
|
(rr)
|
Run till exit from #0 0x000055c3451e7664 in ha_innobase::commit_inplace_alter_table (this=0x61d0008a48b8, altered_table=0x7f6d1e37f990, ha_alter_info=0x7f6d1e37f2b0, commit=true)
|
at /data/Server/bb-10.5-MDEV-26450/storage/innobase/handler/handler0alter.cc:11109
|
|
|
Thread 3 received signal SIGKILL, Killed.
|
[Switching to Thread 79076.104468]
|
So, due to the broken DDL design that was only fixed in 10.6, we got an inconsistency between t6.frm and InnoDB. That this dictionary inconsistency (columns being swapped) was not flagged by CHECK TABLE should be worth a new bug report.
For the 10.5 recovery problem, I filed MDEV-26668 CHECK TABLE fails to report schema mismatch
origin/bb-10.6-MDEV-26450 456479690b9ee38b0b8a912bf4b6217952c5903b 2021-09-23T11:21:51+03:00
|
which should contain fixes for MDEV-26450 and MDEV-26445 behaved well in RQG testing.
|
I can get some occasional crashes when running innodb.undo_truncate on a 10.6 RelWithDebInfo build. One of them was in neighbor flushing. Even with the following, I got a crash in fil_invalid_page_access_msg() during a page flush:
/mtr --mysqld=--innodb-flush-neighbors=0 --repeat=10 --parallel=auto innodb.undo_truncate{,,,,,,,,,,}So, we already have a somewhat workable test case.