[MDEV-17596] Assertion `block->page.flush_observer == __null || block->page.flush_observer == observer' failed in buf_flush_note_modification Created: 2018-11-01  Updated: 2020-08-22  Resolved: 2020-08-12

Status: Closed
Project: MariaDB Server
Component/s: Encryption, Storage Engine - InnoDB
Affects Version/s: 10.2, 10.3, 10.4, 10.5
Fix Version/s: 10.5.2

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Marko Mäkelä
Resolution: Won't Fix Votes: 0
Labels: rr-profile-analyzed

Issue Links:
Blocks
is blocked by MDEV-8139 Fix scrubbing Closed
is blocked by MDEV-15528 Avoid writing freed InnoDB pages Closed
Relates
relates to MDEV-19747 Deprecate and ignore innodb_log_optim... Closed
relates to MDEV-20399 SEGV in fil_system_t::keyrotate_next ... Closed
relates to MDEV-23456 fil_space_crypt_t::write_page0() is a... Closed
relates to MDEV-12967 innodb-encryption-threads with scrubb... Closed
relates to MDEV-23165 Assertion `level <= 50' failed in btr... Confirmed

 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.

 Comments   
Comment by Elena Stepanova [ 2018-11-02 ]

marko said on Slack:

The `buf_page_t::flush_observer` should only be non-NULL during `FLUSH TABLES FOR EXPORT` or certain `ALTER TABLE`. I would guess that either one set the pointer, but then for some reason did not reset it back to `NULL`.

Comment by Matthias Leich [ 2019-08-14 ] 

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

Comment by Marko Mäkelä [ 2020-03-04 ]

MDEV-19747 removed the FlushObserver in 10.5.1.

Comment by Marko Mäkelä [ 2020-08-12 ]

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.)

Comment by Marko Mäkelä [ 2020-08-12 ]

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

Comment by Marko Mäkelä [ 2020-08-12 ]

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.

Generated at Thu Feb 08 08:37:40 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.