Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-31877

ASAN errors in Exec_time_tracker::get_cycles with innodb slow log verbosity

Details

    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.

      Attachments

        Activity

          Ascending order - Click to sort in descending order
          psergei Sergei Petrunia added a comment -

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

          psergei Sergei Petrunia added a comment - The problem is caused by the added code for MDEV-31558 .
          psergei Sergei Petrunia added a comment -

          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(...);

          psergei Sergei Petrunia added a comment - 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(...);
          psergei Sergei Petrunia added a comment -

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

          psergei Sergei Petrunia added a comment - bb-10.6- MDEV-31877 . sanja could you review?
          sanja Oleksandr Byelkin added a comment -

          OK to push in the release tree

          sanja Oleksandr Byelkin added a comment - OK to push in the release tree

          People

            psergei Sergei Petrunia
            elenst Elena Stepanova
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved:

              Git Integration

                Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.