Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
10.5
-
None
Description
|
10.5 c8ae3573 |
mysqld: /data/src/10.5/storage/innobase/include/mtr0log.h:203: bool mtr_t::write(const buf_block_t&, void*, V) [with unsigned int l = 8u; mtr_t::write_type w = (mtr_t::write_type)0u; V = long unsigned int]: Assertion `w == OPT' failed.
|
200315 13:51:49 [ERROR] mysqld got signal 6 ;
|
|
|
#15 0x00007fc06260ef12 in __GI___assert_fail (assertion=0x5650284f6e32 "w == OPT", file=0x5650284f5060 "/data/src/10.5/storage/innobase/include/mtr0log.h", line=203, function=0x5650284f72e0 <bool mtr_t::write<8u, (mtr_t::write_type)0, unsigned long>(buf_block_t const&, void*, unsigned long)::__PRETTY_FUNCTION__> "bool mtr_t::write(const buf_block_t&, void*, V) [with unsigned int l = 8u; mtr_t::write_type w = (mtr_t::write_type)0u; V = long unsigned int]") at assert.c:101
|
#16 0x0000565027d08bf6 in mtr_t::write<8u, (mtr_t::write_type)0, unsigned long> (this=0x7fc03c063c60, block=..., ptr=0x7fc040aa8517, val=2048) at /data/src/10.5/storage/innobase/include/mtr0log.h:203
|
#17 0x0000565027e38bfd in trx_purge_add_undo_to_history (trx=0x7fc058a683c0, undo=@0x7fc058a693f0: 0x7fc0080f2418, mtr=0x7fc03c063c60) at /data/src/10.5/storage/innobase/trx/trx0purge.cc:301
|
#18 0x0000565027e67477 in trx_write_serialisation_history (trx=0x7fc058a683c0, mtr=0x7fc03c063c60) at /data/src/10.5/storage/innobase/trx/trx0trx.cc:1120
|
#19 0x0000565027e6989f in trx_commit_low (trx=0x7fc058a683c0, mtr=0x7fc03c063c60) at /data/src/10.5/storage/innobase/trx/trx0trx.cc:1557
|
#20 0x0000565027e699ff in trx_commit (trx=0x7fc058a683c0) at /data/src/10.5/storage/innobase/trx/trx0trx.cc:1625
|
#21 0x0000565027e69ee6 in trx_commit_for_mysql (trx=0x7fc058a683c0) at /data/src/10.5/storage/innobase/trx/trx0trx.cc:1771
|
#22 0x0000565027bd785f in innobase_commit_low (trx=0x7fc058a683c0) at /data/src/10.5/storage/innobase/handler/ha_innodb.cc:4150
|
#23 0x0000565027bd7c85 in innobase_commit_ordered_2 (trx=0x7fc058a683c0, thd=0x7fbfc4000b18) at /data/src/10.5/storage/innobase/handler/ha_innodb.cc:4272
|
#24 0x0000565027bd82c8 in innobase_commit (hton=0x56502ab06c18, thd=0x7fbfc4000b18, commit_trx=false) at /data/src/10.5/storage/innobase/handler/ha_innodb.cc:4389
|
#25 0x000056502778858e in commit_one_phase_2 (thd=0x7fbfc4000b18, all=false, trans=0x7fbfc4004110, is_real_trans=true) at /data/src/10.5/sql/handler.cc:1872
|
#26 0x000056502778848a in ha_commit_one_phase (thd=0x7fbfc4000b18, all=false) at /data/src/10.5/sql/handler.cc:1852
|
#27 0x000056502778762c in ha_commit_trans (thd=0x7fbfc4000b18, all=false) at /data/src/10.5/sql/handler.cc:1653
|
#28 0x00005650275eba37 in trans_commit_stmt (thd=0x7fbfc4000b18) at /data/src/10.5/sql/transaction.cc:460
|
#29 0x000056502743fc39 in mysql_execute_command (thd=0x7fbfc4000b18) at /data/src/10.5/sql/sql_parse.cc:5946
|
#30 0x00005650274459ce in mysql_parse (thd=0x7fbfc4000b18, rawbuf=0x7fbfc4012460 "DELETE /* QNO 896 CON_ID 9 */ FROM `t9` WHERE `col_date` = 17105", length=64, parser_state=0x7fc03c065520, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:7926
|
#31 0x00005650274314d7 in dispatch_command (command=COM_QUERY, thd=0x7fbfc4000b18, packet=0x7fbfc4008809 "DELETE /* QNO 896 CON_ID 9 */ FROM `t9` WHERE `col_date` = 17105", packet_length=64, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:1840
|
#32 0x000056502742fc0d in do_command (thd=0x7fbfc4000b18) at /data/src/10.5/sql/sql_parse.cc:1359
|
#33 0x00005650275d15f9 in do_handle_one_connection (connect=0x56502b961688, put_in_cache=true) at /data/src/10.5/sql/sql_connect.cc:1422
|
#34 0x00005650275d1328 in handle_one_connection (arg=0x56502b961688) at /data/src/10.5/sql/sql_connect.cc:1319
|
#35 0x0000565027b007a2 in pfs_spawn_thread (arg=0x56502b853dd8) at /data/src/10.5/storage/perfschema/pfs.cc:2201
|
#36 0x00007fc0645974a4 in start_thread (arg=0x7fc03c066700) at pthread_create.c:456
|
#37 0x00007fc0626cbd0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
|
rr profile and mysqld binary obtained on Debian 9 (Stretch) x86_64:
Linux 4.9.0-11-amd64 #1 SMP Debian 4.9.189-3+deb9u2 (2019-11-11) x86_64 GNU/Linux
|
Distributor ID: Debian
|
Description: Debian GNU/Linux 9.12 (stretch)
|
Release: 9.12
|
Codename: stretch
|
The workflow is a simple 2-thread test which only performs this:
query:
|
INSERT IGNORE INTO _table ( _field_pk ) VALUES ( NULL ) |
|
DELETE FROM _table WHERE _field_pk = _smallint_unsigned
|
;
|
To reproduce from scratch:
git clone https://github.com/MariaDB/randgen --branch mdev21945 rqg-mdev21945
|
cd rqg-mdev21945
|
. ./mdev21945.cmd <your basedir>
|
But the probability appears to be very low. The test above runs 50 test runs, ~4 min each, until the first time this failure occurs (if ever). It usually fails for me, but it can take any number of runs from 1 to 40+. Probably rr profile gives a better chance for debugging.
Attachments
Issue Links
- is caused by
-
MDEV-12353 Efficient InnoDB redo log record format
-
- Closed
-
Activity
By default, when redo log is being written for modifying a persistent data page, the data page must actually be changed. If the write can sometimes be optimized away, then the template parameter w=mtr_t::OPT should be passed in order to silence the debug assertion failure.
InnoDB undo log pages can be reused without properly freeing or initializing them in between. In particular, the undo log header page field TRX_UNDO_TRX_NO could have been part of an undo log record page, and those bytes could accidentally have the desired value when the page is reused as an undo log header page of another transaction.
Because the function trx_undo_set_state_at_finish() always changes the TRX_UNDO_STATE of the page, and because recovery is only reading TRX_UNDO_TRX_NO for pages that either have the correct TRX_UNDO_STATE or, in trx_rseg_array_init(), are attached to the TRX_SYS page, the garbage values in TRX_UNDO_TRX_NO do not seem to cause a problem.
This bug affects debug builds only.
In the recorded trace, we are trying to write trx->no==0x800 to a page that already contains that value.
The anomaly is related to InnoDB’s reuse of undo pages without properly freeing or initializing them in between. The value was written previously as part of an undo log record:
Thread 4 hit Hardware watchpoint 1: *(unsigned*)0x7fa4cc99c8e8Old value = 0New value = 524288mach_write_to_1 (b=0x7fa4cc99c8ea "\b", n=8)at /home/mariadb/MDEV-21945/10.5/storage/innobase/include/mach0data.ic:4444 }(rr) bt#0 mach_write_to_1 (b=0x7fa4cc99c8ea "\b", n=8)at /home/mariadb/MDEV-21945/10.5/storage/innobase/include/mach0data.ic:44#1 0x000056424c30f860 in mach_write_compressed (b=0x7fa4cc99c8ea "\b", n=8)at /home/mariadb/MDEV-21945/10.5/storage/innobase/include/mach0data.ic:204#2 0x000056424c3160ab in trx_undo_page_report_insert (undo_block=0x7fa4cc02f260, trx=0x7fa4db200290, index=0x7fa48c0b22f8,clust_entry=0x7fa48c00c9a8, mtr=0x7fa4d80a91d0)at /home/mariadb/MDEV-21945/10.5/storage/innobase/trx/trx0rec.cc:420#3 0x000056424c31bb56 in trx_undo_report_row_operation (thr=0x7fa48c567e18,index=0x7fa48c0b22f8, clust_entry=0x7fa48c00c9a8, update=0x0, cmpl_info=0,rec=0x0, offsets=0x0, roll_ptr=0x7fa4d80a9710)at /home/mariadb/MDEV-21945/10.5/storage/innobase/trx/trx0rec.cc:2003#4 0x000056424c384679 in btr_cur_ins_lock_and_undo (flags=0,cursor=0x7fa4d80a9c20, entry=0x7fa48c00c9a8, thr=0x7fa48c567e18,mtr=0x7fa4d80a9f80, inherit=0x7fa4d80a9799)at /home/mariadb/MDEV-21945/10.5/storage/innobase/btr/btr0cur.cc:3297#5 0x000056424c3851e5 in btr_cur_optimistic_insert (flags=0,cursor=0x7fa4d80a9c20, offsets=0x7fa4d80a9bb8, heap=0x7fa4d80a9bb0,entry=0x7fa48c00c9a8, rec=0x7fa4d80a9bc0, big_rec=0x7fa4d80a9ba8, n_ext=0,thr=0x7fa48c567e18, mtr=0x7fa4d80a9f80)at /home/mariadb/MDEV-21945/10.5/storage/innobase/btr/btr0cur.cc:3505I think that it is easiest to relax the assertion by passing the template parameter w=mtr_t::OPT.
This assertion failure should have no impact on the non-debug version.