[MDEV-18546] ASAN heap-use-after-free in innobase_get_computed_value / row_purge Created: 2019-02-11  Updated: 2021-04-27  Resolved: 2019-10-11

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, Virtual Columns
Affects Version/s: 10.3, 10.4
Fix Version/s: 10.2.28, 10.3.19, 10.4.9

Type: Bug Priority: Major
Reporter: Alice Sherepa Assignee: Nikita Malyavin
Resolution: Fixed Votes: 0
Labels: affects-tests

Issue Links:
Relates
relates to MDEV-15855 Assertion `mysql_table' failed in inn... Closed
relates to MDEV-16222 Assertion `0' failed in row_purge_rem... Closed
relates to MDEV-17005 ASAN heap-use-after-free in innobase_... Closed

 Description   

10.4 3c305d3f1951f1667f84e48

 
    #0 0x7f96f940c934 in __asan_memcpy (/usr/lib/x86_64-linux-gnu/libasan.so.2+0x8c934)
 
    #1 0x55ed26e2b9dc in innobase_get_computed_value(dtuple_t const*, dict_v_col_t const*, dict_index_t const*, mem_block_info_t**, mem_block_info_t*, dict_field_t const*, THD*, TABLE*, unsigned char*, dict_table_t const*, upd_t*, dict_foreign_t*) /10.4/storage/innobase/handler/ha_innodb.cc:20699
 
    #2 0x55ed27149034 in row_vers_build_clust_v_col /10.4/storage/innobase/row/row0vers.cc:484
 
    #3 0x55ed2714af9a in row_vers_old_has_index_entry(bool, unsigned char const*, mtr_t*, dict_index_t*, dtuple_t const*, unsigned long, unsigned long, purge_vcol_info_t*) /10.4/storage/innobase/row/row0vers.cc:958
 
    #4 0x55ed270dfc66 in row_purge_poss_sec(purge_node_t*, dict_index_t*, dtuple_t const*, btr_pcur_t*, mtr_t*, bool) /10.4/storage/innobase/row/row0purge.cc:345
 
    #5 0x55ed270e0de6 in row_purge_remove_sec_if_poss_leaf /10.4/storage/innobase/row/row0purge.cc:607
 
    #6 0x55ed270e1406 in row_purge_remove_sec_if_poss /10.4/storage/innobase/row/row0purge.cc:720
 
    #7 0x55ed270e1872 in row_purge_del_mark /10.4/storage/innobase/row/row0purge.cc:794
 
    #8 0x55ed270e44fd in row_purge_record_func /10.4/storage/innobase/row/row0purge.cc:1194
 
    #9 0x55ed270e4c1b in row_purge /10.4/storage/innobase/row/row0purge.cc:1261
 
    #10 0x55ed270e53e2 in row_purge_step(que_thr_t*) /10.4/storage/innobase/row/row0purge.cc:1347
 
    #11 0x55ed26ff925c in que_thr_step /10.4/storage/innobase/que/que0que.cc:1042
 
    #12 0x55ed26ff965b in que_run_threads_low /10.4/storage/innobase/que/que0que.cc:1104
 
    #13 0x55ed26ff99a2 in que_run_threads(que_thr_t*) /10.4/storage/innobase/que/que0que.cc:1144
 
    #14 0x55ed27159743 in srv_task_execute /10.4/storage/innobase/srv/srv0srv.cc:2437
 
    #15 0x55ed2715997d in srv_worker_thread /10.4/storage/innobase/srv/srv0srv.cc:2485
 
    #16 0x7f96f81a26b9 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x76b9)
 
    #17 0x7f96f743341c in clone (/lib/x86_64-linux-gnu/libc.so.6+0x10741c)



 Comments   
Comment by Elena Stepanova [ 2019-02-25 ]

The test case below fails quite readily on 10.3. Run with --repeat=N. It usually fails for me within 5 attempts, but it can vary on different machines and builds.
I didn't get a failure with this test case on 10.4, I had it on more complicated ones, so it's still reproducible on 10.4 as well.

--source include/have_innodb.inc
 
 
 
CREATE TABLE t1 ( 
  pk INT AUTO_INCREMENT,
 
  b BIT(15),
 
  v BIT(15) AS (b) VIRTUAL,
 
  PRIMARY KEY(pk),
 
  UNIQUE(v)
 
) ENGINE=InnoDB;
 
INSERT IGNORE INTO t1 (b) VALUES
 
  (NULL),(b'011'),(b'000110100'),
 
  (b'01101101010'),(b'01111001001011'),(NULL);
 
 
 
REPLACE INTO t1 (pk, b) SELECT pk, b FROM t1;
 
FLUSH TABLES;
 
 
 
# Cleanup
 
DROP TABLE t1;

10.3 09bd2138 ASAN

 
==29229==ERROR: AddressSanitizer: heap-use-after-free on address 0x61900001020d at pc 0x5612b0d0838c bp 0x7f1f77b45320 sp 0x7f1f77b45318
 
READ of size 2 at 0x61900001020d thread T19
 
    #0 0x5612b0d0838b in innobase_get_computed_value(dtuple_t const*, dict_v_col_t const*, dict_index_t const*, mem_block_info_t**, mem_block_info_t*, dict_field_t const*, THD*, TABLE*, unsigned char*, dict_table_t const*, upd_t*, dict_foreign_t*) /data/src/10.3/storage/innobase/handler/ha_innodb.cc:20882
 
    #1 0x5612b102756d in row_vers_build_clust_v_col /data/src/10.3/storage/innobase/row/row0vers.cc:484
 
    #2 0x5612b10294db in row_vers_old_has_index_entry(bool, unsigned char const*, mtr_t*, dict_index_t*, dtuple_t const*, unsigned long, unsigned long, purge_vcol_info_t*) /data/src/10.3/storage/innobase/row/row0vers.cc:958
 
    #3 0x5612b0fa90eb in row_purge_poss_sec(purge_node_t*, dict_index_t*, dtuple_t const*, btr_pcur_t*, mtr_t*, bool) /data/src/10.3/storage/innobase/row/row0purge.cc:346
 
    #4 0x5612b0faa203 in row_purge_remove_sec_if_poss_leaf /data/src/10.3/storage/innobase/row/row0purge.cc:604
 
    #5 0x5612b0faa814 in row_purge_remove_sec_if_poss /data/src/10.3/storage/innobase/row/row0purge.cc:717
 
    #6 0x5612b0faac17 in row_purge_del_mark /data/src/10.3/storage/innobase/row/row0purge.cc:791
 
    #7 0x5612b0fad6c8 in row_purge_record_func /data/src/10.3/storage/innobase/row/row0purge.cc:1190
 
    #8 0x5612b0fadd85 in row_purge /data/src/10.3/storage/innobase/row/row0purge.cc:1257
 
    #9 0x5612b0fae570 in row_purge_step(que_thr_t*) /data/src/10.3/storage/innobase/row/row0purge.cc:1343
 
    #10 0x5612b0ec35db in que_thr_step /data/src/10.3/storage/innobase/que/que0que.cc:1042
 
    #11 0x5612b0ec39fe in que_run_threads_low /data/src/10.3/storage/innobase/que/que0que.cc:1104
 
    #12 0x5612b0ec3d55 in que_run_threads(que_thr_t*) /data/src/10.3/storage/innobase/que/que0que.cc:1144
 
    #13 0x5612b10377bf in srv_task_execute /data/src/10.3/storage/innobase/srv/srv0srv.cc:2449
 
    #14 0x5612b10379c8 in srv_worker_thread /data/src/10.3/storage/innobase/srv/srv0srv.cc:2497
 
    #15 0x7f1f8e064493 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x7493)
 
    #16 0x7f1f8c44a93e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0xe893e)
 
 
 
0x61900001020d is located 653 bytes inside of 1100-byte region [0x61900000ff80,0x6190000103cc)
 
freed by thread T27 here:
 
    #0 0x7f1f8e2ce527 in __interceptor_free (/usr/lib/x86_64-linux-gnu/libasan.so.1+0x54527)
 
    #1 0x5612b163926f in free_memory /data/src/10.3/mysys/safemalloc.c:279
 
    #2 0x5612b1638875 in sf_free /data/src/10.3/mysys/safemalloc.c:197
 
    #3 0x5612b16092be in my_free /data/src/10.3/mysys/my_malloc.c:223
 
    #4 0x5612b15e92b9 in free_root /data/src/10.3/mysys/my_alloc.c:419
 
    #5 0x5612b0081705 in TABLE_SHARE::destroy() /data/src/10.3/sql/table.cc:481
 
    #6 0x5612b0081911 in free_table_share(TABLE_SHARE*) /data/src/10.3/sql/table.cc:497
 
    #7 0x5612b0304056 in tdc_delete_share_from_hash /data/src/10.3/sql/table_cache.cc:549
 
    #8 0x5612b0307416 in tdc_release_share(TABLE_SHARE*) /data/src/10.3/sql/table_cache.cc:996
 
    #9 0x5612b0301ef7 in intern_close_table /data/src/10.3/sql/table_cache.cc:223
 
    #10 0x5612b0302540 in tc_purge(bool) /data/src/10.3/sql/table_cache.cc:335
 
    #11 0x5612afc9016a in close_cached_tables(THD*, TABLE_LIST*, bool, unsigned long) /data/src/10.3/sql/sql_base.cc:377
 
    #12 0x5612b01bc487 in reload_acl_and_cache(THD*, unsigned long long, TABLE_LIST*, int*) /data/src/10.3/sql/sql_reload.cc:344
 
    #13 0x5612afdfabe2 in mysql_execute_command(THD*) /data/src/10.3/sql/sql_parse.cc:5625
 
    #14 0x5612afe09fa2 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.3/sql/sql_parse.cc:8095
 
    #15 0x5612afde407a in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.3/sql/sql_parse.cc:1854
 
    #16 0x5612afde108c in do_command(THD*) /data/src/10.3/sql/sql_parse.cc:1396
 
    #17 0x5612b0154861 in do_handle_one_connection(CONNECT*) /data/src/10.3/sql/sql_connect.cc:1403
 
    #18 0x5612b015426d in handle_one_connection /data/src/10.3/sql/sql_connect.cc:1309
 
    #19 0x5612b0c89349 in pfs_spawn_thread /data/src/10.3/storage/perfschema/pfs.cc:1862
 
    #20 0x7f1f8e064493 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x7493)
 
 
 
previously allocated by thread T27 here:
 
    #0 0x7f1f8e2ce73f in malloc (/usr/lib/x86_64-linux-gnu/libasan.so.1+0x5473f)
 
    #1 0x5612b1637fe5 in sf_malloc /data/src/10.3/mysys/safemalloc.c:118
 
    #2 0x5612b16088e0 in my_malloc /data/src/10.3/mysys/my_malloc.c:101
 
    #3 0x5612b15e818c in alloc_root /data/src/10.3/mysys/my_alloc.c:250
 
    #4 0x5612b15e9cfe in memdup_root /data/src/10.3/mysys/my_alloc.c:491
 
    #5 0x5612b0086d80 in TABLE_SHARE::init_from_binary_frm_image(THD*, bool, unsigned char const*, unsigned long) /data/src/10.3/sql/table.cc:1273
 
    #6 0x5612b008252d in open_table_def(THD*, TABLE_SHARE*, unsigned int) /data/src/10.3/sql/table.cc:677
 
    #7 0x5612b0305ba0 in tdc_acquire_share(THD*, TABLE_LIST*, unsigned int, TABLE**) /data/src/10.3/sql/table_cache.cc:840
 
    #8 0x5612afc96d66 in open_table(THD*, TABLE_LIST*, Open_table_context*) /data/src/10.3/sql/sql_base.cc:1831
 
    #9 0x5612afc9ef2e in open_and_process_table /data/src/10.3/sql/sql_base.cc:3596
 
    #10 0x5612afca190f in open_tables(THD*, DDL_options_st const&, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*) /data/src/10.3/sql/sql_base.cc:4121
 
    #11 0x5612afca6127 in open_and_lock_tables(THD*, DDL_options_st const&, TABLE_LIST*, bool, unsigned int, Prelocking_strategy*) /data/src/10.3/sql/sql_base.cc:4996
 
    #12 0x5612afc17328 in open_and_lock_tables(THD*, TABLE_LIST*, bool, unsigned int) /data/src/10.3/sql/sql_base.h:502
 
    #13 0x5612afd575b7 in mysql_insert(THD*, TABLE_LIST*, List<Item>&, List<List<Item> >&, List<Item>&, List<Item>&, enum_duplicates, bool) /data/src/10.3/sql/sql_insert.cc:760
 
    #14 0x5612afdf4113 in mysql_execute_command(THD*) /data/src/10.3/sql/sql_parse.cc:4730
 
    #15 0x5612afe09fa2 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.3/sql/sql_parse.cc:8095
 
    #16 0x5612afde407a in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.3/sql/sql_parse.cc:1854
 
    #17 0x5612afde108c in do_command(THD*) /data/src/10.3/sql/sql_parse.cc:1396
 
    #18 0x5612b0154861 in do_handle_one_connection(CONNECT*) /data/src/10.3/sql/sql_connect.cc:1403
 
    #19 0x5612b015426d in handle_one_connection /data/src/10.3/sql/sql_connect.cc:1309
 
    #20 0x5612b0c89349 in pfs_spawn_thread /data/src/10.3/storage/perfschema/pfs.cc:1862
 
    #21 0x7f1f8e064493 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x7493)
 
 
 
Thread T19 created by T0 here:
 
    #0 0x7f1f8e29dbba in pthread_create (/usr/lib/x86_64-linux-gnu/libasan.so.1+0x23bba)
 
    #1 0x5612b0e6b44d in os_thread_create_func(void* (*)(void*), void*, unsigned long*) /data/src/10.3/storage/innobase/os/os0thread.cc:132
 
    #2 0x5612b10468a0 in srv_start(bool) /data/src/10.3/storage/innobase/srv/srv0start.cc:2418
 
    #3 0x5612b0cbfe86 in innodb_init /data/src/10.3/storage/innobase/handler/ha_innodb.cc:4266
 
    #4 0x5612b0507677 in ha_initialize_handlerton(st_plugin_int*) /data/src/10.3/sql/handler.cc:523
 
    #5 0x5612afe23ff0 in plugin_initialize /data/src/10.3/sql/sql_plugin.cc:1432
 
    #6 0x5612afe25910 in plugin_init(int*, char**, int) /data/src/10.3/sql/sql_plugin.cc:1715
 
    #7 0x5612afb5e5fe in init_server_components /data/src/10.3/sql/mysqld.cc:5387
 
    #8 0x5612afb607a9 in mysqld_main(int, char**) /data/src/10.3/sql/mysqld.cc:5998
 
    #9 0x5612afb49c8f in main /data/src/10.3/sql/main.cc:25
 
    #10 0x7f1f8c3822b0 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x202b0)
 
 
 
Thread T27 created by T0 here:
 
    #0 0x7f1f8e29dbba in pthread_create (/usr/lib/x86_64-linux-gnu/libasan.so.1+0x23bba)
 
    #1 0x5612b0c89911 in spawn_thread_v1 /data/src/10.3/storage/perfschema/pfs.cc:1912
 
    #2 0x5612afb4bc08 in inline_mysql_thread_create /data/src/10.3/include/mysql/psi/mysql_thread.h:1268
 
    #3 0x5612afb61d9a in create_thread_to_handle_connection(CONNECT*) /data/src/10.3/sql/mysqld.cc:6573
 
    #4 0x5612afb6249f in create_new_thread /data/src/10.3/sql/mysqld.cc:6643
 
    #5 0x5612afb634b6 in handle_connections_sockets() /data/src/10.3/sql/mysqld.cc:6918
 
    #6 0x5612afb61257 in mysqld_main(int, char**) /data/src/10.3/sql/mysqld.cc:6195
 
    #7 0x5612afb49c8f in main /data/src/10.3/sql/main.cc:25
 
    #8 0x7f1f8c3822b0 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x202b0)
 
 
 
SUMMARY: AddressSanitizer: heap-use-after-free /data/src/10.3/storage/innobase/handler/ha_innodb.cc:20882 innobase_get_computed_value(dtuple_t const*, dict_v_col_t const*, dict_index_t const*, mem_block_info_t**, mem_block_info_t*, dict_field_t const*, THD*, TABLE*, unsigned char*, dict_table_t const*, upd_t*, dict_foreign_t*)
 
Shadow bytes around the buggy address:
 
  0x0c327fff9ff0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c327fffa000: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c327fffa010: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c327fffa020: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c327fffa030: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
=>0x0c327fffa040: fd[fd]fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c327fffa050: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c327fffa060: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c327fffa070: fd fd fd fd fd fd fd fd fd fd fa fa fa fa fa fa
 
  0x0c327fffa080: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c327fffa090: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
Shadow byte legend (one shadow byte represents 8 application bytes):
 
  Addressable:           00
 
  Partially addressable: 01 02 03 04 05 06 07 
  Heap left redzone:       fa
 
  Heap right redzone:      fb
 
  Freed heap region:       fd
 
  Stack left redzone:      f1
 
  Stack mid redzone:       f2
 
  Stack right redzone:     f3
 
  Stack partial redzone:   f4
 
  Stack after return:      f5
 
  Stack use after scope:   f8
 
  Global redzone:          f9
 
  Global init order:       f6
 
  Poisoned by user:        f7
 
  Contiguous container OOB:fc
 
  ASan internal:           fe
 
==29229==ABORTING

Stack trace from a more complicated test case failing on 10.4:

10.4 fb01193c ASAN

 
==28788==ERROR: AddressSanitizer: heap-use-after-free on address 0x621000505640 at pc 0x5570a96f21a9 bp 0x7f6c5e437350 sp 0x7f6c5e437348
 
READ of size 2 at 0x621000505640 thread T24
 
==28788==AddressSanitizer: while reporting a bug found another one.Ignoring.
 
    #0 0x5570a96f21a8 in innobase_get_computed_value(dtuple_t const*, dict_v_col_t const*, dict_index_t const*, mem_block_info_t**, mem_block_info_t*, dict_field_t const*, THD*, TABLE*, unsigned char*, dict_table_t const*, upd_t*, dict_foreign_t*) /data/src/10.4/storage/innobase/handler/ha_innodb.cc:20750
 
    #1 0x5570a9a181fb in row_vers_build_clust_v_col /data/src/10.4/storage/innobase/row/row0vers.cc:484
 
    #2 0x5570a9a1a169 in row_vers_old_has_index_entry(bool, unsigned char const*, mtr_t*, dict_index_t*, dtuple_t const*, unsigned long, unsigned long, purge_vcol_info_t*) /data/src/10.4/storage/innobase/row/row0vers.cc:958
 
    #3 0x5570a99aea0b in row_purge_poss_sec(purge_node_t*, dict_index_t*, dtuple_t const*, btr_pcur_t*, mtr_t*, bool) /data/src/10.4/storage/innobase/row/row0purge.cc:349
 
    #4 0x5570a99afb10 in row_purge_remove_sec_if_poss_leaf /data/src/10.4/storage/innobase/row/row0purge.cc:607
 
    #5 0x5570a99b011b in row_purge_remove_sec_if_poss /data/src/10.4/storage/innobase/row/row0purge.cc:720
 
    #6 0x5570a99b051e in row_purge_del_mark /data/src/10.4/storage/innobase/row/row0purge.cc:794
 
    #7 0x5570a99b301d in row_purge_record_func /data/src/10.4/storage/innobase/row/row0purge.cc:1194
 
    #8 0x5570a99b36da in row_purge /data/src/10.4/storage/innobase/row/row0purge.cc:1261
 
    #9 0x5570a99b3ec5 in row_purge_step(que_thr_t*) /data/src/10.4/storage/innobase/row/row0purge.cc:1347
 
    #10 0x5570a98c60cf in que_thr_step /data/src/10.4/storage/innobase/que/que0que.cc:1042
 
    #11 0x5570a98c64f2 in que_run_threads_low /data/src/10.4/storage/innobase/que/que0que.cc:1104
 
    #12 0x5570a98c6849 in que_run_threads(que_thr_t*) /data/src/10.4/storage/innobase/que/que0que.cc:1144
 
    #13 0x5570a9a284a5 in srv_task_execute /data/src/10.4/storage/innobase/srv/srv0srv.cc:2437
 
    #14 0x5570a9a286df in srv_worker_thread /data/src/10.4/storage/innobase/srv/srv0srv.cc:2485
 
    #15 0x7f6c8da00493 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x7493)
 
    #16 0x7f6c8bde693e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0xe893e)
 
 
 
ASAN:SIGSEGV

The problem might be closely related to MDEV-16222. If I remove FLUSH from the test case above, I get the assertion failure from MDEV-16222, although it takes quite a few attempts with this test case (within --repeat=200 or so).
We also have MDEV-17005 with a similar ASAN failure, but in update instead of purge.
I suppose marko can make an expert conclusion whom it should be assigned to, or even close it if it appears to be a duplicate of either of the two.

Comment by Marko Mäkelä [ 2019-02-26 ]

It seems to me that the problem is an access to TABLE_SHARE that has been evicted despite the purge thread holding an open table handle.
Without ASAN, I got the following:

10.3 09bd2138522787a4e0b015695c462903f4a9e728

 
mysqltest: At line 14: query 'FLUSH TABLES' failed: 2013: Lost connection to MySQL server during query
 
…
 
2019-02-27  0:09:11 3 [ERROR] InnoDB: tried to purge non-delete-marked record in index `v` of table `test`.`t1`: tuple: TUPLE (info_bits=0, 2 fields): {[2] j(0x036A),[4]    (0x80000004)}, record: COMPACT RECORD(info_bits=0, 2 fields): {[2] j(0x036A),[4]    (0x80000004)}
 
mysqld: /mariadb/10.3/storage/innobase/row/row0purge.cc:621: bool row_purge_remove_sec_if_poss_leaf(purge_node_t *, dict_index_t *, const dtuple_t *): Assertion `0' failed.

The ASAN message suggests that the problem might occur when accessing one of the 2-byte columns b or v.
I shortly debugged a core dump from ASAN_OPTIONS=abort_on_error=1,disable_coredump=0, but could not identify where exactly the buggy address came from.

Note: the TABLE should be allocated by innobase_allocate_row_for_vcol() and freed by close_thread_tables(). Between those calls, my understanding is that FLUSH TABLES should not be allowed to free the memory.

Comment by Nikita Malyavin [ 2019-08-01 ]

I think it can be a race in tdc acquire/release.
with 

--debug=+d:f,innobase_build_v_templ,row_vers_build_clust_v_col,close_cached_tables,tdc_release_share,tdc_acquire_share,TABLE_SHARE::destroy:T:t:i:n:O,debug}}

and some patches for logging I've got this:

T@18   : 21:29:01.497453   11: | | | | | | | | | | >TABLE_SHARE::destroy
 
T@18   : 21:29:01.497524   11: | | | | | | | | | | | info: db: test table: t1
 
T@18   : 21:29:01.497597   11: | | | | | | | | | | <TABLE_SHARE::destroy
 
T@18   : 21:29:01.498532   10: | | | | | | | | | >tdc_acquire_share
 
T@18   : 21:29:01.498992   10: | | | | | | | | | | exit: share: 0x61a00006d2a8  name: 0x62b000000390  ref_count: 1  def_rec: 0x6190000d6db8
 
T@18   : 21:29:01.499032   10: | | | | | | | | | <tdc_acquire_share
 
T@18   : 21:29:01.499282   13: | | | | | | | | | | | | >innobase_build_v_templ
 
T@18   : 21:29:01.499327   13: | | | | | | | | | | | | <innobase_build_v_templ
 
T@18   : 21:29:01.503239    9: | | | | | | | | >tdc_acquire_share
 
T@18   : 21:29:01.503305    9: | | | | | | | | <tdc_acquire_share
 
T@18   : 21:29:01.503347    9: | | | | | | | | >tdc_acquire_share
 
T@18   : 21:29:01.503373    9: | | | | | | | | | exit: share: 0x61a00006d2a8  name: 0x62b000000ec0  ref_count: 2  def_rec: 0x6190000d6db8
 
T@18   : 21:29:01.503398    9: | | | | | | | | <tdc_acquire_share
 
T@18   : 21:29:01.517168    5: | | | | >close_cached_tables
 
T@18   : 21:29:01.517236    5: | | | | | tcache: incremented global refresh_version to: 1
 
T@10   : 21:29:01.518402    1: >row_vers_build_clust_v_col
 
T@10   : 21:29:01.518459    1: | asan: allocate_row. table: 0x0
 
T@10   : 21:29:01.518631    4: | | | >tdc_acquire_share
 
T@10   : 21:29:01.518727    4: | | | <tdc_acquire_share
 
T@10   : 21:29:01.518818    1: <row_vers_build_clust_v_col
 
T@11   : 21:29:01.518945    1: >row_vers_build_clust_v_col
 
T@11   : 21:29:01.519007    1: | asan: allocate_row. table: 0x0
 
T@10   : 21:29:01.519182    1: >row_vers_build_clust_v_col
 
T@10   : 21:29:01.519212    1: | asan: allocate_row. table: 0x61f000043688
 
T@10   : 21:29:01.519260    1: | asan: Start computing. def_rec: 0x6190000d6db8
 
T@10   : 21:29:01.519326    1: <row_vers_build_clust_v_col
 
T@11   : 21:29:01.519373    4: | | | >tdc_acquire_share
 
T@11   : 21:29:01.519468    4: | | | <tdc_acquire_share
 
T@11   : 21:29:01.519599    1: <row_vers_build_clust_v_col
 
T@11   : 21:29:01.519704    1: >row_vers_build_clust_v_col
 
T@11   : 21:29:01.519734    1: | asan: allocate_row. table: 0x61f000044488
 
T@11   : 21:29:01.519777    1: | asan: Start computing. def_rec: 0x6190000d6db8
 
T@11   : 21:29:01.519829    1: <row_vers_build_clust_v_col
 
T@10   : 21:29:01.519866    1: >row_vers_build_clust_v_col
 
T@10   : 21:29:01.519890    1: | asan: allocate_row. table: 0x0
 
T@10   : 21:29:01.519959    4: | | | >tdc_acquire_share
 
T@10   : 21:29:01.519987    4: | | | <tdc_acquire_share
 
T@10   : 21:29:01.520046    1: <row_vers_build_clust_v_col
 
T@10   : 21:29:01.520127    1: >row_vers_build_clust_v_col
 
T@10   : 21:29:01.520146    1: | asan: allocate_row. table: 0x61f000043688
 
T@10   : 21:29:01.520201    1: | asan: Start computing. def_rec: 0x6190000d6db8
 
T@10   : 21:29:01.520235    1: <row_vers_build_clust_v_col
 
T@11   : 21:29:01.520558    1: >row_vers_build_clust_v_col
 
T@11   : 21:29:01.520589    1: | asan: allocate_row. table: 0x0
 
T@10   : 21:29:01.520673    1: >row_vers_build_clust_v_col
 
T@10   : 21:29:01.520694    1: | asan: allocate_row. table: 0x0
 
T@11   : 21:29:01.520726    4: | | | >tdc_acquire_share
 
T@10   : 21:29:01.520798    4: | | | >tdc_acquire_share
 
T@11   : 21:29:01.520832    4: | | | | exit: share: 0x61a00006d2a8  name: 0x7faa1f2d1360  ref_count: 3  def_rec: 0x6190000d6db8
 
T@11   : 21:29:01.520866    4: | | | <tdc_acquire_share
 
T@11   : 21:29:01.520890    4: | | | >tdc_release_share
 
T@11   : 21:29:01.520918    4: | | | | enter: share: 0x61a00006d2a8  table: test.t1  ref_count: 3  version: 1  def_rec: 0x6190000d6db8
 
T@11   : 21:29:01.520958    4: | | | <tdc_release_share
 
T@10   : 21:29:01.521116    4: | | | | exit: share: 0x61a00006d2a8  name: 0x7faa1fad2360  ref_count: 3  def_rec: 0x6190000d6db8
 
T@10   : 21:29:01.521136    4: | | | <tdc_acquire_share
 
T@10   : 21:29:01.521149    4: | | | >tdc_release_share
 
T@10   : 21:29:01.521162    4: | | | | enter: share: 0x61a00006d2a8  table: test.t1  ref_count: 3  version: 1  def_rec: 0x6190000d6db8
 
T@10   : 21:29:01.521181    4: | | | <tdc_release_share
 
T@18   : 21:29:01.523405    6: | | | | | >tdc_release_share
 
T@18   : 21:29:01.523469    6: | | | | | | enter: share: 0x61a00006d2a8  table: test.t1  ref_count: 2  version: 1  def_rec: 0x6190000d6db8
 
T@18   : 21:29:01.523509    6: | | | | | <tdc_release_share
 
T@18   : 21:29:01.523591    6: | | | | | >tdc_release_share
 
T@18   : 21:29:01.523612    6: | | | | | | enter: share: 0x61a00006d2a8  table: test.t1  ref_count: 1  version: 1  def_rec: 0x6190000d6db8
 
T@11   : 21:29:01.523796    4: | | | >tdc_acquire_share
 
T@10   : 21:29:01.523836    4: | | | >tdc_acquire_share
 
T@18   : 21:29:01.523872    9: | | | | | | | | >TABLE_SHARE::destroy
 
T@18   : 21:29:01.523902    9: | | | | | | | | | info: db: test table: t1
 
T@18   : 21:29:01.524033    9: | | | | | | | | <TABLE_SHARE::destroy
 
T@18   : 21:29:01.524053    6: | | | | | <tdc_release_share
 
T@11   : 21:29:01.525464    4: | | | | exit: share: 0x61a0000234a8  name: 0x7faa1f2d1360  ref_count: 1  def_rec: 0x6190000408b8
 
T@11   : 21:29:01.525493    4: | | | <tdc_acquire_share
 
T@10   : 21:29:01.525517    4: | | | | exit: share: 0x61a0000234a8  name: 0x7faa1fad2360  ref_count: 2  def_rec: 0x6190000408b8
 
T@10   : 21:29:01.525546    4: | | | <tdc_acquire_share
 
T@10   : 21:29:01.526369    1: <row_vers_build_clust_v_col
 
T@11   : 21:29:01.526407    1: <row_vers_build_clust_v_col
 
T@10   : 21:29:01.526473    1: >row_vers_build_clust_v_col
 
T@10   : 21:29:01.526493    1: | asan: allocate_row. table: 0x61f00005f688
 
T@11   : 21:29:01.526521    1: >row_vers_build_clust_v_col
 
T@11   : 21:29:01.526542    1: | asan: allocate_row. table: 0x61f00004fa88
 
T@10   : 21:29:01.526568    1: | asan: Start computing. def_rec: 0x6190000d6db8
 
T@11   : 21:29:01.526605    1: | asan: Start computing. def_rec: 0x6190000d6db8
 
T@11   : 21:29:01.526663    1: <row_vers_build_clust_v_col
 
T@18   : 21:29:01.526788    5: | | | | | info: open table definitions: 1
 
T@18   : 21:29:01.526818    5: | | | | | info: Waiting for other threads to close their open tables
 
T@18   : 21:29:01.526858    5: | | | | <close_cached_tables

In the end you can see that SHARE::destroy is called at the same time with tdc_acquire_share, and share->default_values (def_rec) is still the same.

SHARE::destroy is called from tdc_release_share when ref_count becomes 0. There are also cases when purge threads race with each other in the same manner, e.g. one thread releases SHARE, sets its refcount to 0, then calls destroy, and another one calls acquire at the same time, incrementing refcount back to 1

Comment by Nikita Malyavin [ 2019-09-26 ]

Turns out that it is literally the same bug as MDEV-17005. It was racing on ha_innobase::open which is forced to be done by a FLUSH TABLES. In some cases both threads could make ha_innobase::open at the same time. MDEV-17005 fix does not remove this race, but makes it harmless.

Comment by Nikita Malyavin [ 2019-09-27 ]

the conclusion is that this task completely duplicates MDEV-17005.

marko I have adopted DEBUG_SYNC for purge threads to manipulate the sync points from SQL, and added this test as an example usage. Please review last two commits at bb-10.3-MDEV-18546-nikita (link).

Currently, first is baf80cbc and second is a2439db28.

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

The patch fails to compile the non-debug build. It looks like you are missing ut_d() around at least thread_slot operation in the first commit.

The definitions and declarations of all new code should be inside #ifdef UNIV_DEBUG. Also the parameter of srv_do_purge() and trx_purge() should only be added for debug builds. You could rename the functions to have _func suffix and define wrapper macros that take care of discarding the parameter for non-debug builds.

If you are modifying some static const constants, you could as well make them constexpr.

Other than this, it looks OK to push. I’d recommend to push it to 10.2 already.

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