| Bug #74481 | buf_page_get_gen() assert; innodb_fil_make_page_dirty_debug=[missing tablespace] | ||
|---|---|---|---|
| Submitted: | 21 Oct 2014 12:28 | Modified: | 4 Dec 2015 11:32 |
| Reporter: | Ramesh Sivaraman | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Server: InnoDB storage engine | Severity: | S3 (Non-critical) |
| Version: | 5.6.20-debug, 5.6.22 | OS: | Linux (CentOS 7) |
| Assigned to: | CPU Architecture: | Any | |
| Tags: | Debug only | ||
[21 Oct 2014 12:28]
Ramesh Sivaraman
[21 Oct 2014 13:21]
MySQL Verification Team
Hello Ramesh Sivaraman, Thank you for the bug report and test case. Verified as described with 5.6.22 debug build. Thanks, Umesh
[21 Oct 2014 13:21]
MySQL Verification Team
// Debug build affected
mysql> show variables like '%version%';
+-------------------------+---------------------------------------------------------------+
| Variable_name | Value |
+-------------------------+---------------------------------------------------------------+
| innodb_version | 5.6.22 |
| protocol_version | 10 |
| slave_type_conversions | |
| version | 5.6.22-enterprise-commercial-advanced-debug |
| version_comment | MySQL Enterprise Server - Advanced Edition Debug (Commercial) |
| version_compile_machine | x86_64 |
| version_compile_os | Linux |
+-------------------------+---------------------------------------------------------------+
7 rows in set (0.00 sec)
mysql> create table t1(d1 decimal unsigned,d2 decimal unsigned,d3 decimal unsigned);
Query OK, 0 rows affected (0.03 sec)
mysql> select space from information_schema.innodb_sys_tables where name='test/t1' into @space_id;
Query OK, 1 row affected (0.00 sec)
mysql> ALTER TABLE t1 engine=InnoDB;
Query OK, 0 rows affected (0.07 sec)
Records: 0 Duplicates: 0 Warnings: 0
mysql> set global innodb_fil_make_page_dirty_debug=@space_id;
ERROR 2013 (HY000): Lost connection to MySQL server during query
//
2014-10-23 09:49:49 7fb0bb2cc700 InnoDB: Assertion failure in thread 140397031245568 in file buf0buf.cc line 2536
InnoDB: Failing assertion: zip_size == fil_space_get_zip_size(space)
//
(gdb) bt
#0 0x0000003bf260c8ac in pthread_kill () from /lib64/libpthread.so.0
#1 0x0000000000afe982 in my_write_core (sig=6) at /export/home/pb2/build/sb_0-13146752-1409933888.09/mysqlcom-pro-5.6.22/mysys/stacktrace.c:422
#2 0x000000000077e6cc in handle_fatal_signal (sig=6) at /export/home/pb2/build/sb_0-13146752-1409933888.09/mysqlcom-pro-5.6.22/sql/signal_handler.cc:230
#3 <signal handler called>
#4 0x0000003bf2232635 in raise () from /lib64/libc.so.6
#5 0x0000003bf2233e15 in abort () from /lib64/libc.so.6
#6 0x0000000000d67117 in buf_page_get_gen (space=8, zip_size=0, offset=0, rw_latch=2, guess=0x0, mode=10,
file=0x1106cb0 "/export/home/pb2/build/sb_0-13146752-1409933888.09/mysqlcom-pro-5.6.22/storage/innobase/handler/ha_innodb.cc", line=14425, mtr=0x7fb0bb2c9a10)
at /export/home/pb2/build/sb_0-13146752-1409933888.09/mysqlcom-pro-5.6.22/storage/innobase/buf/buf0buf.cc:2536
#7 0x0000000000ba8438 in innodb_make_page_dirty (thd=0x9516af0, var=0x1693860, var_ptr=0x19a0fc0, save=0x7fb0a0005208)
at /export/home/pb2/build/sb_0-13146752-1409933888.09/mysqlcom-pro-5.6.22/storage/innobase/handler/ha_innodb.cc:14424
#8 0x0000000000844ee3 in sys_var_pluginvar::global_update (this=0x397a760, thd=0x9516af0, var=0x7fb0a00051e8)
at /export/home/pb2/build/sb_0-13146752-1409933888.09/mysqlcom-pro-5.6.22/sql/sql_plugin.cc:3271
#9 0x000000000077c196 in sys_var::update (this=0x397a760, thd=0x9516af0, var=0x7fb0a00051e8) at /export/home/pb2/build/sb_0-13146752-1409933888.09/mysqlcom-pro-5.6.22/sql/set_var.cc:194
#10 0x000000000077d2d0 in set_var::update (this=0x7fb0a00051e8, thd=0x9516af0) at /export/home/pb2/build/sb_0-13146752-1409933888.09/mysqlcom-pro-5.6.22/sql/set_var.cc:670
#11 0x000000000077cea2 in sql_set_variables (thd=0x9516af0, var_list=0x9519900) at /export/home/pb2/build/sb_0-13146752-1409933888.09/mysqlcom-pro-5.6.22/sql/set_var.cc:573
#12 0x0000000000830807 in mysql_execute_command (thd=0x9516af0) at /export/home/pb2/build/sb_0-13146752-1409933888.09/mysqlcom-pro-5.6.22/sql/sql_parse.cc:3713
#13 0x00000000008375d1 in mysql_parse (thd=0x9516af0, rawbuf=0x7fb0a0004fd0 "set global innodb_fil_make_page_dirty_debug=@space_id", length=53, parser_state=0x7fb0bb2cb680)
at /export/home/pb2/build/sb_0-13146752-1409933888.09/mysqlcom-pro-5.6.22/sql/sql_parse.cc:6245
#14 0x000000000082a3a2 in dispatch_command (command=COM_QUERY, thd=0x9516af0, packet=0x96454c1 "set global innodb_fil_make_page_dirty_debug=@space_id", packet_length=53)
at /export/home/pb2/build/sb_0-13146752-1409933888.09/mysqlcom-pro-5.6.22/sql/sql_parse.cc:1332
#15 0x0000000000829407 in do_command (thd=0x9516af0) at /export/home/pb2/build/sb_0-13146752-1409933888.09/mysqlcom-pro-5.6.22/sql/sql_parse.cc:1034
#16 0x00000000007f0887 in do_handle_one_connection (thd_arg=0x9516af0) at /export/home/pb2/build/sb_0-13146752-1409933888.09/mysqlcom-pro-5.6.22/sql/sql_connect.cc:982
#17 0x00000000007f0358 in handle_one_connection (arg=0x9516af0) at /export/home/pb2/build/sb_0-13146752-1409933888.09/mysqlcom-pro-5.6.22/sql/sql_connect.cc:898
#18 0x0000000000e5c19d in pfs_spawn_thread (arg=0x9608eb0) at /export/home/pb2/build/sb_0-13146752-1409933888.09/mysqlcom-pro-5.6.22/storage/perfschema/pfs.cc:1860
#19 0x0000003bf26079d1 in start_thread () from /lib64/libpthread.so.0
#20 0x0000003bf22e886d in clone () from /lib64/libc.so.6
[24 Oct 2014 8:17]
Roel Van de Paar
DROP DATABASE test;CREATE DATABASE test;USE test; FLUSH LOCAL TABLES;DROP TABLE t0;CREATE TABLE t0(id INT KEY);t0TABLES;USE mysql; select space from information_schema.innodb_sys_tables where name='test/t0' into @space_id; USE test; FLUSH LOCAL TABLES;DROP TABLE t0;CREATE TABLE t0(id INT KEY);t0TABLES;USE mysql; set global innodb_fil_make_page_dirty_debug=@space_id;
[10 Nov 2014 11:17]
Marko Mäkelä
Posted by developer: The cause of this assertion failure is that the tablespace referred to by innodb_fil_make_page_dirty_debug is not found. In the "How to repeat", the statement ALTER TABLE t1 ENGINE=InnoDB; is rebuilding the tablespace, assigning a new tablespace ID. So, the old space_id=6 will not be found. I would say that this is misuse of the debug-only variable. It is similar to complaining that the server crashes if you SET DEBUG='+d,crash_commit_before' and run some SQL. Sometimes, we can add consistency checks to protect against misuse of debug-only variables. I recently fixed this one in MySQL 5.5 and later: Bug#19904003 INNODB_LIMIT_OPTIMISTIC_INSERT_DEBUG=1 CAUSES INFINITE PAGE SPLIT In this case, I do not think that it is feasible to prevent misuse. We would have to implement some meta-data-locking (MDL) to protect us from concurrent DROP TABLE or ALTER TABLE while the update callback of innodb_fil_make_page_dirty_debug is executing. It is simply not worth the effort before buf_page_get_gen() has been refactored in a way that allows it to return an error to the caller.
[10 Nov 2014 23:11]
Roel Van de Paar
Marko, understood and agreed. We have a decision to make here; do we leave semi-random innodb_fil_make_page_dirty_debug calls in our testing SQL, or do we remove them altogether. Leaving them may show more bugs, but has the disadvantage of bugs like these (though it seems at least a number of them could be improved over time by debug variable checking), or do we remove them, potentially missing bugs. What is your opinion?
[25 Jan 2015 20:55]
Roel Van de Paar
Another example in 5.7? DROP DATABASE test;CREATE DATABASE test;USE test; set global innodb_saved_page_number_debug=100; set global innodb_fil_make_page_dirty_debug=0;
[12 Feb 2015 9:19]
Roel Van de Paar
Comment above crashes in file ut0ut.cc line 981 2015-02-12 20:16:47 0x7f829ba60700 InnoDB: Assertion failure in thread 140198933825280 in file ut0ut.cc line 981
[12 Feb 2015 9:22]
Roel Van de Paar
Another 5.7.5-m15 one DROP DATABASE test;CREATE DATABASE test;USE test; CREATE TABLE t1(c1 INT); select space from information_schema.innodb_sys_tables where name='test/t1' into @space_id; set global innodb_saved_page_number_debug=100; set global innodb_fil_make_page_dirty_debug=@space_id; Crashes in another place; 2015-02-12T09:19:33.524663Z 1 [Note] InnoDB: Saving InnoDB page number: 100 2015-02-12T09:19:34.499694Z 1 [ERROR] InnoDB: Trying to access page number 94 in space 20, space name test/t1, which is outside the tablespace bounds. Byte offset 0, len 16384, i/o type 10. If you get this error at mysqld startup, please check that your my.cnf matches the ibdata files that you have in the MySQL server. 2015-02-12 20:19:34 0x7f020794b700 InnoDB: Assertion failure in thread 139646693848832 in file fil0fil.cc line 5133 Maybe this should be revisited...
[4 Dec 2015 6:47]
Marko Mäkelä
A duplicate of the original bug was filed as Bug#75833 InnoDB: Failing assertion: found in buf0buf.cc line 3856 and that was fixed in MySQL 5.7.7. There is another bug that InnoDB is not validating the page number (innodb_saved_page_number_debug). We will file a follow-up bug for that.
[4 Dec 2015 6:50]
Marko Mäkelä
Posted by developer: This was fixed in the duplicate bug report: Bug#20511314 INNODB: FAILING ASSERTION: FOUND IN BUF0BUF.CC LINE 3856
[4 Dec 2015 7:00]
Naga Satyanarayana Bodapati
Created new Bug#79516 - Server crashes on invalid value for variable innodb_saved_page_number_debug
[4 Dec 2015 7:48]
Roel Van de Paar
Thanks guys, very appreciated
[4 Dec 2015 13:00]
Daniel Price
Posted by developer: This bug is documented under the duplicate bug (Bug #20511314 / MySQL Bug #75833) in MySQL 5.7.7 and 5.8.0.
[13 Aug 2017 23:29]
Roel Van de Paar
A testcase posted earlier in this bug still crashes 5.7.17: DROP DATABASE test;CREATE DATABASE test;USE test; set global innodb_saved_page_number_debug=100; set global innodb_fil_make_page_dirty_debug=0; Version: '5.7.17-debug-log' socket: '/sda/MS010217-mysql-5.7.17-linux-x86_64-debug/socket.sock' port: 18388 MySQL Community Server (GPL) 2017-08-13T23:01:41.236107Z 3 [Note] InnoDB: Saving InnoDB page number: 100 2017-08-13T23:01:41.934494Z 3 [ERROR] InnoDB: Trying to read doublewrite buffer page [page id: space=0, page number=100] ...repeats 2017-08-13T23:01:41.936076Z 3 [ERROR] InnoDB: Trying to read doublewrite buffer page [page id: space=0, page number=100] 2017-08-13T23:01:41.936091Z 3 [ERROR] InnoDB: Trying to read doublewrite buffer page [page id: space=0, page number=100] 2017-08-13T23:01:41.936111Z 3 [ERROR] InnoDB: Trying to read doublewrite buffer page [page id: space=0, page number=100] 2017-08-13T23:01:41.936127Z 3 [ERROR] InnoDB: Trying to read doublewrite buffer page [page id: space=0, page number=100] 2017-08-13T23:01:41.936141Z 3 [ERROR] [FATAL] InnoDB: Unable to read page [page id: space=0, page number=100] into the buffer pool after 100 attempts. The most probable cause of this error may be that the table has been corrupted. Or, the table was compressed with with an algorithm that is not supported by this instance. If it is not a decompress failure, you can try to fix this problem by using innodb_force_recovery. Please see http://dev.mysql.com/doc/refman/5.7/en/ for more details. Aborting... 2017-08-14 09:01:41 0x7f968951a700 InnoDB: Assertion failure in thread 140284525651712 in file ut0ut.cc line 916 InnoDB: We intentionally generate a memory trap.
[13 Aug 2017 23:30]
Roel Van de Paar
Core was generated by `/sda/MS010217-mysql-5.7.17-linux-x86_64-debug/bin/mysqld --no-defaults --log-bi'.
Program terminated with signal 6, Aborted.
#0 0x00007f9688f28741 in __pthread_kill (threadid=<optimized out>, signo=6) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:61
61 val = INTERNAL_SYSCALL (tgkill, err, 3, THREAD_GETMEM (THREAD_SELF, pid),
(gdb) bt
#0 0x00007f9688f28741 in __pthread_kill (threadid=<optimized out>, signo=6) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:61
#1 0x0000000001826d71 in my_write_core (sig=6) at /git/mysql-server_dbg/mysys/stacktrace.c:249
#2 0x0000000000e75574 in handle_fatal_signal (sig=6) at /git/mysql-server_dbg/sql/signal_handler.cc:220
#3 <signal handler called>
#4 0x00007f96872bc1d7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#5 0x00007f96872bd8c8 in __GI_abort () at abort.c:90
#6 0x0000000001b8d79a in ut_dbg_assertion_failed (expr=0x0, file=0x2119888 "/git/mysql-server_dbg/storage/innobase/ut/ut0ut.cc", line=916) at /git/mysql-server_dbg/storage/innobase/ut/ut0dbg.cc:67
#7 0x0000000001b920b0 in ib::fatal::~fatal (this=0x7f96895176a0, __in_chrg=<optimized out>) at /git/mysql-server_dbg/storage/innobase/ut/ut0ut.cc:916
#8 0x0000000001bf071a in buf_page_get_gen (page_id=..., page_size=..., rw_latch=2, guess=0x0, mode=10, file=0x20a1a80 "/git/mysql-server_dbg/storage/innobase/handler/ha_innodb.cc", line=17822, mtr=0x7f9689517b90, dirty_with_no_latch=false)
at /git/mysql-server_dbg/storage/innobase/buf/buf0buf.cc:4207
#9 0x0000000001972623 in innodb_make_page_dirty (thd=0x7f964b819000, var=0x2aabb20 <mysql_sysvar_fil_make_page_dirty_debug>, var_ptr=0x2bae978 <srv_fil_make_page_dirty_debug>, save=0x7f964b82bbb8) at /git/mysql-server_dbg/storage/innobase/handler/ha_innodb.cc:17820
#10 0x0000000001526fe5 in sys_var_pluginvar::global_update (this=0x7f967b7e88d8, thd=0x7f964b819000, var=0x7f964b82bb98) at /git/mysql-server_dbg/sql/sql_plugin.cc:3510
#11 0x000000000142f766 in sys_var::update (this=0x7f967b7e88d8, thd=0x7f964b819000, var=0x7f964b82bb98) at /git/mysql-server_dbg/sql/set_var.cc:183
#12 0x0000000001430de0 in set_var::update (this=0x7f964b82bb98, thd=0x7f964b819000) at /git/mysql-server_dbg/sql/set_var.cc:802
#13 0x0000000001430703 in sql_set_variables (thd=0x7f964b819000, var_list=0x7f964b81b6d0) at /git/mysql-server_dbg/sql/set_var.cc:662
#14 0x00000000014f63e5 in mysql_execute_command (thd=0x7f964b819000, first_level=true) at /git/mysql-server_dbg/sql/sql_parse.cc:3717
#15 0x00000000014fb5f5 in mysql_parse (thd=0x7f964b819000, parser_state=0x7f9689519550) at /git/mysql-server_dbg/sql/sql_parse.cc:5611
#16 0x00000000014f0c1d in dispatch_command (thd=0x7f964b819000, com_data=0x7f9689519cb0, command=COM_QUERY) at /git/mysql-server_dbg/sql/sql_parse.cc:1461
#17 0x00000000014efa44 in do_command (thd=0x7f964b819000) at /git/mysql-server_dbg/sql/sql_parse.cc:999
#18 0x000000000161f9d0 in handle_connection (arg=0x7f965e788960) at /git/mysql-server_dbg/sql/conn_handler/connection_handler_per_thread.cc:300
#19 0x00000000018534f9 in pfs_spawn_thread (arg=0x7f966ce76220) at /git/mysql-server_dbg/storage/perfschema/pfs.cc:2188
#20 0x00007f9688f23dc5 in start_thread (arg=0x7f968951a700) at pthread_create.c:308
#21 0x00007f968737e73d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113
[5 Sep 2018 7:07]
Roel Van de Paar
Please fix this shortcoming... We're filtering a large block of code (ut0ut.cc line 9[0-4][0-9]) to prevent this bug from repeatedly showing up on radar after minor line changes.
