[MDEV-31877] ASAN errors in Exec_time_tracker::get_cycles with innodb slow log verbosity Created: 2023-08-08  Updated: 2023-08-24  Resolved: 2023-08-09

Status: Closed
Project: MariaDB Server
Component/s: Server, Stored routines
Affects Version/s: 10.6
Fix Version/s: 10.6.15, 10.9.8, 10.10.6, 10.11.5, 11.0.3, 11.1.2, 11.2.1

Type: Bug Priority: Blocker
Reporter: Elena Stepanova Assignee: Sergei Petrunia
Resolution: Fixed Votes: 0
Labels: regression


 Description    

CREATE TABLE t (a INT, b INT);
 
INSERT INTO t VALUES (1,2);
 
SET SESSION log_slow_verbosity= 'innodb';
 
--delimiter $
 
BEGIN NOT ATOMIC DECLARE r ROW TYPE OF t DEFAULT (SELECT * FROM t); SELECT r.a; END $
 
--delimiter ;
 
 
 
# Cleanup
 
DROP TABLE t;

10.6 c7b6707f

 
==122112==ERROR: AddressSanitizer: use-after-poison on address 0x625000183f48 at pc 0x55aacc0612a7 bp 0x7f775a84e730 sp 0x7f775a84e728
 
READ of size 8 at 0x625000183f48 thread T5
 
    #0 0x55aacc0612a6 in Exec_time_tracker::get_cycles() const (/mnt8t/bld/10.6-asan/bin/mariadbd+0x19432a6)
 
    #1 0x55aacc02f22d in close_thread_table(THD*, TABLE**) /data/src/10.6/sql/sql_base.cc:992
 
    #2 0x55aacc02ea80 in close_thread_tables(THD*) /data/src/10.6/sql/sql_base.cc:955
 
    #3 0x55aacbf83797 in sp_lex_keeper::reset_lex_and_exec_core(THD*, unsigned int*, bool, sp_instr*) /data/src/10.6/sql/sp_head.cc:3519
 
    #4 0x55aacbf8528c in sp_instr_set::execute(THD*, unsigned int*) /data/src/10.6/sql/sp_head.cc:3796
 
    #5 0x55aacbf75a59 in sp_head::execute(THD*, bool) /data/src/10.6/sql/sp_head.cc:1435
 
    #6 0x55aacbf7bf77 in sp_head::execute_procedure(THD*, List<Item>*) /data/src/10.6/sql/sp_head.cc:2449
 
    #7 0x55aacc1d1d71 in do_execute_sp /data/src/10.6/sql/sql_parse.cc:3036
 
    #8 0x55aacc1e62fa in mysql_execute_command(THD*, bool) /data/src/10.6/sql/sql_parse.cc:5749
 
    #9 0x55aacc1f5454 in mysql_parse(THD*, char*, unsigned int, Parser_state*) /data/src/10.6/sql/sql_parse.cc:8053
 
    #10 0x55aacc1cb115 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool) /data/src/10.6/sql/sql_parse.cc:1896
 
    #11 0x55aacc1c7e49 in do_command(THD*, bool) /data/src/10.6/sql/sql_parse.cc:1409
 
    #12 0x55aacc637cbb in do_handle_one_connection(CONNECT*, bool) /data/src/10.6/sql/sql_connect.cc:1416
 
    #13 0x55aacc63767c in handle_one_connection /data/src/10.6/sql/sql_connect.cc:1318
 
    #14 0x55aacd2931e7 in pfs_spawn_thread /data/src/10.6/storage/perfschema/pfs.cc:2201
 
    #15 0x7f77620a7fd3 in start_thread nptl/pthread_create.c:442
 
    #16 0x7f77621285bb in clone3 ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
 
 
 
0x625000183f48 is located 1608 bytes inside of 8176-byte region [0x625000183900,0x6250001858f0)
 
allocated by thread T5 here:
 
    #0 0x7f7762cb89cf in __interceptor_malloc ../../../../src/libsanitizer/asan/asan_malloc_linux.cpp:69
 
    #1 0x55aacde93692 in my_malloc /data/src/10.6/mysys/my_malloc.c:91
 
    #2 0x55aacde6fffc in alloc_root /data/src/10.6/mysys/my_alloc.c:249
 
    #3 0x55aacbeda8f9 in Sql_alloc::operator new(unsigned long, st_mem_root*) /data/src/10.6/sql/sql_alloc.h:37
 
    #4 0x55aacbedaafb in base_list::push_back(void*, st_mem_root*) /data/src/10.6/sql/sql_list.h:195
 
    #5 0x55aacc38fea6 in List<JOIN_TAB_RANGE>::push_back(JOIN_TAB_RANGE*, st_mem_root*) (/mnt8t/bld/10.6-asan/bin/mariadbd+0x1c71ea6)
 
    #6 0x55aacc2e0a97 in JOIN::get_best_combination() /data/src/10.6/sql/sql_select.cc:11232
 
    #7 0x55aacc29bc0a in JOIN::optimize_stage2() /data/src/10.6/sql/sql_select.cc:2576
 
    #8 0x55aacc29b6e6 in JOIN::optimize_inner() /data/src/10.6/sql/sql_select.cc:2555
 
    #9 0x55aacc2943c8 in JOIN::optimize() /data/src/10.6/sql/sql_select.cc:1868
 
    #10 0x55aaccc94e37 in subselect_single_select_engine::exec() /data/src/10.6/sql/item_subselect.cc:4011
 
    #11 0x55aaccc71529 in Item_subselect::exec() /data/src/10.6/sql/item_subselect.cc:811
 
    #12 0x55aaccc76a4c in Item_singlerow_subselect::bring_value() /data/src/10.6/sql/item_subselect.cc:1413
 
    #13 0x55aacc9bb7d7 in Field_row::sp_prepare_and_store_item(THD*, Item**) /data/src/10.6/sql/field.cc:2683
 
    #14 0x55aacbf6def8 in THD::sp_eval_expr(Field*, Item**) /data/src/10.6/sql/sp_head.cc:432
 
    #15 0x55aacbfaa59e in sp_rcontext::set_variable(THD*, unsigned int, Item**) /data/src/10.6/sql/sp_rcontext.cc:639
 
    #16 0x55aacbf85462 in sp_instr_set::exec_core(THD*, unsigned int*) /data/src/10.6/sql/sp_head.cc:3809
 
    #17 0x55aacbf83647 in sp_lex_keeper::reset_lex_and_exec_core(THD*, unsigned int*, bool, sp_instr*) /data/src/10.6/sql/sp_head.cc:3501
 
    #18 0x55aacbf8528c in sp_instr_set::execute(THD*, unsigned int*) /data/src/10.6/sql/sp_head.cc:3796
 
    #19 0x55aacbf75a59 in sp_head::execute(THD*, bool) /data/src/10.6/sql/sp_head.cc:1435
 
    #20 0x55aacbf7bf77 in sp_head::execute_procedure(THD*, List<Item>*) /data/src/10.6/sql/sp_head.cc:2449
 
    #21 0x55aacc1d1d71 in do_execute_sp /data/src/10.6/sql/sql_parse.cc:3036
 
    #22 0x55aacc1e62fa in mysql_execute_command(THD*, bool) /data/src/10.6/sql/sql_parse.cc:5749
 
    #23 0x55aacc1f5454 in mysql_parse(THD*, char*, unsigned int, Parser_state*) /data/src/10.6/sql/sql_parse.cc:8053
 
    #24 0x55aacc1cb115 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool) /data/src/10.6/sql/sql_parse.cc:1896
 
    #25 0x55aacc1c7e49 in do_command(THD*, bool) /data/src/10.6/sql/sql_parse.cc:1409
 
    #26 0x55aacc637cbb in do_handle_one_connection(CONNECT*, bool) /data/src/10.6/sql/sql_connect.cc:1416
 
    #27 0x55aacc63767c in handle_one_connection /data/src/10.6/sql/sql_connect.cc:1318
 
    #28 0x55aacd2931e7 in pfs_spawn_thread /data/src/10.6/storage/perfschema/pfs.cc:2201
 
    #29 0x7f77620a7fd3 in start_thread nptl/pthread_create.c:442
 
 
 
Thread T5 created by T0 here:
 
    #0 0x7f7762c49726 in __interceptor_pthread_create ../../../../src/libsanitizer/asan/asan_interceptors.cpp:207
 
    #1 0x55aacd28ef22 in my_thread_create /data/src/10.6/storage/perfschema/my_thread.h:52
 
    #2 0x55aacd2935d6 in pfs_spawn_thread_v1 /data/src/10.6/storage/perfschema/pfs.cc:2252
 
    #3 0x55aacbeb789b in inline_mysql_thread_create /data/src/10.6/include/mysql/psi/mysql_thread.h:1139
 
    #4 0x55aacbeceae4 in create_thread_to_handle_connection(CONNECT*) /data/src/10.6/sql/mysqld.cc:5991
 
    #5 0x55aacbecf0f5 in create_new_thread(CONNECT*) /data/src/10.6/sql/mysqld.cc:6050
 
    #6 0x55aacbecf3e0 in handle_accepted_socket(st_mysql_socket, st_mysql_socket) /data/src/10.6/sql/mysqld.cc:6112
 
    #7 0x55aacbecfd70 in handle_connections_sockets() /data/src/10.6/sql/mysqld.cc:6236
 
    #8 0x55aacbece361 in mysqld_main(int, char**) /data/src/10.6/sql/mysqld.cc:5886
 
    #9 0x55aacbeb69a8 in main /data/src/10.6/sql/main.cc:34
 
    #10 0x7f7762046189 in __libc_start_call_main ../sysdeps/nptl/libc_start_call_main.h:58
 
 
 
SUMMARY: AddressSanitizer: use-after-poison (/mnt8t/bld/10.6-asan/bin/mariadbd+0x19432a6) in Exec_time_tracker::get_cycles() const
 
Shadow bytes around the buggy address:
 
  0x0c4a80028790: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
 
  0x0c4a800287a0: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
 
  0x0c4a800287b0: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
 
  0x0c4a800287c0: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
 
  0x0c4a800287d0: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
 
=>0x0c4a800287e0: f7 f7 f7 f7 f7 f7 f7 f7 f7[f7]f7 f7 f7 f7 f7 f7
 
  0x0c4a800287f0: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 00 00 00 00 00 00
 
  0x0c4a80028800: 00 00 f7 00 00 00 00 00 00 00 00 00 00 00 00 00
 
  0x0c4a80028810: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 
  0x0c4a80028820: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 
  0x0c4a80028830: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 
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
 
  Freed heap region:       fd
 
  Stack left redzone:      f1
 
  Stack mid redzone:       f2
 
  Stack right redzone:     f3
 
  Stack after return:      f5
 
  Stack use after scope:   f8
 
  Global redzone:          f9
 
  Global init order:       f6
 
  Poisoned by user:        f7
 
  Container overflow:      fc
 
  Array cookie:            ac
 
  Intra object redzone:    bb
 
  ASan internal:           fe
 
  Left alloca redzone:     ca
 
  Right alloca redzone:    cb

The failure started happening on 10.6 after this merge

commit 6bf8483cac34651f331bc2dece91580b003cf3a4
 
Merge: 72928e640e6 65405308a13
 
Author: Oleksandr Byelkin
 
Date:   Tue Aug 1 15:08:52 2023 +0200
 
 
 
    Merge branch '10.5' into 10.6

But it also must be related to MDEV-31558 (Add InnoDB engine information to the slow query log). I assume that some changes which came from lower versions interfere with the new development for slow log. But it is a fairly big merge, I cannot guess which exactly commit brought the problem.

 Comments   
Comment by Sergei Petrunia [ 2023-08-09 ]

The problem is caused by the added code for MDEV-31558.

Comment by Sergei Petrunia [ 2023-08-09 ]

Analysis:
The crash happens like this:

sp_instr_set::execute {
 
  sp_lex_keeper::reset_lex_and_exec_core {
 
    
    ...
 
    // Here the tables are opened
 



    // Then the instruction itself is executed:
 
    sp_instr_set::exec_core {
 
 
 
    //... we create query plan for the subquery
 
    JOIN_TAB::save_explain_data {
 
      ...
 
      table->file->set_time_tracker(&eta->op_tracker);
 
 
 
      // and set table t's time_tracker to point to the counter 
      // inside Explain Data Structure. Ok so far.
 
       } // JOIN_TAB::save_explain_data


      // But here in sp_instr_set::exec_core(), we delete the query plan:
 
      delete_explain_query(thd->lex); // (1)
 
    } // sp_instr_set::exec_core()
 
 
 
    // and then we get ASAN error, because we're trying to get the 
    // time_tracker value that's already deleted:
 
    //  (Note: the MEM_ROOT that Explain Data Structure was allocated
 
    //  on is still not free'd, so this will NOT cause crash in production)
 
    close_thread_tables();  // (2)


 
 
    // Note that sp_lex_keeper::reset_lex_and_exec_core() has another
 
    // call to delete the query plan:
 
    delete_explain_query(...);

Comment by Sergei Petrunia [ 2023-08-09 ]

bb-10.6-MDEV-31877. sanja could you review?

Comment by Oleksandr Byelkin [ 2023-08-09 ]

OK to push in the release tree

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