[MDEV-24695] Encryption is modifying a freed page - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Blocker
Resolution: Fixed
Affects Version/s: 10.5
Fix Version/s: 10.5.9, 10.6.0
Component/s: Storage Engine - InnoDB
Labels:
- regression-10.5
- rr-profile

Description

10.5 927a8823
2021-01-26 19:18:12 0 [Note] InnoDB: Opened 127 undo tablespaces
2021-01-26 19:18:12 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=103948,103948
2021-01-26 19:18:12 0 [Note] InnoDB: Opened 127 undo tablespaces
2021-01-26 19:18:12 0 [Note] InnoDB: Starting final batch to recover 563 pages from redo log.
mysqld: /data/src/10.5/storage/innobase/log/log0recv.cc:274: log_phys_t::apply_status log_phys_t::apply(const buf_block_t&, uint16_t&) const: Assertion `mach_read_from_4(frame + 4U) == block.page.id().page_no()' failed.
210126 19:18:12 [ERROR] mysqld got signal 6 ;

#7 0x00007fbcc52c9f36 in __GI___assert_fail (assertion=0x55c97e4131a0 "mach_read_from_4(frame + 4U) == block.page.id().page_no()", file=0x55c97e412b40 "/data/src/10.5/storage/innobase/log/log0recv.cc", line=274, function=0x55c97e412f20 "log_phys_t::apply_status log_phys_t::apply(const buf_block_t&, uint16_t&) const") at assert.c:101
#8 0x000055c97cdb5855 in log_phys_t::apply (this=0x7fbca8eeb500, block=..., last_offset=@0x6080004b81e4: 0) at /data/src/10.5/storage/innobase/log/log0recv.cc:274
#9 0x000055c97cda2d68 in recv_recover_page (block=0x7fbca8a0f090, mtr=..., p=Python Exception <class 'AttributeError'> 'NoneType' object has no attribute 'pointer':
..., space=0x615000002398, init=0x60700000c9a0) at /data/src/10.5/storage/innobase/log/log0recv.cc:2312
#10 0x000055c97cdbce31 in recv_sys_t::recover_low (this=0x55c97f6c99c0 <recv_sys>, page_id=..., p=Python Exception <class 'AttributeError'> 'NoneType' object has no attribute 'pointer':
..., mtr=..., b=0x7fbca8a0f090) at /data/src/10.5/storage/innobase/log/log0recv.cc:2559
#11 0x000055c97cda5a74 in recv_sys_t::apply (this=0x55c97f6c99c0 <recv_sys>, last_batch=true) at /data/src/10.5/storage/innobase/log/log0recv.cc:2662
#12 0x000055c97d040150 in srv_start (create_new_db=false) at /data/src/10.5/storage/innobase/srv/srv0start.cc:1491
#13 0x000055c97cb9a526 in innodb_init (p=0x616000021708) at /data/src/10.5/storage/innobase/handler/ha_innodb.cc:3909
#14 0x000055c97c0754ab in ha_initialize_handlerton (plugin=0x62100002cc80) at /data/src/10.5/sql/handler.cc:645
#15 0x000055c97b8ad406 in plugin_initialize (tmp_root=0x7ffe64870080, plugin=0x62100002cc80, argc=0x55c97fc31da0 <remaining_argc>, argv=0x6160000004f8, options_only=false) at /data/src/10.5/sql/sql_plugin.cc:1459
#16 0x000055c97b8af394 in plugin_init (argc=0x55c97fc31da0 <remaining_argc>, argv=0x6160000004f8, flags=0) at /data/src/10.5/sql/sql_plugin.cc:1751
#17 0x000055c97b5683ac in init_server_components () at /data/src/10.5/sql/mysqld.cc:4913
#18 0x000055c97b56a39f in mysqld_main (argc=26, argv=0x6160000004f8) at /data/src/10.5/sql/mysqld.cc:5497
#19 0x000055c97b553d9d in main (argc=25, argv=0x7ffe64871e18) at /data/src/10.5/sql/main.cc:25

rr profile is available.
To reproduce the problem, I was using the following test:

git clone https://github.com/MariaDB/randgen --branch mdev24695 rqg-mdev24695

cd rqg-mdev24695

. ./mdev24695.cmd <basedir>

It runs a short DML flow in one thread, kills the server and restarts it with --innodb-force-recovery=3, at which point the failure happens. If it doesn't, the test will restart the server again, without forced recovery, and run some more DML.

Non-default server options used (also can be found in mdev24695.cmd):

--mysqld=--innodb-use-native-aio=OFF \

--mysqld=--innodb-encrypt-tables \

--mysqld=--innodb-encrypt-log \

--mysqld=--innodb-encryption-threads=4 \

--mysqld=--file-key-management --mysqld=--file-key-management-filename=`pwd`/data/file_key_management_keys.txt \

--mysqld=--plugin-load-add=file_key_management \

--mysqld=--innodb-undo-tablespaces=127

Reproducibility seems to depend heavily on the machine and build; for example, on my local machine it happens much more readily (almost every time) on an ASAN build, while not so much on a non-ASA debug build; on another machine it's vice versa.
Couldn't reproduce without any of the options listed above, but it's not an absolute guarantee, maybe they just change the dynamics.
Couldn't reproduce on 10.4, the same disclaimer applies.

Attachments

Issue Links

causes

MDEV-24864 Fatal error in buf_page_get_low() / fseg_page_is_free()

Closed

is caused by

MDEV-15528 Avoid writing freed InnoDB pages

Closed

relates to

MDEV-24792 Assertion `!newest_lsn || fil_page_get_type(page)' failed upon MariaBackup prepare in buf_flush_init_for_writing with innodb_log_optimize_ddl=off

Closed

MDEV-25026 Various code paths are accessing freed pages

Closed

Activity

Thirunarayanan Balathandayuthapani added a comment - 2021-01-27 00:55

Problematic page id is

(rr) p /x $1

$2 = {m_id = 0x500000005}

(rr) p space->id

$9 = 5

(rr) p space->name

$10 = 0x55abd0e57398 "innodb_undo005"

Initialization of page happened in rr-profile-before

mtr_t::init:

when

(rr) when

Current event: 59245

Thread 2 hit Breakpoint 4, mtr_t::init (this=0x7f700edfabb0, b=0x7f70240c04e0)

    at /home/mariadb/MDEV-24695/10.5/storage/innobase/include/mtr0log.h:528

528	  b->page.status= buf_page_t::INIT_ON_FLUSH;

(rr) where

#0  mtr_t::init (this=0x7f700edfabb0, b=0x7f70240c04e0) at /home/mariadb/MDEV-24695/10.5/storage/innobase/include/mtr0log.h:528

#1  0x000055abcd0072e3 in fsp_init_file_page (space=0x55abd0e571a8, block=0x7f70240c04e0, mtr=0x7f700edfabb0)

    at /home/mariadb/MDEV-24695/10.5/storage/innobase/include/fsp0fsp.h:575

#2  0x000055abcd000344 in fsp_page_create (space=0x55abd0e571a8, offset=5, mtr=0x7f700edfabb0)

    at /home/mariadb/MDEV-24695/10.5/storage/innobase/fsp/fsp0fsp.cc:1053

#3  0x000055abcd0008a8 in fsp_alloc_free_page (space=0x55abd0e571a8, hint=5, mtr=0x7f700edfabb0, init_mtr=0x7f700edfabb0)

    at /home/mariadb/MDEV-24695/10.5/storage/innobase/fsp/fsp0fsp.cc:1163

#4  0x000055abcd004092 in fseg_alloc_free_page_low (space=0x55abd0e571a8, seg_inode=0x7f70247b40f2 "", iblock=0x7f702401bc60, hint=5,

    direction=111 'o', has_done_reservation=true, mtr=0x7f700edfabb0, init_mtr=0x7f700edfabb0)

    at /home/mariadb/MDEV-24695/10.5/storage/innobase/fsp/fsp0fsp.cc:2085

#5  0x000055abcd0049f5 in fseg_alloc_free_page_general (seg_header=0x7f702430403c "", hint=5, direction=111 'o', has_done_reservation=true,

    mtr=0x7f700edfabb0, init_mtr=0x7f700edfabb0) at /home/mariadb/MDEV-24695/10.5/storage/innobase/fsp/fsp0fsp.cc:2215

#6  0x000055abcced90fc in trx_undo_add_page (undo=0x55abd0ea1678, mtr=0x7f700edfabb0)

    at /home/mariadb/MDEV-24695/10.5/storage/innobase/trx/trx0undo.cc:571

#7  0x000055abcceb7f89 in trx_undo_report_row_operation (thr=0x7f6ff0018018, index=0x7f7018017688, clust_entry=0x7f6ff0015698, update=0x0,

    cmpl_info=0, rec=0x7f702546cb23 "testtable100_innodb_int_autoincc35n_diff_pfx02", offsets=0x7f700edfb6e0, roll_ptr=0x7f700edfb0e8)

    at /home/mariadb/MDEV-24695/10.5/storage/innobase/trx/trx0rec.cc:2121

#8  0x000055abccf26da0 in btr_cur_del_mark_set_clust_rec (block=0x7f7024063510,

    rec=0x7f702546cb23 "testtable100_innodb_int_autoincc35n_diff_pfx02", index=0x7f7018017688, offsets=0x7f700edfb6e0, thr=0x7f6ff0018018,

    entry=0x7f6ff0015698, mtr=0x7f700edfb940) at /home/mariadb/MDEV-24695/10.5/storage/innobase/btr/btr0cur.cc:5362

#9  0x000055abcce5fdbc in row_upd_del_mark_clust_rec (node=0x7f6ff00165b8, index=0x7f7018017688, offsets=0x7f700edfb6e0, thr=0x7f6ff0018018,

    referenced=0, foreign=false, mtr=0x7f700edfb940) at /home/mariadb/MDEV-24695/10.5/storage/innobase/row/row0upd.cc:2683

#10 0x000055abcce6085b in row_upd_clust_step (node=0x7f6ff00165b8, thr=0x7f6ff0018018)

    at /home/mariadb/MDEV-24695/10.5/storage/innobase/row/row0upd.cc:2860

#11 0x000055abcce60e49 in row_upd (node=0x7f6ff00165b8, thr=0x7f6ff0018018) at /home/mariadb/MDEV-24695/10.5/storage/innobase/row/row0upd.cc:2992

#12 0x000055abcce6140f in row_upd_step (thr=0x7f6ff0018018) at /home/mariadb/MDEV-24695/10.5/storage/innobase/row/row0upd.cc:3136

#13 0x000055abccd96569 in que_thr_step (thr=0x7f6ff0018018) at /home/mariadb/MDEV-24695/10.5/storage/innobase/que/que0que.cc:928

#14 0x000055abccd968dd in que_run_threads_low (thr=0x7f6ff0018018) at /home/mariadb/MDEV-24695/10.5/storage/innobase/que/que0que.cc:1008

#15 0x000055abccd96b2b in que_run_threads (thr=0x7f6ff0018018) at /home/mariadb/MDEV-24695/10.5/storage/innobase/que/que0que.cc:1048

#16 0x000055abccd96dc2 in que_eval_sql (info=0x7f6ff0015938,

    sql=0x55abcd74b2c8 "PROCEDURE INDEX_STATS_SAVE () IS\nBEGIN\nDELETE FROM \"mysql/innodb_index_stats\"\nWHERE\ndatabase_name = :database_name AND\ntable_name = :table_name AND\nindex_name = :index_name AND\nstat_name = :stat_name;"..., reserve_dict_mutex=false, trx=0x7f70336ff828)

    at /home/mariadb/MDEV-24695/10.5/storage/innobase/que/que0que.cc:1125

#17 0x000055abccfcac23 in dict_stats_exec_sql (pinfo=0x7f6ff0015938,

    sql=0x55abcd74b2c8 "PROCEDURE INDEX_STATS_SAVE () IS\nBEGIN\nDELETE FROM \"mysql/innodb_index_stats\"\nWHERE\ndatabase_name = :database_name AND\ntable_name = :table_name AND\nindex_name = :index_name AND\nstat_name = :stat_name;"..., trx=0x7f70336ff828)

    at /home/mariadb/MDEV-24695/10.5/storage/innobase/dict/dict0stats.cc:305

---Type <return> to continue, or q <return> to quit---

#18 0x000055abccfd00b5 in dict_stats_save_index_stat (index=0x7f6ff000d070, last_update=1611685653, stat_name=0x7f700edfc490 "n_diff_pfx02",

    stat_value=100, sample_size=0x7f6ff000d2e0, stat_description=0x7f700edfc640 "c35,pk", trx=0x7f70336ff828)

    at /home/mariadb/MDEV-24695/10.5/storage/innobase/dict/dict0stats.cc:2377

#19 0x000055abccfd0b62 in dict_stats_save (table_orig=0x7f6fdc0bc1b8, only_for_index=0x0)

    at /home/mariadb/MDEV-24695/10.5/storage/innobase/dict/dict0stats.cc:2593

#20 0x000055abccfd24aa in dict_stats_update (table=0x7f6fdc0bc1b8, stats_upd_option=DICT_STATS_RECALC_PERSISTENT)

    at /home/mariadb/MDEV-24695/10.5/storage/innobase/dict/dict0stats.cc:3233

#21 0x000055abccfd8124 in dict_stats_process_entry_from_recalc_pool ()

    at /home/mariadb/MDEV-24695/10.5/storage/innobase/dict/dict0stats_bg.cc:390

#22 0x000055abccfd81f4 in dict_stats_func () at /home/mariadb/MDEV-24695/10.5/storage/innobase/dict/dict0stats_bg.cc:424

#23 0x000055abcd0822b2 in tpool::thread_pool_generic::timer_generic::run (this=0x55abd0e708c0)

    at /home/mariadb/MDEV-24695/10.5/tpool/tpool_generic.cc:309

#24 0x000055abcd0823cd in tpool::thread_pool_generic::timer_generic::execute (arg=0x55abd0e708c0)

    at /home/mariadb/MDEV-24695/10.5/tpool/tpool_generic.cc:329

#25 0x000055abcd087713 in tpool::task::execute (this=0x55abd0e70900) at /home/mariadb/MDEV-24695/10.5/tpool/task.cc:52

#26 0x000055abcd0809d2 in tpool::thread_pool_generic::worker_main (this=0x55abd05cd5e0, thread_var=0x55abd05dd080)

    at /home/mariadb/MDEV-24695/10.5/tpool/tpool_generic.cc:546

#27 0x000055abcd08419b in std::__invoke_impl<void, void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> (__f=

    @0x55abd0ea3fd8: (void (tpool::thread_pool_generic::*)(tpool::thread_pool_generic * const, tpool::worker_data *)) 0x55abcd08093a <tpool::thread_pool_generic::worker_main(tpool::worker_data*)>, __t=@0x55abd0ea3fd0: 0x55abd05cd5e0) at /usr/include/c++/7/bits/invoke.h:73

#28 0x000055abcd083335 in std::__invoke<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> (__fn=

    @0x55abd0ea3fd8: (void (tpool::thread_pool_generic::*)(tpool::thread_pool_generic * const, tpool::worker_data *)) 0x55abcd08093a <tpool::thread_pool_generic::worker_main(tpool::worker_data*)>) at /usr/include/c++/7/bits/invoke.h:95

#29 0x000055abcd08701b in std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::_M_invoke<0ul, 1ul, 2ul> (this=0x55abd0ea3fc8) at /usr/include/c++/7/thread:234

#30 0x000055abcd086fb5 in std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::operator() (this=0x55abd0ea3fc8) at /usr/include/c++/7/thread:243

#31 0x000055abcd086f94 in std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> > >::_M_run (this=0x55abd0ea3fc0) at /usr/include/c++/7/thread:186

#32 0x00007f70499546df in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6

#33 0x00007f7049e2b6db in start_thread (arg=0x7f700edfd700) at pthread_create.c:463

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

Freeing of page mtr_t::free:
========================

(rr) when

Current event: 73992

Thread 26 hit Breakpoint 5, mtr_t::free (this=0x7f6fee5faac0, space=..., offset=5)

    at /home/mariadb/MDEV-24695/10.5/storage/innobase/include/mtr0log.h:545

545	  ut_ad(is_named_space(&space));

(rr) when

Current event: 73992

(rr) where

#0  mtr_t::free (this=0x7f6fee5faac0, space=..., offset=5) at /home/mariadb/MDEV-24695/10.5/storage/innobase/include/mtr0log.h:545

#1  0x000055abcd000ca8 in fsp_free_page (space=0x55abd0e571a8, offset=5, mtr=0x7f6fee5faac0)

    at /home/mariadb/MDEV-24695/10.5/storage/innobase/fsp/fsp0fsp.cc:1223

#2  0x000055abcd005673 in fseg_free_page_low (seg_inode=0x7f70247b40f2 "", iblock=0x7f702401bc60, space=0x55abd0e571a8, offset=5,

    mtr=0x7f6fee5faac0) at /home/mariadb/MDEV-24695/10.5/storage/innobase/fsp/fsp0fsp.cc:2468

#3  0x000055abcd006905 in fseg_free_step_not_header (header=0x7f702430403c "", mtr=0x7f6fee5faac0)

    at /home/mariadb/MDEV-24695/10.5/storage/innobase/fsp/fsp0fsp.cc:2772

#4  0x000055abcce9e1f5 in trx_purge_free_segment (rseg=0x55abd0ea1478, hdr_addr=...)

    at /home/mariadb/MDEV-24695/10.5/storage/innobase/trx/trx0purge.cc:372

#5  0x000055abcce9e87a in trx_purge_truncate_rseg_history (rseg=..., limit=...)

    at /home/mariadb/MDEV-24695/10.5/storage/innobase/trx/trx0purge.cc:492

#6  0x000055abcce9ed6e in trx_purge_truncate_history () at /home/mariadb/MDEV-24695/10.5/storage/innobase/trx/trx0purge.cc:569

#7  0x000055abccea18b3 in trx_purge (n_tasks=3, truncate=true) at /home/mariadb/MDEV-24695/10.5/storage/innobase/trx/trx0purge.cc:1305

#8  0x000055abcce7279f in srv_do_purge (n_total_purged=0x7f6fee5fbc88) at /home/mariadb/MDEV-24695/10.5/storage/innobase/srv/srv0srv.cc:1994

#9  0x000055abcce72ca4 in purge_coordinator_callback_low () at /home/mariadb/MDEV-24695/10.5/storage/innobase/srv/srv0srv.cc:2084

#10 0x000055abcce72d85 in purge_coordinator_callback () at /home/mariadb/MDEV-24695/10.5/storage/innobase/srv/srv0srv.cc:2113

#11 0x000055abcd087346 in tpool::task_group::execute (this=0x55abce9f3620 <purge_coordinator_task_group>,

    t=0x55abce9f36c0 <purge_coordinator_task>) at /home/mariadb/MDEV-24695/10.5/tpool/task_group.cc:55

#12 0x000055abcd0876fc in tpool::task::execute (this=0x55abce9f36c0 <purge_coordinator_task>) at /home/mariadb/MDEV-24695/10.5/tpool/task.cc:47

#13 0x000055abcd0809d2 in tpool::thread_pool_generic::worker_main (this=0x55abd05cd5e0, thread_var=0x55abd05dce00)

    at /home/mariadb/MDEV-24695/10.5/tpool/tpool_generic.cc:546

#14 0x000055abcd08419b in std::__invoke_impl<void, void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> (__f=

    @0x7f7008003258: (void (tpool::thread_pool_generic::*)(tpool::thread_pool_generic * const, tpool::worker_data *)) 0x55abcd08093a <tpool::thread_pool_generic::worker_main(tpool::worker_data*)>, __t=@0x7f7008003250: 0x55abd05cd5e0) at /usr/include/c++/7/bits/invoke.h:73

#15 0x000055abcd083335 in std::__invoke<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> (__fn=

    @0x7f7008003258: (void (tpool::thread_pool_generic::*)(tpool::thread_pool_generic * const, tpool::worker_data *)) 0x55abcd08093a <tpool::thread_pool_generic::worker_main(tpool::worker_data*)>) at /usr/include/c++/7/bits/invoke.h:95

#16 0x000055abcd08701b in std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::_M_invoke<0ul, 1ul, 2ul> (this=0x7f7008003248) at /usr/include/c++/7/thread:234

#17 0x000055abcd086fb5 in std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::operator() (this=0x7f7008003248) at /usr/include/c++/7/thread:243

#18 0x000055abcd086f94 in std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> > >::_M_run (this=0x7f7008003240) at /usr/include/c++/7/thread:186

#19 0x00007f70499546df in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6

#20 0x00007f7049e2b6db in start_thread (arg=0x7f6fee5fc700) at pthread_create.c:463

---Type <return> to continue, or q <return> to quit---

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

After freeing the page, crypt thread again access the page and does force write of space id :

Thread 11 hit Breakpoint 6, buf_page_get_low (page_id=..., zip_size=0, rw_latch=2, guess=0x0, mode=12,

    file=0x55abcd75b350 "/home/mariadb/MDEV-24695/10.5/storage/innobase/fil/fil0crypt.cc", line=1842, mtr=0x7f70210f98f0, err=0x7f70210f9834,

    allow_ibuf_merge=false) at /home/mariadb/MDEV-24695/10.5/storage/innobase/buf/buf0buf.cc:2896

2896	{

(rr) where

#0  buf_page_get_low (page_id=..., zip_size=0, rw_latch=2, guess=0x0, mode=12,

    file=0x55abcd75b350 "/home/mariadb/MDEV-24695/10.5/storage/innobase/fil/fil0crypt.cc", line=1842, mtr=0x7f70210f98f0, err=0x7f70210f9834,

    allow_ibuf_merge=false) at /home/mariadb/MDEV-24695/10.5/storage/innobase/buf/buf0buf.cc:2896

#1  0x000055abccf56c8a in buf_page_get_gen (page_id=..., zip_size=0, rw_latch=2, guess=0x0, mode=12,

    file=0x55abcd75b350 "/home/mariadb/MDEV-24695/10.5/storage/innobase/fil/fil0crypt.cc", line=1842, mtr=0x7f70210f98f0, err=0x7f70210f9834,

    allow_ibuf_merge=false) at /home/mariadb/MDEV-24695/10.5/storage/innobase/buf/buf0buf.cc:3480

#2  0x000055abccff98e9 in fil_crypt_get_page_throttle_func (state=0x7f70210f9e40, offset=5, mtr=0x7f70210f98f0, sleeptime_ms=0x7f70210f98b0,

    file=0x55abcd75b350 "/home/mariadb/MDEV-24695/10.5/storage/innobase/fil/fil0crypt.cc", line=1842)

    at /home/mariadb/MDEV-24695/10.5/storage/innobase/fil/fil0crypt.cc:1763

#3  0x000055abccff9c53 in fil_crypt_rotate_page (key_state=0x7f70210f9e34, state=0x7f70210f9e40)

    at /home/mariadb/MDEV-24695/10.5/storage/innobase/fil/fil0crypt.cc:1840

#4  0x000055abccffa2a1 in fil_crypt_rotate_pages (key_state=0x7f70210f9e34, state=0x7f70210f9e40)

    at /home/mariadb/MDEV-24695/10.5/storage/innobase/fil/fil0crypt.cc:1968

#5  0x000055abccffab73 in fil_crypt_thread () at /home/mariadb/MDEV-24695/10.5/storage/innobase/fil/fil0crypt.cc:2159

#6  0x00007f7049e2b6db in start_thread (arg=0x7f70210fa700) at pthread_create.c:463

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

(rr) when

Current event: 75036

(rr) n

2899		ulint		retries = 0;

(rr) p page_id

$11 = {m_id = 21474836485}

(rr) p /x page_id

$12 = {m_id = 0x500000005}

It is reading the page from disk. Yes, it does force write of space id.

Thread 3 received signal SIGKILL, Killed.

[Switching to Thread 61177.61178]

0x0000000070000002 in ?? ()

(rr) when

Current event: 141902

Thirunarayanan Balathandayuthapani added a comment - 2021-01-27 00:55 Problematic page id is (rr) p /x $1 $2 = {m_id = 0x500000005} (rr) p space->id $9 = 5 (rr) p space->name $10 = 0x55abd0e57398 "innodb_undo005" Initialization of page happened in rr-profile-before mtr_t::init: when (rr) when Current event: 59245 Thread 2 hit Breakpoint 4, mtr_t::init (this=0x7f700edfabb0, b=0x7f70240c04e0) at /home/mariadb/MDEV-24695/10.5/storage/innobase/include/mtr0log.h:528 528 b->page.status= buf_page_t::INIT_ON_FLUSH; (rr) where #0 mtr_t::init (this=0x7f700edfabb0, b=0x7f70240c04e0) at /home/mariadb/MDEV-24695/10.5/storage/innobase/include/mtr0log.h:528 #1 0x000055abcd0072e3 in fsp_init_file_page (space=0x55abd0e571a8, block=0x7f70240c04e0, mtr=0x7f700edfabb0) at /home/mariadb/MDEV-24695/10.5/storage/innobase/include/fsp0fsp.h:575 #2 0x000055abcd000344 in fsp_page_create (space=0x55abd0e571a8, offset=5, mtr=0x7f700edfabb0) at /home/mariadb/MDEV-24695/10.5/storage/innobase/fsp/fsp0fsp.cc:1053 #3 0x000055abcd0008a8 in fsp_alloc_free_page (space=0x55abd0e571a8, hint=5, mtr=0x7f700edfabb0, init_mtr=0x7f700edfabb0) at /home/mariadb/MDEV-24695/10.5/storage/innobase/fsp/fsp0fsp.cc:1163 #4 0x000055abcd004092 in fseg_alloc_free_page_low (space=0x55abd0e571a8, seg_inode=0x7f70247b40f2 "", iblock=0x7f702401bc60, hint=5, direction=111 'o', has_done_reservation=true, mtr=0x7f700edfabb0, init_mtr=0x7f700edfabb0) at /home/mariadb/MDEV-24695/10.5/storage/innobase/fsp/fsp0fsp.cc:2085 #5 0x000055abcd0049f5 in fseg_alloc_free_page_general (seg_header=0x7f702430403c "", hint=5, direction=111 'o', has_done_reservation=true, mtr=0x7f700edfabb0, init_mtr=0x7f700edfabb0) at /home/mariadb/MDEV-24695/10.5/storage/innobase/fsp/fsp0fsp.cc:2215 #6 0x000055abcced90fc in trx_undo_add_page (undo=0x55abd0ea1678, mtr=0x7f700edfabb0) at /home/mariadb/MDEV-24695/10.5/storage/innobase/trx/trx0undo.cc:571 #7 0x000055abcceb7f89 in trx_undo_report_row_operation (thr=0x7f6ff0018018, index=0x7f7018017688, clust_entry=0x7f6ff0015698, update=0x0, cmpl_info=0, rec=0x7f702546cb23 "testtable100_innodb_int_autoincc35n_diff_pfx02", offsets=0x7f700edfb6e0, roll_ptr=0x7f700edfb0e8) at /home/mariadb/MDEV-24695/10.5/storage/innobase/trx/trx0rec.cc:2121 #8 0x000055abccf26da0 in btr_cur_del_mark_set_clust_rec (block=0x7f7024063510, rec=0x7f702546cb23 "testtable100_innodb_int_autoincc35n_diff_pfx02", index=0x7f7018017688, offsets=0x7f700edfb6e0, thr=0x7f6ff0018018, entry=0x7f6ff0015698, mtr=0x7f700edfb940) at /home/mariadb/MDEV-24695/10.5/storage/innobase/btr/btr0cur.cc:5362 #9 0x000055abcce5fdbc in row_upd_del_mark_clust_rec (node=0x7f6ff00165b8, index=0x7f7018017688, offsets=0x7f700edfb6e0, thr=0x7f6ff0018018, referenced=0, foreign=false, mtr=0x7f700edfb940) at /home/mariadb/MDEV-24695/10.5/storage/innobase/row/row0upd.cc:2683 #10 0x000055abcce6085b in row_upd_clust_step (node=0x7f6ff00165b8, thr=0x7f6ff0018018) at /home/mariadb/MDEV-24695/10.5/storage/innobase/row/row0upd.cc:2860 #11 0x000055abcce60e49 in row_upd (node=0x7f6ff00165b8, thr=0x7f6ff0018018) at /home/mariadb/MDEV-24695/10.5/storage/innobase/row/row0upd.cc:2992 #12 0x000055abcce6140f in row_upd_step (thr=0x7f6ff0018018) at /home/mariadb/MDEV-24695/10.5/storage/innobase/row/row0upd.cc:3136 #13 0x000055abccd96569 in que_thr_step (thr=0x7f6ff0018018) at /home/mariadb/MDEV-24695/10.5/storage/innobase/que/que0que.cc:928 #14 0x000055abccd968dd in que_run_threads_low (thr=0x7f6ff0018018) at /home/mariadb/MDEV-24695/10.5/storage/innobase/que/que0que.cc:1008 #15 0x000055abccd96b2b in que_run_threads (thr=0x7f6ff0018018) at /home/mariadb/MDEV-24695/10.5/storage/innobase/que/que0que.cc:1048 #16 0x000055abccd96dc2 in que_eval_sql (info=0x7f6ff0015938, sql=0x55abcd74b2c8 "PROCEDURE INDEX_STATS_SAVE () IS\nBEGIN\nDELETE FROM \"mysql/innodb_index_stats\"\nWHERE\ndatabase_name = :database_name AND\ntable_name = :table_name AND\nindex_name = :index_name AND\nstat_name = :stat_name;"..., reserve_dict_mutex=false, trx=0x7f70336ff828) at /home/mariadb/MDEV-24695/10.5/storage/innobase/que/que0que.cc:1125 #17 0x000055abccfcac23 in dict_stats_exec_sql (pinfo=0x7f6ff0015938, sql=0x55abcd74b2c8 "PROCEDURE INDEX_STATS_SAVE () IS\nBEGIN\nDELETE FROM \"mysql/innodb_index_stats\"\nWHERE\ndatabase_name = :database_name AND\ntable_name = :table_name AND\nindex_name = :index_name AND\nstat_name = :stat_name;"..., trx=0x7f70336ff828) at /home/mariadb/MDEV-24695/10.5/storage/innobase/dict/dict0stats.cc:305 ---Type <return> to continue, or q <return> to quit--- #18 0x000055abccfd00b5 in dict_stats_save_index_stat (index=0x7f6ff000d070, last_update=1611685653, stat_name=0x7f700edfc490 "n_diff_pfx02", stat_value=100, sample_size=0x7f6ff000d2e0, stat_description=0x7f700edfc640 "c35,pk", trx=0x7f70336ff828) at /home/mariadb/MDEV-24695/10.5/storage/innobase/dict/dict0stats.cc:2377 #19 0x000055abccfd0b62 in dict_stats_save (table_orig=0x7f6fdc0bc1b8, only_for_index=0x0) at /home/mariadb/MDEV-24695/10.5/storage/innobase/dict/dict0stats.cc:2593 #20 0x000055abccfd24aa in dict_stats_update (table=0x7f6fdc0bc1b8, stats_upd_option=DICT_STATS_RECALC_PERSISTENT) at /home/mariadb/MDEV-24695/10.5/storage/innobase/dict/dict0stats.cc:3233 #21 0x000055abccfd8124 in dict_stats_process_entry_from_recalc_pool () at /home/mariadb/MDEV-24695/10.5/storage/innobase/dict/dict0stats_bg.cc:390 #22 0x000055abccfd81f4 in dict_stats_func () at /home/mariadb/MDEV-24695/10.5/storage/innobase/dict/dict0stats_bg.cc:424 #23 0x000055abcd0822b2 in tpool::thread_pool_generic::timer_generic::run (this=0x55abd0e708c0) at /home/mariadb/MDEV-24695/10.5/tpool/tpool_generic.cc:309 #24 0x000055abcd0823cd in tpool::thread_pool_generic::timer_generic::execute (arg=0x55abd0e708c0) at /home/mariadb/MDEV-24695/10.5/tpool/tpool_generic.cc:329 #25 0x000055abcd087713 in tpool::task::execute (this=0x55abd0e70900) at /home/mariadb/MDEV-24695/10.5/tpool/task.cc:52 #26 0x000055abcd0809d2 in tpool::thread_pool_generic::worker_main (this=0x55abd05cd5e0, thread_var=0x55abd05dd080) at /home/mariadb/MDEV-24695/10.5/tpool/tpool_generic.cc:546 #27 0x000055abcd08419b in std::__invoke_impl<void, void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> (__f= @0x55abd0ea3fd8: (void (tpool::thread_pool_generic::*)(tpool::thread_pool_generic * const, tpool::worker_data *)) 0x55abcd08093a <tpool::thread_pool_generic::worker_main(tpool::worker_data*)>, __t=@0x55abd0ea3fd0: 0x55abd05cd5e0) at /usr/include/c++/7/bits/invoke.h:73 #28 0x000055abcd083335 in std::__invoke<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> (__fn= @0x55abd0ea3fd8: (void (tpool::thread_pool_generic::*)(tpool::thread_pool_generic * const, tpool::worker_data *)) 0x55abcd08093a <tpool::thread_pool_generic::worker_main(tpool::worker_data*)>) at /usr/include/c++/7/bits/invoke.h:95 #29 0x000055abcd08701b in std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::_M_invoke<0ul, 1ul, 2ul> (this=0x55abd0ea3fc8) at /usr/include/c++/7/thread:234 #30 0x000055abcd086fb5 in std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::operator() (this=0x55abd0ea3fc8) at /usr/include/c++/7/thread:243 #31 0x000055abcd086f94 in std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> > >::_M_run (this=0x55abd0ea3fc0) at /usr/include/c++/7/thread:186 #32 0x00007f70499546df in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6 #33 0x00007f7049e2b6db in start_thread (arg=0x7f700edfd700) at pthread_create.c:463 #34 0x00007f7049011a3f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 Freeing of page mtr_t::free: ======================== (rr) when Current event: 73992 Thread 26 hit Breakpoint 5, mtr_t::free (this=0x7f6fee5faac0, space=..., offset=5) at /home/mariadb/MDEV-24695/10.5/storage/innobase/include/mtr0log.h:545 545 ut_ad(is_named_space(&space)); (rr) when Current event: 73992 (rr) where #0 mtr_t::free (this=0x7f6fee5faac0, space=..., offset=5) at /home/mariadb/MDEV-24695/10.5/storage/innobase/include/mtr0log.h:545 #1 0x000055abcd000ca8 in fsp_free_page (space=0x55abd0e571a8, offset=5, mtr=0x7f6fee5faac0) at /home/mariadb/MDEV-24695/10.5/storage/innobase/fsp/fsp0fsp.cc:1223 #2 0x000055abcd005673 in fseg_free_page_low (seg_inode=0x7f70247b40f2 "", iblock=0x7f702401bc60, space=0x55abd0e571a8, offset=5, mtr=0x7f6fee5faac0) at /home/mariadb/MDEV-24695/10.5/storage/innobase/fsp/fsp0fsp.cc:2468 #3 0x000055abcd006905 in fseg_free_step_not_header (header=0x7f702430403c "", mtr=0x7f6fee5faac0) at /home/mariadb/MDEV-24695/10.5/storage/innobase/fsp/fsp0fsp.cc:2772 #4 0x000055abcce9e1f5 in trx_purge_free_segment (rseg=0x55abd0ea1478, hdr_addr=...) at /home/mariadb/MDEV-24695/10.5/storage/innobase/trx/trx0purge.cc:372 #5 0x000055abcce9e87a in trx_purge_truncate_rseg_history (rseg=..., limit=...) at /home/mariadb/MDEV-24695/10.5/storage/innobase/trx/trx0purge.cc:492 #6 0x000055abcce9ed6e in trx_purge_truncate_history () at /home/mariadb/MDEV-24695/10.5/storage/innobase/trx/trx0purge.cc:569 #7 0x000055abccea18b3 in trx_purge (n_tasks=3, truncate=true) at /home/mariadb/MDEV-24695/10.5/storage/innobase/trx/trx0purge.cc:1305 #8 0x000055abcce7279f in srv_do_purge (n_total_purged=0x7f6fee5fbc88) at /home/mariadb/MDEV-24695/10.5/storage/innobase/srv/srv0srv.cc:1994 #9 0x000055abcce72ca4 in purge_coordinator_callback_low () at /home/mariadb/MDEV-24695/10.5/storage/innobase/srv/srv0srv.cc:2084 #10 0x000055abcce72d85 in purge_coordinator_callback () at /home/mariadb/MDEV-24695/10.5/storage/innobase/srv/srv0srv.cc:2113 #11 0x000055abcd087346 in tpool::task_group::execute (this=0x55abce9f3620 <purge_coordinator_task_group>, t=0x55abce9f36c0 <purge_coordinator_task>) at /home/mariadb/MDEV-24695/10.5/tpool/task_group.cc:55 #12 0x000055abcd0876fc in tpool::task::execute (this=0x55abce9f36c0 <purge_coordinator_task>) at /home/mariadb/MDEV-24695/10.5/tpool/task.cc:47 #13 0x000055abcd0809d2 in tpool::thread_pool_generic::worker_main (this=0x55abd05cd5e0, thread_var=0x55abd05dce00) at /home/mariadb/MDEV-24695/10.5/tpool/tpool_generic.cc:546 #14 0x000055abcd08419b in std::__invoke_impl<void, void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> (__f= @0x7f7008003258: (void (tpool::thread_pool_generic::*)(tpool::thread_pool_generic * const, tpool::worker_data *)) 0x55abcd08093a <tpool::thread_pool_generic::worker_main(tpool::worker_data*)>, __t=@0x7f7008003250: 0x55abd05cd5e0) at /usr/include/c++/7/bits/invoke.h:73 #15 0x000055abcd083335 in std::__invoke<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> (__fn= @0x7f7008003258: (void (tpool::thread_pool_generic::*)(tpool::thread_pool_generic * const, tpool::worker_data *)) 0x55abcd08093a <tpool::thread_pool_generic::worker_main(tpool::worker_data*)>) at /usr/include/c++/7/bits/invoke.h:95 #16 0x000055abcd08701b in std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::_M_invoke<0ul, 1ul, 2ul> (this=0x7f7008003248) at /usr/include/c++/7/thread:234 #17 0x000055abcd086fb5 in std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::operator() (this=0x7f7008003248) at /usr/include/c++/7/thread:243 #18 0x000055abcd086f94 in std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> > >::_M_run (this=0x7f7008003240) at /usr/include/c++/7/thread:186 #19 0x00007f70499546df in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6 #20 0x00007f7049e2b6db in start_thread (arg=0x7f6fee5fc700) at pthread_create.c:463 ---Type <return> to continue, or q <return> to quit--- #21 0x00007f7049011a3f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 After freeing the page, crypt thread again access the page and does force write of space id : Thread 11 hit Breakpoint 6, buf_page_get_low (page_id=..., zip_size=0, rw_latch=2, guess=0x0, mode=12, file=0x55abcd75b350 "/home/mariadb/MDEV-24695/10.5/storage/innobase/fil/fil0crypt.cc", line=1842, mtr=0x7f70210f98f0, err=0x7f70210f9834, allow_ibuf_merge=false) at /home/mariadb/MDEV-24695/10.5/storage/innobase/buf/buf0buf.cc:2896 2896 { (rr) where #0 buf_page_get_low (page_id=..., zip_size=0, rw_latch=2, guess=0x0, mode=12, file=0x55abcd75b350 "/home/mariadb/MDEV-24695/10.5/storage/innobase/fil/fil0crypt.cc", line=1842, mtr=0x7f70210f98f0, err=0x7f70210f9834, allow_ibuf_merge=false) at /home/mariadb/MDEV-24695/10.5/storage/innobase/buf/buf0buf.cc:2896 #1 0x000055abccf56c8a in buf_page_get_gen (page_id=..., zip_size=0, rw_latch=2, guess=0x0, mode=12, file=0x55abcd75b350 "/home/mariadb/MDEV-24695/10.5/storage/innobase/fil/fil0crypt.cc", line=1842, mtr=0x7f70210f98f0, err=0x7f70210f9834, allow_ibuf_merge=false) at /home/mariadb/MDEV-24695/10.5/storage/innobase/buf/buf0buf.cc:3480 #2 0x000055abccff98e9 in fil_crypt_get_page_throttle_func (state=0x7f70210f9e40, offset=5, mtr=0x7f70210f98f0, sleeptime_ms=0x7f70210f98b0, file=0x55abcd75b350 "/home/mariadb/MDEV-24695/10.5/storage/innobase/fil/fil0crypt.cc", line=1842) at /home/mariadb/MDEV-24695/10.5/storage/innobase/fil/fil0crypt.cc:1763 #3 0x000055abccff9c53 in fil_crypt_rotate_page (key_state=0x7f70210f9e34, state=0x7f70210f9e40) at /home/mariadb/MDEV-24695/10.5/storage/innobase/fil/fil0crypt.cc:1840 #4 0x000055abccffa2a1 in fil_crypt_rotate_pages (key_state=0x7f70210f9e34, state=0x7f70210f9e40) at /home/mariadb/MDEV-24695/10.5/storage/innobase/fil/fil0crypt.cc:1968 #5 0x000055abccffab73 in fil_crypt_thread () at /home/mariadb/MDEV-24695/10.5/storage/innobase/fil/fil0crypt.cc:2159 #6 0x00007f7049e2b6db in start_thread (arg=0x7f70210fa700) at pthread_create.c:463 #7 0x00007f7049011a3f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 (rr) when Current event: 75036 (rr) n 2899 ulint retries = 0; (rr) p page_id $11 = {m_id = 21474836485} (rr) p /x page_id $12 = {m_id = 0x500000005} It is reading the page from disk. Yes, it does force write of space id. Thread 3 received signal SIGKILL, Killed. [Switching to Thread 61177.61178] 0x0000000070000002 in ?? () (rr) when Current event: 141902

MariaDB Server

Encryption is modifying a freed page

Details

Description

Attachments

Issue Links

Activity

People

Dates

Git Integration