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

Valgrind errors 'invalid write' or assorted server crashes on concurrent flow with partitioned Aria tables

    Details

    • Type: Bug
    • Status: Closed (View Workflow)
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: 10.0.1, 5.5.28a
    • Fix Version/s: 10.0.3, 5.5.31
    • Component/s: None
    • Labels:
      None

      Description

      All stack traces below were received by running the same test on the same build. I've also seen other traces on the same test; basically, every time I run it and it crashes, the stack is different. I will only quote a few examples.

      The crashes happen on all 3 different machines where I tried: Ubuntu 11.10 64-bit (VM with reasonable performance), openSUSE 12.2 32-bit (very slow box), Windows Server 2012 64-bit (fast enough comparing to the other two).

      Reproducible on maria/5.5 and maria/10.0-base, both release and debug builds.
      Stack traces are from

      branch: 10.0-base 
      revno: 3457
      revision-id: igor@askmonty.org-20121220233829-rcbryu0uy5z5kdz1 
      build: BUILD/compile-pentium-debug-max-no-ndb
      Ubuntu 11.10 oneiric 64-bit

      The provided test uses a standard grammar and dataset (included into the randgen tree) so you don't need anything but the recent tree to run it; but due to that the test flow is overly complicated, it can be simplified if needed.

      RQG command line (assuming you have already started a server on port 3306; if you use a different port, modify the dsn line):

      perl gentest.pl --gendata=conf/partitioning/partition_pruning.zz --engine=Aria --reporter=ErrorLog --threads=16 --queries=100M --duration=300 --dsn=dbi:mysql:host=127.0.0.1:port=3306:user=root:database=test --grammar=conf/partitioning/partition_pruning.yy --rows=50

      If you want to run the full test, which starts the server etc., the command line is as follows (set your basedir and vardir):

      perl ./runall.pl --threads=16 --duration=300 --queries=100M --reporters=ErrorLog  --grammar=conf/partitioning/partition_pruning.yy --gendata=conf/partitioning/partition_pruning.zz --engine=Aria --rows=50  --basedir=<your basedir> --vardir=<your vardir>

      If you want to run the full test with Valgrind, the command line is the same plus valgrind:

      perl ./runall.pl --valgrind --threads=16 --duration=300 --queries=100M --reporters=ErrorLog,ValgrindErrors  --grammar=conf/partitioning/partition_pruning.yy --gendata=conf/partitioning/partition_pruning.zz --engine=Aria --rows=50  --basedir=<your basedir> --vardir=<your vardir>

      branch: randgen
      revision-id: saikumar.v@oracle.com-20121106115227-cnig7ez4zdb11eqp
      revno: 792

      Example of a Valgrind warning:

      ==12798== Thread 31:
      ==12798== Invalid write of size 8
      ==12798==    at 0x96AAA1: ha_maria::external_lock(THD*, int) (ha_maria.cc:2665)
      ==12798==    by 0x7D9FBD: handler::ha_external_lock(THD*, int) (handler.cc:5102)
      ==12798==    by 0xC7F88B: ha_partition::external_lock(THD*, int) (ha_partition.cc:3148)
      ==12798==    by 0x7D9FBD: handler::ha_external_lock(THD*, int) (handler.cc:5102)
      ==12798==    by 0x8A61B3: lock_external(THD*, TABLE**, unsigned int) (lock.cc:359)
      ==12798==    by 0x8A5F09: mysql_lock_tables(THD*, st_mysql_lock*, unsigned int) (lock.cc:309)
      ==12798==    by 0x8A5E1F: mysql_lock_tables(THD*, TABLE**, unsigned int, unsigned int) (lock.cc:276)
      ==12798==    by 0x5B384C: lock_tables(THD*, TABLE_LIST*, unsigned int, unsigned int) (sql_base.cc:5840)
      ==12798==    by 0x5B3065: open_and_lock_tables(THD*, TABLE_LIST*, bool, unsigned int, Prelocking_strateg
      y*) (sql_base.cc:5610)
      ==12798==    by 0x5A6490: open_and_lock_tables(THD*, TABLE_LIST*, bool, unsigned int) (sql_base.h:501)
      ==12798==    by 0x613A0F: execute_sqlcom_select(THD*, TABLE_LIST*) (sql_parse.cc:4717)
      ==12798==    by 0x60C384: mysql_execute_command(THD*) (sql_parse.cc:2246)
      ==12798==    by 0x61650E: mysql_parse(THD*, char*, unsigned int, Parser_state*) (sql_parse.cc:5874)
      ==12798==    by 0x6096CA: dispatch_command(enum_server_command, THD*, char*, unsigned int) (sql_parse.cc:1072)
      ==12798==    by 0x608981: do_command(THD*) (sql_parse.cc:811)
      ==12798==    by 0x716F46: do_handle_one_connection(THD*) (sql_connect.cc:1253)
      ==12798==  Address 0x1f23e058 is 168 bytes inside a block of size 228 free'd
      ==12798==    at 0x4C282E0: free (vg_replace_malloc.c:366)
      ==12798==    by 0xCC6A21: free_memory (safemalloc.c:205)
      ==12798==    by 0xCC6945: sf_free (safemalloc.c:182)
      ==12798==    by 0xCB16B7: my_free (my_malloc.c:115)
      ==12798==    by 0x9562BA: _ma_trnman_end_trans_hook (ma_state.c:532)
      ==12798==    by 0x96F3FE: trnman_end_trn (trnman.c:479)
      ==12798==    by 0x9A283E: ma_commit (ma_commit.c:72)
      ==12798==    by 0x96B0F4: ha_maria::implicit_commit(THD*, bool) (ha_maria.cc:2835)
      ==12798==    by 0x6136BB: mysql_execute_command(THD*) (sql_parse.cc:4651)
      ==12798==    by 0x61650E: mysql_parse(THD*, char*, unsigned int, Parser_state*) (sql_parse.cc:5874)
      ==12798==    by 0x6096CA: dispatch_command(enum_server_command, THD*, char*, unsigned int) (sql_parse.cc:1072)
      ==12798==    by 0x608981: do_command(THD*) (sql_parse.cc:811)
      ==12798==    by 0x716F46: do_handle_one_connection(THD*) (sql_connect.cc:1253)
      ==12798==    by 0x716931: handle_one_connection (sql_connect.cc:1168)
      ==12798==    by 0x5458EFB: start_thread (pthread_create.c:304)
      ==12798==    by 0x611AF4C: clone (clone.S:112)

      Examples of crashes:

      #3  <signal handler called>
      #4  __memset_sse2 () at ../sysdeps/x86_64/multiarch/../memset.S:390
      #5  0x00000000006df75d in TABLE::init (this=0x7fe874a2b1c0, thd=0x7fe8742e5ce0, tl=0x45bc038) at 10.0-base/sql/table.cc:3972
      #6  0x00000000005aed86 in open_table (thd=0x7fe8742e5ce0, table_list=0x45bc038, mem_root=0x7fe87b673b80, ot_ctx=0x7fe87b673bc0) at 10.0-base/sql/sql_base.cc:3220
      #7  0x00000000005b1113 in open_and_process_table (thd=0x7fe8742e5ce0, lex=0x7fe8742e81a8, tables=0x45bc038, counter=0x7fe87b673cdc, flags=0, prelocking_strategy=0x7fe87b673d10, has_prelocking_list=false, ot_ctx=0x7fe87b673bc0, new_frm_mem=0x7fe87b673b80) at 10.0-base/sql/sql_base.cc:4524
      #8  0x00000000005b2155 in open_tables (thd=0x7fe8742e5ce0, start=0x7fe87b673c90, counter=0x7fe87b673cdc, flags=0, prelocking_strategy=0x7fe87b673d10) at 10.0-base/sql/sql_base.cc:4996
      #9  0x00000000005b2fef in open_and_lock_tables (thd=0x7fe8742e5ce0, tables=0x3ab7bc0, derived=true, flags=0, prelocking_strategy=0x7fe87b673d10) at 10.0-base/sql/sql_base.cc:5601
      #10 0x00000000005a6491 in open_and_lock_tables (thd=0x7fe8742e5ce0, tables=0x3ab7bc0, derived=true, flags=0) at 10.0-base/sql/sql_base.h:501
      #11 0x000000000060e7c2 in mysql_execute_command (thd=0x7fe8742e5ce0) at 10.0-base/sql/sql_parse.cc:3117
      #12 0x000000000061650f in mysql_parse (thd=0x7fe8742e5ce0, rawbuf=0x3ab7118 "INSERT INTO `PP_H` SELECT `col_date`,`col_date_key`,`col_datetime`,`col_datetime_key`,`col_int_signed`,`col_int_signed_key`,`col_varchar_256_cp932`,`col_varchar_256_cp932_key`,`col_varchar_256_latin1`"..., length=1270, parser_state=0x7fe87b674550) at 10.0-base/sql/sql_parse.cc:5874
      #13 0x00000000006096cb in dispatch_command (command=COM_QUERY, thd=0x7fe8742e5ce0, packet=0x7fe8742e9931 " INSERT INTO `PP_H` SELECT `col_date`,`col_date_key`,`col_datetime`,`col_datetime_key`,`col_int_signed`,`col_int_signed_key`,`col_varchar_256_cp932`,`col_varchar_256_cp932_key`,`col_varchar_256_latin1"..., packet_length=1271) at 10.0-base/sql/sql_parse.cc:1072
      #14 0x0000000000608982 in do_command (thd=0x7fe8742e5ce0) at 10.0-base/sql/sql_parse.cc:811
      #15 0x0000000000716f47 in do_handle_one_connection (thd_arg=0x7fe8742e5ce0) at 10.0-base/sql/sql_connect.cc:1253
      #16 0x0000000000716932 in handle_one_connection (arg=0x7fe8742e5ce0) at 10.0-base/sql/sql_connect.cc:1168
      #17 0x00007fe893107efc in start_thread (arg=0x7fe87b675700) at pthread_create.c:304
      #18 0x00007fe892479f4d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112

      #3  <signal handler called>
      #4  __strlen_sse2 () at ../sysdeps/x86_64/multiarch/../strlen.S:32
      #5  0x000000000056ed20 in Protocol::send_result_set_metadata (this=0x57f9f68, list=0x5809458, flags=5) at 10.0-base/sql/protocol.cc:771
      #6  0x00000000005d45f9 in select_send::send_result_set_metadata (this=0x58090b8, list=..., flags=5) at 10.0-base/sql/sql_class.cc:2293
      #7  0x00000000006443cd in JOIN::exec_inner (this=0x58090d8) at 10.0-base/sql/sql_select.cc:2965
      #8  0x0000000000641777 in JOIN::exec (this=0x58090d8) at 10.0-base/sql/sql_select.cc:2258
      #9  0x0000000000644ca3 in mysql_select (thd=0x57f99a0, rref_pointer_array=0x57fc850, tables=0x5808368, wild_num=0, fields=..., conds=0x5808c20, og_num=2, order=0x0, group=0x5808e98, having=0x0, proc_param=0x0, select_options=2147748608, result=0x58090b8, unit=0x57fbf18, select_lex=0x57fc5f0) at 10.0-base/sql/sql_select.cc:3194
      #10 0x000000000063b6e0 in handle_select (thd=0x57f99a0, lex=0x57fbe68, result=0x58090b8, setup_tables_done_option=0) at 10.0-base/sql/sql_select.cc:368
      #11 0x0000000000613ca8 in execute_sqlcom_select (thd=0x57f99a0, all_tables=0x5808368) at 10.0-base/sql/sql_parse.cc:4759
      #12 0x000000000060c385 in mysql_execute_command (thd=0x57f99a0) at 10.0-base/sql/sql_parse.cc:2246
      #13 0x000000000061650f in mysql_parse (thd=0x57f99a0, rawbuf=0x5807b08 "SELECT table1 . `col_date_key` AS field1, MAX( distinct table1 . `col_int_signed` ) AS field2, table1 . `col_int_signed_key` AS field3 FROM `PP_K` AS table1 WHERE  ( table1 . `col_varchar_256_cp932_ke"..., length=262, parser_state=0x7ff00c967550) at 10.0-base/sql/sql_parse.cc:5874
      #14 0x00000000006096cb in dispatch_command (command=COM_QUERY, thd=0x57f99a0, packet=0x57ff071 "", packet_length=266) at 10.0-base/sql/sql_parse.cc:1072
      #15 0x0000000000608982 in do_command (thd=0x57f99a0) at 10.0-base/sql/sql_parse.cc:811
      #16 0x0000000000716f47 in do_handle_one_connection (thd_arg=0x57f99a0) at 10.0-base/sql/sql_connect.cc:1253
      #17 0x0000000000716932 in handle_one_connection (arg=0x57f99a0) at 10.0-base/sql/sql_connect.cc:1168
      #18 0x00007ff027823efc in start_thread (arg=0x7ff00c968700) at pthread_create.c:304
      #19 0x00007ff026b95f4d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
       
      #19 0x0000000000000000 in ?? ()

      #3  <signal handler called>
      #4  0x0000000000c8dee6 in movelink (array=0x49076d0, find=106, next_link=4294967295, newlink=22) at 10.0-base/mysys/hash.c:333
      #5  0x0000000000c8e3e6 in my_hash_insert (info=0x38c0c30, record=0x4b543b0 "\340\305", <incomplete sequence \336>) at 10.0-base/mysys/hash.c:499
      #6  0x0000000000cc111d in add_to_locked_mutex (locked_mutex=0x4b543b0, current_mutex=0x7f2e98104520) at 10.0-base/mysys/thr_mutex.c:740
      #7  0x0000000000cc108d in add_used_to_locked_mutex (used_mutex=0x7f2e98104520, locked_mutex=0x4b543b0) at 10.0-base/mysys/thr_mutex.c:723
      #8  0x0000000000c8eda5 in my_hash_iterate (hash=0x389d678, action=0xcc103c <add_used_to_locked_mutex>, argument=0x4b543b0) at 10.0-base/mysys/hash.c:759
      #9  0x0000000000cc03cb in safe_mutex_lock (mp=0x4b50d58, my_flags=0, file=0xdec5e0 "10.0-base/storage/maria/ma_state.c", line=218) at 10.0-base/mysys/thr_mutex.c:380
      #10 0x00000000009552ba in inline_mysql_mutex_lock (that=0x4b50d58, src_file=0xdec5e0 "10.0-base/storage/maria/ma_state.c", src_line=218) at 10.0-base/include/mysql/psi/mysql_thread.h:618
      #11 0x000000000095584d in _ma_remove_not_visible_states_with_lock (share=0x4b50510, all=1 '\001') at 10.0-base/storage/maria/ma_state.c:218
      #12 0x00000000009ee7cf in maria_close (info=0x4c97d60) at 10.0-base/storage/maria/ma_close.c:185
      #13 0x000000000096653e in ha_maria::close (this=0x4b4b1a8) at 10.0-base/storage/maria/ha_maria.cc:1250
      #14 0x00000000007d4af2 in handler::ha_close (this=0x4b4b1a8) at 10.0-base/sql/handler.cc:2334
      #15 0x000000000096a96f in ha_maria::drop_table (this=0x4b4b1a8, name=0x4925258 "test_results/max-query-time-analyze-18/tmp/#sql_318a_0") at 10.0-base/storage/maria/ha_maria.cc:2616
      #16 0x00000000007d7238 in handler::ha_drop_table (this=0x4b4b1a8, name=0x4925258 "test_results/max-query-time-analyze-18/tmp/#sql_318a_0") at 10.0-base/sql/handler.cc:3716
      #17 0x00000000006632f6 in free_tmp_table (thd=0x4054970, entry=0x49242c8) at 10.0-base/sql/sql_select.cc:15749
      #18 0x00000000006447b8 in JOIN::destroy (this=0x4063b80) at 10.0-base/sql/sql_select.cc:3038
      #19 0x00000000006c6043 in st_select_lex::cleanup (this=0x40575c0) at 10.0-base/sql/sql_union.cc:991
      #20 0x0000000000644d31 in mysql_select (thd=0x4054970, rref_pointer_array=0x4057820, tables=0x4062e80, wild_num=0, fields=..., conds=0x4063810, og_num=1, order=0x0, group=0x4063a88, having=0x0, proc_param=0x0, select_options=2147748608, result=0x4063b60, unit=0x4056ee8, select_lex=0x40575c0) at 10.0-base/sql/sql_select.cc:3206
      #21 0x000000000063b6e0 in handle_select (thd=0x4054970, lex=0x4056e38, result=0x4063b60, setup_tables_done_option=0) at 10.0-base/sql/sql_select.cc:368
      #22 0x0000000000613ca8 in execute_sqlcom_select (thd=0x4054970, all_tables=0x4062e80) at 10.0-base/sql/sql_parse.cc:4759
      #23 0x000000000060c385 in mysql_execute_command (thd=0x4054970) at 10.0-base/sql/sql_parse.cc:2246
      #24 0x000000000061650f in mysql_parse (thd=0x4054970, rawbuf=0x4062ad8 "SELECT table1 . `col_varchar_256_utf8_key` AS field1 FROM `PP_K` AS table1 WHERE NOT ( table1 . `col_datetime` <= '2009-06-17 10:24:26.030794' )  GROUP BY field1", length=161, parser_state=0x7f2e9c1eb550) at 10.0-base/sql/sql_parse.cc:5874
      #25 0x00000000006096cb in dispatch_command (command=COM_QUERY, thd=0x4054970, packet=0x405a041 "", packet_length=165) at 10.0-base/sql/sql_parse.cc:1072
      #26 0x0000000000608982 in do_command (thd=0x4054970) at 10.0-base/sql/sql_parse.cc:811
      #27 0x0000000000716f47 in do_handle_one_connection (thd_arg=0x4054970) at 10.0-base/sql/sql_connect.cc:1253
      #28 0x0000000000716932 in handle_one_connection (arg=0x4054970) at 10.0-base/sql/sql_connect.cc:1168
      #29 0x00007f2eb605cefc in start_thread (arg=0x7f2e9c1ec700) at pthread_create.c:304
      #30 0x00007f2eb53cef4d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112

        Attachments

          Activity

            People

            • Assignee:
              monty Michael Widenius
              Reporter:
              elenst Elena Stepanova
            • Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: