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

Statistics: Server crashes in Warning_info::current_row_for_warning on concurrent ANALYZE TABLE and DML with reconnecting threads

Details

    • Bug
    • Status: Closed (View Workflow)
    • Major
    • Resolution: Fixed
    • None
    • 10.0.2
    • None
    • None

    Description

      #3  <signal handler called>
      #4  0x000000000058d626 in Warning_info::current_row_for_warning (this=0x8f8f8f8f8f8f8f8f)
          at sql/sql_error.h:463
      #5  0x000000000070542a in make_truncated_value_warning (thd=0x2055d80,
          level=MYSQL_ERROR::WARN_LEVEL_WARN, sval=0x7f675949ff00, time_type=MYSQL_TIMESTAMP_DATE,
          field_name=0x20a7504 "fdate") at sql/sql_time.cc:828
      #6  0x00000000007d8f1d in Field::set_datetime_warning (this=0x2039b20,
          level=MYSQL_ERROR::WARN_LEVEL_WARN, code=1264, str=0x7f675949ff00,
          ts_type=MYSQL_TIMESTAMP_DATE, cuted_increment=1)
          at sql/field.cc:9789
      #7  0x00000000007c86a2 in Field_temporal::store_TIME_with_warning (this=0x2039b20,
          ltime=0x7f67594a0120, str=0x7f675949ff00, was_cut=2, have_smth_to_conv=0)
          at sql/field.cc:5018
      #8  0x00000000007c87ae in Field_temporal::store (this=0x2039b20,
          from=0x7f67540220be "0000-00-00\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217"..., len=10, cs=0x14f6860) at sql/field.cc:5039
      #9  0x00000000006be51a in Column_stat::get_stat_values (this=0x7f67594a1700)
          at sql/sql_statistics.cc:973
      #10 0x00000000006bbbcc in read_statistics_for_table (thd=0x20404c0, table=0x7f675400c360)
          at sql/sql_statistics.cc:2308
      #11 0x00000000005d6135 in open_and_process_table (thd=0x20404c0, lex=0x2075ad8, tables=0x2031600,
          counter=0x7f67594a1bf4, flags=0, prelocking_strategy=0x7f67594a1c40,
          has_prelocking_list=false, ot_ctx=0x7f67594a1ad0, new_frm_mem=0x7f67594a1a90)
          at sql/sql_base.cc:4672
      #12 0x00000000005d6af4 in open_tables (thd=0x20404c0, start=0x7f67594a1bb0,
          counter=0x7f67594a1bf4, flags=0, prelocking_strategy=0x7f67594a1c40)
          at sql/sql_base.cc:5008
      #13 0x00000000005d79c5 in open_and_lock_tables (thd=0x20404c0, tables=0x2031600, derived=true,
          flags=0, prelocking_strategy=0x7f67594a1c40)
          at sql/sql_base.cc:5606
      #14 0x00000000005caf32 in open_and_lock_tables (thd=0x20404c0, tables=0x2031600, derived=true,
          flags=0) at sql/sql_base.h:518
      #15 0x000000000073f51a in mysql_admin_table (thd=0x20404c0, tables=0x2031600, check_opt=0x2076958,
          operator_name=0xd67979 "analyze", lock_type=TL_READ_NO_INSERT, open_for_modify=true,
          repair_table_use_frm=false, extra_open_options=0, prepare_func=0, operator_func=
          (int (handler::*)(handler *, THD *, HA_CHECK_OPT *)) 0x7ed302 <handler::ha_analyze(THD*, HA_CHECK_OPT*)>, view_operator_func=0) at sql/sql_admin.cc:420
      #16 0x0000000000741890 in Analyze_table_statement::execute (this=0x2031bc8, thd=0x20404c0)
          at sql/sql_admin.cc:1089
      #17 0x0000000000636365 in mysql_execute_command (thd=0x20404c0)
          at sql/sql_parse.cc:4459
      #18 0x00000000009144f4 in sp_instr_stmt::exec_core (this=0x2031bd8, thd=0x20404c0,
          nextp=0x7f67594a2d58) at sql/sp_head.cc:3190
      #19 0x0000000000913d07 in sp_lex_keeper::reset_lex_and_exec_core (this=0x2031c18, thd=0x20404c0,
          nextp=0x7f67594a2d58, open_tables=false, instr=0x2031bd8)
          at sql/sp_head.cc:2983
      #20 0x00000000009142ab in sp_instr_stmt::execute (this=0x2031bd8, thd=0x20404c0,
          nextp=0x7f67594a2d58) at sql/sp_head.cc:3122
      #21 0x0000000000910022 in sp_head::execute (this=0x1fcb6b8, thd=0x20404c0,
          merge_da_on_success=true) at sql/sp_head.cc:1425
      #22 0x0000000000911d62 in sp_head::execute_procedure (this=0x1fcb6b8, thd=0x20404c0,
          args=0x20434a0) at sql/sp_head.cc:2182
      #23 0x0000000000635120 in mysql_execute_command (thd=0x20404c0)
          at sql/sql_parse.cc:4068
      #24 0x000000000063946b in mysql_parse (thd=0x20404c0, rawbuf=0x206d3b8 "CALL p_analyze()",
          length=16, parser_state=0x7f67594a3600) at sql/sql_parse.cc:5736
      #25 0x000000000062d2ed in dispatch_command (command=COM_QUERY, thd=0x20404c0, packet=0x205c191 "",
          packet_length=16) at sql/sql_parse.cc:1055
      #26 0x000000000062c5c0 in do_command (thd=0x20404c0)
          at sql/sql_parse.cc:794
      #27 0x0000000000731235 in do_handle_one_connection (thd_arg=0x20404c0)
          at sql/sql_connect.cc:1253
      #28 0x0000000000730cf8 in handle_one_connection (arg=0x20404c0)
          at sql/sql_connect.cc:1168
      #29 0x0000000000abbb83 in pfs_spawn_thread (arg=0x202f600)
          at storage/perfschema/pfs.cc:1015
      #30 0x00007f6764f40a4f in start_thread () from /lib64/libpthread.so.0
      #31 0x00007f6763cd582d in clone () from /lib64/libc.so.6
       

      bzr version-info
      revision-id: igor@askmonty.org-20120902065147-1b2kr5wc1eks7aaf
      date: 2012-09-01 23:51:47 -0700
      build-date: 2012-09-02 15:46:52 +0300
      revno: 3366

      Test case
      (Note: the procedures are unimportant for the crash as such, they just allow to convert the flow into an MTR test case)

      CREATE TABLE A (
        pk INTEGER AUTO_INCREMENT PRIMARY KEY,
        fdate DATE
      ) ENGINE=MyISAM;
       
      --delimiter |
       
      CREATE PROCEDURE p_analyze()
      BEGIN
        DECLARE attempts INTEGER DEFAULT 20;
        wl_loop: WHILE attempts > 0 DO
          ANALYZE TABLE A;
          SET attempts = attempts - 1;
        END WHILE wl_loop;
      END |
       
      CREATE FUNCTION rnd3() RETURNS INT
      BEGIN
        RETURN ROUND(3 * RAND() + 0.5);
      END |
       
      --delimiter ;
       
      SET GLOBAL use_stat_tables = PREFERABLY;
       
      --let $trial = 1000
       
      while ($trial)
      {
       
        --connect (con1,localhost,root,,)
        --send CALL p_analyze()
       
        --connect (con2,localhost,root,,)
        --send CALL p_analyze()
       
        --let $run = 20
       
        while ($run)
        {
          --connect (con3,localhost,root,,)
       
          let $query = `SELECT CASE rnd3()
            WHEN 1 THEN 'INSERT INTO A (pk) VALUES (NULL)'
            WHEN 2 THEN 'DELETE FROM A LIMIT 1'
            ELSE 'UPDATE A SET fdate = 2 LIMIT 1' END`;
          --eval $query
          --disconnect con3
          --dec $run
        }
       
        --connection con2
        --reap
        --disconnect con2
        --connection con1
        --reap
        --disconnect con1
       
        --dec $trial
      }
       
      # Cleanup
      --connection default
      DROP TABLE A;
      SET GLOBAL use_stat_tables = DEFAULT;

      An alternative test case:

      # Run as perl ./mtr main.<test name>
       
      --write_file $MYSQLTEST_VARDIR/test_init
      DROP TABLE IF EXISTS A
      CREATE TABLE A ( pk INTEGER AUTO_INCREMENT PRIMARY KEY, fdate DATE NOT NULL DEFAULT '2012-12-12' ) ENGINE=MyISAM
      SET GLOBAL use_stat_tables = PREFERABLY
      EOF
       
      --write_file $MYSQLTEST_VARDIR/test_queries
      ANALYZE TABLE A
      INSERT INTO A (pk) VALUES (NULL)
      UPDATE A SET fdate = 2 LIMIT 1
      DELETE FROM A LIMIT 1
      INSERT INTO A (pk) VALUES (NULL)
      UPDATE A SET fdate = 2 LIMIT 1
      DELETE FROM A LIMIT 1
      EOF
       
      --write_file $MYSQLTEST_VARDIR/test_cleanup
      DROP TABLE A
      SET GLOBAL use_stat_tables = DEFAULT
      EOF
       
      --echo # Running the test with 3 parallel threads...
      --exec $MYSQL_SLAP --silent --create=$MYSQLTEST_VARDIR/test_init --query=$MYSQLTEST_VARDIR/test_queries --concurrency=3 --number-of-queries=300000 --detach=5 --post-query=$MYSQLTEST_VARDIR/test_cleanup
       
      --echo # Running the test with 4 parallel threads...
      --exec $MYSQL_SLAP --silent --create=$MYSQLTEST_VARDIR/test_init --query=$MYSQLTEST_VARDIR/test_queries --concurrency=4 --number-of-queries=400000 --detach=5 --post-query=$MYSQLTEST_VARDIR/test_cleanup
       
      --echo # Running the test with 10 parallel threads...
      --exec $MYSQL_SLAP --silent --create=$MYSQLTEST_VARDIR/test_init --query=$MYSQLTEST_VARDIR/test_queries --concurrency=10 --number-of-queries=1000000 --detach=5 --post-query=$MYSQLTEST_VARDIR/test_cleanup
       
      --echo # Running the test with 20 parallel threads...
      --exec $MYSQL_SLAP --silent --create=$MYSQLTEST_VARDIR/test_init --query=$MYSQLTEST_VARDIR/test_queries --concurrency=20 --number-of-queries=2000000 --detach=5 --post-query=$MYSQLTEST_VARDIR/test_cleanup
       
      --echo # All done.

      Attachments

        Issue Links

          Activity

            Taking the bug back since it's not reproducible on Igor's machines, and we don't have a confirmation from buildbot yet (the test case is pushed to mwl248 tree as mdev-504.test)

            elenst Elena Stepanova added a comment - Taking the bug back since it's not reproducible on Igor's machines, and we don't have a confirmation from buildbot yet (the test case is pushed to mwl248 tree as mdev-504.test)
            elenst Elena Stepanova added a comment - - edited

            Please try the test case added at the end of the description under "Alternative test case" (I cannot add it as a comment because there is "noformat" mode here, and it's important to have the test without formatting).

            Run as perl ./mtr main.<test name>, no other parameters needed.

            This one fails within 30 seconds for me on all previous machines (where it took several minutes before), and also on a fb machine. It has also a higher probability to crash in a DML command rather than in ANALYZE.

            Please note that with both old and new test cases I could only get the crash on a debug server built with safemalloc (it shouldn't be the reason why the previous one wasn't failing on your machines before, but better to take it into account to avoid wasting time on other build types, e.g. release). So, I didn't push the test into maria-5.5-mwl248, because the only debug builder has a long queue at the moment. The previous test crashed in the buildbot though, see http://buildbot.askmonty.org/buildbot/builders/kvm-dgcov-jaunty-i386/builds/1858/steps/test_1/logs/stdio .

            elenst Elena Stepanova added a comment - - edited Please try the test case added at the end of the description under "Alternative test case" (I cannot add it as a comment because there is "noformat" mode here, and it's important to have the test without formatting). Run as perl ./mtr main.<test name>, no other parameters needed. This one fails within 30 seconds for me on all previous machines (where it took several minutes before), and also on a fb machine. It has also a higher probability to crash in a DML command rather than in ANALYZE. Please note that with both old and new test cases I could only get the crash on a debug server built with safemalloc (it shouldn't be the reason why the previous one wasn't failing on your machines before, but better to take it into account to avoid wasting time on other build types, e.g. release). So, I didn't push the test into maria-5.5-mwl248, because the only debug builder has a long queue at the moment. The previous test crashed in the buildbot though, see http://buildbot.askmonty.org/buildbot/builders/kvm-dgcov-jaunty-i386/builds/1858/steps/test_1/logs/stdio .

            fixed in the maria-5.5-mwl248 tree

            serg Sergei Golubchik added a comment - fixed in the maria-5.5-mwl248 tree

            People

              igor Igor Babaev (Inactive)
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              2 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.