Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Won't Fix
-
10.2(EOL), 10.3(EOL), 10.4(EOL), 10.5
Description
The test case uses innodb_background_scrub_data_uncompressed, but I don't think it's absolutely necessary for the assertion failure to happen, apparently it just makes it reasonably reproducible. The identical failure was observed without any scrubbing-related options (but with encryption enabled) upon upgrade from MySQL 5.7.24 to 10.2.
- The test case is non-deterministic and it uses a loop. Please don't put it into the regression suite, it's for reproducing purposes only.
- Run with --repeat=N if it doesn't fail right away. It usually fails for me within 3 attempts. Increasing the number of loops doesn't seem to increase the probability. Make sure the server is restarted between attempts (in the test case below, the commented part of the cleanup makes sure of that).
- Run with --mem or on SSD. I don't know if it's reproducible on a spinning disk, the test case takes too long.
- Remember to run with encryption options.
|
Run with |
--mysqld=--innodb-encrypt-tables --mysqld=--innodb-encryption-threads=4 --mysqld=--file-key-management --mysqld=--plugin-load-add=file_key_management --mysqld=--file-key-management-filename=`pwd`/std_data/keys.txt --mysqld=--plugin-load-add=file_key_management --repeat=5 --mem
|
--source include/have_innodb.inc
|
|
|
SET @scrub.save= @@innodb_background_scrub_data_uncompressed; |
|
|
--connect (con1,localhost,root,,)
|
CREATE TABLE t1 (pk INT, a INT, PRIMARY KEY(pk)) ENGINE=InnoDB; |
INSERT INTO t1 VALUES (1,2),(2,3),(3,4),(4,5),(5,6),(6,7),(7,8),(8,9); |
SET GLOBAL innodb_background_scrub_data_uncompressed=ON; |
--disconnect con1
|
|
|
--connection default
|
--let $i= 1000
|
while ($i)
|
{
|
--eval ALTER TABLE t1 FORCE /* $i */ |
--dec $i |
}
|
|
|
# Cleanup
|
--delimiter ;
|
DROP TABLE t1; |
|
|
# This is intentionally commented, so that when you run with --repeat, |
# the server is restarted every time between the runs |
# SET GLOBAL innodb_background_scrub_data_uncompressed = @scrub.save; |
|
10.4 18af13b8 debug |
mysqld: /data/src/10.4/storage/innobase/include/buf0flu.ic:65: void buf_flush_note_modification(buf_block_t*, lsn_t, lsn_t, FlushObserver*): Assertion `block->page.flush_observer == __null || block->page.flush_observer == observer' failed.
|
190906 18:34:16 [ERROR] mysqld got signal 6 ;
|
|
|
#7 0x00007fb27288ef12 in __GI___assert_fail (assertion=0x555abe139f18 "block->page.flush_observer == __null || block->page.flush_observer == observer", file=0x555abe139e18 "/data/src/10.4/storage/innobase/include/buf0flu.ic", line=65, function=0x555abe13bd80 <_ZZL27buf_flush_note_modificationP11buf_block_tmmP13FlushObserverE19__PRETTY_FUNCTION__> "void buf_flush_note_modification(buf_block_t*, lsn_t, lsn_t, FlushObserver*)") at assert.c:101
|
#8 0x0000555abd8836da in buf_flush_note_modification (block=0x7fb26782a8f8, start_lsn=484825, end_lsn=484831, observer=0x0) at /data/src/10.4/storage/innobase/include/buf0flu.ic:65
|
#9 0x0000555abd887420 in ReleaseBlocks::add_dirty_page_to_flush_list (this=0x7fb24d7f9780, slot=0x7fb24d7f98e8) at /data/src/10.4/storage/innobase/mtr/mtr0mtr.cc:379
|
#10 0x0000555abd88746f in ReleaseBlocks::operator() (this=0x7fb24d7f9780, slot=0x7fb24d7f98e8) at /data/src/10.4/storage/innobase/mtr/mtr0mtr.cc:390
|
#11 0x0000555abd88829e in CIterate<ReleaseBlocks const>::operator() (this=0x7fb24d7f9780, block=0x7fb24d7f98d8) at /data/src/10.4/storage/innobase/mtr/mtr0mtr.cc:60
|
#12 0x0000555abd887c0c in mtr_buf_t::for_each_block_in_reverse<CIterate<ReleaseBlocks const> > (this=0x7fb24d7f98a0, functor=...) at /data/src/10.4/storage/innobase/include/dyn0buf.h:371
|
#13 0x0000555abd886282 in mtr_t::Command::release_blocks (this=0x7fb24d7f97f0) at /data/src/10.4/storage/innobase/mtr/mtr0mtr.cc:885
|
#14 0x0000555abd8863c5 in mtr_t::Command::execute (this=0x7fb24d7f97f0) at /data/src/10.4/storage/innobase/mtr/mtr0mtr.cc:910
|
#15 0x0000555abd8845b5 in mtr_t::commit (this=0x7fb24d7f98a0) at /data/src/10.4/storage/innobase/mtr/mtr0mtr.cc:558
|
#16 0x0000555abdb6efdb in fil_crypt_rotate_page (key_state=0x7fb24d7f9e34, state=0x7fb24d7f9e40) at /data/src/10.4/storage/innobase/fil/fil0crypt.cc:2052
|
#17 0x0000555abdb6f6f4 in fil_crypt_rotate_pages (key_state=0x7fb24d7f9e34, state=0x7fb24d7f9e40) at /data/src/10.4/storage/innobase/fil/fil0crypt.cc:2179
|
#18 0x0000555abdb701e1 in fil_crypt_thread () at /data/src/10.4/storage/innobase/fil/fil0crypt.cc:2403
|
#19 0x00007fb2744034a4 in start_thread (arg=0x7fb24d7fa700) at pthread_create.c:456
|
#20 0x00007fb27294bd0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
|
Reproducible on 10.2+.
Couldn't reproduce on 10.1.
No immediate obvious effect on a release build.
Attachments
Issue Links
- is blocked by
-
-
- Closed
-
-
-
- Closed
-
- relates to
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Confirmed
-
(2 relates to)
Activity
When running some RQG test round on actual (2019-08) 10.3 the assert mentioned on top
|
showed up only if innodb_log_optimize_ddl was set to ON.
|
perl rqg.pl \
|
--mysqld=--innodb_adaptive_hash_index=OFF \
|
--mysqld=--innodb_use_native_aio=0 \
|
--mysqld=--innodb_log_optimize_ddl=ON \
|
--no-mask --duration=300 --engine=InnoDB --queries=100000000 \
|
--reporters=Backtrace,ErrorLog,RestartConsistency --restart_timeout=30\
|
--mysqld=--log_output=FILE --sqltrace=MarkErrors \
|
--grammar=conf/mariadb/innodb_compression_encryption.yy --gendata=conf/mariadb/innodb_compression_encryption.zz \
|
--mysqld=--loose-innodb-use-atomic-writes \
|
--mysqld=--plugin-load-add=file_key_management.so --mysqld=--loose-file-key-management-filename=conf/mariadb/encryption_keys.txt \
|
--mysqld=--loose-innodb_buffer_pool_instances=1 --mysqld=--loose-innodb_doublewrite=0 \
|
--mysqld=--loose-innodb-encryption-threads=1 --threads=13 \
|
--workdir=.... --vardir=.... --mtr-build-thread=.... --basedir1=.... --seed=1565710950
|
MDEV-15528 removed or replaced the background scrubbing in 10.5.2 with something that adheres to the tried-and-true write-ahead-logging protocol.
I can repeat two different things with the test case.
- fil_space_crypt_t::write_page0() is being invoked on a freed page, and a debug assertion in mlog_write_initial_log_record_low() will fail because of space_id=4278124286, page_no=4278124286 (0xfefefefe)
- With ./mtr --rr, I got the reported assertion failure.
I would suspect that the background scrubbing is violating the latching rules. It might be a fundamental design problem that was fixed in MDEV-15528 by performing the scrubbing of freed pages via the normal page flushing mechanism. I will analyze the rr replay trace to find out if we can ‘rescue’ any part of this. (Scrubbing never worked reliably until MDEV-8139 was fixed by MDEV-15528.)
The reported assertion failure looks like a race condition between the encryption threads and native ALTER TABLE that is creating secondary indexes or rebuilding tables while the default setting innodb_log_optimize_ddl=ON is enabled. I do not think that this is limited to scrubbing.
Here are the relevant details from my trace:
|
10.2 01738d08f30315f10c14faa605d0087e54156cd0 |
Thread 32 hit Hardware watchpoint 1: -location $4->page.flush_observer
|
|
|
Old value = (FlushObserver *) 0x0
|
New value = (FlushObserver *) 0x7fdf400459d0
|
buf_flush_note_modification (block=0x7fdfbd164700, start_lsn=1778329,
|
end_lsn=<optimized out>, observer=0x7fdf400459d0)
|
at /mariadb/10.2o/storage/innobase/include/buf0flu.ic:93
|
93 if (block->page.oldest_modification == 0) {
|
(rr) bt
|
#0 buf_flush_note_modification (block=0x7fdfbd164700, start_lsn=1778329,
|
end_lsn=<optimized out>, observer=0x7fdf400459d0)
|
at /mariadb/10.2o/storage/innobase/include/buf0flu.ic:93
|
#1 ReleaseBlocks::add_dirty_page_to_flush_list (this=<optimized out>,
|
slot=<optimized out>) at /mariadb/10.2o/storage/innobase/mtr/mtr0mtr.cc:333
|
#2 0x000055826346556c in ReleaseBlocks::operator() (this=0x7fdf9c0ef908,
|
slot=<optimized out>) at /mariadb/10.2o/storage/innobase/mtr/mtr0mtr.cc:345
|
#3 CIterate<ReleaseBlocks const>::operator() (this=0x7fdf9c0ef908,
|
block=<optimized out>) at /mariadb/10.2o/storage/innobase/mtr/mtr0mtr.cc:58
|
#4 dyn_buf_t<512ul>::for_each_block_in_reverse<CIterate<ReleaseBlocks const> >
|
(this=<optimized out>, functor=
|
@0x7fdf9c0ef908: {functor = {m_end_lsn = 1778329, m_start_lsn = 1778329, m_flush_observer = 0x7fdf400459d0}})
|
at /mariadb/10.2o/storage/innobase/include/dyn0buf.h:378
|
#5 0x0000558263462f07 in mtr_t::commit (this=0x7fdf9c0ef9e8)
|
at /mariadb/10.2o/storage/innobase/mtr/mtr0mtr.cc:454
|
#6 0x00005582635c5bb1 in BtrBulk::pageCommit (this=0x7fdf40060ea0,
|
page_bulk=0x7fdf9c0ef9d8, next_page_bulk=0x0, insert_father=false)
|
at /mariadb/10.2o/storage/innobase/btr/btr0bulk.cc:813
|
#7 0x00005582635c70f7 in BtrBulk::finish (this=0x7fdf40060ea0, err=DB_SUCCESS)
|
at /mariadb/10.2o/storage/innobase/btr/btr0bulk.cc:1082
|
#8 0x00005582634d691c in row_merge_read_clustered_index (trx=<optimized out>,
|
table=<optimized out>, old_table=<optimized out>,
|
…
|
(rr) thr 3
|
[Switching to thread 3 (Thread 21707.21730)]
|
#0 0x00007fdfc3b0f537 in sched_yield () at ./src/preload/overrides.c:160
|
160 ./src/preload/overrides.c: Tiedostoa tai hakemistoa ei ole.
|
(rr) bt
|
#0 0x00007fdfc3b0f537 in sched_yield () at ./src/preload/overrides.c:160
|
#1 0x0000558263557235 in rw_lock_x_lock_func (lock=0x7fdfbd1647c0,
|
pass=<optimized out>,
|
file_name=0x558263a5884c "/mariadb/10.2o/storage/innobase/fil/fil0crypt.cc", line=1816) at /mariadb/10.2o/storage/innobase/sync/sync0rw.cc:698
|
#2 0x000055826360afb1 in pfs_rw_lock_x_lock_func (lock=0x7fdfbd1647c0,
|
pass=0,
|
file_name=0x558263a5884c "/mariadb/10.2o/storage/innobase/fil/fil0crypt.cc", line=1816) at /mariadb/10.2o/storage/innobase/include/sync0rw.ic:544
|
#3 buf_page_mtr_lock (block=0x7fdfbd164700, rw_latch=<optimized out>,
|
mtr=0x7fdf73ffe960,
|
file=0x558263a5884c "/mariadb/10.2o/storage/innobase/fil/fil0crypt.cc",
|
line=1816) at /mariadb/10.2o/storage/innobase/buf/buf0buf.cc:4190
|
#4 0x0000558263609926 in buf_page_get_low (page_id=
|
{m_space = 22, m_page_no = 3}, page_size=
|
@0x7fdf73ffe790: {m_physical = 16384, m_logical = 16384, m_is_compressed = 0}, rw_latch=140597700589312, guess=0x7fdfbd164700, mode=<optimized out>,
|
file=0x558263a5884c "/mariadb/10.2o/storage/innobase/fil/fil0crypt.cc",
|
line=1816, mtr=0x7fdf73ffe960, err=0x7fdf73ffe79c)
|
at /mariadb/10.2o/storage/innobase/buf/buf0buf.cc:4860
|
#5 0x000055826360b481 in buf_page_get_gen (page_id=<optimized out>,
|
page_size=<optimized out>, rw_latch=<optimized out>,
|
guess=<optimized out>, mode=<optimized out>, file=<optimized out>,
|
…
|
(rr) when
|
Current event: 358704
|
(rr) c
|
Continuing.
|
|
|
Thread 3 received signal SIGABRT, Aborted.
|
__GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
|
50 ../sysdeps/unix/sysv/linux/raise.c: Tiedostoa tai hakemistoa ei ole.
|
(rr) when
|
Current event: 359656
|
(rr) bt
|
…
|
#3 0x00007fdfc303d5b2 in __GI___assert_fail (
|
assertion=0x5582639f810b "block->page.flush_observer == __null || block->page.flush_observer == observer",
|
file=0x5582639f4a44 "/mariadb/10.2o/storage/innobase/include/buf0flu.ic",
|
line=90,
|
function=0x5582639f80bc "void buf_flush_note_modification(buf_block_t *, lsn_t, lsn_t, FlushObserver *)") at assert.c:101
|
#4 0x000055826346613c in buf_flush_note_modification (block=0x7fdfbd164700,
|
start_lsn=<optimized out>, end_lsn=<optimized out>,
|
observer=<optimized out>)
|
at /mariadb/10.2o/storage/innobase/include/buf0flu.ic:89
|
#5 ReleaseBlocks::add_dirty_page_to_flush_list (this=<optimized out>,
|
slot=<optimized out>) at /mariadb/10.2o/storage/innobase/mtr/mtr0mtr.cc:333
|
#6 0x000055826346556c in ReleaseBlocks::operator() (this=0x7fdf73ffe778,
|
slot=<optimized out>) at /mariadb/10.2o/storage/innobase/mtr/mtr0mtr.cc:345
|
#7 CIterate<ReleaseBlocks const>::operator() (this=0x7fdf73ffe778,
|
block=<optimized out>) at /mariadb/10.2o/storage/innobase/mtr/mtr0mtr.cc:58
|
#8 dyn_buf_t<512ul>::for_each_block_in_reverse<CIterate<ReleaseBlocks const> >
|
(this=<optimized out>, functor=
|
@0x7fdf73ffe778: {functor = {m_end_lsn = 1778377, m_start_lsn = 1778371, m_flush_observer = 0x0}})
|
at /mariadb/10.2o/storage/innobase/include/dyn0buf.h:378
|
#9 0x0000558263462f07 in mtr_t::commit (this=0x7fdf73ffe960)
|
at /mariadb/10.2o/storage/innobase/mtr/mtr0mtr.cc:454
|
#10 0x00005582636a11db in fil_crypt_rotate_page (key_state=<optimized out>,
|
state=0x7fdf73ffe840)
|
at /mariadb/10.2o/storage/innobase/fil/fil0crypt.cc:1879
|
#11 fil_crypt_rotate_pages (key_state=<optimized out>, state=0x7fdf73ffe840)
|
at /mariadb/10.2o/storage/innobase/fil/fil0crypt.cc:2006
|
#12 fil_crypt_thread ()
|
at /mariadb/10.2o/storage/innobase/fil/fil0crypt.cc:2235
|
In this observed case, the encryption thread is marking dirty a page on which redo logging has been disabled. The assertion fails, because we expect there not to exist any FlushObserver.
If I work around this problem by SET GLOBAL innodb_log_optimize_ddl=OFF, I can still repeat the fil_space_crypt_t::write_page0() problem. That one is much harder to reproduce in rr, but I will keep trying. I already got an incomplete trace once.
For the record, the remaining failure looks like this:
|
10.2 01738d08f30315f10c14faa605d0087e54156cd0 |
Version: '10.2.34-MariaDB-debug-log' socket: '/dev/shm/10.2o/mysql-test/var/tmp/mysqld.1.sock' port: 16000 Source distribution
|
mysqld: /mariadb/10.2o/storage/innobase/include/mtr0log.ic:192: byte *mlog_write_initial_log_record_low(mlog_id_t, ulint, ulint, byte *, mtr_t *): Assertion `type == MLOG_FILE_NAME || type == MLOG_FILE_DELETE || type == MLOG_FILE_CREATE2 || type == MLOG_FILE_RENAME2 || type == MLOG_INDEX_LOAD || type == MLOG_TRUNCATE || type == MLOG_FILE_WRITE_CRYPT_DATA || mtr->is_named_space(space_id)' failed.
|
…
|
#8 0x0000561f63730078 in mlog_write_initial_log_record_low (type=MLOG_WRITE_STRING, space_id=4278124286, page_no=4278124286, log_ptr=0x7f59637fd560 "\036\201\211", mtr=0x7f59637fd2d8) at /mariadb/10.2o/storage/innobase/include/mtr0log.ic:185
|
The originally reported bug can be worked around by setting innodb_log_optimize_ddl=OFF in 10.2, 10.3, 10.4.
ralf.gebhardt@mariadb.com, should we change the parameter to the safe setting by default? It is only unsafe in this respect when encryption threads are enabled via other settings, such as innodb_encrypt_tables.
marko said on Slack: