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

Server crashes in Expression_cache_tracker::fetch_current_stats

Details

    Description

      colored text

      CREATE TABLE t (a INT, b INT);
      		 
      INSERT INTO t VALUES (1,2),(3,4);
      		 
       
      		 
      ANALYZE FORMAT=JSON SELECT DISTINCT (SELECT MIN(a) FROM t WHERE b <= ANY (SELECT a FROM t)) AS f FROM t;
      		 
       
      		 
      # Cleanup
      		 
      DROP TABLE t;

      10.2 debug 5a8766a9

      		 
      #3  <signal handler called>
      		 
      #4  0x0000557cd775fad1 in Expression_cache_tracker::fetch_current_stats (this=0x7f938418e870) at /data/src/10.2/sql/sql_expression_cache.h:97
      		 
      #5  0x0000557cd77591aa in Explain_node::print_explain_json_cache (this=0x7f9384098448, writer=0x7f939490d4c0, is_analyze=true) at /data/src/10.2/sql/sql_explain.cc:685
      		 
      #6  0x0000557cd77598f4 in Explain_select::print_explain_json (this=0x7f9384098448, query=0x7f9384017600, writer=0x7f939490d4c0, is_analyze=true) at /data/src/10.2/sql/sql_explain.cc:825
      		 
      #7  0x0000557cd775911b in Explain_node::print_explain_json_for_children (this=0x7f938418e9c8, query=0x7f9384017600, writer=0x7f939490d4c0, is_analyze=true) at /data/src/10.2/sql/sql_explain.cc:671
      		 
      #8  0x0000557cd775a321 in Explain_basic_join::print_explain_json_interns (this=0x7f938418e9c8, query=0x7f9384017600, writer=0x7f939490d4c0, is_analyze=true) at /data/src/10.2/sql/sql_explain.cc:1019
      		 
      #9  0x0000557cd7759d49 in Explain_select::print_explain_json (this=0x7f938418e9c8, query=0x7f9384017600, writer=0x7f939490d4c0, is_analyze=true) at /data/src/10.2/sql/sql_explain.cc:913
      		 
      #10 0x0000557cd7757594 in Explain_query::print_explain_json (this=0x7f9384017600, output=0x7f938418f010, is_analyze=true) at /data/src/10.2/sql/sql_explain.cc:224
      		 
      #11 0x0000557cd77572d1 in Explain_query::send_explain (this=0x7f9384017600, thd=0x7f9384000d90) at /data/src/10.2/sql/sql_explain.cc:167
      		 
      #12 0x0000557cd75d7b89 in execute_sqlcom_select (thd=0x7f9384000d90, all_tables=0x7f93840155a0) at /data/src/10.2/sql/sql_parse.cc:6283
      		 
      #13 0x0000557cd75ce663 in mysql_execute_command (thd=0x7f9384000d90) at /data/src/10.2/sql/sql_parse.cc:3582
      		 
      #14 0x0000557cd75db7e2 in mysql_parse (thd=0x7f9384000d90, rawbuf=0x7f9384012708 "ANALYZE FORMAT=JSON SELECT DISTINCT (SELECT MIN(a) FROM t WHERE b <= ANY (SELECT a FROM t)) AS f FROM t", length=103, parser_state=0x7f939490e5e0, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:7793
      		 
      #15 0x0000557cd75c9b85 in dispatch_command (command=COM_QUERY, thd=0x7f9384000d90, packet=0x7f9384008b61 "", packet_length=103, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1827
      		 
      #16 0x0000557cd75c869e in do_command (thd=0x7f9384000d90) at /data/src/10.2/sql/sql_parse.cc:1381
      		 
      #17 0x0000557cd77204a4 in do_handle_one_connection (connect=0x557cdab9c630) at /data/src/10.2/sql/sql_connect.cc:1336
      		 
      #18 0x0000557cd7720218 in handle_one_connection (arg=0x557cdab9c630) at /data/src/10.2/sql/sql_connect.cc:1241
      		 
      #19 0x0000557cd7f286eb in pfs_spawn_thread (arg=0x557cdab883d0) at /data/src/10.2/storage/perfschema/pfs.cc:1869
      		 
      #20 0x00007f939ac76ea7 in start_thread (arg=<optimized out>) at pthread_create.c:477
      		 
      #21 0x00007f939a87bdef in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

      10.2 relwithdebinfo asan 5a8766a9

      		 
      ==3523040==ERROR: AddressSanitizer: use-after-poison on address 0x6290000d7f78 at pc 0x564d49ef342c bp 0x7f6302886a30 sp 0x7f6302886a28
      		 
      READ of size 8 at 0x6290000d7f78 thread T5
      		 
          #0 0x564d49ef342b in Expression_cache_tracker::fetch_current_stats() /data/src/10.2/sql/sql_expression_cache.h:97
      		 
          #1 0x564d49ef342b in Explain_node::print_explain_json_cache(Json_writer*, bool) /data/src/10.2/sql/sql_explain.cc:685
      		 
          #2 0x564d49effd21 in Explain_select::print_explain_json(Explain_query*, Json_writer*, bool) /data/src/10.2/sql/sql_explain.cc:825
      		 
          #3 0x564d49ef2c05 in Explain_node::print_explain_json_for_children(Explain_query*, Json_writer*, bool) /data/src/10.2/sql/sql_explain.cc:671
      		 
          #4 0x564d49effb3d in Explain_basic_join::print_explain_json_interns(Explain_query*, Json_writer*, bool) /data/src/10.2/sql/sql_explain.cc:1019
      		 
          #5 0x564d49f00174 in Explain_select::print_explain_json(Explain_query*, Json_writer*, bool) /data/src/10.2/sql/sql_explain.cc:913
      		 
          #6 0x564d49eeff49 in Explain_query::print_explain_json(select_result_sink*, bool) /data/src/10.2/sql/sql_explain.cc:215
      		 
          #7 0x564d49ef0899 in Explain_query::send_explain(THD*) /data/src/10.2/sql/sql_explain.cc:167
      		 
          #8 0x564d49b75959 in execute_sqlcom_select /data/src/10.2/sql/sql_parse.cc:6283
      		 
          #9 0x564d49b9bd2d in mysql_execute_command(THD*) /data/src/10.2/sql/sql_parse.cc:3582
      		 
          #10 0x564d49ba4537 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.2/sql/sql_parse.cc:7793
      		 
          #11 0x564d49baaabe in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.2/sql/sql_parse.cc:1827
      		 
          #12 0x564d49bae95d in do_command(THD*) /data/src/10.2/sql/sql_parse.cc:1381
      		 
          #13 0x564d49e91e76 in do_handle_one_connection(CONNECT*) /data/src/10.2/sql/sql_connect.cc:1336
      		 
          #14 0x564d49e925aa in handle_one_connection /data/src/10.2/sql/sql_connect.cc:1241
      		 
          #15 0x564d4b023284 in pfs_spawn_thread /data/src/10.2/storage/perfschema/pfs.cc:1869
      		 
          #16 0x7f630d492ea6 in start_thread nptl/pthread_create.c:477
      		 
          #17 0x7f630d097dee in __clone (/lib/x86_64-linux-gnu/libc.so.6+0xfddee)
      		 
       
      		 
      0x6290000d7f78 is located 3448 bytes inside of 16352-byte region [0x6290000d7200,0x6290000db1e0)
      		 
      allocated by thread T5 here:
      		 
          #0 0x7f630da09e8f in __interceptor_malloc ../../../../src/libsanitizer/asan/asan_malloc_linux.cpp:145
      		 
          #1 0x564d4b0db842 in my_malloc /data/src/10.2/mysys/my_malloc.c:101
      		 
          #2 0x564d4b0c76c3 in alloc_root /data/src/10.2/mysys/my_alloc.c:243
      		 
          #3 0x564d4b0c7ae7 in multi_alloc_root /data/src/10.2/mysys/my_alloc.c:312
      		 
          #4 0x564d49cb9816 in make_join_statistics /data/src/10.2/sql/sql_select.cc:3951
      		 
          #5 0x564d49cb9816 in JOIN::optimize_inner() /data/src/10.2/sql/sql_select.cc:1597
      		 
          #6 0x564d49cc7015 in JOIN::optimize() /data/src/10.2/sql/sql_select.cc:1127
      		 
          #7 0x564d49cc7015 in JOIN::optimize() /data/src/10.2/sql/sql_select.cc:1119
      		 
          #8 0x564d49ccf1ff in mysql_select(THD*, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*) /data/src/10.2/sql/sql_select.cc:3835
      		 
          #9 0x564d49ccff6a in handle_select(THD*, LEX*, select_result*, unsigned long) /data/src/10.2/sql/sql_select.cc:361
      		 
          #10 0x564d49b7628f in execute_sqlcom_select /data/src/10.2/sql/sql_parse.cc:6271
      		 
          #11 0x564d49b9bd2d in mysql_execute_command(THD*) /data/src/10.2/sql/sql_parse.cc:3582
      		 
          #12 0x564d49ba4537 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.2/sql/sql_parse.cc:7793
      		 
          #13 0x564d49baaabe in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.2/sql/sql_parse.cc:1827
      		 
          #14 0x564d49bae95d in do_command(THD*) /data/src/10.2/sql/sql_parse.cc:1381
      		 
          #15 0x564d49e91e76 in do_handle_one_connection(CONNECT*) /data/src/10.2/sql/sql_connect.cc:1336
      		 
          #16 0x564d49e925aa in handle_one_connection /data/src/10.2/sql/sql_connect.cc:1241
      		 
          #17 0x564d4b023284 in pfs_spawn_thread /data/src/10.2/storage/perfschema/pfs.cc:1869
      		 
          #18 0x7f630d492ea6 in start_thread nptl/pthread_create.c:477
      		 
       
      		 
      Thread T5 created by T0 here:
      		 
          #0 0x7f630d9b52a2 in __interceptor_pthread_create ../../../../src/libsanitizer/asan/asan_interceptors.cpp:214
      		 
          #1 0x564d4b02850a in spawn_thread_v1 /data/src/10.2/storage/perfschema/pfs.cc:1919
      		 
          #2 0x564d4999fe6f in inline_mysql_thread_create /data/src/10.2/include/mysql/psi/mysql_thread.h:1246
      		 
          #3 0x564d4999fe6f in create_thread_to_handle_connection(CONNECT*) /data/src/10.2/sql/mysqld.cc:6580
      		 
          #4 0x564d499b020c in create_new_thread /data/src/10.2/sql/mysqld.cc:6650
      		 
          #5 0x564d499b020c in handle_connections_sockets() /data/src/10.2/sql/mysqld.cc:6908
      		 
          #6 0x564d499b273f in mysqld_main(int, char**) /data/src/10.2/sql/mysqld.cc:6199
      		 
          #7 0x7f630cfc0d09 in __libc_start_main ../csu/libc-start.c:308
      		 
       
      		 
      SUMMARY: AddressSanitizer: use-after-poison /data/src/10.2/sql/sql_expression_cache.h:97 in Expression_cache_tracker::fetch_current_stats()
      		 
      Shadow bytes around the buggy address:
      		 
        0x0c5280012f90: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
      		 
        0x0c5280012fa0: 00 00 00 00 00 00 00 00 00 00 00 f7 f7 f7 f7 f7
      		 
        0x0c5280012fb0: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
      		 
        0x0c5280012fc0: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
      		 
        0x0c5280012fd0: f7 f7 f7 f7 f7 f7 f7 00 00 00 00 00 00 00 00 00
      		 
      =>0x0c5280012fe0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 f7[f7]
      		 
        0x0c5280012ff0: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
      		 
        0x0c5280013000: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
      		 
        0x0c5280013010: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 00 00 00 00 f7
      		 
        0x0c5280013020: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
      		 
        0x0c5280013030: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
      		 
      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
      		 
        Shadow gap:              cc
      		 
      ==3523040==ABORTING

      The failure apparently started happening on 10.2 after this commit:

      commit 3a52569499e2f0c4d1f25db1e81617a9d9755400
      		 
      Author: Sergei Petrunia
      		 
      Date:   Thu Feb 10 14:23:20 2022 +0300
      		 
       
      		 
          MDEV-25636: Bug report: abortion in sql/sql_parse.cc:6294
      		 
          
          The asserion failure was caused by this query

      Set to critical as a recent regression.

      Attachments

        Issue Links

          relates to

          Bug - A problem which impairs or prevents the functions of the product. MDEV-28432 Subquery Items have wrong used_tables() after update_used_tables()

          • Major - Major loss of function.
          • Open

          Activity

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

            Investigation.

            in void Expression_cache_tmptable::init(), execution takes this branch:

                if (items.elements == 0)
            		 
                {
            		 
            =>    DBUG_PRINT("info", ("All parameters were removed by optimizer."));
            		 
                  DBUG_VOID_RETURN;
            		 
                }

            Because of that Expression_cache_tmptable::cache_table is never initialized and remains NULL.

            Then, in Expression_cache_tmptable::~Expression_cache_tmptable()
            execution takes the else branch here:

              if (cache_table)
            		 
                disable_cache();
            		 
              else
            		 
              {
            		 
                update_tracker();
            		 
                tracker= NULL;
            		 
              }

            Note that tracker->cache points to the Expression_cache_tmptable object.

            The if-branch calls disable_cache() which clears tracker->cache:

            void Expression_cache_tmptable::disable_cache()
            		 
            {
            		 
              if (tracker)
            		 
                tracker->cache= NULL;
            		 
              ...
            		 
            }

            while the else branch doesn't.

            Eventually we arrive at Explain_node::print_explain_json_cache which
            calls 

            cache_tracker->fetch_current_stats();

            which tries to access the cache which is deleted already:

              void fetch_current_stats()
            		 
              {
            		 
                if (cache)
            		 
                  cache->update_tracker();
            		 
              }

            psergei Sergei Petrunia added a comment - Investigation. in void Expression_cache_tmptable::init(), execution takes this branch: if (items.elements == 0) { => DBUG_PRINT( "info" , ( "All parameters were removed by optimizer." )); DBUG_VOID_RETURN; } Because of that Expression_cache_tmptable::cache_table is never initialized and remains NULL. Then, in Expression_cache_tmptable::~Expression_cache_tmptable() execution takes the else branch here: if (cache_table) disable_cache(); else { update_tracker(); tracker= NULL; } Note that tracker->cache points to the Expression_cache_tmptable object. The if-branch calls disable_cache() which clears tracker->cache: void Expression_cache_tmptable::disable_cache() { if (tracker) tracker->cache= NULL; ... } while the else branch doesn't. Eventually we arrive at Explain_node::print_explain_json_cache which calls cache_tracker->fetch_current_stats(); which tries to access the cache which is deleted already: void fetch_current_stats() { if (cache) cache->update_tracker(); }
            psergei Sergei Petrunia added a comment -

            https://github.com/MariaDB/server/commit/3c54d8f13a140723d74bc4686c95a093465f55a3

            sanja, please review.

            psergei Sergei Petrunia added a comment - https://github.com/MariaDB/server/commit/3c54d8f13a140723d74bc4686c95a093465f55a3 sanja , please review.
            psergei Sergei Petrunia added a comment -

            The above patch is useful (and needs a review), but how come a fix for MDEV-25636 has caused a crash like this?

            Debugging this MDEV's testcase again, looking at the code touched by patch for MDEV-25636

            CREATE TABLE t (a INT, b INT);
            		 
            ANALYZE FORMAT=JSON
            		 
            SELECT DISTINCT (
            		 
              SELECT MIN(a) FROM t WHERE b <= ANY (SELECT a FROM t)
            		 
            ) AS f FROM t;

            and in st_select_lex::optimize_unflattened_subqueries(), I see that the subselect

              SELECT MIN(a) FROM t WHERE b <= ANY (SELECT a FROM t)

            changes from being uncorrelated to being correlated!
            Narrowing down the point where things go wrong:
            they do in SELECT_LEX::update_used_tables():

              $15 = 0x5555570e3a40 <dbug_item_print_buf> "<nop>(<in_optimizer>(t.b,(subquery#3) >= <cache>(t.b)))"
            		 
            (gdb) p/x join->conds->used_tables()
            		 
              $16 = 0x1
            		 
            (gdb) next

            this executes:

                join->conds->update_used_tables();

            and then

            (gdb) p/x join->conds->used_tables()
            		 
              $17 = 0x4000000000000001

            psergei Sergei Petrunia added a comment - The above patch is useful (and needs a review), but how come a fix for MDEV-25636 has caused a crash like this? Debugging this MDEV's testcase again, looking at the code touched by patch for MDEV-25636 CREATE TABLE t (a INT, b INT); ANALYZE FORMAT=JSON SELECT DISTINCT ( SELECT MIN(a) FROM t WHERE b <= ANY (SELECT a FROM t) ) AS f FROM t; and in st_select_lex::optimize_unflattened_subqueries(), I see that the subselect SELECT MIN(a) FROM t WHERE b <= ANY (SELECT a FROM t) changes from being uncorrelated to being correlated! Narrowing down the point where things go wrong: they do in SELECT_LEX::update_used_tables(): $15 = 0x5555570e3a40 <dbug_item_print_buf> "<nop>(<in_optimizer>(t.b,(subquery#3) >= <cache>(t.b)))" (gdb) p/x join->conds->used_tables() $16 = 0x1 (gdb) next this executes: join->conds->update_used_tables(); and then (gdb) p/x join->conds->used_tables() $17 = 0x4000000000000001
            psergei Sergei Petrunia added a comment -

            This looks like another bug... to be fixed outside of the scope of this MDEV.

            psergei Sergei Petrunia added a comment - This looks like another bug... to be fixed outside of the scope of this MDEV.
            sanja Oleksandr Byelkin added a comment -

            OK to push

            sanja Oleksandr Byelkin added a comment - OK to push

            People

              psergei Sergei Petrunia
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              6 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.