MySQL Bugs: #66645: Assertion `file_entry_buf[2] == 0' failed in deactivate_ddl_log

Bug #66645	Assertion `file_entry_buf[2] == 0' failed in deactivate_ddl_log_entry
Submitted:	1 Sep 2012 16:39	Modified:	11 Dec 2012 13:04
Reporter:	Elena Stepanova	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Partitions	Severity:	S3 (Non-critical)
Version:	5.5-debug	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
lp:mysql-server/5.5 revno 3900, built with CMAKE_BUILD_TYPE=Debug, no other parameters.

/mysql-5.5/sql/sql_table.cc:1322: bool deactivate_ddl_log_entry(uint): Assertion `file_entry_buf[2] == 0' failed.

#6  0x00007fb99abe0235 in __assert_fail () from /lib64/libc.so.6
#7  0x000000000067b86f in deactivate_ddl_log_entry (entry_no=15)
    at mysql-5.5/sql/sql_table.cc:1322
#8  0x000000000067c5c3 in mysql_write_frm (lpt=0x7fb98cad6130, flags=2)
    at mysql-5.5/sql/sql_table.cc:1796
#9  0x0000000000888cfc in fast_alter_partition_table (thd=0x1b35b30, table=0x1b4bc50,
    alter_info=0x7fb98cad8070, create_info=0x7fb98cad7f90, table_list=0x1b40a38,
    db=0x1b40f60 "test", table_name=0x1b40a00 "d", fast_alter_table=0x1b498b0)
    at mysql-5.5/sql/sql_partition.cc:6907
#10 0x00000000006876d6 in mysql_alter_table (thd=0x1b35b30, new_db=0x1b40f60 "test",
    new_name=0x1b40a00 "d", create_info=0x7fb98cad7f90, table_list=0x1b40a38,
    alter_info=0x7fb98cad8070, order_num=0, order=0x0, ignore=false)
    at mysql-5.5/sql/sql_table.cc:6359
#11 0x000000000089b0bf in Alter_table_statement::execute (this=0x1b40fc8, thd=0x1b35b30)
    at mysql-5.5/sql/sql_alter.cc:106
#12 0x00000000006076c8 in mysql_execute_command (thd=0x1b35b30)
    at mysql-5.5/sql/sql_parse.cc:4431
#13 0x000000000060a04f in mysql_parse (thd=0x1b35b30,
    rawbuf=0x1b40930 "ALTER TABLE d REBUILD PARTITION p0,p1,p2,p3", length=43,
    parser_state=0x7fb98cad9710) at mysql-5.5/sql/sql_parse.cc:5627
#14 0x00000000005fe771 in dispatch_command (command=COM_QUERY, thd=0x1b35b30,
    packet=0x1b38901 "ALTER TABLE d REBUILD PARTITION p0,p1,p2,p3", packet_length=43)
    at mysql-5.5/sql/sql_parse.cc:1037
#15 0x00000000005fdae0 in do_command (thd=0x1b35b30) at mysql-5.5/sql/sql_parse.cc:773
#16 0x00000000006d9c76 in do_handle_one_connection (thd_arg=0x1b35b30)
    at mysql-5.5/sql/sql_connect.cc:840
#17 0x00000000006d97a3 in handle_one_connection (arg=0x1b35b30)
    at mysql-5.5/sql/sql_connect.cc:759
#18 0x00007fb99bef0a4f in start_thread () from /lib64/libpthread.so.0
#19 0x00007fb99ac8582d in clone () from /lib64/libc.so.6

How to repeat:
# 1. RQG test
# run as runall.pl --threads=2 --duration=3600 --queries=100M --skip-gendata --grammar=1.yy --basedir=<basedir>
# It crashes for me reliably, but timing depends on the machine -- 
# from several seconds to 10 minutes.
# cat 1.yy

thread1_init:

        CREATE TABLE c ( `col_int_nokey` INTEGER, `col_int_key` INTEGER NOT NULL, KEY (`col_int_key`) ) ENGINE = MyISAM  PARTITION BY LIST ( `col_int_nokey` ) ( PARTITION p0 VALUES IN ( 8, NULL ), PARTITION p1 VALUES IN ( 5, 0, 6 ), PARTITION p2 VALUES IN ( 9, 7, 4 ), PARTITION p3 VALUES IN ( 3, 1, 2 ) )
;       CREATE TABLE d ( `col_int_nokey` INTEGER, `col_int_key` INTEGER NOT NULL, KEY (`col_int_key`) ) ENGINE = MyISAM  PARTITION BY LIST ( `col_int_nokey` ) ( PARTITION p0 VALUES IN ( 6, NULL ), PARTITION p1 VALUES IN ( 5, 9, 3 ), PARTITION p2 VALUES IN ( 1, 7, 8 ), PARTITION p3 VALUES IN ( 0, 4, 2 ) ) ;

query:
       ALTER TABLE table_name REBUILD PARTITION  p0,p1,p2,p3 ;

table_name:
          c | d;

# 2. MTR test case
# Again, depending on the machine, it might be slow, so better run it as 
# perl mysql-test-run.pl --testcase-timeout=60 <testname>

--source include/have_partition.inc

--delimiter |

CREATE PROCEDURE p ()
BEGIN
  DECLARE attempts INTEGER DEFAULT 1;
  wl_loop: WHILE attempts < 10000 DO
    ALTER TABLE t1 REBUILD PARTITION p0,p1,p2,p3;
    SET attempts = attempts + 1;
  END WHILE wl_loop;
END |

--delimiter ;

--disable_warnings
DROP TABLE IF EXISTS t1, t2;
--enable_warnings

CREATE TABLE t1 ( `col_int_nokey` INTEGER, `col_int_key` INTEGER NOT NULL, KEY (`col_int_key`) ) ENGINE = MyISAM PARTITION BY LIST ( `col_int_nokey` ) ( PARTITION p0 VALUES IN ( 8, NULL ), PARTITION p1 VALUES IN ( 5, 0, 6 ), PARTITION p2 VALUES IN ( 9, 7, 4 ), PARTITION p3 VALUES IN ( 3, 1, 2 ) );

 CREATE TABLE t2 ( `col_int_nokey` INTEGER, `col_int_key` INTEGER NOT NULL, KEY (`col_int_key`) ) ENGINE = MyISAM PARTITION BY LIST ( `col_int_nokey` ) ( PARTITION p0 VALUES IN ( 6, NULL ), PARTITION p1 VALUES IN ( 5, 9, 3 ), PARTITION p2 VALUES IN ( 1, 7, 8 ), PARTITION p3 VALUES IN ( 0, 4, 2 ) );

--connect (con1,localhost,root,,)
--send CALL p()

--connect (con2,localhost,root,,)
--let $run = 10000
while ($run)
{
  ALTER TABLE t2 REBUILD PARTITION p0,p1,p2,p3;
  --dec $run
}

--connection con1
--reap

# Cleanup
DROP TABLE t1, t2;

# End of test case

Thank you for the report.

Verified as described with MTR test case.

Backtrace in my case:

Thread 13 (Thread 0x7f219c291700 (LWP 31783)):
#0  0x0000003a4d00ec2d in fsync () from /lib64/libpthread.so.0
#1  0x0000000000751d97 in my_sync (fd=79, my_flags=0) at /home/sveta/src/mysql-5.5/mysys/my_sync.c:76
#2  0x00000000005b6dda in inline_mysql_file_sync () at /home/sveta/src/mysql-5.5/include/mysql/psi/mysql_file.h:1423
#3  sync_ddl_log () at /home/sveta/src/mysql-5.5/sql/sql_table.cc:1365
#4  0x00000000008b1ba2 in ha_partition::rename_partitions (this=0x7f218401dc80, path=0x7f219c28aa40 "./test/t1") at /home/sveta/src/mysql-5.5/sql/ha_partition.cc:868
#5  0x000000000072b073 in mysql_rename_partitions (thd=0x22f5210, table=<value optimized out>, alter_info=<value optimized out>, create_info=<value optimized out>, table_list=0x7f218400f828, db=<value optimized out>, table_name=0x7f2184009e70 "t1", fast_alter_table=0x7f218401c870) at /home/sveta/src/mysql-5.5/sql/sql_partition.cc:5625
#6  fast_alter_partition_table (thd=0x22f5210, table=<value optimized out>, alter_info=<value optimized out>, create_info=<value optimized out>, table_list=0x7f218400f828, db=<value optimized out>, table_name=0x7f2184009e70 "t1", fast_alter_table=0x7f218401c870) at /home/sveta/src/mysql-5.5/sql/sql_partition.cc:6881
#7  0x00000000005be856 in mysql_alter_table (thd=<value optimized out>, new_db=<value optimized out>, new_name=0x7f2184009e70 "t1", create_info=0x7f219c28cfd0, table_list=0x7f2100000001, alter_info=<value optimized out>, order_num=0, order=0x0, ignore=false) at /home/sveta/src/mysql-5.5/sql/sql_table.cc:6359
#8  0x00000000007398e3 in Alter_table_statement::execute (this=<value optimized out>, thd=0x22f5210) at /home/sveta/src/mysql-5.5/sql/sql_alter.cc:106
#9  0x0000000000566bbf in mysql_execute_command (thd=0x22f5210) at /home/sveta/src/mysql-5.5/sql/sql_parse.cc:4431
#10 0x0000000000705c5c in sp_instr_stmt::exec_core (this=0x7f218400fda0, thd=<value optimized out>, nextp=0x7f219c28e8b8) at /home/sveta/src/mysql-5.5/sql/sp_head.cc:3191
#11 0x0000000000705de3 in sp_lex_keeper::reset_lex_and_exec_core (this=0x7f218400fde0, thd=0x22f5210, nextp=0x7f219c28e8b8, open_tables=false, instr=0x7f218400fda0) at /home/sveta/src/mysql-5.5/sql/sp_head.cc:2988
#12 0x000000000070a985 in sp_instr_stmt::execute (this=0x7f218400fda0, thd=0x22f5210, nextp=0x7f219c28e8b8) at /home/sveta/src/mysql-5.5/sql/sp_head.cc:3123
#13 0x00000000007089eb in sp_head::execute (this=0x7f2184007f00, thd=0x22f5210, merge_da_on_success=true) at /home/sveta/src/mysql-5.5/sql/sp_head.cc:1433
#14 0x0000000000709f21 in sp_head::execute_procedure (this=0x7f2184007f00, thd=0x22f5210, args=0x22f76f0) at /home/sveta/src/mysql-5.5/sql/sp_head.cc:2189
#15 0x0000000000567071 in mysql_execute_command (thd=0x22f5210) at /home/sveta/src/mysql-5.5/sql/sql_parse.cc:4044
#16 0x0000000000569fe9 in mysql_parse (thd=0x22f5210, rawbuf=<value optimized out>, length=8, parser_state=0x7f219c290980) at /home/sveta/src/mysql-5.5/sql/sql_parse.cc:5627
#17 0x000000000056b943 in dispatch_command (command=COM_QUERY, thd=0x22f5210, packet=<value optimized out>, packet_length=<value optimized out>) at /home/sveta/src/mysql-5.5/sql/sql_parse.cc:1037
#18 0x00000000005f6736 in do_handle_one_connection (thd_arg=<value optimized out>) at /home/sveta/src/mysql-5.5/sql/sql_connect.cc:840
#19 0x00000000005f679a in handle_one_connection (arg=0x22f5210) at /home/sveta/src/mysql-5.5/sql/sql_connect.cc:759
#20 0x0000000000866e74 in pfs_spawn_thread (arg=0x22e2f20) at /home/sveta/src/mysql-5.5/storage/perfschema/pfs.cc:1015
#21 0x0000003a4d0077e1 in start_thread () from /lib64/libpthread.so.0
#22 0x00000031d74e68ed in clone () from /lib64/libc.so.6

Ups! There was wrong copy-paste. Ignore last comment: not verified yet.

Bug is not repeatable with current development sources, although is repeatable with launchpad tree.

Closing as "Can't repeat". Please upgrade when new version is available.

Internally we found issue is still repeatable, just does not show up. Setting back to "Verified". I am sorry for the confusion.

Thank you for your bug report. This issue has been committed to our source repository of that product and will be incorporated into the next release.

If necessary, you can access the source repository and build the latest available version, including the bug fix. More information about accessing the source trees is available at

    http://dev.mysql.com/doc/en/installing-source.html

Documented fix as follows in the 5.1.68 and 5.5.30 changelogs:

        Concurrent ALTER TABLE ... REBUILD PARTITION operations could
        interfere with one another, even when not running against the
        same table, because they both used global memory for storage.
        Now each partition rebuild operation stores intermediate data in
        memory that is local to that process.

Also noted the issue & fix in "ALTER TABLE Syntax" section of the 5.1/5.5 Manual.

Closed.