[MDEV-504] Statistics: Server crashes in Warning_info::current_row_for_warning on concurrent ANALYZE TABLE and DML with reconnecting threads Created: 2012-09-02  Updated: 2021-09-21  Resolved: 2012-12-10

Status: Closed
Project: MariaDB Server
Component/s: None
Affects Version/s: None
Fix Version/s: 10.0.2

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Igor Babaev
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
PartOf
is part of MDEV-3806 Engine independent statistics Closed
Relates

 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.



 Comments   
Comment by Elena Stepanova [ 2012-09-04 ]

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)

Comment by Elena Stepanova [ 2012-09-04 ]

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 .

Comment by Sergei Golubchik [ 2012-12-10 ]

fixed in the maria-5.5-mwl248 tree

Generated at Thu Feb 08 06:29:14 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.