MySQL Bugs: #74729: assertion:mode == BUF_GET_POSSIBLY_FREED || !fix_block->page.file_page_was

Bug #74729	assertion:mode == BUF_GET_POSSIBLY_FREED \|\| !fix_block->page.file_page_was_freed
Submitted:	7 Nov 2014 10:19	Modified:	7 Nov 2014 10:42
Reporter:	Ramesh Sivaraman	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: Options	Severity:	S3 (Non-critical)
Version:	5.6.20-debug, 5.6.22, 5.7.6	OS:	Linux (CentOS 7)
Assigned to:		CPU Architecture:	Any

Description:
2014-11-07 10:00:31 7fe001f49700  InnoDB: Assertion failure in thread 140600082208512 in file buf0buf.cc line 2969
InnoDB: Failing assertion: mode == BUF_GET_POSSIBLY_FREED || !fix_block->page.file_page_was_freed

**** GDB info

#0  0x00007fe001742644 in __io_getevents_0_4 () from /lib64/libaio.so.1
#1  0x0000000000bcbb01 in os_aio_linux_collect (array=0x7fdfffc3c100, segment=3, seg_size=256) at /ssd/ramesh/mysql-server/mysql-5.6/storage/innobase/os/os0file.cc:4934
#2  0x0000000000bcbede in os_aio_linux_handle (global_seg=5, message1=0x7fdf683f9e90, message2=0x7fdf683f9e88, type=0x7fdf683f9e80) at /ssd/ramesh/mysql-server/mysql-5.6/storage/innobase/os/os0file.cc:5078
#3  0x0000000000d884e6 in fil_aio_wait (segment=5) at /ssd/ramesh/mysql-server/mysql-5.6/storage/innobase/fil/fil0fil.cc:5739
#4  0x0000000000c94246 in io_handler_thread (arg=0x1821ee8 <n+40>) at /ssd/ramesh/mysql-server/mysql-5.6/storage/innobase/srv/srv0start.cc:485
#5  0x00007fe00194bdf3 in start_thread () from /lib64/libpthread.so.0
#6  0x00007fe00081d01d in clone () from /lib64/libc.so.6

Thread 1 (Thread 0x7fe001f49700 (LWP 6618)):
+bt
#0  0x00007fe001950771 in pthread_kill () from /lib64/libpthread.so.0
#1  0x0000000000a9035e in my_write_core (sig=6) at /ssd/ramesh/mysql-server/mysql-5.6/mysys/stacktrace.c:422
#2  0x0000000000723688 in handle_fatal_signal (sig=6) at /ssd/ramesh/mysql-server/mysql-5.6/sql/signal_handler.cc:230
#3  <signal handler called>
#4  0x00007fe00075c5c9 in raise () from /lib64/libc.so.6
#5  0x00007fe00075dcd8 in abort () from /lib64/libc.so.6
#6  0x0000000000d1b0e6 in buf_page_get_gen (space=8, zip_size=0, offset=10, rw_latch=2, guess=0x0, mode=10, file=0xfed2f0 "/ssd/ramesh/mysql-server/mysql-5.6/storage/innobase/handler/ha_innodb.cc", line=14432, mtr=0x7fe001f46720) at /ssd/ramesh/mysql-server/mysql-5.6/storage/innobase/buf/buf0buf.cc:2968
#7  0x0000000000b5d383 in innodb_make_page_dirty (thd=0x7fdf6e724000, var=0x1517720 <mysql_sysvar_fil_make_page_dirty_debug>, var_ptr=0x18151a0 <srv_fil_make_page_dirty_debug>, save=0x7fdf6481f248) at /ssd/ramesh/mysql-server/mysql-5.6/storage/innobase/handler/ha_innodb.cc:14431
#8  0x00000000007e6788 in sys_var_pluginvar::global_update (this=0x7fdffb36f668, thd=0x7fdf6e724000, var=0x7fdf6481f228) at /ssd/ramesh/mysql-server/mysql-5.6/sql/sql_plugin.cc:3271
#9  0x00000000007211af in sys_var::update (this=0x7fdffb36f668, thd=0x7fdf6e724000, var=0x7fdf6481f228) at /ssd/ramesh/mysql-server/mysql-5.6/sql/set_var.cc:193
#10 0x00000000007222b8 in set_var::update (this=0x7fdf6481f228, thd=0x7fdf6e724000) at /ssd/ramesh/mysql-server/mysql-5.6/sql/set_var.cc:670
#11 0x0000000000721e86 in sql_set_variables (thd=0x7fdf6e724000, var_list=0x7fdf6e726e10) at /ssd/ramesh/mysql-server/mysql-5.6/sql/set_var.cc:573
#12 0x00000000007d2449 in mysql_execute_command (thd=0x7fdf6e724000) at /ssd/ramesh/mysql-server/mysql-5.6/sql/sql_parse.cc:3713
#13 0x00000000007d8fa4 in mysql_parse (thd=0x7fdf6e724000, rawbuf=0x7fdf6481f010 "set global innodb_fil_make_page_dirty_debug=@space_id", length=53, parser_state=0x7fe001f47e70) at /ssd/ramesh/mysql-server/mysql-5.6/sql/sql_parse.cc:6245
#14 0x00000000007cc557 in dispatch_command (command=COM_QUERY, thd=0x7fdf6e724000, packet=0x7fdf6e762001 "set global innodb_fil_make_page_dirty_debug=@space_id", packet_length=53) at /ssd/ramesh/mysql-server/mysql-5.6/sql/sql_parse.cc:1332
#15 0x00000000007cb646 in do_command (thd=0x7fdf6e724000) at /ssd/ramesh/mysql-server/mysql-5.6/sql/sql_parse.cc:1034
#16 0x0000000000793a61 in do_handle_one_connection (thd_arg=0x7fdf6e724000) at /ssd/ramesh/mysql-server/mysql-5.6/sql/sql_connect.cc:982
#17 0x000000000079354a in handle_one_connection (arg=0x7fdf6e724000) at /ssd/ramesh/mysql-server/mysql-5.6/sql/sql_connect.cc:898
#18 0x0000000000ad4b5c in pfs_spawn_thread (arg=0x7fdffdffeb00) at /ssd/ramesh/mysql-server/mysql-5.6/storage/perfschema/pfs.cc:1860
#19 0x00007fe00194bdf3 in start_thread () from /lib64/libpthread.so.0
#20 0x00007fe00081d01d in clone () from /lib64/libc.so.6

How to repeat:
DROP DATABASE test;CREATE DATABASE test;USE test;
set global innodb_limit_optimistic_insert_debug=2;
set global innodb_saved_page_number_debug=10;
CREATE TABLE t1(a TIME,b TIME(1),c INT,d CHAR (1),e INT);
ALTER TABLE t1 ADD KEY(d(1));
insert into t1(a)values (1),(1) on duplicate key update b=3,c=c;
INSERT INTO t1(a)VALUES (0),(0),(0);
select space from information_schema.innodb_sys_tables where name='test/t1' into @space_id;
set global innodb_limit_optimistic_insert_debug=0;
INSERT INTO t1(a,b)VALUES (1,1),(1,2),(1,3),(1,4),(1,5),(2,2),(2,3),(2,1),(3,1),(4,1),(4,2),(4,3),(4,4),(4,5),(4,6);
UPDATE t1 SET b=0;
set global innodb_fil_make_page_dirty_debug=@space_id;

When I removed first line from testcase got different assertion : http://bugs.mysql.com/bug.php?id=74730

Hello Ramesh Sivaraman,

Thank you for the bug report and test case.
Confirmed that only debug builds are affected - 5.6.22.

Thanks,
Umesh

// 5.6.22

(gdb) bt
#0  0x0000003deb00c8ac in pthread_kill () from /lib64/libpthread.so.0
#1  0x0000000000b0011b in my_write_core (sig=6) at /pb2/build/sb_0-13562263-1414689457.82/mysqlcom-pro-5.6.22/mysys/stacktrace.c:422
#2  0x000000000077ecb8 in handle_fatal_signal (sig=6) at /pb2/build/sb_0-13562263-1414689457.82/mysqlcom-pro-5.6.22/sql/signal_handler.cc:230
#3  <signal handler called>
#4  0x0000003deac32625 in raise () from /lib64/libc.so.6
#5  0x0000003deac33e05 in abort () from /lib64/libc.so.6
#6  0x0000000000d676f2 in buf_page_get_gen (space=6, zip_size=0, offset=10, rw_latch=2, guess=0x0, mode=10,
    file=0x110ad30 "/pb2/build/sb_0-13562263-1414689457.82/mysqlcom-pro-5.6.22/storage/innobase/handler/ha_innodb.cc", line=14480, mtr=0x7fa7c4dcfa10)
    at /pb2/build/sb_0-13562263-1414689457.82/mysqlcom-pro-5.6.22/storage/innobase/buf/buf0buf.cc:2973
#7  0x0000000000ba766c in innodb_make_page_dirty (thd=0x3b3ac90, var=0x1696840, var_ptr=0x19a4100, save=0x7fa79c005208)
    at /pb2/build/sb_0-13562263-1414689457.82/mysqlcom-pro-5.6.22/storage/innobase/handler/ha_innodb.cc:14479
#8  0x0000000000845a63 in sys_var_pluginvar::global_update (this=0x3483ef8, thd=0x3b3ac90, var=0x7fa79c0051e8)
    at /pb2/build/sb_0-13562263-1414689457.82/mysqlcom-pro-5.6.22/sql/sql_plugin.cc:3271
#9  0x000000000077c782 in sys_var::update (this=0x3483ef8, thd=0x3b3ac90, var=0x7fa79c0051e8) at /pb2/build/sb_0-13562263-1414689457.82/mysqlcom-pro-5.6.22/sql/set_var.cc:194
#10 0x000000000077d8bc in set_var::update (this=0x7fa79c0051e8, thd=0x3b3ac90) at /pb2/build/sb_0-13562263-1414689457.82/mysqlcom-pro-5.6.22/sql/set_var.cc:670
#11 0x000000000077d48e in sql_set_variables (thd=0x3b3ac90, var_list=0x3b3daa0) at /pb2/build/sb_0-13562263-1414689457.82/mysqlcom-pro-5.6.22/sql/set_var.cc:573
#12 0x0000000000830ec8 in mysql_execute_command (thd=0x3b3ac90) at /pb2/build/sb_0-13562263-1414689457.82/mysqlcom-pro-5.6.22/sql/sql_parse.cc:3713
#13 0x00000000008380e1 in mysql_parse (thd=0x3b3ac90, rawbuf=0x7fa79c004fd0 "set global innodb_fil_make_page_dirty_debug=@space_id", length=53, parser_state=0x7fa7c4dd1680)
    at /pb2/build/sb_0-13562263-1414689457.82/mysqlcom-pro-5.6.22/sql/sql_parse.cc:6357
#14 0x000000000082aa63 in dispatch_command (command=COM_QUERY, thd=0x3b3ac90, packet=0x3c6a5b1 "set global innodb_fil_make_page_dirty_debug=@space_id", packet_length=53)
    at /pb2/build/sb_0-13562263-1414689457.82/mysqlcom-pro-5.6.22/sql/sql_parse.cc:1332
#15 0x0000000000829ac8 in do_command (thd=0x3b3ac90) at /pb2/build/sb_0-13562263-1414689457.82/mysqlcom-pro-5.6.22/sql/sql_parse.cc:1034
#16 0x00000000007f0f17 in do_handle_one_connection (thd_arg=0x3b3ac90) at /pb2/build/sb_0-13562263-1414689457.82/mysqlcom-pro-5.6.22/sql/sql_connect.cc:982
#17 0x00000000007f09e8 in handle_one_connection (arg=0x3b3ac90) at /pb2/build/sb_0-13562263-1414689457.82/mysqlcom-pro-5.6.22/sql/sql_connect.cc:898
#18 0x0000000000e64c25 in pfs_spawn_thread (arg=0x3c2dce0) at /pb2/build/sb_0-13562263-1414689457.82/mysqlcom-pro-5.6.22/storage/perfschema/pfs.cc:1860
#19 0x0000003deb0079d1 in start_thread () from /lib64/libpthread.so.0
#20 0x0000003deace89dd in clone () from /lib64/libc.so.6
(gdb)

// 5.7.6 debug builds only

(gdb) bt
#0  0x0000003deb00c8ac in pthread_kill () from /lib64/libpthread.so.0
#1  0x0000000000f990a1 in my_write_core (sig=6) at /pb2/build/sb_0-13559856-1414670154.69/mysqlcom-pro-5.7.6-m16/mysys/stacktrace.c:247
#2  0x000000000092d7cc in handle_fatal_signal (sig=6) at /pb2/build/sb_0-13559856-1414670154.69/mysqlcom-pro-5.7.6-m16/sql/signal_handler.cc:219
#3  <signal handler called>
#4  0x0000003deac32625 in raise () from /lib64/libc.so.6
#5  0x0000003deac33e05 in abort () from /lib64/libc.so.6
#6  0x000000000121b81b in ut_dbg_assertion_failed (expr=0x1765c58 "mode == BUF_GET_POSSIBLY_FREED || !fix_block->page.file_page_was_freed",
    file=0x1763df0 "/pb2/build/sb_0-13559856-1414670154.69/mysqlcom-pro-5.7.6-m16/storage/innobase/buf/buf0buf.cc", line=4316)
    at /pb2/build/sb_0-13559856-1414670154.69/mysqlcom-pro-5.7.6-m16/storage/innobase/ut/ut0dbg.cc:67
#7  0x000000000127e208 in buf_page_get_gen (page_id=..., page_size=..., rw_latch=2, guess=0x0, mode=10,
    file=0x16e19c0 "/pb2/build/sb_0-13559856-1414670154.69/mysqlcom-pro-5.7.6-m16/storage/innobase/handler/ha_innodb.cc", line=14952, mtr=0x7f95766c2670, dirty_with_no_latch=false)
    at /pb2/build/sb_0-13559856-1414670154.69/mysqlcom-pro-5.7.6-m16/storage/innobase/buf/buf0buf.cc:4315
#8  0x000000000104d5d0 in innodb_make_page_dirty (thd=0x7f9538000cf0, var=0x2049de0, var_ptr=0x2109b20, save=0x7f9538005fe0)
    at /pb2/build/sb_0-13559856-1414670154.69/mysqlcom-pro-5.7.6-m16/storage/innobase/handler/ha_innodb.cc:14950
#9  0x0000000000cd7a16 in sys_var_pluginvar::global_update (this=0x2fff440, thd=0x7f9538000cf0, var=0x7f9538005fc0)
    at /pb2/build/sb_0-13559856-1414670154.69/mysqlcom-pro-5.7.6-m16/sql/sql_plugin.cc:3362
#10 0x0000000000c020c8 in sys_var::update (this=0x2fff440, thd=0x7f9538000cf0, var=0x7f9538005fc0) at /pb2/build/sb_0-13559856-1414670154.69/mysqlcom-pro-5.7.6-m16/sql/set_var.cc:192
#11 0x0000000000c03306 in set_var::update (this=0x7f9538005fc0, thd=0x7f9538000cf0) at /pb2/build/sb_0-13559856-1414670154.69/mysqlcom-pro-5.7.6-m16/sql/set_var.cc:679
#12 0x0000000000c02ed6 in sql_set_variables (thd=0x7f9538000cf0, var_list=0x7f95380033d0) at /pb2/build/sb_0-13559856-1414670154.69/mysqlcom-pro-5.7.6-m16/sql/set_var.cc:582
#13 0x0000000000cb7d95 in mysql_execute_command (thd=0x7f9538000cf0) at /pb2/build/sb_0-13559856-1414670154.69/mysqlcom-pro-5.7.6-m16/sql/sql_parse.cc:3643
#14 0x0000000000cbce6a in mysql_parse (thd=0x7f9538000cf0, parser_state=0x7f95766c4660) at /pb2/build/sb_0-13559856-1414670154.69/mysqlcom-pro-5.7.6-m16/sql/sql_parse.cc:5397
#15 0x0000000000cb0f2c in dispatch_command (command=COM_QUERY, thd=0x7f9538000cf0, packet=0x7f9538009a21 "set global innodb_fil_make_page_dirty_debug=@space_id", packet_length=53)
    at /pb2/build/sb_0-13559856-1414670154.69/mysqlcom-pro-5.7.6-m16/sql/sql_parse.cc:1249
#16 0x0000000000cafbd4 in do_command (thd=0x7f9538000cf0) at /pb2/build/sb_0-13559856-1414670154.69/mysqlcom-pro-5.7.6-m16/sql/sql_parse.cc:833
#17 0x0000000000dbe89c in handle_connection (arg=0x3b7b370) at /pb2/build/sb_0-13559856-1414670154.69/mysqlcom-pro-5.7.6-m16/sql/conn_handler/connection_handler_per_thread.cc:298
#18 0x000000000138347f in pfs_spawn_thread (arg=0x3c1a040) at /pb2/build/sb_0-13559856-1414670154.69/mysqlcom-pro-5.7.6-m16/storage/perfschema/pfs.cc:2137
#19 0x0000003deb0079d1 in start_thread () from /lib64/libpthread.so.0
#20 0x0000003deace89dd in clone () from /lib64/libc.so.6