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

Unexpected bogus locking errors upon partitioning operations

    XMLWordPrintable

Details

    Description

      Contrary to its appearance, the test case is quite non-deterministic. It fails with different probability and with different errors depending on the version and build. Run with --repeat=N. Sometimes the first error causes further effects, some of which are shown below.

      On 10.5 the issue appeared after this commit:

      commit ea37b144094a0c2ebfc6774047fd473c1b2a8658
      		 
      Author: Marko Mäkelä
      		 
      Date:   Tue Dec 10 15:42:50 2019 +0200
      		 
       
      		 
          MDEV-16678 Prefer MDL to dict_sys.latch for innodb background tasks


      --source include/have_innodb.inc
      		 
      --source include/have_partition.inc
      		 
       
      		 
      CREATE TABLE t (a INT, b INT) ENGINE=InnoDB PARTITION BY KEY(b) PARTITIONS 2;
      		 
      INSERT INTO t VALUES (0,9),(1,8),(2,7),(3,6),(4,5),(5,4),(6,3),(7,2),(8,1),(9,0);
      		 
       
      		 
      ALTER TABLE t NOWAIT REBUILD PARTITION p0;
      		 
      ALTER TABLE t NOWAIT TRUNCATE PARTITION p0;
      		 
      DROP TABLE t;

      10.5 debug builds usually fail for me like this:

      10.5 674842be

      		 
      ALTER TABLE t NOWAIT REBUILD PARTITION p0;
      		 
      ALTER TABLE t NOWAIT TRUNCATE PARTITION p0;
      		 
      mysqltest: At line 8: query 'ALTER TABLE t NOWAIT TRUNCATE PARTITION p0' failed: 1205: Lock wait timeout exceeded; try restarting transaction

      10.6 more often fails on the first ALTER already:

      10.6 0e4cf497

      		 
      ALTER TABLE t NOWAIT REBUILD PARTITION p0;
      		 
      mysqltest: At line 7: query 'ALTER TABLE t NOWAIT REBUILD PARTITION p0' failed: ER_LOCK_WAIT_TIMEOUT (1205): Lock wait timeout exceeded; try restarting transaction
      		 
      ALTER TABLE t NOWAIT TRUNCATE PARTITION p0;
      		 
      DROP TABLE t;

      or on both:

      CREATE TABLE t (a INT, b INT) ENGINE=InnoDB PARTITION BY KEY(b) PARTITIONS 2;
      		 
      INSERT INTO t VALUES (0,9),(1,8),(2,7),(3,6),(4,5),(5,4),(6,3),(7,2),(8,1),(9,0);
      		 
      ALTER TABLE t NOWAIT REBUILD PARTITION p0;
      		 
      mysqltest: At line 7: query 'ALTER TABLE t NOWAIT REBUILD PARTITION p0' failed: ER_LOCK_WAIT_TIMEOUT (1205): Lock wait timeout exceeded; try restarting transaction
      		 
      ALTER TABLE t NOWAIT TRUNCATE PARTITION p0;
      		 
      mysqltest: At line 8: query 'ALTER TABLE t NOWAIT TRUNCATE PARTITION p0' failed: ER_LOCK_WAIT_TIMEOUT (1205): Lock wait timeout exceeded; try restarting transaction
      		 
      DROP TABLE t;

      10.8 adds more variety. It must be coming from the per-partition options, but for now I will consider it all side-effects of the same problem:

      10.8 cb19e211

      		 
      ALTER TABLE t NOWAIT REBUILD PARTITION p0;
      		 
      mysqltest: At line 7: query 'ALTER TABLE t NOWAIT REBUILD PARTITION p0' failed: ER_LOCK_WAIT_TIMEOUT (1205): Lock wait timeout exceeded; try restarting transaction
      		 
      ALTER TABLE t NOWAIT TRUNCATE PARTITION p0;
      		 
      mysqltest: At line 8: query 'ALTER TABLE t NOWAIT TRUNCATE PARTITION p0' failed: ER_GET_ERRNO (1030): Got error 140 "Wrong create options" from storage engine InnoDB
      		 
      SHOW WARNINGS;
      		 
      Level	Code	Message
      		 
      Warning	140	InnoDB: invalid PAGE_COMPRESSION_LEVEL = 11936128518282651045. Valid values are [1, 2, 3, 4, 5, 6, 7, 8, 9]
      		 
      Error	1030	Got error 140 "Wrong create options" from storage engine InnoDB
      		 
      DROP TABLE t;

      10.8 cb19e211 ASAN

      		 
      ==1726155==ERROR: AddressSanitizer: heap-use-after-free on address 0x61d0000b75bc at pc 0x557d30ea37c3 bp 0x7f3d25931800 sp 0x7f3d259317f8
      		 
      READ of size 4 at 0x61d0000b75bc thread T11
      		 
          #0 0x557d30ea37c2 in create_table_info_t::check_table_options() /data/src/10.8/storage/innobase/handler/ha_innodb.cc:11249
      		 
          #1 0x557d30ef07ad in create_table_info_t::prepare_create_table(char const*, bool) /data/src/10.8/storage/innobase/handler/ha_innodb.cc:12020
      		 
          #2 0x557d30ef07ad in ha_innobase::create(char const*, TABLE*, HA_CREATE_INFO*, bool, trx_t*) /data/src/10.8/storage/innobase/handler/ha_innodb.cc:13194
      		 
          #3 0x557d30edfaaf in ha_innobase::truncate() /data/src/10.8/storage/innobase/handler/ha_innodb.cc:13962
      		 
          #4 0x557d30c91ab1 in ha_partition::truncate_partition(Alter_info*, bool*) /data/src/10.8/sql/ha_partition.cc:4918
      		 
          #5 0x557d301e2060 in Sql_cmd_alter_table_truncate_partition::execute(THD*) /data/src/10.8/sql/sql_partition_admin.cc:958
      		 
          #6 0x557d2fe07c07 in mysql_execute_command(THD*, bool) /data/src/10.8/sql/sql_parse.cc:5988
      		 
          #7 0x557d2fe14c0a in mysql_parse(THD*, char*, unsigned int, Parser_state*) /data/src/10.8/sql/sql_parse.cc:8027
      		 
          #8 0x557d2fe1a274 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool) /data/src/10.8/sql/sql_parse.cc:1894
      		 
          #9 0x557d2fe1fc75 in do_command(THD*, bool) /data/src/10.8/sql/sql_parse.cc:1407
      		 
          #10 0x557d301da83d in do_handle_one_connection(CONNECT*, bool) /data/src/10.8/sql/sql_connect.cc:1418
      		 
          #11 0x557d301dad7c in handle_one_connection /data/src/10.8/sql/sql_connect.cc:1312
      		 
          #12 0x557d30cb3a6b in pfs_spawn_thread /data/src/10.8/storage/perfschema/pfs.cc:2201
      		 
          #13 0x7f3d344faea6 in start_thread nptl/pthread_create.c:477
      		 
          #14 0x7f3d340f9dee in __clone (/lib/x86_64-linux-gnu/libc.so.6+0xfddee)
      		 
       
      		 
      0x61d0000b75bc is located 828 bytes inside of 2064-byte region [0x61d0000b7280,0x61d0000b7a90)
      		 
      freed by thread T11 here:
      		 
          #0 0x7f3d34a00b6f in __interceptor_free ../../../../src/libsanitizer/asan/asan_malloc_linux.cpp:123
      		 
          #1 0x557d315a3454 in root_free /data/src/10.8/mysys/my_alloc.c:78
      		 
          #2 0x557d315a3454 in free_root /data/src/10.8/mysys/my_alloc.c:501
      		 
          #3 0x557d301240e9 in closefrm(TABLE*) /data/src/10.8/sql/table.cc:4540
      		 
          #4 0x557d30402a1f in intern_close_table /data/src/10.8/sql/table_cache.cc:220
      		 
          #5 0x557d30402a1f in tc_remove_table /data/src/10.8/sql/table_cache.cc:258
      		 
          #6 0x557d2fe2e505 in handle_alter_part_error /data/src/10.8/sql/sql_partition.cc:7073
      		 
          #7 0x557d2fe4c5be in fast_alter_partition_table(THD*, TABLE*, Alter_info*, Alter_table_ctx*, HA_CREATE_INFO*, TABLE_LIST*) /data/src/10.8/sql/sql_partition.cc:7773
      		 
          #8 0x557d30091285 in mysql_alter_table(THD*, st_mysql_const_lex_string const*, st_mysql_const_lex_string const*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool, bool) /data/src/10.8/sql/sql_table.cc:10408
      		 
          #9 0x557d301eca63 in Sql_cmd_alter_table::execute(THD*) /data/src/10.8/sql/sql_alter.cc:547
      		 
          #10 0x557d2fe07c07 in mysql_execute_command(THD*, bool) /data/src/10.8/sql/sql_parse.cc:5988
      		 
          #11 0x557d2fe14c0a in mysql_parse(THD*, char*, unsigned int, Parser_state*) /data/src/10.8/sql/sql_parse.cc:8027
      		 
          #12 0x557d2fe1a274 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool) /data/src/10.8/sql/sql_parse.cc:1894
      		 
          #13 0x557d2fe1fc75 in do_command(THD*, bool) /data/src/10.8/sql/sql_parse.cc:1407
      		 
          #14 0x557d301da83d in do_handle_one_connection(CONNECT*, bool) /data/src/10.8/sql/sql_connect.cc:1418
      		 
          #15 0x557d301dad7c in handle_one_connection /data/src/10.8/sql/sql_connect.cc:1312
      		 
          #16 0x557d30cb3a6b in pfs_spawn_thread /data/src/10.8/storage/perfschema/pfs.cc:2201
      		 
          #17 0x7f3d344faea6 in start_thread nptl/pthread_create.c:477
      		 
       
      		 
      previously allocated by thread T11 here:
      		 
          #0 0x7f3d34a00e8f in __interceptor_malloc ../../../../src/libsanitizer/asan/asan_malloc_linux.cpp:145
      		 
          #1 0x557d315b5968 in my_malloc /data/src/10.8/mysys/my_malloc.c:90
      		 
          #2 0x557d315a2b45 in alloc_root /data/src/10.8/mysys/my_alloc.c:332
      		 
          #3 0x557d2fe3eb33 in Sql_alloc::operator new(unsigned long) /data/src/10.8/sql/sql_alloc.h:28
      		 
          #4 0x557d2fe3eb33 in mysql_unpack_partition(THD*, char*, unsigned int, TABLE*, bool, handlerton*, bool*) /data/src/10.8/sql/sql_partition.cc:4428
      		 
          #5 0x557d30147545 in open_table_from_share(THD*, TABLE_SHARE*, st_mysql_const_lex_string const*, unsigned int, unsigned int, unsigned int, TABLE*, bool, List<String>*) /data/src/10.8/sql/table.cc:4312
      		 
          #6 0x557d2fc8d0c5 in open_table(THD*, TABLE_LIST*, Open_table_context*) /data/src/10.8/sql/sql_base.cc:2016
      		 
          #7 0x557d2fc963c1 in open_and_process_table /data/src/10.8/sql/sql_base.cc:3826
      		 
          #8 0x557d2fc963c1 in open_tables(THD*, DDL_options_st const&, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*) /data/src/10.8/sql/sql_base.cc:4309
      		 
          #9 0x557d2fc9802e in open_and_lock_tables(THD*, DDL_options_st const&, TABLE_LIST*, bool, unsigned int, Prelocking_strategy*) /data/src/10.8/sql/sql_base.cc:5282
      		 
          #10 0x557d2fd4fd7a in open_and_lock_tables(THD*, TABLE_LIST*, bool, unsigned int) /data/src/10.8/sql/sql_base.h:509
      		 
          #11 0x557d2fd4fd7a in mysql_insert(THD*, TABLE_LIST*, List<Item>&, List<List<Item> >&, List<Item>&, List<Item>&, enum_duplicates, bool, select_result*) /data/src/10.8/sql/sql_insert.cc:758
      		 
          #12 0x557d2fe093dd in mysql_execute_command(THD*, bool) /data/src/10.8/sql/sql_parse.cc:4562
      		 
          #13 0x557d2fe14c0a in mysql_parse(THD*, char*, unsigned int, Parser_state*) /data/src/10.8/sql/sql_parse.cc:8027
      		 
          #14 0x557d2fe1a274 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool) /data/src/10.8/sql/sql_parse.cc:1894
      		 
          #15 0x557d2fe1fc75 in do_command(THD*, bool) /data/src/10.8/sql/sql_parse.cc:1407
      		 
          #16 0x557d301da83d in do_handle_one_connection(CONNECT*, bool) /data/src/10.8/sql/sql_connect.cc:1418
      		 
          #17 0x557d301dad7c in handle_one_connection /data/src/10.8/sql/sql_connect.cc:1312
      		 
          #18 0x557d30cb3a6b in pfs_spawn_thread /data/src/10.8/storage/perfschema/pfs.cc:2201
      		 
          #19 0x7f3d344faea6 in start_thread nptl/pthread_create.c:477
      		 
       
      		 
      Thread T11 created by T0 here:
      		 
          #0 0x7f3d349ac2a2 in __interceptor_pthread_create ../../../../src/libsanitizer/asan/asan_interceptors.cpp:214
      		 
          #1 0x557d30cb3ce9 in my_thread_create /data/src/10.8/storage/perfschema/my_thread.h:52
      		 
          #2 0x557d30cb3ce9 in pfs_spawn_thread_v1 /data/src/10.8/storage/perfschema/pfs.cc:2252
      		 
          #3 0x557d2fae56ad in inline_mysql_thread_create /data/src/10.8/include/mysql/psi/mysql_thread.h:1139
      		 
          #4 0x557d2fae56ad in create_thread_to_handle_connection(CONNECT*) /data/src/10.8/sql/mysqld.cc:6014
      		 
          #5 0x557d2faf1447 in handle_accepted_socket(st_mysql_socket, st_mysql_socket) /data/src/10.8/sql/mysqld.cc:6135
      		 
          #6 0x557d2faf1fbf in handle_connections_sockets() /data/src/10.8/sql/mysqld.cc:6259
      		 
          #7 0x557d2faf38d0 in mysqld_main(int, char**) /data/src/10.8/sql/mysqld.cc:5909
      		 
          #8 0x7f3d34022d09 in __libc_start_main ../csu/libc-start.c:308
      		 
       
      		 
      SUMMARY: AddressSanitizer: heap-use-after-free /data/src/10.8/storage/innobase/handler/ha_innodb.cc:11249 in create_table_info_t::check_table_options()
      		 
      Shadow bytes around the buggy address:
      		 
        0x0c3a8000ee60: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
      		 
        0x0c3a8000ee70: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
      		 
        0x0c3a8000ee80: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
      		 
        0x0c3a8000ee90: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
      		 
        0x0c3a8000eea0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
      		 
      =>0x0c3a8000eeb0: fd fd fd fd fd fd fd[fd]fd fd fd fd fd fd fd fd
      		 
        0x0c3a8000eec0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
      		 
        0x0c3a8000eed0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
      		 
        0x0c3a8000eee0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
      		 
        0x0c3a8000eef0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
      		 
        0x0c3a8000ef00: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
      		 
      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
      		 
      ==1726155==ABORTING
      		 
      220619  1:48:36 [ERROR] mysqld got signal 6 ;
      		 
      This could be because you hit a bug. It is also possible that this binary
      		 
      or one of the libraries it was linked against is corrupt, improperly built,
      		 
      or misconfigured. This error can also be caused by malfunctioning hardware.
      		 
       
      		 
      To report this bug, see https://mariadb.com/kb/en/reporting-bugs
      		 
       
      		 
      We will try our best to scrape up some info that will hopefully help
      		 
      diagnose the problem, but since we have already crashed, 
      something is definitely wrong and this may fail.
      		 
       
      		 
      Server version: 10.8.4-MariaDB-log
      		 
      key_buffer_size=1048576
      		 
      read_buffer_size=131072
      		 
      max_used_connections=1
      		 
      max_threads=153
      		 
      thread_count=1
      		 
      It is possible that mysqld could use up to 
      key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63773 K  bytes of memory
      		 
      Hope that's ok; if not, decrease some variables in the equation.
      		 
       
      		 
      Thread pointer: 0x62b00017a218
      		 
      Attempting backtrace. You can use the following information to find out
      		 
      where mysqld died. If you see no messages after this, something went
      		 
      terribly wrong...
      		 
      stack_bottom = 0x7f3d25934990 thread_stack 0x5fc00
      		 
      sanitizer_common/sanitizer_common_interceptors.inc:4101(__interceptor_backtrace.part.0)[0x7f3d3499adf1]
      		 
      mysys/stacktrace.c:213(my_print_stacktrace)[0x557d315be436]
      		 
      sql/signal_handler.cc:223(handle_fatal_signal)[0x557d3056af44]
      		 
      sigaction.c:0(__restore_rt)[0x7f3d34506140]
      		 
      linux/raise.c:51(__GI_raise)[0x7f3d34037ce1]
      		 
      stdlib/abort.c:81(__GI_abort)[0x7f3d34021537]
      		 
      sanitizer_common/sanitizer_posix_libcdep.cpp:149(__sanitizer::Abort())[0x7f3d34a1c11b]
      		 
      sanitizer_common/sanitizer_termination.cpp:59(__sanitizer::Die())[0x7f3d34a26ce8]
      		 
      asan/asan_report.cpp:186(__asan::ScopedInErrorReport::~ScopedInErrorReport())[0x7f3d34a0944c]
      		 
      asan/asan_report.cpp:474(__asan::ReportGenericError(unsigned long, unsigned long, unsigned long, unsigned long, bool, unsigned long, unsigned int, bool))[0x7f3d34a08d47]
      		 
      asan/asan_rtl.cpp:119(__asan_report_load4)[0x7f3d34a098a8]
      		 
      handler/ha_innodb.cc:11314(create_table_info_t::check_table_options())[0x557d30ea37c3]
      		 
      handler/ha_innodb.cc:12020(create_table_info_t::prepare_create_table(char const*, bool))[0x557d30ef07ae]
      		 
      handler/ha_innodb.cc:13965(ha_innobase::truncate())[0x557d30edfab0]
      		 
      sql/ha_partition.cc:4920(ha_partition::truncate_partition(Alter_info*, bool*))[0x557d30c91ab2]
      		 
      sql/sql_partition_admin.cc:958(Sql_cmd_alter_table_truncate_partition::execute(THD*))[0x557d301e2061]
      		 
      sql/sql_parse.cc:5988(mysql_execute_command(THD*, bool))[0x557d2fe07c08]
      		 
      sql/sql_parse.cc:8044(mysql_parse(THD*, char*, unsigned int, Parser_state*))[0x557d2fe14c0b]
      		 
      sql/sql_parse.cc:1896(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool))[0x557d2fe1a275]
      		 
      sql/sql_parse.cc:1409(do_command(THD*, bool))[0x557d2fe1fc76]
      		 
      sql/sql_connect.cc:1418(do_handle_one_connection(CONNECT*, bool))[0x557d301da83e]
      		 
      sql/sql_connect.cc:1312(handle_one_connection)[0x557d301dad7d]
      		 
      perfschema/pfs.cc:2204(pfs_spawn_thread)[0x557d30cb3a6c]
      		 
      nptl/pthread_create.c:478(start_thread)[0x7f3d344faea7]
      		 
      x86_64/clone.S:97(__GI___clone)[0x7f3d340f9def]
      		 
       
      		 
      Trying to get some variables.
      		 
      Some pointers may be invalid and cause the dump to abort.
      		 
      Query (0x6290000b9238): ALTER TABLE t NOWAIT TRUNCATE PARTITION p0
      		 
       
      		 
      Connection ID (thread ID): 4
      		 
      Status: NOT_KILLED
      		 
       
      		 
      Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=on,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_materialized=on,condition_pushdown_for_subquery=on,rowid_filter=on,condition_pushdown_from_having=on,not_null_range_scan=off
      		 
       
      		 
      The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ contains
      		 
      information that should help you find out what is causing the crash.
      		 
      Writing a core file...
      		 
      Working directory at /dev/shm/var_auto_oY1f/mysqld.1/data
      		 
      Resource Limits:
      		 
      Limit                     Soft Limit           Hard Limit           Units     
      Max cpu time              unlimited            unlimited            seconds   
      Max file size             unlimited            unlimited            bytes     
      Max data size             unlimited            unlimited            bytes     
      Max stack size            8388608              unlimited            bytes     
      Max core file size        unlimited            unlimited            bytes     
      Max resident set          unlimited            unlimited            bytes     
      Max processes             385885               385885               processes 
      Max open files            1024                 1024                 files     
      Max locked memory         12659513344          12659513344          bytes     
      Max address space         unlimited            unlimited            bytes     
      Max file locks            unlimited            unlimited            locks     
      Max pending signals       385885               385885               signals   
      Max msgqueue size         819200               819200               bytes     
      Max nice priority         0                    0                    
      Max realtime priority     0                    0                    
      Max realtime timeout      unlimited            unlimited            us        
      Core pattern: core

      Attachments

        Activity

          People

            marko Marko Mäkelä
            elenst Elena Stepanova
            Votes:
            0 Vote for this issue
            Watchers:
            5 Start watching this issue

            Dates

              Created:
              Updated:

              Git Integration

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