[MDEV-23260] Draft: Crash when running encryption.innodb-encryption-alter-cbc,innodb - Jira

Matthias Leich created issue - 2020-07-22 15:38

Marko Mäkelä added a comment - 2020-07-23 05:54 - edited

I think that the fatal error message is worth mentioning. Quoting the buildbot log:

10.2 6898eae7f8ef3f0b773687c0308520f072da0bc9

2020-07-22  6:20:40 140227487697216 [ERROR] [FATAL] InnoDB: Trying to read page number 4278108161 in space 0, space name innodb_system, which is outside the tablespace bounds. Byte offset 0, len 16384Please check that the configuration matches the InnoDB system tablespace location (ibdata files)

The value 4278108161 is 0xFEFEC001.

thiru reported that when he repeated this failure locally by repeatedly running something like

./mtr --parallel=auto --mysqld=--debug=d,ib_log_checkpoint_avoid --repeat=100 encryption.innodb-encryption-alter,cbc,innodb{,,,}

he found a request for the invalid page number 4278124286 (0xFEFEFEFE) which prompted a read request for the corresponding change buffer bitmap page 0xFEFEC001.

The value 0xfe is being written to buf_block_t::frame in the function buf_LRU_block_free_non_file_page(), but ít is not established yet whether there is any connection to that.

Marko Mäkelä added a comment - 2020-07-23 05:54 - edited I think that the fatal error message is worth mentioning. Quoting the buildbot log : 10.2 6898eae7f8ef3f0b773687c0308520f072da0bc9 2020-07-22 6:20:40 140227487697216 [ERROR] [FATAL] InnoDB: Trying to read page number 4278108161 in space 0, space name innodb_system, which is outside the tablespace bounds. Byte offset 0, len 16384Please check that the configuration matches the InnoDB system tablespace location (ibdata files) The value 4278108161 is 0xFEFEC001. thiru reported that when he repeated this failure locally by repeatedly running something like ./mtr --parallel=auto --mysqld=--debug=d,ib_log_checkpoint_avoid --repeat=100 encryption.innodb-encryption-alter,cbc,innodb{,,,} he found a request for the invalid page number 4278124286 (0xFEFEFEFE) which prompted a read request for the corresponding change buffer bitmap page 0xFEFEC001. The value 0xfe is being written to buf_block_t::frame in the function buf_LRU_block_free_non_file_page() , but ít is not established yet whether there is any connection to that.

Matthias Leich made changes - 2020-07-24 15:25

Field	Original Value	New Value
Attachment		MDEV-23260B.test [ 52954 ]

Matthias Leich added a comment - 2020-07-24 15:31

MDEV-23260B.test   is a simplified version of the original test.

I made several hundred attempts to replay the problem when the tool "rr" is invoked.

while ./mtr --parallel=`nproc` --vardir=/dev/shm/omo --rr --rr-arg="-h" --mysqld="--debug_dbug=d,ib_log_checkpoint_avoid" --mysqld=--innodb_log_files_in_group=1 --mysqld=--innodb_log_buffer_size=1048576 --mysqld=--innodb_log_file_size=2097152 encryption.MDEV-23260B{,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,}; do :; done

None of these tests replayed the problem.

When omitting "rr"

while ./mtr --parallel=`nproc` --vardir=/dev/shm/omo  --mysqld="--debug_dbug=d,ib_log_checkpoint_avoid" --mysqld=--innodb_log_files_in_group=1 --mysqld=--innodb_log_buffer_size=1048576 --mysqld=--innodb_log_file_size=2097152 encryption.MDEV-23260B{,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,}; do :; done

a replay comes quite fast.

I am giving up with replay attempts using "rr".

Matthias Leich added a comment - 2020-07-24 15:31 MDEV-23260B.test is a simplified version of the original test. I made several hundred attempts to replay the problem when the tool "rr" is invoked. while ./mtr --parallel=`nproc` --vardir=/dev/shm/omo --rr --rr-arg="-h" --mysqld="--debug_dbug=d,ib_log_checkpoint_avoid" --mysqld=--innodb_log_files_in_group=1 --mysqld=--innodb_log_buffer_size=1048576 --mysqld=--innodb_log_file_size=2097152 encryption.MDEV-23260B{,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,}; do :; done None of these tests replayed the problem. When omitting "rr" while ./mtr --parallel=`nproc` --vardir=/dev/shm/omo --mysqld="--debug_dbug=d,ib_log_checkpoint_avoid" --mysqld=--innodb_log_files_in_group=1 --mysqld=--innodb_log_buffer_size=1048576 --mysqld=--innodb_log_file_size=2097152 encryption.MDEV-23260B{,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,}; do :; done a replay comes quite fast. I am giving up with replay attempts using "rr".

Marko Mäkelä added a comment - 2020-08-10 11:57

I got this failure again on 10.2 with some cleanup and a fix of ~~MDEV-16115~~:

10.2 845e3c9801d17905bf2392f27cda66669c00f75f
encryption.innodb-encryption-alter 'cbc,innodb' w54 [ fail ]
…
2020-08-10 14:44:46 140695089317824 [Note] InnoDB: Starting final batch to recover 69 pages from redo log.
2020-08-10 14:44:46 140695089317824 [ERROR] [FATAL] InnoDB: Trying to read page number 4278108161 in space 0, space name innodb_system, which is outside the tablespace bounds. Byte offset 0, len 16384Please check that the configuration matches the InnoDB system tablespace location (ibdata files)

mleich, could you try the following variation of the test:

Kill the server just like we used to do it.
Before the attempt to restart the server, back up the data directory.
Start up the server.
If the recovery failed in this way, attach the backed-up data directory.

Once we have a copy of a data directory where the recovery may fail, I believe that it should be possible to repeat the recovery failure under rr replay. I think that the error is something that happens during recovery, and does not necessarily depend on any error that occurred before the server was killed.

Marko Mäkelä added a comment - 2020-08-10 11:57 I got this failure again on 10.2 with some cleanup and a fix of MDEV-16115 : 10.2 845e3c9801d17905bf2392f27cda66669c00f75f encryption.innodb-encryption-alter 'cbc,innodb' w54 [ fail ] … 2020-08-10 14:44:46 140695089317824 [Note] InnoDB: Starting final batch to recover 69 pages from redo log. 2020-08-10 14:44:46 140695089317824 [ERROR] [FATAL] InnoDB: Trying to read page number 4278108161 in space 0, space name innodb_system, which is outside the tablespace bounds. Byte offset 0, len 16384Please check that the configuration matches the InnoDB system tablespace location (ibdata files) mleich , could you try the following variation of the test: Kill the server just like we used to do it. Before the attempt to restart the server, back up the data directory. Start up the server. If the recovery failed in this way, attach the backed-up data directory. Once we have a copy of a data directory where the recovery may fail, I believe that it should be possible to repeat the recovery failure under rr replay . I think that the error is something that happens during recovery, and does not necessarily depend on any error that occurred before the server was killed.

Thirunarayanan Balathandayuthapani added a comment - 2020-08-31 10:44

I added the assert in mtr_t::finish_write to check whether page no > 10000 to crash. (I put 10000 as kind of big number)

#0  my_read (Filedes=69,

    Buffer=0x7f84867f9d00 "Limit", ' ' <repeats 21 times>, "Soft Limit", ' ' <repeats 11 times>, "Hard Limit", ' ' <repeats 11 times>, "Units     \nMax cpu time", ' ' <repeats 14 times>, "unlimited", ' ' <repeats 12 times>, "unlimited", ' ' <repeats 12 times>, "seconds   \nMax file size", ' ' <repeats 13 times>, "unlimited       "..., Count=4096, MyFlags=0) at ../mysys/my_read.c:63

#1  0x000055e136b73db0 in output_core_info () at ../sql/signal_handler.cc:66

#2  0x000055e136b745a8 in handle_fatal_signal (sig=6) at ../sql/signal_handler.cc:339

#3  <signal handler called>

#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50

#5  0x00007f84d17ab859 in __GI_abort () at abort.c:79

#6  0x00007f84d17ab729 in __assert_fail_base (fmt=0x7f84d1941588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55e13752aa5d "page_no < 10000",

    file=0x55e13752a9d0 "../storage/innobase/include/log0log.ic", line=344, function=<optimized out>) at assert.c:92

#7  0x00007f84d17bcf36 in __GI___assert_fail (assertion=0x55e13752aa5d "page_no < 10000", file=0x55e13752a9d0 "../storage/innobase/include/log0log.ic",

    line=344, function=0x55e13752a990 "lsn_t log_reserve_and_write_fast(const void*, ulint, lsn_t*)") at assert.c:101

#8  0x000055e136e30b00 in log_reserve_and_write_fast (str=0x7f84867fbb38, len=10, start_lsn=0x7f84867fb7a0) at ../storage/innobase/include/log0log.ic:344

#9  0x000055e136e31c74 in mtr_t::finish_write (this=0x7f84867fb8b0, len=10) at ../storage/innobase/mtr/mtr0mtr.cc:766

#10 0x000055e136e2f614 in mtr_t::commit (this=0x7f84867fb8b0) at ../storage/innobase/mtr/mtr0mtr.cc:442

#11 0x000055e13707dff3 in fil_crypt_rotate_page (key_state=0x7f84867fbe14, state=0x7f84867fbe20) at ../storage/innobase/fil/fil0crypt.cc:1879

#12 0x000055e13707e4f0 in fil_crypt_rotate_pages (key_state=0x7f84867fbe14, state=0x7f84867fbe20) at ../storage/innobase/fil/fil0crypt.cc:2006

#13 0x000055e13707eeb3 in fil_crypt_thread () at ../storage/innobase/fil/fil0crypt.cc:2235

#14 0x00007f84d1cce609 in start_thread (arg=<optimized out>) at pthread_create.c:477

#15 0x00007f84d18a8103 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

(gdb) f 8

#8  0x000055e136e30b00 in log_reserve_and_write_fast (str=0x7f84867fbb38, len=10, start_lsn=0x7f84867fb7a0) at ../storage/innobase/include/log0log.ic:344

344	            ut_ad(page_no < 10000);

(gdb) p page_no

$11 = 4278124286

(gdb) p state

$12 = (rotate_thread_t *) 0x7f84867fbe20

(gdb) p *state

$13 = {thread_no = 0, first = false, space = 0x55e139b83b50, offset = 408, batch = 60, min_key_version_found = 0, end_lsn = 1797229,

  estimated_max_iops = 20, allocated_iops = 20, cnt_waited = 8, sum_waited_us = 842, crypt_stat = {pages_read_from_cache = 40, pages_read_from_disk = 8,

    pages_modified = 40, pages_flushed = 0, estimated_iops = 20}, scrub_data = {space = 0, scrubbing = false, compressed = false, current_table = 0x0,

    current_index = 0x0, savepoint = 0, scrub_stat = {page_reorganizations = 0, page_splits = 0, page_split_failures_underflow = 0,

      page_split_failures_out_of_filespace = 0, page_split_failures_missing_index = 0, page_split_failures_unknown = 0}}}

(gdb) p state->space->name

$14 = 0x55e139b83d30 "innodb_system"

[Switching to thread 25 (Thread 0x7f84cc496700 (LWP 41995))]

#0  futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x55e139ac0098) at ../sysdeps/nptl/futex-internal.h:183

183	../sysdeps/nptl/futex-internal.h: No such file or directory.

(gdb) where

#0  futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x55e139ac0098) at ../sysdeps/nptl/futex-internal.h:183

#1  __pthread_cond_wait_common (abstime=0x0, clockid=0, mutex=0x55e139ac0048, cond=0x55e139ac0070) at pthread_cond_wait.c:508

#2  __pthread_cond_wait (cond=0x55e139ac0070, mutex=0x55e139ac0048) at pthread_cond_wait.c:638

#3  0x000055e136e3f082 in os_event::wait (this=0x55e139ac0030) at ../storage/innobase/os/os0event.cc:158

#4  0x000055e136e3eb32 in os_event::wait_low (this=0x55e139ac0030, reset_sig_count=1) at ../storage/innobase/os/os0event.cc:325

#5  0x000055e136e3ee4c in os_event_wait_low (event=0x55e139ac0030, reset_sig_count=1) at ../storage/innobase/os/os0event.cc:507

#6  0x000055e136f32eab in sync_array_wait_event (arr=0x55e139a35b90, cell=@0x7f84cc48fe80: 0x7f84ccbf70d0) at ../storage/innobase/sync/sync0arr.cc:471

#7  0x000055e136f36815 in rw_lock_sx_lock_func (lock=0x7f84c77a93c0, pass=0, file_name=0x55e13760a330 "../storage/innobase/fsp/fsp0fsp.cc", line=1301)

    at ../storage/innobase/sync/sync0rw.cc:838

#8  0x000055e137080efa in pfs_rw_lock_sx_lock_func (lock=0x7f84c77a93c0, pass=0, file_name=0x55e13760a330 "../storage/innobase/fsp/fsp0fsp.cc", line=1301)

    at ../storage/innobase/include/sync0rw.ic:672

#9  0x000055e137085502 in fsp_page_create (space=0x55e139b83b50, offset=408, page_size=..., rw_latch=RW_SX_LATCH, mtr=0x7f84cc4905d0,

    init_mtr=0x7f84cc4905d0) at ../storage/innobase/fsp/fsp0fsp.cc:1301

#10 0x000055e137085bbb in fsp_alloc_free_page (space=0x55e139b83b50, page_size=..., hint=0, rw_latch=RW_SX_LATCH, mtr=0x7f84cc4905d0,

    init_mtr=0x7f84cc4905d0) at ../storage/innobase/fsp/fsp0fsp.cc:1434

#11 0x000055e137086935 in fsp_alloc_seg_inode_page (space=0x55e139b83b50, space_header=0x7f84c7a60026 "", mtr=0x7f84cc4905d0)

    at ../storage/innobase/fsp/fsp0fsp.cc:1672

#12 0x000055e137086bf4 in fsp_alloc_seg_inode (space=0x55e139b83b50, space_header=0x7f84c7a60026 "", mtr=0x7f84cc4905d0)

    at ../storage/innobase/fsp/fsp0fsp.cc:1724

#13 0x000055e137087a36 in fseg_create_general (space_id=0, page=0, byte_offset=60, has_done_reservation=1, mtr=0x7f84cc4905d0)

    at ../storage/innobase/fsp/fsp0fsp.cc:2052

#14 0x000055e136f84da6 in trx_undo_seg_create (rseg=0x55e139be53f0, rseg_hdr=0x7f84c78e0026 "\377\377\377\376", type=2, id=0x7f84cc490558,

    undo_page=0x7f84cc490560, mtr=0x7f84cc4905d0) at ../storage/innobase/trx/trx0undo.cc:449

#15 0x000055e136f872a3 in trx_undo_create (trx=0x7f84cc7f8268, rseg=0x55e139be53f0, type=2, trx_id=1509, xid=0x55e139a58030, undo=0x7f84cc7f92a0,

    mtr=0x7f84cc4905d0) at ../storage/innobase/trx/trx0undo.cc:1423

#16 0x000055e136f87b16 in trx_undo_assign_undo (trx=0x7f84cc7f8268, rseg=0x55e139be53f0, undo=0x7f84cc7f92a0, type=2)

    at ../storage/innobase/trx/trx0undo.cc:1609

#17 0x000055e136f65906 in trx_undo_report_row_operation (thr=0x7f846804b970, index=0x55e139bd6bf0, clust_entry=0x7f846815d270, update=0x0, cmpl_info=0,

    rec=0x7f84c7a642fb "test/t1", offsets=0x7f84cc4914a0, roll_ptr=0x7f84cc4910b0) at ../storage/innobase/trx/trx0rec.cc:2073

#18 0x000055e136fbce73 in btr_cur_del_mark_set_clust_rec (block=0x7f84c77bcb00, rec=0x7f84c7a642fb "test/t1", index=0x55e139bd6bf0, offsets=0x7f84cc4914a0,

    thr=0x7f846804b970, entry=0x7f846815d270, mtr=0x7f84cc491b70) at ../storage/innobase/btr/btr0cur.cc:4890

#19 0x000055e136f145ca in row_upd_clust_rec_by_insert (node=0x7f846804a5f0, index=0x55e139bd6bf0, thr=0x7f846804b970, referenced=0, foreign=false,

    mtr=0x7f84cc491b70) at ../storage/innobase/row/row0upd.cc:2737

#20 0x000055e136f15bc6 in row_upd_clust_step (node=0x7f846804a5f0, thr=0x7f846804b970) at ../storage/innobase/row/row0upd.cc:3211

#21 0x000055e136f15ed1 in row_upd (node=0x7f846804a5f0, thr=0x7f846804b970) at ../storage/innobase/row/row0upd.cc:3287

#22 0x000055e136f163a5 in row_upd_step (thr=0x7f846804b970) at ../storage/innobase/row/row0upd.cc:3433

#23 0x000055e136e6e594 in que_thr_step (thr=0x7f846804b970) at ../storage/innobase/que/que0que.cc:1024

#24 0x000055e136e6e875 in que_run_threads_low (thr=0x7f846804b970) at ../storage/innobase/que/que0que.cc:1104

#25 0x000055e136e6ea3f in que_run_threads (thr=0x7f846804b970) at ../storage/innobase/que/que0que.cc:1144

#26 0x000055e136e6ece7 in que_eval_sql (info=0x7f8468037c60,

    sql=0x55e1375676a8 "PROCEDURE RENAME_TABLES () IS\nBEGIN\nUPDATE SYS_TABLES SET NAME = :tmp_name\n WHERE NAME = :old_name;\nUPDATE SYS_TABLES SET NAME = :--Type <RET> for more, q to quit, c to continue without paging--

old_name\n WHERE NAME = :new_name;\nEND;\n", reserve_dict_mutex=0, trx=0x7f84cc7f8268) at ../storage/innobase/que/que0que.cc:1221

#27 0x000055e136eb24a7 in row_merge_rename_tables_dict (old_table=0x7f8468175230, new_table=0x7f84680ac620, tmp_name=0x7f84680479d8 "test/#sql-ib42",

    trx=0x7f84cc7f8268) at ../storage/innobase/row/row0merge.cc:4224

#28 0x000055e136dc4f01 in commit_try_rebuild (ha_alter_info=0x7f84cc493020, ctx=0x7f8468013c00, altered_table=0x7f8468045f80, old_table=0x7f8468065e30,

    trx=0x7f84cc7f8268, table_name=0x7f846815e52d "t1") at ../storage/innobase/handler/handler0alter.cc:7578

#29 0x000055e136dc1662 in ha_innobase::commit_inplace_alter_table (this=0x7f8468071558, altered_table=0x7f8468045f80, ha_alter_info=0x7f84cc493020,

    commit=true) at ../storage/innobase/handler/handler0alter.cc:8424

#30 0x000055e136b7fc06 in handler::ha_commit_inplace_alter_table (this=0x7f8468071558, altered_table=0x7f8468045f80, ha_alter_info=0x7f84cc493020,

    commit=true) at ../sql/handler.cc:4378

#31 0x000055e1369c8b1b in mysql_inplace_alter_table (thd=0x7f8468000d90, table_list=0x7f8468012810, table=0x7f8468065e30, altered_table=0x7f8468045f80,

    ha_alter_info=0x7f84cc493020, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, target_mdl_request=0x7f84cc4930b0, alter_ctx=0x7f84cc493660)

    at ../sql/sql_table.cc:7480

#32 0x000055e1369ce85b in mysql_alter_table (thd=0x7f8468000d90, new_db=0x7f8468012e28 "test", new_name=0x0, create_info=0x7f84cc494280,

    table_list=0x7f8468012810, alter_info=0x7f84cc4941d0, order_num=0, order=0x0, ignore=false) at ../sql/sql_table.cc:9622

#33 0x000055e136a4c8ba in Sql_cmd_alter_table::execute (this=0x7f8468012ed0, thd=0x7f8468000d90) at ../sql/sql_alter.cc:333

#34 0x000055e1368fbaf7 in mysql_execute_command (thd=0x7f8468000d90) at ../sql/sql_parse.cc:5964

#35 0x000055e136900b0d in mysql_parse (thd=0x7f8468000d90, rawbuf=0x7f84680126f8 "ALTER TABLE t1 ENCRYPTED=NO ENCRYPTION_KEY_ID=1", length=47,

    parser_state=0x7f84cc4955f0, is_com_multi=false, is_next_command=false) at ../sql/sql_parse.cc:7733

#36 0x000055e1368eee1c in dispatch_command (command=COM_QUERY, thd=0x7f8468000d90, packet=0x7f8468008b51 "ALTER TABLE t1 ENCRYPTED=NO ENCRYPTION_KEY_ID=1",

    packet_length=47, is_com_multi=false, is_next_command=false) at ../sql/sql_parse.cc:1823

#37 0x000055e1368ed917 in do_command (thd=0x7f8468000d90) at ../sql/sql_parse.cc:1377

#38 0x000055e136a472af in do_handle_one_connection (connect=0x55e139bf5850) at ../sql/sql_connect.cc:1336

#39 0x000055e136a47014 in handle_one_connection (arg=0x55e139bf5850) at ../sql/sql_connect.cc:1241

#40 0x000055e137269dc6 in pfs_spawn_thread (arg=0x55e139ef0040) at ../storage/perfschema/pfs.cc:1869

#41 0x00007f84d1cce609 in start_thread (arg=<optimized out>) at pthread_create.c:477

#42 0x00007f84d18a8103 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

This problem is same as ~~MDEV-23456~~.

Thirunarayanan Balathandayuthapani added a comment - 2020-08-31 10:44 I added the assert in mtr_t::finish_write to check whether page no > 10000 to crash. (I put 10000 as kind of big number) #0 my_read (Filedes=69, Buffer=0x7f84867f9d00 "Limit", ' ' <repeats 21 times>, "Soft Limit", ' ' <repeats 11 times>, "Hard Limit", ' ' <repeats 11 times>, "Units \nMax cpu time", ' ' <repeats 14 times>, "unlimited", ' ' <repeats 12 times>, "unlimited", ' ' <repeats 12 times>, "seconds \nMax file size", ' ' <repeats 13 times>, "unlimited "..., Count=4096, MyFlags=0) at ../mysys/my_read.c:63 #1 0x000055e136b73db0 in output_core_info () at ../sql/signal_handler.cc:66 #2 0x000055e136b745a8 in handle_fatal_signal (sig=6) at ../sql/signal_handler.cc:339 #3 <signal handler called> #4 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #5 0x00007f84d17ab859 in __GI_abort () at abort.c:79 #6 0x00007f84d17ab729 in __assert_fail_base (fmt=0x7f84d1941588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55e13752aa5d "page_no < 10000", file=0x55e13752a9d0 "../storage/innobase/include/log0log.ic", line=344, function=<optimized out>) at assert.c:92 #7 0x00007f84d17bcf36 in __GI___assert_fail (assertion=0x55e13752aa5d "page_no < 10000", file=0x55e13752a9d0 "../storage/innobase/include/log0log.ic", line=344, function=0x55e13752a990 "lsn_t log_reserve_and_write_fast(const void*, ulint, lsn_t*)") at assert.c:101 #8 0x000055e136e30b00 in log_reserve_and_write_fast (str=0x7f84867fbb38, len=10, start_lsn=0x7f84867fb7a0) at ../storage/innobase/include/log0log.ic:344 #9 0x000055e136e31c74 in mtr_t::finish_write (this=0x7f84867fb8b0, len=10) at ../storage/innobase/mtr/mtr0mtr.cc:766 #10 0x000055e136e2f614 in mtr_t::commit (this=0x7f84867fb8b0) at ../storage/innobase/mtr/mtr0mtr.cc:442 #11 0x000055e13707dff3 in fil_crypt_rotate_page (key_state=0x7f84867fbe14, state=0x7f84867fbe20) at ../storage/innobase/fil/fil0crypt.cc:1879 #12 0x000055e13707e4f0 in fil_crypt_rotate_pages (key_state=0x7f84867fbe14, state=0x7f84867fbe20) at ../storage/innobase/fil/fil0crypt.cc:2006 #13 0x000055e13707eeb3 in fil_crypt_thread () at ../storage/innobase/fil/fil0crypt.cc:2235 #14 0x00007f84d1cce609 in start_thread (arg=<optimized out>) at pthread_create.c:477 #15 0x00007f84d18a8103 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 (gdb) f 8 #8 0x000055e136e30b00 in log_reserve_and_write_fast (str=0x7f84867fbb38, len=10, start_lsn=0x7f84867fb7a0) at ../storage/innobase/include/log0log.ic:344 344 ut_ad(page_no < 10000); (gdb) p page_no $11 = 4278124286 (gdb) p state $12 = (rotate_thread_t *) 0x7f84867fbe20 (gdb) p *state $13 = {thread_no = 0, first = false, space = 0x55e139b83b50, offset = 408, batch = 60, min_key_version_found = 0, end_lsn = 1797229, estimated_max_iops = 20, allocated_iops = 20, cnt_waited = 8, sum_waited_us = 842, crypt_stat = {pages_read_from_cache = 40, pages_read_from_disk = 8, pages_modified = 40, pages_flushed = 0, estimated_iops = 20}, scrub_data = {space = 0, scrubbing = false, compressed = false, current_table = 0x0, current_index = 0x0, savepoint = 0, scrub_stat = {page_reorganizations = 0, page_splits = 0, page_split_failures_underflow = 0, page_split_failures_out_of_filespace = 0, page_split_failures_missing_index = 0, page_split_failures_unknown = 0}}} (gdb) p state->space->name $14 = 0x55e139b83d30 "innodb_system" [Switching to thread 25 (Thread 0x7f84cc496700 (LWP 41995))] #0 futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x55e139ac0098) at ../sysdeps/nptl/futex-internal.h:183 183 ../sysdeps/nptl/futex-internal.h: No such file or directory. (gdb) where #0 futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x55e139ac0098) at ../sysdeps/nptl/futex-internal.h:183 #1 __pthread_cond_wait_common (abstime=0x0, clockid=0, mutex=0x55e139ac0048, cond=0x55e139ac0070) at pthread_cond_wait.c:508 #2 __pthread_cond_wait (cond=0x55e139ac0070, mutex=0x55e139ac0048) at pthread_cond_wait.c:638 #3 0x000055e136e3f082 in os_event::wait (this=0x55e139ac0030) at ../storage/innobase/os/os0event.cc:158 #4 0x000055e136e3eb32 in os_event::wait_low (this=0x55e139ac0030, reset_sig_count=1) at ../storage/innobase/os/os0event.cc:325 #5 0x000055e136e3ee4c in os_event_wait_low (event=0x55e139ac0030, reset_sig_count=1) at ../storage/innobase/os/os0event.cc:507 #6 0x000055e136f32eab in sync_array_wait_event (arr=0x55e139a35b90, cell=@0x7f84cc48fe80: 0x7f84ccbf70d0) at ../storage/innobase/sync/sync0arr.cc:471 #7 0x000055e136f36815 in rw_lock_sx_lock_func (lock=0x7f84c77a93c0, pass=0, file_name=0x55e13760a330 "../storage/innobase/fsp/fsp0fsp.cc", line=1301) at ../storage/innobase/sync/sync0rw.cc:838 #8 0x000055e137080efa in pfs_rw_lock_sx_lock_func (lock=0x7f84c77a93c0, pass=0, file_name=0x55e13760a330 "../storage/innobase/fsp/fsp0fsp.cc", line=1301) at ../storage/innobase/include/sync0rw.ic:672 #9 0x000055e137085502 in fsp_page_create (space=0x55e139b83b50, offset=408, page_size=..., rw_latch=RW_SX_LATCH, mtr=0x7f84cc4905d0, init_mtr=0x7f84cc4905d0) at ../storage/innobase/fsp/fsp0fsp.cc:1301 #10 0x000055e137085bbb in fsp_alloc_free_page (space=0x55e139b83b50, page_size=..., hint=0, rw_latch=RW_SX_LATCH, mtr=0x7f84cc4905d0, init_mtr=0x7f84cc4905d0) at ../storage/innobase/fsp/fsp0fsp.cc:1434 #11 0x000055e137086935 in fsp_alloc_seg_inode_page (space=0x55e139b83b50, space_header=0x7f84c7a60026 "", mtr=0x7f84cc4905d0) at ../storage/innobase/fsp/fsp0fsp.cc:1672 #12 0x000055e137086bf4 in fsp_alloc_seg_inode (space=0x55e139b83b50, space_header=0x7f84c7a60026 "", mtr=0x7f84cc4905d0) at ../storage/innobase/fsp/fsp0fsp.cc:1724 #13 0x000055e137087a36 in fseg_create_general (space_id=0, page=0, byte_offset=60, has_done_reservation=1, mtr=0x7f84cc4905d0) at ../storage/innobase/fsp/fsp0fsp.cc:2052 #14 0x000055e136f84da6 in trx_undo_seg_create (rseg=0x55e139be53f0, rseg_hdr=0x7f84c78e0026 "\377\377\377\376", type=2, id=0x7f84cc490558, undo_page=0x7f84cc490560, mtr=0x7f84cc4905d0) at ../storage/innobase/trx/trx0undo.cc:449 #15 0x000055e136f872a3 in trx_undo_create (trx=0x7f84cc7f8268, rseg=0x55e139be53f0, type=2, trx_id=1509, xid=0x55e139a58030, undo=0x7f84cc7f92a0, mtr=0x7f84cc4905d0) at ../storage/innobase/trx/trx0undo.cc:1423 #16 0x000055e136f87b16 in trx_undo_assign_undo (trx=0x7f84cc7f8268, rseg=0x55e139be53f0, undo=0x7f84cc7f92a0, type=2) at ../storage/innobase/trx/trx0undo.cc:1609 #17 0x000055e136f65906 in trx_undo_report_row_operation (thr=0x7f846804b970, index=0x55e139bd6bf0, clust_entry=0x7f846815d270, update=0x0, cmpl_info=0, rec=0x7f84c7a642fb "test/t1", offsets=0x7f84cc4914a0, roll_ptr=0x7f84cc4910b0) at ../storage/innobase/trx/trx0rec.cc:2073 #18 0x000055e136fbce73 in btr_cur_del_mark_set_clust_rec (block=0x7f84c77bcb00, rec=0x7f84c7a642fb "test/t1", index=0x55e139bd6bf0, offsets=0x7f84cc4914a0, thr=0x7f846804b970, entry=0x7f846815d270, mtr=0x7f84cc491b70) at ../storage/innobase/btr/btr0cur.cc:4890 #19 0x000055e136f145ca in row_upd_clust_rec_by_insert (node=0x7f846804a5f0, index=0x55e139bd6bf0, thr=0x7f846804b970, referenced=0, foreign=false, mtr=0x7f84cc491b70) at ../storage/innobase/row/row0upd.cc:2737 #20 0x000055e136f15bc6 in row_upd_clust_step (node=0x7f846804a5f0, thr=0x7f846804b970) at ../storage/innobase/row/row0upd.cc:3211 #21 0x000055e136f15ed1 in row_upd (node=0x7f846804a5f0, thr=0x7f846804b970) at ../storage/innobase/row/row0upd.cc:3287 #22 0x000055e136f163a5 in row_upd_step (thr=0x7f846804b970) at ../storage/innobase/row/row0upd.cc:3433 #23 0x000055e136e6e594 in que_thr_step (thr=0x7f846804b970) at ../storage/innobase/que/que0que.cc:1024 #24 0x000055e136e6e875 in que_run_threads_low (thr=0x7f846804b970) at ../storage/innobase/que/que0que.cc:1104 #25 0x000055e136e6ea3f in que_run_threads (thr=0x7f846804b970) at ../storage/innobase/que/que0que.cc:1144 #26 0x000055e136e6ece7 in que_eval_sql (info=0x7f8468037c60, sql=0x55e1375676a8 "PROCEDURE RENAME_TABLES () IS\nBEGIN\nUPDATE SYS_TABLES SET NAME = :tmp_name\n WHERE NAME = :old_name;\nUPDATE SYS_TABLES SET NAME = :--Type <RET> for more, q to quit, c to continue without paging-- old_name\n WHERE NAME = :new_name;\nEND;\n", reserve_dict_mutex=0, trx=0x7f84cc7f8268) at ../storage/innobase/que/que0que.cc:1221 #27 0x000055e136eb24a7 in row_merge_rename_tables_dict (old_table=0x7f8468175230, new_table=0x7f84680ac620, tmp_name=0x7f84680479d8 "test/#sql-ib42", trx=0x7f84cc7f8268) at ../storage/innobase/row/row0merge.cc:4224 #28 0x000055e136dc4f01 in commit_try_rebuild (ha_alter_info=0x7f84cc493020, ctx=0x7f8468013c00, altered_table=0x7f8468045f80, old_table=0x7f8468065e30, trx=0x7f84cc7f8268, table_name=0x7f846815e52d "t1") at ../storage/innobase/handler/handler0alter.cc:7578 #29 0x000055e136dc1662 in ha_innobase::commit_inplace_alter_table (this=0x7f8468071558, altered_table=0x7f8468045f80, ha_alter_info=0x7f84cc493020, commit=true) at ../storage/innobase/handler/handler0alter.cc:8424 #30 0x000055e136b7fc06 in handler::ha_commit_inplace_alter_table (this=0x7f8468071558, altered_table=0x7f8468045f80, ha_alter_info=0x7f84cc493020, commit=true) at ../sql/handler.cc:4378 #31 0x000055e1369c8b1b in mysql_inplace_alter_table (thd=0x7f8468000d90, table_list=0x7f8468012810, table=0x7f8468065e30, altered_table=0x7f8468045f80, ha_alter_info=0x7f84cc493020, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, target_mdl_request=0x7f84cc4930b0, alter_ctx=0x7f84cc493660) at ../sql/sql_table.cc:7480 #32 0x000055e1369ce85b in mysql_alter_table (thd=0x7f8468000d90, new_db=0x7f8468012e28 "test", new_name=0x0, create_info=0x7f84cc494280, table_list=0x7f8468012810, alter_info=0x7f84cc4941d0, order_num=0, order=0x0, ignore=false) at ../sql/sql_table.cc:9622 #33 0x000055e136a4c8ba in Sql_cmd_alter_table::execute (this=0x7f8468012ed0, thd=0x7f8468000d90) at ../sql/sql_alter.cc:333 #34 0x000055e1368fbaf7 in mysql_execute_command (thd=0x7f8468000d90) at ../sql/sql_parse.cc:5964 #35 0x000055e136900b0d in mysql_parse (thd=0x7f8468000d90, rawbuf=0x7f84680126f8 "ALTER TABLE t1 ENCRYPTED=NO ENCRYPTION_KEY_ID=1", length=47, parser_state=0x7f84cc4955f0, is_com_multi=false, is_next_command=false) at ../sql/sql_parse.cc:7733 #36 0x000055e1368eee1c in dispatch_command (command=COM_QUERY, thd=0x7f8468000d90, packet=0x7f8468008b51 "ALTER TABLE t1 ENCRYPTED=NO ENCRYPTION_KEY_ID=1", packet_length=47, is_com_multi=false, is_next_command=false) at ../sql/sql_parse.cc:1823 #37 0x000055e1368ed917 in do_command (thd=0x7f8468000d90) at ../sql/sql_parse.cc:1377 #38 0x000055e136a472af in do_handle_one_connection (connect=0x55e139bf5850) at ../sql/sql_connect.cc:1336 #39 0x000055e136a47014 in handle_one_connection (arg=0x55e139bf5850) at ../sql/sql_connect.cc:1241 #40 0x000055e137269dc6 in pfs_spawn_thread (arg=0x55e139ef0040) at ../storage/perfschema/pfs.cc:1869 #41 0x00007f84d1cce609 in start_thread (arg=<optimized out>) at pthread_create.c:477 #42 0x00007f84d18a8103 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 This problem is same as MDEV-23456 .

Thirunarayanan Balathandayuthapani made changes - 2020-08-31 10:44

Link

This issue is blocked by ~~MDEV-23456~~ [ ~~MDEV-23456~~ ]

Thirunarayanan Balathandayuthapani made changes - 2020-08-31 10:44

Description

{noformat}
Thread 1 (Thread 0x7fcadf365740 (LWP 89766)):
#0 __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
#1 0x00005654efb68df9 in my_write_core (sig=sig@entry=6) at /home/mleich/10.2/mysys/stacktrace.c:477
#2 0x00005654ef475171 in handle_fatal_signal (sig=6) at /home/mleich/10.2/sql/signal_handler.cc:343
#3 <signal handler called>
#4 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
#5 0x00007fcadcf6d8b1 in __GI_abort () at abort.c:79
#6 0x00005654ef85127c in ib::fatal::~fatal (this=<optimized out>, __in_chrg=<optimized out>) at /home/mleich/10.2/storage/innobase/ut/ut0ut.cc:649
#7 0x00005654ef947968 in fil_report_invalid_page_access (block_offset=<optimized out>, space_id=<optimized out>, space_name=<optimized out>, byte_offset=<optimized out>, byte_offset@entry=0, len=<optimized out>, is_read=<optimized out>) at /home/mleich/10.2/storage/innobase/fil/fil0fil.cc:4792
#8 0x00005654ef955aa3 in fil_io (type=..., sync=<optimized out>, page_id=..., page_size=..., byte_offset=byte_offset@entry=0, len=<optimized out>, buf=0x7fcad3b18000, message=0x7fcad33f1338, ignore_missing_space=false) at /home/mleich/10.2/storage/innobase/fil/fil0fil.cc:4938
#9 0x00005654ef8efbd9 in buf_read_page_low (err=err@entry=0x7ffff003733c, sync=<optimized out>, sync@entry=true, type=type@entry=0, mode=mode@entry=132, page_id=..., page_size=..., unzip=<optimized out>, ignore_missing_space=<optimized out>) at /home/mleich/10.2/storage/innobase/buf/buf0rea.cc:182
#10 0x00005654ef8f07ca in buf_read_page (page_id=..., page_size=...) at /home/mleich/10.2/storage/innobase/buf/buf0rea.cc:435
#11 0x00005654ef8c6751 in buf_page_get_low (page_id=..., page_size=..., rw_latch=rw_latch@entry=2, guess=<optimized out>, guess@entry=0x0, mode=mode@entry=10, file=file@entry=0x5654efdd21d0 "/home/mleich/10.2/storage/innobase/fil/fil0fil.cc", line=4871, mtr=0x7ffff0037830, err=0x7ffff00377fc) at /home/mleich/10.2/storage/innobase/buf/buf0buf.cc:4390
#12 0x00005654ef8c7a24 in buf_page_get_gen (page_id=..., page_size=..., rw_latch=rw_latch@entry=2, guess=guess@entry=0x0, mode=mode@entry=10, file=file@entry=0x5654efdd21d0 "/home/mleich/10.2/storage/innobase/fil/fil0fil.cc", line=4871, mtr=0x7ffff0037830, err=0x7ffff00377fc) at /home/mleich/10.2/storage/innobase/buf/buf0buf.cc:4911
#13 0x00005654ef68c3b5 in ibuf_bitmap_get_map_page_func (page_id=..., page_id@entry=..., page_size=..., file=file@entry=0x5654efdd21d0 "/home/mleich/10.2/storage/innobase/fil/fil0fil.cc", line=line@entry=4871, mtr=mtr@entry=0x7ffff0037830) at /home/mleich/10.2/storage/innobase/ibuf/ibuf0ibuf.cc:768
#14 0x00005654ef693e0b in ibuf_page_low (page_id=..., page_size=..., x_latch=x_latch@entry=1, file=file@entry=0x5654efdd21d0 "/home/mleich/10.2/storage/innobase/fil/fil0fil.cc", line=line@entry=4871, mtr=0x7ffff0037830, mtr@entry=0x0) at /home/mleich/10.2/storage/innobase/ibuf/ibuf0ibuf.cc:1147
#15 0x00005654ef9557ea in fil_io (type=..., sync=<optimized out>, page_id=..., page_size=..., byte_offset=byte_offset@entry=0, len=<optimized out>, buf=0x7fcad3a70000, message=0x7fcad33e93e8, ignore_missing_space=false) at /home/mleich/10.2/storage/innobase/fil/fil0fil.cc:4871
#16 0x00005654ef8efbd9 in buf_read_page_low (err=err@entry=0x7ffff00382c0, sync=<optimized out>, sync@entry=false, type=type@entry=64, mode=mode@entry=132, page_id=..., page_size=..., unzip=<optimized out>, ignore_missing_space=<optimized out>) at /home/mleich/10.2/storage/innobase/buf/buf0rea.cc:182
#17 0x00005654ef8f1fc2 in buf_read_recv_pages (sync=sync@entry=false, space_id=space_id@entry=0, page_nos=page_nos@entry=0x7ffff0038520, n_stored=n_stored@entry=1) at /home/mleich/10.2/storage/innobase/buf/buf0rea.cc:958
#18 0x00005654ef6c5f50 in recv_read_in_area (page_id=..., page_id@entry=...) at /home/mleich/10.2/storage/innobase/log/log0recv.cc:2290
#19 0x00005654ef6cb941 in recv_apply_hashed_log_recs (last_batch=last_batch@entry=true) at /home/mleich/10.2/storage/innobase/log/log0recv.cc:2489
#20 0x00005654ef7f4402 in innobase_start_or_create_for_mysql () at /home/mleich/10.2/storage/innobase/srv/srv0start.cc:2240
#21 0x00005654ef652cf4 in innobase_init (p=<optimized out>) at /home/mleich/10.2/storage/innobase/handler/ha_innodb.cc:4306
#22 0x00005654ef477abf in ha_initialize_handlerton (plugin=0x5654f2449df0) at /home/mleich/10.2/sql/handler.cc:555
#23 0x00005654ef295551 in plugin_initialize (tmp_root=tmp_root@entry=0x7ffff003d380, plugin=0x5654f2449df0, argc=argc@entry=0x5654f0601ff8 <remaining_argc>, argv=argv@entry=0x5654f2317e98, options_only=options_only@entry=false) at /home/mleich/10.2/sql/sql_plugin.cc:1417
#24 0x00005654ef296679 in plugin_init (argc=argc@entry=0x5654f0601ff8 <remaining_argc>, argv=0x5654f2317e98, flags=2) at /home/mleich/10.2/sql/sql_plugin.cc:1698
#25 0x00005654ef1c1baf in init_server_components () at /home/mleich/10.2/sql/mysqld.cc:5341
#26 0x00005654ef1c60d1 in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /home/mleich/10.2/sql/mysqld.cc:5939
#27 0x00005654ef1b6213 in main (argc=<optimized out>, argv=<optimized out>) at /home/mleich/10.2/sql/main.cc:25

See also
http://buildbot.askmonty.org/buildbot/builders/kvm-rpm-centos74-amd64-debug/builds/4526/steps/mtr/logs/stdio
{noformat}

Thirunarayanan Balathandayuthapani made changes - 2020-08-31 10:44

Assignee

Matthias Leich [ mleich ]

Thirunarayanan Balathandayuthapani [ thiru ]

Thirunarayanan Balathandayuthapani made changes - 2020-10-08 16:29

Fix Version/s		10.2.35 [ 25022 ]
Fix Version/s		10.3.26 [ 25021 ]
Fix Version/s		10.4.16 [ 25020 ]
Fix Version/s		10.5.7 [ 25019 ]
Fix Version/s	10.2 [ 14601 ]
Resolution		Duplicate [ 3 ]
Status	Open [ 1 ]	Closed [ 6 ]

Thirunarayanan Balathandayuthapani made changes - 2020-10-08 16:30

Link

This issue is duplicated by ~~MDEV-23456~~ [ ~~MDEV-23456~~ ]

Thirunarayanan Balathandayuthapani made changes - 2020-10-08 16:30

Link

This issue is blocked by ~~MDEV-23456~~ [ ~~MDEV-23456~~ ]

Sergei Golubchik made changes - 2021-12-06 21:52

Workflow

MariaDB v3 [ 111594 ]

MariaDB v4 [ 158132 ]

MariaDB Server

Draft: Crash when running encryption.innodb-encryption-alter-cbc,innodb

Details

Description

Attachments

Attachments

Issue Links

Activity

People

Dates

Git Integration