[MDEV-16136] Various ASAN failures when testing 10.2/10.3 Created: 2018-05-10  Updated: 2019-08-27  Resolved: 2018-08-16

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.2.15, 10.3.6
Fix Version/s: 10.2.18, 10.3.10

Type: Bug Priority: Major
Reporter: Matthias Leich Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: affects-tests
Environment:

Ubuntu 17.04 but I assume this is not important.


Issue Links:
Blocks
is blocked by MDEV-16063 [Draft] ASAN use-after-poison in row_... Closed
Problem/Incident
is caused by MDEV-15030 Add ASAN instrumentation Closed
Relates
relates to MDEV-16781 InnoDB: AddressSanitizer: use-after-p... Closed

 Description   

MariaDB 10.3 commit 8b087c63b56408edfae21f3234bae0b5391759b6 (2018-05-09)
compiled with ASAN.

I have some rather simple RQG test containing mostly DDL.
When executing this test via combinations.pl in parallel (leads to high loaded box) with many trials than some significant share of the test runs fail with ASAN failures like
SUMMARY: AddressSanitizer: use-after-poison .../storage/innobase/row/row0upd.cc:3422 in row_upd_step(que_thr_t*)
SUMMARY: AddressSanitizer: use-after-poison .../storage/innobase/trx/trx0purge.cc:224 in trx_purge_add_undo_to_history(trx_t const*, trx_undo_t*&, mtr_t*)
SUMMARY: AddressSanitizer: use-after-poison .../storage/innobase/trx/trx0purge.cc:226 in trx_purge_add_undo_to_history(trx_t const*, trx_undo_t*&, mtr_t*)

There were >= 52 different unique ASAN Summary lines.
(grep -h 'SUMMARY: AddressSanitizer: ' last_comb_workdir/trial*.log | sort -u)

I am aware that

  • a significant fraction of these ASAN failures are already reported
    But these reports lack often some fast replay testcase.
  • some clear decision about which part in MariaDB is "guilty" (InnoDB or the server or both) cannot be made based on the current information available
  • there is some significant but not big likelihood that the failures reported during testing might be caused by
  • exceeding OS/testing box resources -> server/InnoDB meet conditions they cannot handle good enough in the moment -> ....
    There are at least no signs that the OS starts to "attack" the mass of perl processes because of resource shortages or similar.
  • weaknesses in RQG mechanics
    Basically RQG has also sometimes problems to handle slow reacting servers/processes.
    Sorry in case that is valid.
    The dilemma is that we need extreme CPU and memory IO load for getting a short bug replay time etc. On a system with low load the test passes nearly all time.

 Comments   
Comment by Matthias Leich [ 2018-05-11 ]

Roughly the same ASAN failures show up in 10.2.15.

Comment by Matthias Leich [ 2018-05-11 ]

I have run ~ 150 trials with the RQG test and threads = 1.
No ASAN failure showed up.
So that all seem to be concurrency problems.

Comment by Matthias Leich [ 2018-05-15 ]

Examples: 10.2 commit 16319409bf53ffb9860d82778ae0997a7a19d381 (2018-05-08)
comb_storage/1526032572/trial7*.log

==218848==ERROR: AddressSanitizer: use-after-poison on address 0x7f3410ed6e78 at pc 0x55d7e809692f bp 0x7f33e5910320 sp 0x7f33e5910310
READ of size 8 at 0x7f3410ed6e78 thread T33
#0 0x55d7e809692e in trx_t::has_logged_persistent() const storage/innobase/include/trx0trx.h:1169
#1 0x55d7e809699b in trx_t::has_logged() const storage/innobase/include/trx0trx.h:1175
#2 0x55d7e843bde3 in trx_create_low storage/innobase/trx/trx0trx.cc:390
#3 0x55d7e843caaa in trx_allocate_for_background() storage/innobase/trx/trx0trx.cc:469
#4 0x55d7e8604c9e in dict_stats_fetch_from_ps storage/innobase/dict/dict0stats.cc:2983
#5 0x55d7e8605e98 in dict_stats_update(dict_table_t*, dict_stats_upd_option_t) storage/innobase/dict/dict0stats.cc:3286
#6 0x55d7e8035604 in dict_stats_init storage/innobase/include/dict0stats.ic:166
#7 0x55d7e8049670 in ha_innobase::open(char const*, int, unsigned int) storage/innobase/handler/ha_innodb.cc:6297
#8 0x55d7e7b67e78 in handler::ha_open(TABLE*, char const*, int, unsigned int) sql/handler.cc:2501
#9 0x55d7e7818c3a in open_table_from_share(THD*, TABLE_SHARE*, char const*, unsigned int, unsigned int, unsigned int, TABLE*, bool) sql/table.cc:3328
#10 0x55d7e748fe66 in open_table(THD*, TABLE_LIST*, Open_table_context*) sql/sql_base.cc:1878
#11 0x55d7e779d805 in mysql_inplace_alter_table sql/sql_table.cc:7392
#12 0x55d7e77a96c4 in mysql_alter_table(THD*, char*, char*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool) sql/sql_table.cc:9353
#13 0x55d7e78cafb8 in Sql_cmd_alter_table::execute(THD*) sql/sql_alter.cc:318
#14 0x55d7e75af712 in mysql_execute_command(THD*) sql/sql_parse.cc:6224
#15 0x55d7e75b9ca6 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) sql/sql_parse.cc:7940
#16 0x55d7e7594df4 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) sql/sql_parse.cc:1820
#17 0x55d7e7591e95 in do_command(THD*) sql/sql_parse.cc:1373
#18 0x55d7e78bcff3 in do_handle_one_connection(CONNECT*) sql/sql_connect.cc:1335
#19 0x55d7e78bc9d8 in handle_one_connection sql/sql_connect.cc:1241
#20 0x7f341d01b6d9 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x76d9)
#21 0x7f341c4add7e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0x108d7e)
ALTER TABLE test.t1_2 ENGINE = InnoDB, ALGORITHM INPLACE, LOCK SHARED;
—
==218214==ERROR: AddressSanitizer: use-after-poison on address 0x7f16146fc878 at pc 0x55a0e1fd886d bp 0x7f15e32ff900 sp 0x7f15e32ff8f0
READ of size 8 at 0x7f16146fc878 thread T38
==218214==AddressSanitizer: while reporting a bug found another one. Ignoring.
#0 0x55a0e1fd886c in row_sel storage/innobase/row/row0sel.cc:1839
#1 0x55a0e1fda5c0 in row_sel_step(que_thr_t*) storage/innobase/row/row0sel.cc:2386
#2 0x55a0e1ed7fa5 in que_thr_step storage/innobase/que/que0que.cc:1027
#3 0x55a0e1ed8468 in que_run_threads_low storage/innobase/que/que0que.cc:1111
#4 0x55a0e1ed8774 in que_run_threads(que_thr_t*) storage/innobase/que/que0que.cc:1151
#5 0x55a0e1ed8d2e in que_eval_sql(pars_info_t*, char const*, unsigned long, trx_t*) storage/innobase/que/que0que.cc:1228
#6 0x55a0e229ec62 in dict_stats_exec_sql storage/innobase/dict/dict0stats.cc:311
#7 0x55a0e22a79d5 in dict_stats_save storage/innobase/dict/dict0stats.cc:2470
#8 0x55a0e22aabe5 in dict_stats_update(dict_table_t*, dict_stats_upd_option_t) storage/innobase/dict/dict0stats.cc:3239
#9 0x55a0e1d114ac in create_table_info_t::create_table_update_dict() storage/innobase/handler/ha_innodb.cc:12867
#10 0x55a0e1d11e19 in ha_innobase::create(char const*, TABLE*, HA_CREATE_INFO*) storage/innobase/handler/ha_innodb.cc:12996
#11 0x55a0e1819bf8 in handler::ha_create(char const*, TABLE*, HA_CREATE_INFO*) sql/handler.cc:4359
#12 0x55a0e181c574 in ha_create_table(THD*, char const*, char const*, char const*, HA_CREATE_INFO*, st_mysql_const_unsigned_lex_string*) sql/handler.cc:4729
#13 0x55a0e144eb2a in mysql_alter_table(THD*, char*, char*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool) sql/sql_table.cc:9408
#14 0x55a0e156ffb8 in Sql_cmd_alter_table::execute(THD*) sql/sql_alter.cc:318
#15 0x55a0e1254712 in mysql_execute_command(THD*) sql/sql_parse.cc:6224
#16 0x55a0e125eca6 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) sql/sql_parse.cc:7940
#17 0x55a0e1239df4 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) sql/sql_parse.cc:1820
#18 0x55a0e1236e95 in do_command(THD*) sql/sql_parse.cc:1373
#19 0x55a0e1561ff3 in do_handle_one_connection(CONNECT*) sql/sql_connect.cc:1335
#20 0x55a0e15619d8 in handle_one_connection sql/sql_connect.cc:1241
#21 0x7f16208926d9 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x76d9)
#22 0x7f161fd24d7e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0x108d7e)
ALTER TABLE test_2.t3_2 ENGINE = InnoDB, ALGORITHM COPY, LOCK SHARED
—
==218535==ERROR: AddressSanitizer: use-after-poison on address 0x7f75386fb7e0 at pc 0x5643aa6ede38 bp 0x7f75073feb20 sp 0x7f75073feb10
READ of size 8 at 0x7f75386fb7e0 thread T38
#0 0x5643aa6ede37 in lock_rec_other_trx_holds_expl storage/innobase/lock/lock0lock.cc:1304
#1 0x5643aa705f45 in lock_rec_convert_impl_to_expl storage/innobase/lock/lock0lock.cc:6107
#2 0x5643aa707248 in lock_sec_rec_read_check_and_lock(unsigned long, buf_block_t const*, unsigned char const*, dict_index_t*, unsigned long const*, lock_mode, unsigned long, que_thr_t*) storage/innobase/lock/lock0lock.cc:6324
#3 0x5643aa830466 in row_ins_set_shared_rec_lock storage/innobase/row/row0ins.cc:1483
#4 0x5643aa83254f in row_ins_scan_sec_index_for_duplicate storage/innobase/row/row0ins.cc:2102
#5 0x5643aa835eda in row_ins_sec_index_entry_low(unsigned long, unsigned long, dict_index_t*, mem_block_info_t*, mem_block_info_t*, dtuple_t*, unsigned long, que_thr_t*, bool) storage/innobase/row/row0ins.cc:2947
#6 0x5643aa837310 in row_ins_sec_index_entry(dict_index_t*, dtuple_t*, que_thr_t*, bool) storage/innobase/row/row0ins.cc:3242
#7 0x5643aa91f853 in row_upd_sec_index_entry storage/innobase/row/row0upd.cc:2503
#8 0x5643aa91fbab in row_upd_sec_step storage/innobase/row/row0upd.cc:2530
#9 0x5643aa923c17 in row_upd storage/innobase/row/row0upd.cc:3289
#10 0x5643aa92453a in row_upd_step(que_thr_t*) storage/innobase/row/row0upd.cc:3406
#11 0x5643aa7d1fdd in que_thr_step storage/innobase/que/que0que.cc:1031
#12 0x5643aa7d2468 in que_run_threads_low storage/innobase/que/que0que.cc:1111
#13 0x5643aa7d2774 in que_run_threads(que_thr_t*) storage/innobase/que/que0que.cc:1151
#14 0x5643aa7d2d2e in que_eval_sql(pars_info_t*, char const*, unsigned long, trx_t*) storage/innobase/que/que0que.cc:1228
#15 0x5643aa85af16 in row_merge_rename_tables_dict(dict_table_t*, dict_table_t*, char const*, trx_t*) storage/innobase/row/row0merge.cc:4233
#16 0x5643aa683e93 in commit_try_rebuild(Alter_inplace_info*, ha_innobase_inplace_ctx*, TABLE*, TABLE const*, trx_t*, char const*) (/mnt/r0/mleich/10.2/bld_asan/sql/mysqld+0x1939e93)
#17 0x5643aa67c49f in ha_innobase::commit_inplace_alter_table(TABLE*, Alter_inplace_info*, bool) storage/innobase/handler/handler0alter.cc:8616
#18 0x5643aa11335d in handler::ha_commit_inplace_alter_table(TABLE*, Alter_inplace_info*, bool) sql/handler.cc:4230
#19 0x5643a9d3c5ba in mysql_inplace_alter_table sql/sql_table.cc:7360
#20 0x5643a9d486c4 in mysql_alter_table(THD*, char*, char*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool) sql/sql_table.cc:9353
#21 0x5643a9e69fb8 in Sql_cmd_alter_table::execute(THD*) sql/sql_alter.cc:318
#22 0x5643a9b4e712 in mysql_execute_command(THD*) sql/sql_parse.cc:6224
#23 0x5643a9b58ca6 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) sql/sql_parse.cc:7940
#24 0x5643a9b33df4 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) sql/sql_parse.cc:1820
#25 0x5643a9b30e95 in do_command(THD*) sql/sql_parse.cc:1373
#26 0x5643a9e5bff3 in do_handle_one_connection(CONNECT*) sql/sql_connect.cc:1335
#27 0x5643a9e5b9d8 in handle_one_connection sql/sql_connect.cc:1241
#28 0x7f75448846d9 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x76d9)
#29 0x7f7543d16d7e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0x108d7e)

ALTER TABLE test_2.t3_1 ENGINE = InnoDB, ALGORITHM INPLACE, LOCK SHARED
—
==218633==ERROR: AddressSanitizer: use-after-poison on address 0x7fb353bfa8d8 at pc 0x562e5fc0fefa bp 0x7fb322d3ff40 sp 0x7fb322d3ff30
READ of size 8 at 0x7fb353bfa8d8 thread T35
#0 0x562e5fc0fef9 in trx_create_low storage/innobase/trx/trx0trx.cc:390
#1 0x562e5fc10aaa in trx_allocate_for_background() storage/innobase/trx/trx0trx.cc:469
#2 0x562e5fdcdac5 in dict_stats_exec_sql storage/innobase/dict/dict0stats.cc:301
#3 0x562e5fddb43d in dict_stats_rename_table_in_table_stats storage/innobase/dict/dict0stats.cc:3634
#4 0x562e5fddbac3 in dict_stats_rename_table(char const*, char const*, char*, unsigned long) storage/innobase/dict/dict0stats.cc:3737
#5 0x562e5f843767 in ha_innobase::rename_table(char const*, char const*) storage/innobase/handler/ha_innodb.cc:13586
#6 0x562e5f34899f in handler::ha_rename_table(char const*, char const*) sql/handler.cc:4311
#7 0x562e5ef64f1f in mysql_rename_table(handlerton*, char const*, char const*, char const*, char const*, unsigned int) sql/sql_table.cc:5307
#8 0x562e5ef7e902 in mysql_alter_table(THD*, char*, char*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool) sql/sql_table.cc:9586
#9 0x562e5f09efb8 in Sql_cmd_alter_table::execute(THD*) sql/sql_alter.cc:318
#10 0x562e5ed83712 in mysql_execute_command(THD*) sql/sql_parse.cc:6224
#11 0x562e5ed8dca6 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) sql/sql_parse.cc:7940
#12 0x562e5ed68df4 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) sql/sql_parse.cc:1820
#13 0x562e5ed65e95 in do_command(THD*) sql/sql_parse.cc:1373
#14 0x562e5f090ff3 in do_handle_one_connection(CONNECT*) sql/sql_connect.cc:1335
#15 0x562e5f0909d8 in handle_one_connection sql/sql_connect.cc:1241
#16 0x7fb35fd966d9 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x76d9)
#17 0x7fb35f228d7e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0x108d7e)
ALTER TABLE test_2.t3_2 ENGINE = InnoDB, ALGORITHM COPY, LOCK SHARED

==218809==ERROR: AddressSanitizer: use-after-poison on address 0x7f8d809fbd30 at pc 0x56489864a67b bp 0x7f8d554a63e0 sp 0x7f8d554a63d0
WRITE of size 8 at 0x7f8d809fbd30 thread T33
==218809==AddressSanitizer: while reporting a bug found another one. Ignoring.
#0 0x56489864a67a in void ut_list_prepend<ut_list_base<trx_t, ut_list_node<trx_t> trx_t::> >(ut_list_base<trx_t, ut_list_node<trx_t> trx_t::>&, ut_list_base<trx_t, ut_list_node<trx_t> trx_t::>::elem_type) storage/innobase/include/ut0lst.h:161
#1 0x564898638cca in trx_allocate_for_mysql() storage/innobase/trx/trx0trx.cc:488
#2 0x56489823797c in innobase_trx_allocate(THD*) storage/innobase/handler/ha_innodb.cc:2824
#3 0x5648982c3a56 in prepare_inplace_alter_table_dict storage/innobase/handler/handler0alter.cc:4402
#4 0x5648982cf408 in ha_innobase::prepare_inplace_alter_table(TABLE*, Alter_inplace_info*) storage/innobase/handler/handler0alter.cc:6238
#5 0x564897d701ad in handler::ha_prepare_inplace_alter_table(TABLE*, Alter_inplace_info*) sql/handler.cc:4210
#6 0x56489799909a in mysql_inplace_alter_table sql/sql_table.cc:7301
#7 0x5648979a56c4 in mysql_alter_table(THD*, char*, char*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool) sql/sql_table.cc:9353
#8 0x564897ac6fb8 in Sql_cmd_alter_table::execute(THD*) sql/sql_alter.cc:318
#9 0x5648977ab712 in mysql_execute_command(THD*) sql/sql_parse.cc:6224
#10 0x5648977b5ca6 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) sql/sql_parse.cc:7940
#11 0x564897790df4 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) sql/sql_parse.cc:1820
#12 0x56489778de95 in do_command(THD*) sql/sql_parse.cc:1373
#13 0x564897ab8ff3 in do_handle_one_connection(CONNECT*) sql/sql_connect.cc:1335
#14 0x564897ab89d8 in handle_one_connection sql/sql_connect.cc:1241
#15 0x7f8d8cbb06d9 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x76d9)
#16 0x7f8d8c042d7e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0x108d7e)
ALTER TABLE test.t3_2 ENGINE = InnoDB, ALGORITHM INPLACE, LOCK SHARED
—
6*.log
==216699==ERROR: AddressSanitizer: use-after-poison on address 0x7f8f81b05a60 at pc 0x55d177a5b193 bp 0x7f8f681c9fe0 sp 0x7f8f681c9fd0
WRITE of size 8 at 0x7f8f81b05a60 thread T57
#0 0x55d177a5b192 in trx_undo_assign_undo(trx_t*, trx_rseg_t*, trx_undo_t**, unsigned long) storage/innobase/trx/trx0undo.cc:1613
#1 0x55d177a14e35 in trx_undo_report_row_operation(que_thr_t*, dict_index_t*, dtuple_t const*, upd_t const*, unsigned long, unsigned char const*, unsigned long const*, unsigned long*) storage/innobase/trx/trx0rec.cc:1963
#2 0x55d177abed19 in btr_cur_del_mark_set_clust_rec(buf_block_t*, unsigned char*, dict_index_t*, unsigned long const*, que_thr_t*, dtuple_t const*, mtr_t*) storage/innobase/btr/btr0cur.cc:4721
#3 0x55d17797a8bf in row_upd_clust_rec_by_insert storage/innobase/row/row0upd.cc:2705
#4 0x55d17797d125 in row_upd_clust_step storage/innobase/row/row0upd.cc:3184
#5 0x55d17797d821 in row_upd storage/innobase/row/row0upd.cc:3260
#6 0x55d17797e53a in row_upd_step(que_thr_t*) storage/innobase/row/row0upd.cc:3406
#7 0x55d17782bfdd in que_thr_step storage/innobase/que/que0que.cc:1031
#8 0x55d17782c468 in que_run_threads_low storage/innobase/que/que0que.cc:1111
#9 0x55d17782c774 in que_run_threads(que_thr_t*) storage/innobase/que/que0que.cc:1151
#10 0x55d17782cd2e in que_eval_sql(pars_info_t*, char const*, unsigned long, trx_t*) storage/innobase/que/que0que.cc:1228
#11 0x55d177bf2c62 in dict_stats_exec_sql storage/innobase/dict/dict0stats.cc:311
#12 0x55d177c0043d in dict_stats_rename_table_in_table_stats storage/innobase/dict/dict0stats.cc:3634
#13 0x55d177c00ac3 in dict_stats_rename_table(char const*, char const*, char*, unsigned long) storage/innobase/dict/dict0stats.cc:3737
#14 0x55d177668767 in ha_innobase::rename_table(char const*, char const*) storage/innobase/handler/ha_innodb.cc:13586
#15 0x55d17716d99f in handler::ha_rename_table(char const*, char const*) sql/handler.cc:4311
#16 0x55d176d89f1f in mysql_rename_table(handlerton*, char const*, char const*, char const*, char const*, unsigned int) sql/sql_table.cc:5307
#17 0x55d176da3902 in mysql_alter_table(THD*, char*, char*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool) sql/sql_table.cc:9586
#18 0x55d176ec3fb8 in Sql_cmd_alter_table::execute(THD*) sql/sql_alter.cc:318
#19 0x55d176ba8712 in mysql_execute_command(THD*) sql/sql_parse.cc:6224
#20 0x55d176bb2ca6 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) sql/sql_parse.cc:7940
#21 0x55d176b8ddf4 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) sql/sql_parse.cc:1820
#22 0x55d176b8ae95 in do_command(THD*) sql/sql_parse.cc:1373
#23 0x55d176eb5ff3 in do_handle_one_connection(CONNECT*) sql/sql_connect.cc:1335
#24 0x55d176eb59d8 in handle_one_connection sql/sql_connect.cc:1241
#25 0x7f8f8dc396d9 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x76d9)
#26 0x7f8f8d0cbd7e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0x108d7e)

==216824==ERROR: AddressSanitizer: use-after-poison on address 0x7f698c5fcf70 at pc 0x556a503bd247 bp 0x7f695b6e19b0 sp 0x7f695b6e19a0
READ of size 4 at 0x7f698c5fcf70 thread T35
==216824==AddressSanitizer: while reporting a bug found another one. Ignoring.
#0 0x556a503bd246 in que_thr_peek_stop storage/innobase/include/que0que.ic:279
#1 0x556a503bf833 in que_thr_node_step storage/innobase/que/que0que.cc:622
#2 0x556a503c106b in que_thr_step storage/innobase/que/que0que.cc:1043
#3 0x556a503c1468 in que_run_threads_low storage/innobase/que/que0que.cc:1111
#4 0x556a503c1774 in que_run_threads(que_thr_t*) storage/innobase/que/que0que.cc:1151
#5 0x556a503c1d2e in que_eval_sql(pars_info_t*, char const*, unsigned long, trx_t*) storage/innobase/que/que0que.cc:1228
#6 0x556a50792f7b in dict_stats_fetch_from_ps storage/innobase/dict/dict0stats.cc:3018
#7 0x556a50793e98 in dict_stats_update(dict_table_t*, dict_stats_upd_option_t) storage/innobase/dict/dict0stats.cc:3286
#8 0x556a501c3604 in dict_stats_init storage/innobase/include/dict0stats.ic:166
#9 0x556a501d7670 in ha_innobase::open(char const*, int, unsigned int) storage/innobase/handler/ha_innodb.cc:6297
#10 0x556a4fcf5e78 in handler::ha_open(TABLE*, char const*, int, unsigned int) sql/handler.cc:2501
#11 0x556a4f9a6c3a in open_table_from_share(THD*, TABLE_SHARE*, char const*, unsigned int, unsigned int, unsigned int, TABLE*, bool) sql/table.cc:3328
#12 0x556a4fbb080f in THD::open_temporary_table(TMP_TABLE_SHARE*, char const*, bool) sql/temporary_tables.cc:1104
#13 0x556a4fbabc0b in THD::create_and_open_tmp_table(handlerton*, st_mysql_const_unsigned_lex_string*, char const*, char const*, char const*, bool) sql/temporary_tables.cc:76
#14 0x556a4f937d64 in mysql_alter_table(THD*, char*, char*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool) sql/sql_table.cc:9456
#15 0x556a4fa58fb8 in Sql_cmd_alter_table::execute(THD*) sql/sql_alter.cc:318
#16 0x556a4f73d712 in mysql_execute_command(THD*) sql/sql_parse.cc:6224
#17 0x556a4f747ca6 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) sql/sql_parse.cc:7940
#18 0x556a4f722df4 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) sql/sql_parse.cc:1820
#19 0x556a4f71fe95 in do_command(THD*) sql/sql_parse.cc:1373
#20 0x556a4fa4aff3 in do_handle_one_connection(CONNECT*) sql/sql_connect.cc:1335
#21 0x556a4fa4a9d8 in handle_one_connection sql/sql_connect.cc:1241
#22 0x7f699877d6d9 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x76d9)
#23 0x7f6997c0fd7e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0x108d7e)
—
==216942==ERROR: AddressSanitizer: use-after-poison on address 0x7f38da6fd330 at pc 0x55919fc97d79 bp 0x7f38a912dc30 sp 0x7f38a912dc20
WRITE of size 8 at 0x7f38da6fd330 thread T41
#0 0x55919fc97d78 in void ut_list_remove<ut_list_base<trx_t, ut_list_node<trx_t> trx_t::>, GenericGetNode<trx_t> >(ut_list_base<trx_t, ut_list_node<trx_t> trx_t::>&, ut_list_base<trx_t, ut_list_node<trx_t> trx_t::*>::node_type&, GenericGetNode<trx_t>) storage/innobase/include/ut0lst.h:340
#1 0x55919fc97a56 in void ut_list_remove<ut_list_base<trx_t, ut_list_node<trx_t> trx_t::> >(ut_list_base<trx_t, ut_list_node<trx_t> trx_t::>&, ut_list_base<trx_t, ut_list_node<trx_t> trx_t::>::elem_type) storage/innobase/include/ut0lst.h:385
#2 0x55919fca4605 in trx_erase_lists storage/innobase/trx/trx0trx.cc:1624
#3 0x55919fca4f4a in trx_commit_in_memory storage/innobase/trx/trx0trx.cc:1690
#4 0x55919fca6893 in trx_commit_low(trx_t*, mtr_t*) storage/innobase/trx/trx0trx.cc:1913
#5 0x55919fca69e1 in trx_commit(trx_t*) storage/innobase/trx/trx0trx.cc:1937
#6 0x55919fca7ec6 in trx_commit_for_mysql(trx_t*) storage/innobase/trx/trx0trx.cc:2145
#7 0x55919fe59d20 in dict_stats_exec_sql storage/innobase/dict/dict0stats.cc:324
#8 0x55919fe629d5 in dict_stats_save storage/innobase/dict/dict0stats.cc:2470
#9 0x55919fe65be5 in dict_stats_update(dict_table_t*, dict_stats_upd_option_t) storage/innobase/dict/dict0stats.cc:3239
#10 0x55919f8cc4ac in create_table_info_t::create_table_update_dict() storage/innobase/handler/ha_innodb.cc:12867
#11 0x55919f8cce19 in ha_innobase::create(char const*, TABLE*, HA_CREATE_INFO*) storage/innobase/handler/ha_innodb.cc:12996
#12 0x55919f3d4bf8 in handler::ha_create(char const*, TABLE*, HA_CREATE_INFO*) sql/handler.cc:4359
#13 0x55919f3d7574 in ha_create_table(THD*, char const*, char const*, char const*, HA_CREATE_INFO*, st_mysql_const_unsigned_lex_string*) sql/handler.cc:4729
#14 0x55919f009b2a in mysql_alter_table(THD*, char*, char*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool) sql/sql_table.cc:9408
#15 0x55919f12afb8 in Sql_cmd_alter_table::execute(THD*) sql/sql_alter.cc:318
#16 0x55919ee0f712 in mysql_execute_command(THD*) sql/sql_parse.cc:6224
#17 0x55919ee19ca6 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) sql/sql_parse.cc:7940
#18 0x55919edf4df4 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) sql/sql_parse.cc:1820
#19 0x55919edf1e95 in do_command(THD*) sql/sql_parse.cc:1373
#20 0x55919f11cff3 in do_handle_one_connection(CONNECT*) sql/sql_connect.cc:1335
#21 0x55919f11c9d8 in handle_one_connection sql/sql_connect.cc:1241
#22 0x7f38e68b56d9 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x76d9)
#23 0x7f38e5d47d7e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0x108d7e)

There are many more other backtraces.

Comment by Matthias Leich [ 2018-05-15 ]

grep -h 'SUMMARY: AddressSanitizer' comb_storage/1526032572/trial*.log | sort -u

SUMMARY: AddressSanitizer: use-after-poison /usr/include/c++/6/bits/stl_vector.h:576 in std::vector<ib_lock_t*, ut_allocator<ib_lock_t*, true> >::end() const
SUMMARY: AddressSanitizer: use-after-poison /work_m/10.2/storage/innobase/dict/dict0crea.cc:2667 in dict_table_assign_new_id(dict_table_t*, trx_t*)
SUMMARY: AddressSanitizer: use-after-poison /work_m/10.2/storage/innobase/include/que0que.ic:279 in que_thr_peek_stop
SUMMARY: AddressSanitizer: use-after-poison /work_m/10.2/storage/innobase/include/trx0sys.ic:257 in trx_rw_min_trx_id_low
SUMMARY: AddressSanitizer: use-after-poison /work_m/10.2/storage/innobase/include/trx0trx.h:1169 in trx_t::has_logged_persistent() const
SUMMARY: AddressSanitizer: use-after-poison /work_m/10.2/storage/innobase/include/trx0trx.ic:50 in trx_state_eq
SUMMARY: AddressSanitizer: use-after-poison /work_m/10.2/storage/innobase/include/trx0trx.ic:72 in trx_state_eq
SUMMARY: AddressSanitizer: use-after-poison /work_m/10.2/storage/innobase/include/ut0lst.h:161 in void ut_list_prepend<ut_list_base<trx_t, ut_list_node<trx_t> trx_t::> >(ut_list_base<trx_t, ut_list_node<trx_t> trx_t::>&, ut_list_base<trx_t, ut_list_node<trx_t> trx_t::>::elem_type)
SUMMARY: AddressSanitizer: use-after-poison /work_m/10.2/storage/innobase/include/ut0lst.h:340 in void ut_list_remove<ut_list_base<trx_t, ut_list_node<trx_t> trx_t::>, GenericGetNode<trx_t> >(ut_list_base<trx_t, ut_list_node<trx_t> trx_t::>&, ut_list_base<trx_t, ut_list_node<trx_t> trx_t::*>::node_type&, GenericGetNode<trx_t>)
SUMMARY: AddressSanitizer: use-after-poison /work_m/10.2/storage/innobase/include/ut0lst.h:349 in void ut_list_remove<ut_list_base<trx_t, ut_list_node<trx_t> trx_t::>, GenericGetNode<trx_t> >(ut_list_base<trx_t, ut_list_node<trx_t> trx_t::>&, ut_list_base<trx_t, ut_list_node<trx_t> trx_t::*>::node_type&, GenericGetNode<trx_t>)
SUMMARY: AddressSanitizer: use-after-poison /work_m/10.2/storage/innobase/lock/lock0lock.cc:1304 in lock_rec_other_trx_holds_expl
SUMMARY: AddressSanitizer: use-after-poison /work_m/10.2/storage/innobase/lock/lock0lock.cc:1472 in lock_rec_create_low(ib_lock_t*, que_thr_t*, unsigned long, unsigned long, unsigned long, unsigned char const*, unsigned long, dict_index_t*, trx_t*, bool)
SUMMARY: AddressSanitizer: use-after-poison /work_m/10.2/storage/innobase/que/que0que.cc:1073 in que_thr_step
SUMMARY: AddressSanitizer: use-after-poison /work_m/10.2/storage/innobase/que/que0que.cc:1222 in que_eval_sql(pars_info_t*, char const*, unsigned long, trx_t*)
SUMMARY: AddressSanitizer: use-after-poison /work_m/10.2/storage/innobase/row/row0ins.cc:2287 in row_ins_duplicate_error_in_clust
SUMMARY: AddressSanitizer: use-after-poison /work_m/10.2/storage/innobase/row/row0mysql.cc:2176 in row_mysql_lock_data_dictionary_func(trx_t*, char const*, unsigned int)
SUMMARY: AddressSanitizer: use-after-poison /work_m/10.2/storage/innobase/row/row0mysql.cc:2222 in row_create_table_for_mysql(dict_table_t*, trx_t*, fil_encryption_t, unsigned int)
SUMMARY: AddressSanitizer: use-after-poison /work_m/10.2/storage/innobase/row/row0sel.cc:1839 in row_sel
SUMMARY: AddressSanitizer: use-after-poison /work_m/10.2/storage/innobase/row/row0upd.cc:3409 in row_upd_step(que_thr_t*)
SUMMARY: AddressSanitizer: use-after-poison /work_m/10.2/storage/innobase/trx/trx0purge.cc:311 in trx_purge_add_update_undo_to_history(trx_t*, unsigned char*, mtr_t*)
SUMMARY: AddressSanitizer: use-after-poison /work_m/10.2/storage/innobase/trx/trx0rec.cc:2037 in trx_undo_report_row_operation(que_thr_t*, dict_index_t*, dtuple_t const*, upd_t const*, unsigned long, unsigned char const*, unsigned long const*, unsigned long*)
SUMMARY: AddressSanitizer: use-after-poison /work_m/10.2/storage/innobase/trx/trx0rec.cc:884 in trx_undo_page_report_modify
SUMMARY: AddressSanitizer: use-after-poison /work_m/10.2/storage/innobase/trx/trx0sys.cc:1019 in trx_sys_validate_trx_list_low
SUMMARY: AddressSanitizer: use-after-poison /work_m/10.2/storage/innobase/trx/trx0trx.cc:1282 in trx_start_low
SUMMARY: AddressSanitizer: use-after-poison /work_m/10.2/storage/innobase/trx/trx0trx.cc:390 in trx_create_low
SUMMARY: AddressSanitizer: use-after-poison /work_m/10.2/storage/innobase/trx/trx0trx.cc:406 in trx_create_low
SUMMARY: AddressSanitizer: use-after-poison /work_m/10.2/storage/innobase/trx/trx0undo.cc:1443 in trx_undo_create
SUMMARY: AddressSanitizer: use-after-poison /work_m/10.2/storage/innobase/trx/trx0undo.cc:1613 in trx_undo_assign_undo(trx_t*, trx_rseg_t*, trx_undo_t**, unsigned long)

Comment by Marko Mäkelä [ 2018-05-15 ]

I analyzed one 10.2 core so far. There are 2 transactions in trx_sys->rw_trx_set: the faulty one, and another one that is waiting for dict_operation_lock for updating persistent statistics when committing ALTER TABLE test_1.t3_1, in alter_stats_rebuild().

The faulty transaction is executing the final RENAME phase of ALTER TABLE…ALGORITHM=COPY, renaming the original table to a temporary name before renaming the rebuilt table:

/work_m/RQG_new/comb_storage/1526032572/weg/1/data/core

 
#21 0x000055d177bf2c63 in dict_stats_exec_sql (pinfo=0x617000a70f88, 
    sql=0x55d17899b6a0 "PROCEDURE RENAME_TABLE_IN_TABLE_STATS () IS\nBEGIN\nUPDATE \"mysql/innodb_table_stats\" SET\ndatabase_name = :new_dbname_utf8,\ntable_name = :new_tablename_utf8\nWHERE\ndatabase_name = :old_dbname_utf8 AND\nta"..., 
    trx=0x7f8f81b05770) at /work_m/10.2/storage/innobase/dict/dict0stats.cc:311
 
#22 0x000055d177c0043e in dict_stats_rename_table_in_table_stats (
 
    old_dbname_utf8=0x7f8f681cc480 "test_2", 
    old_tablename_utf8=0x7f8f681cc680 "t3_2", 
    new_dbname_utf8=0x7f8f681cc580 "test_2", 
    new_tablename_utf8=0x7f8f681cc780 "#mysql50##sql2-34e7b-27")
 
    at /work_m/10.2/storage/innobase/dict/dict0stats.cc:3634
 
#23 0x000055d177c00ac4 in dict_stats_rename_table (
 
    old_name=0x7f8f681ccd10 "test_2/t3_2", 
    new_name=0x7f8f681ccfd0 "test_2/#sql2-34e7b-27", 
    errstr=0x7f8f681ccaf0 "\222\066#x\321U", errstr_sz=512)
 
    at /work_m/10.2/storage/innobase/dict/dict0stats.cc:3737
 
#24 0x000055d177668768 in ha_innobase::rename_table (this=0x62b00015f7c8, 
    from=0x7f8f681cd5c0 "./test_2/t3_2", 
    to=0x7f8f681cd800 "./test_2/#sql2-34e7b-27")
 
    at /work_m/10.2/storage/innobase/handler/ha_innodb.cc:13586
 
#25 0x000055d17716d9a0 in handler::ha_rename_table (this=0x62b00015f7c8, 
    from=0x7f8f681cd5c0 "./test_2/t3_2", 
    to=0x7f8f681cd800 "./test_2/#sql2-34e7b-27")
 
    at /work_m/10.2/sql/handler.cc:4311

It looks like the trx must have been allocated in dict_stats_exec_sql():

	if (trx == NULL) {
 
		trx = trx_allocate_for_background();
 
		trx_started = true;
 
 
 
		if (srv_read_only_mode) {
 
			trx_start_internal_read_only(trx);
 
		} else {
 
			trx_start_internal(trx);
 
		}
 
	}

I do not see anything obviously wrong in trx_allocate_for_background() or trx_start_internal(), nor in Pool::get() which is invoked as trx_pools->get().

It is too early to say if this is a false alarm or a genuine problem. A false alarm should be unlikely, because the Pool::get() operation should be protected by TrxPoolLock::m_mutex and TrxPoolManagerLock::m_mutex. (User-driven memory poisoning in AddressSanitizer is not thread-safe by itself.)

It would be interesting to run tests with skip_innodb_stats_persistent and see if this is mostly related to persistent statistics. A quick mysql-test-run --mysqld=--innodb-stats-persistent=1 did not reveal anything.

Comment by Matthias Leich [ 2018-05-15 ]

No replay within ~ 100 RQG test runs after assigning innodb_stats_persistent=off to the server start.
Usually I get a lot replays in that amount of test runs.
So the innodb_stats_persistent seems to be guilty.

Comment by Marko Mäkelä [ 2018-07-26 ]

In MDEV-16781 there is a failure reported during a DDL operation (not during the update of persistent statistics, or dict_stats_exec_sql()). I hope we can repeat that while setting innodb_stats_persistent=off.

Comment by Marko Mäkelä [ 2018-08-15 ]

The Pool poisoning added in MDEV-15030 was not thread-safe. After I protected the poisoning and unpoisoning with a common mutex, I was unable to repeat failures with a test case of MDEV-16781.

Comment by Marko Mäkelä [ 2018-08-16 ]

There was a race condition in the AddressSanitizer instrumentation that I introduced in MDEV-15030.

Also, I believe that there was a race condition between trx_reference() and trx_free()/trx_create_low(), but I do not think that it would have triggered ASAN. Furthermore, related to this work, I simplified the memory management of trx->lock.rec_pool and trx->lock.table_pool.

Comment by Marko Mäkelä [ 2019-08-27 ]

I had added some unreachable code to trx_reference() in an early attempt of fixing this. That will be reverted in 10.2.27, 10.3.18, 10.4.8 onwards.

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