Bug #75833 InnoDB: Failing assertion: found in buf0buf.cc line 3856

• Submitted: 10 Feb 2015 6:45
• Modified: 16 Feb 2015 13:06
• Reporter: Roel Van de Paar
• Status: Closed
• Category: MySQL Server: DML
• Severity: S3 (Non-critical)
• Version: 5.7.5-m15, 5.7.6
• OS: Any
• CPU Architecture: Any

[10 Feb 2015 6:45] Roel Van de Paar

Description:
2015-02-10T06:38:26.899109Z 0 [Note] /sda/MS-mysql-5.7.5-m15-linux-x86_64-debug/bin/mysqld: ready for connections.
Version: '5.7.5-m15-debug'  socket: '/sda/MS-mysql-5.7.5-m15-linux-x86_64-debug/socket.sock'  port: 16633  MySQL Community Server (GPL)
2015-02-10 17:38:42 0x7fd5273ff700  InnoDB: Assertion failure in thread 140553463265024 in file buf0buf.cc line 3856
InnoDB: Failing assertion: found

(gdb) bt
#0  0x00007f9db5bb5771 in pthread_kill () from /lib64/libpthread.so.0
#1  0x0000000000e15cd8 in my_write_core (sig=6) at /bzr/testbuild/mysql-5.7.5-m15_dbg/mysys/stacktrace.c:247
#2  0x0000000000822044 in handle_fatal_signal (sig=6) at /bzr/testbuild/mysql-5.7.5-m15_dbg/sql/signal_handler.cc:219
#3  <signal handler called>
#4  0x00007f9db47b95c9 in raise () from /lib64/libc.so.6
#5  0x00007f9db47bacd8 in abort () from /lib64/libc.so.6
#6  0x00000000010d4a9b in ut_dbg_assertion_failed (expr=0x14ff777 "found", file=0x14fdbe0 "/bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/buf/buf0buf.cc",line=3856) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/ut/ut0dbg.cc:68
#7  0x0000000001134e9a in buf_page_get_gen (page_id=..., page_size=..., rw_latch=2, guess=0x0, mode=10, file=0x1483768 "/bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/handler/ha_innodb.cc", line=15082, mtr=0x7f9db609b550, dirty_with_no_latch=false) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/buf/buf0buf.cc:3856
#8  0x0000000000f2119d in innodb_make_page_dirty (thd=0x7f9cf801c000, var=0x1d5e280 <mysql_sysvar_fil_make_page_dirty_debug>, var_ptr=0x1e13020 <srv_fil_make_page_dirty_debug>, save=0x7f9cf8027ba8) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/innobase/handler/ha_innodb.cc:15080
#9  0x0000000000b6a6e7 in sys_var_pluginvar::global_update (this=0x7f9d95fa7d78, thd=0x7f9cf801c000, var=0x7f9cf8027b88) at /bzr/testbuild/mysql-5.7.5-m15_dbg/sql/sql_plugin.cc:3363
#10 0x0000000000a98593 in sys_var::update (this=0x7f9d95fa7d78, thd=0x7f9cf801c000, var=0x7f9cf8027b88) at /bzr/testbuild/mysql-5.7.5-m15_dbg/sql/set_var.cc:192
#11 0x0000000000a9978a in set_var::update (this=0x7f9cf8027b88, thd=0x7f9cf801c000) at /bzr/testbuild/mysql-5.7.5-m15_dbg/sql/set_var.cc:680
#12 0x0000000000a99354 in sql_set_variables (thd=0x7f9cf801c000, var_list=0x7f9cf801e6e0) at /bzr/testbuild/mysql-5.7.5-m15_dbg/sql/set_var.cc:583
#13 0x0000000000b4ae5e in mysql_execute_command (thd=0x7f9cf801c000) at /bzr/testbuild/mysql-5.7.5-m15_dbg/sql/sql_parse.cc:3672
#14 0x0000000000b4fcc1 in mysql_parse (thd=0x7f9cf801c000, parser_state=0x7f9db609ce60) at /bzr/testbuild/mysql-5.7.5-m15_dbg/sql/sql_parse.cc:5427
#15 0x0000000000b44814 in dispatch_command (command=COM_QUERY, thd=0x7f9cf801c000, packet=0x7f9cf8033011 "set global innodb_fil_make_page_dirty_debug=@space_id", packet_length=53) at /bzr/testbuild/mysql-5.7.5-m15_dbg/sql/sql_parse.cc:1250
#16 0x0000000000b4354d in do_command (thd=0x7f9cf801c000) at /bzr/testbuild/mysql-5.7.5-m15_dbg/sql/sql_parse.cc:834
#17 0x0000000000c4d4ce in handle_connection (arg=0x7f9d97bfff40) at /bzr/testbuild/mysql-5.7.5-m15_dbg/sql/conn_handler/connection_handler_per_thread.cc:298
#18 0x0000000000e394b8 in pfs_spawn_thread (arg=0x7f9d983f8b10) at /bzr/testbuild/mysql-5.7.5-m15_dbg/storage/perfschema/pfs.cc:2137
#19 0x00007f9db5bb0df3 in start_thread () from /lib64/libpthread.so.0
#20 0x00007f9db487a1ad in clone () from /lib64/libc.so.6

How to repeat:
DROP DATABASE test;CREATE DATABASE test;USE test;
create TABLE t0(id int key,fk int,index index_fk (fk)) engine=innodb;
select space from information_schema.innodb_sys_tables where name='test/t0' into @space_id;
DROP TABLE t0;
set global innodb_fil_make_page_dirty_debug=@space_id;

Suggested fix:
1) Fix non-descriptive assertion message
2) Why assert at all when table is already dropped (unless somehow that same page was still changed subsequently?) etc.

[10 Feb 2015 9:16] MySQL Verification Team

Hello Roel,

Thank you for the report and test case.
Observed that latest 5.7.6 debug build is affected( but I see diff stack traces).

Thanks,
Umesh

[10 Feb 2015 9:17] MySQL Verification Team

// Startup and build used for tests

bin/mysql_install_db --basedir=/export/umesh/mysql-5.7.6 --datadir=/export/umesh/mysql-5.7.6/75833 -v
bin/mysqld-debug --basedir=/export/umesh/mysql-5.7.6 --datadir=/export/umesh/mysql-5.7.6/75833 --core-file --socket=/tmp/mysql_ushastry.sock  --port=15000 --log-error=/export/umesh/mysql-5.7.6/75833/log.err 2>&1 &

commit: 0cca166312484b18946717d1c0cc02f7d939f3fb
date: 2015-02-09 14:17:56 +0530
build-date: 2015-02-09 10:14:44 +0100
short: 0cca166
branch: mysql-trunk

MySQL source 5.7.6

// Extract from error log

2015-02-10T09:08:26.878258Z 0 [Note] bin/mysqld-debug: ready for connections.
Version: '5.7.6-m16-enterprise-commercial-advanced-debug'  socket: '/tmp/mysql_ushastry.sock'  port: 15000  MySQL Enterprise Server - Advanced Edition Debug (Commercial)
2015-02-10 10:08:39 0x7fe8bcd11700  InnoDB: Assertion failure in thread 140637576959744 in file mtr0mtr.cc line 661
InnoDB: Failing assertion: m_impl.m_user_space

(gdb) bt
#0  0x00007fe8c84e7771 in pthread_kill () from /lib64/libpthread.so.0
#1  0x00000000013d2078 in my_write_core (sig=6) at /export/home/pb2/build/sb_0-14366248-1423476223.94/mysqlcom-pro-5.7.6-m16/mysys/stacktrace.c:247
#2  0x0000000000be5a8e in handle_fatal_signal (sig=6) at /export/home/pb2/build/sb_0-14366248-1423476223.94/mysqlcom-pro-5.7.6-m16/sql/signal_handler.cc:220
#3  <signal handler called>
#4  0x00007fe8c70ed5c9 in raise () from /lib64/libc.so.6
#5  0x00007fe8c70eecd8 in abort () from /lib64/libc.so.6
#6  0x00000000016f843f in ut_dbg_assertion_failed (expr=0x1d04f88 "m_impl.m_user_space",
    file=0x1d04a08 "/export/home/pb2/build/sb_0-14366248-1423476223.94/mysqlcom-pro-5.7.6-m16/storage/innobase/mtr/mtr0mtr.cc", line=661)
    at /export/home/pb2/build/sb_0-14366248-1423476223.94/mysqlcom-pro-5.7.6-m16/storage/innobase/ut/ut0dbg.cc:67
#7  0x00000000015aa791 in mtr_t::lookup_user_space (this=0x7fe8bcd0e440, space_id=24)
    at /export/home/pb2/build/sb_0-14366248-1423476223.94/mysqlcom-pro-5.7.6-m16/storage/innobase/mtr/mtr0mtr.cc:661
#8  0x000000000151d1ac in mtr_t::set_named_space (this=0x7fe8bcd0e440, space_id=24)
    at /export/home/pb2/build/sb_0-14366248-1423476223.94/mysqlcom-pro-5.7.6-m16/storage/innobase/include/mtr0mtr.h:330
#9  0x0000000001518ef4 in innodb_make_page_dirty (thd=0x7fe854000bb0, var=0x2705cc0 <mysql_sysvar_fil_make_page_dirty_debug>, var_ptr=0x27f0588 <srv_fil_make_page_dirty_debug>,
    save=0x7fe854005e00) at /export/home/pb2/build/sb_0-14366248-1423476223.94/mysqlcom-pro-5.7.6-m16/storage/innobase/handler/ha_innodb.cc:15712
#10 0x000000000110579c in sys_var_pluginvar::global_update (this=0x3daac40, thd=0x7fe854000bb0, var=0x7fe854005de0)
    at /export/home/pb2/build/sb_0-14366248-1423476223.94/mysqlcom-pro-5.7.6-m16/sql/sql_plugin.cc:3430
#11 0x0000000001020d9c in sys_var::update (this=0x3daac40, thd=0x7fe854000bb0, var=0x7fe854005de0)
    at /export/home/pb2/build/sb_0-14366248-1423476223.94/mysqlcom-pro-5.7.6-m16/sql/set_var.cc:182
#12 0x00000000010223ac in set_var::update (this=0x7fe854005de0, thd=0x7fe854000bb0) at /export/home/pb2/build/sb_0-14366248-1423476223.94/mysqlcom-pro-5.7.6-m16/sql/set_var.cc:780
#13 0x0000000001021d2d in sql_set_variables (thd=0x7fe854000bb0, var_list=0x7fe854002e58) at /export/home/pb2/build/sb_0-14366248-1423476223.94/mysqlcom-pro-5.7.6-m16/sql/set_var.cc:651
#14 0x00000000010d5e70 in mysql_execute_command (thd=0x7fe854000bb0) at /export/home/pb2/build/sb_0-14366248-1423476223.94/mysqlcom-pro-5.7.6-m16/sql/sql_parse.cc:3315
#15 0x00000000010daeb2 in mysql_parse (thd=0x7fe854000bb0, parser_state=0x7fe8bcd0fe40) at /export/home/pb2/build/sb_0-14366248-1423476223.94/mysqlcom-pro-5.7.6-m16/sql/sql_parse.cc:5129
#16 0x00000000010d0bbc in dispatch_command (command=COM_QUERY, thd=0x7fe854000bb0, packet=0x7fe854009ce1 "set global innodb_fil_make_page_dirty_debug=@space_id", packet_length=53)
    at /export/home/pb2/build/sb_0-14366248-1423476223.94/mysqlcom-pro-5.7.6-m16/sql/sql_parse.cc:1249
#17 0x00000000010cf8ee in do_command (thd=0x7fe854000bb0) at /export/home/pb2/build/sb_0-14366248-1423476223.94/mysqlcom-pro-5.7.6-m16/sql/sql_parse.cc:835
#18 0x00000000011f25b9 in handle_connection (arg=0x4a6a610) at /export/home/pb2/build/sb_0-14366248-1423476223.94/mysqlcom-pro-5.7.6-m16/sql/conn_handler/connection_handler_per_thread.cc:298
#19 0x000000000145ee25 in pfs_spawn_thread (arg=0x4a5d4b0) at /export/home/pb2/build/sb_0-14366248-1423476223.94/mysqlcom-pro-5.7.6-m16/storage/perfschema/pfs.cc:2147
#20 0x00007fe8c84e2df3 in start_thread () from /lib64/libpthread.so.0
#21 0x00007fe8c71ae47d in clone () from /lib64/libc.so.6

[16 Feb 2015 13:06] Daniel Price

Posted by developer:
 
Fixed as of the upcoming 5.7.7, 5.8.0 release, and here's the changelog entry:

A debug variable used to modify the first page of a tablespace raised an
assertion when set to a nonexistent tablespace ID.