Bug #78698 | Simple delete query causes InnoDB: Failing assertion: 0 & data corruption | ||
---|---|---|---|
Submitted: | 5 Oct 2015 9:57 | Modified: | 17 Feb 2016 8:17 |
Reporter: | Roel Van de Paar | Email Updates: | |
Status: | Closed | Impact on me: | |
Category: | MySQL Server: DML | Severity: | S6 (Debug Builds) |
Version: | 5.7.8 (RC2), 5.7.10, 8.0.0 | OS: | Any |
Assigned to: | CPU Architecture: | Any | |
Tags: | opt |
[5 Oct 2015 9:57]
Roel Van de Paar
[5 Oct 2015 9:57]
Roel Van de Paar
Optimized fails too, though does not crash: mysql> delete from t1; ERROR 1100 (HY000): Table '#sql-271b_3' was not locked with LOCK TABLES
[5 Oct 2015 10:01]
Roel Van de Paar
Ref bug 75837, fixed in 5.7.8...
[5 Oct 2015 10:05]
Roel Van de Paar
Ref bug 76528
[5 Oct 2015 10:12]
MySQL Verification Team
Optimized crash: 2015-10-05T10:09:12.502112Z 0 [Note] Event Scheduler: Loaded 0 events 2015-10-05T10:09:12.504290Z 0 [Note] 5.7\bin\mysqld: ready for connections. Version: '5.7.10' socket: '' port: 3306 Source distribution PULL: 2015-SEP-26 2015-10-05T10:10:09.993009Z 2 [Warning] InnoDB: Compute virtual column values failed InnoDB: Cannot compute value for following record DATA TUPLE: 5 fields; 0: len 1; hex 30; asc 0;; 1: len 1; hex 30; asc 0;; 2: len 6; hex 000000000205; asc ;; 3: len 6; hex 000000000706; asc ;; 4: len 7; hex 82000000270110; asc ' ;; 2015-10-05T10:10:10.027157Z 2 [ERROR] InnoDB: Record in index `idx` of table `temp`.`#sql1f74_2_1` was not found on update: TUPLE (info_bits=0, 2 fields): {NULL,[6] (0x0000000 00205)} at: COMPACT RECORD(info_bits=0, 1 fields): {[8]infimum (0x090E06090D050D00)} 10:10:10 UTC - mysqld got exception 0xc0000005 ; This could be because you hit a bug. It is also possible that this binary or one of the libraries it was linked against is corrupt, improperly built, or misconfigured. This error can also be caused by malfunctioning hardware. Attempting to collect some information that could help diagnose the problem. As this is a crash and something is definitely wrong, the information collection process might fail. key_buffer_size=8388608 read_buffer_size=131072 max_used_connections=1 max_threads=151 thread_count=1 connection_count=1 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 68005 K bytes of memory Hope that's ok; if not, decrease some variables in the equation. Thread pointer: 0xeba308cac0 Attempting backtrace. You can use the following information to find out where mysqld died. If you see no messages after this, something went terribly wrong... 7ff783f5d745 mysqld.exe!srv_mbr_print()[row0upd.cc:2003] 7ff783f5cdfe mysqld.exe!row_upd_sec_index_entry()[row0upd.cc:2187] 7ff783f591cb mysqld.exe!row_upd()[row0upd.cc:2971] 7ff783f5d1bc mysqld.exe!row_upd_step()[row0upd.cc:3091] 7ff783f070f1 mysqld.exe!row_update_for_mysql_using_upd_graph()[row0mysql.cc:2509] 7ff783dc1b6d mysqld.exe!ha_innobase::delete_row()[ha_innodb.cc:7949] 7ff783616e26 mysqld.exe!handler::ha_delete_row()[handler.cc:7839] 7ff783c1a06b mysqld.exe!Sql_cmd_delete::mysql_delete()[sql_delete.cc:458] 7ff783c18dd9 mysqld.exe!Sql_cmd_delete::execute()[sql_delete.cc:1365] 7ff783669ef5 mysqld.exe!mysql_execute_command()[sql_parse.cc:3360] 7ff78366c7ca mysqld.exe!mysql_parse()[sql_parse.cc:5363] 7ff783665a79 mysqld.exe!dispatch_command()[sql_parse.cc:1287] 7ff783666a1a mysqld.exe!do_command()[sql_parse.cc:854] 7ff78360a874 mysqld.exe!handle_connection()[connection_handler_per_thread.cc:295] 7ff78406c4c2 mysqld.exe!pfs_spawn_thread()[pfs.cc:2195] 7ff783d75bdb mysqld.exe!win_thread_start()[my_thread.c:38] 7ff78413b42f mysqld.exe!_callthreadstartex()[threadex.c:376] 7ff78413b67a mysqld.exe!_threadstartex()[threadex.c:354] 7ffaaa2e2d92 KERNEL32.DLL!BaseThreadInitThunk() 7ffaac389f64 ntdll.dll!RtlUserThreadStart()
[5 Oct 2015 10:20]
MySQL Verification Team
Hello Roel, Thank you for the report. Confirmed that 5.7.10/5.8.0 release builds are affected. Thanks, Umesh
[5 Oct 2015 10:22]
MySQL Verification Team
// 5.8.0 bin/mysql_install_db --insecure --basedir=/export/umesh/server/binaries/mysql-advanced-5.8.0 --datadir=/export/umesh/server/binaries/mysql-advanced-5.8.0/78497 -v bin/mysqld --no-defaults --basedir=/export/umesh/server/binaries/mysql-advanced-5.8.0 --datadir=/export/umesh/server/binaries/mysql-advanced-5.8.0/78497 --core-file --socket=/tmp/mysql_ushastry.sock --port=15000 --log-error=/export/umesh/server/binaries/mysql-advanced-5.8.0/78497/log.err 2>&1 & (gdb) bt #0 0x00007ffde5ec3771 in pthread_kill () from /lib64/libpthread.so.0 #1 0x00000000008b9905 in handle_fatal_signal (sig=11) at /export/home2/pb2/build/sb_0-16631638-1443713022.55/mysqlcom-pro-5.8.0-m17/sql/signal_handler.cc:221 #2 <signal handler called> #3 row_upd_sec_index_entry (node=node@entry=0x7ffd7c025f08, thr=thr@entry=0x7ffd7c01c258) at /export/home2/pb2/build/sb_0-16631638-1443713022.55/mysqlcom-pro-5.8.0-m17/storage/innobase/row/row0upd.cc:2026 #4 0x00000000010330b8 in row_upd_sec_step (thr=<optimized out>, node=0x7ffd7c025f08) at /export/home2/pb2/build/sb_0-16631638-1443713022.55/mysqlcom-pro-5.8.0-m17/storage/innobase/row/row0upd.cc:2269 #5 row_upd (thr=0x7ffd7c01c258, node=0x7ffd7c025f08) at /export/home2/pb2/build/sb_0-16631638-1443713022.55/mysqlcom-pro-5.8.0-m17/storage/innobase/row/row0upd.cc:2974 #6 row_upd_step (thr=thr@entry=0x7ffd7c01c258) at /export/home2/pb2/build/sb_0-16631638-1443713022.55/mysqlcom-pro-5.8.0-m17/storage/innobase/row/row0upd.cc:3091 #7 0x0000000000ffdbf7 in row_update_for_mysql_using_upd_graph (prebuilt=prebuilt@entry=0x7ffd7c0253d8, mysql_rec=0x7ffd7c022898 "\370\060\001\060\001") at /export/home2/pb2/build/sb_0-16631638-1443713022.55/mysqlcom-pro-5.8.0-m17/storage/innobase/row/row0mysql.cc:2495 #8 0x0000000000ffe770 in row_update_for_mysql (mysql_rec=mysql_rec@entry=0x7ffd7c022898 "\370\060\001\060\001", prebuilt=prebuilt@entry=0x7ffd7c0253d8) at /export/home2/pb2/build/sb_0-16631638-1443713022.55/mysqlcom-pro-5.8.0-m17/storage/innobase/row/row0mysql.cc:2692 #9 0x0000000000f1d954 in ha_innobase::delete_row (this=0x7ffd7c0225b0, record=<optimized out>) at /export/home2/pb2/build/sb_0-16631638-1443713022.55/mysqlcom-pro-5.8.0-m17/storage/innobase/handler/ha_innodb.cc:7992 #10 0x00000000009508cf in handler::ha_delete_row (this=0x7ffd7c0225b0, buf=0x7ffd7c022898 "\370\060\001\060\001") at /export/home2/pb2/build/sb_0-16631638-1443713022.55/mysqlcom-pro-5.8.0-m17/sql/handler.cc:7822 #11 0x0000000000da7976 in Sql_cmd_delete::mysql_delete (this=this@entry=0x7ffd7c006458, thd=thd@entry=0x7ffd7c000ae0, limit=18446744073709551615) at /export/home2/pb2/build/sb_0-16631638-1443713022.55/mysqlcom-pro-5.8.0-m17/sql/sql_delete.cc:460 #12 0x0000000000da8090 in Sql_cmd_delete::execute (this=0x7ffd7c006458, thd=0x7ffd7c000ae0) at /export/home2/pb2/build/sb_0-16631638-1443713022.55/mysqlcom-pro-5.8.0-m17/sql/sql_delete.cc:1354 #13 0x00000000007fb880 in mysql_execute_command (thd=thd@entry=0x7ffd7c000ae0, first_level=first_level@entry=true) at /export/home2/pb2/build/sb_0-16631638-1443713022.55/mysqlcom-pro-5.8.0-m17/sql/sql_parse.cc:4598 #14 0x000000000080166d in mysql_parse (thd=thd@entry=0x7ffd7c000ae0, parser_state=parser_state@entry=0x7ffdbc9f77b0) at /export/home2/pb2/build/sb_0-16631638-1443713022.55/mysqlcom-pro-5.8.0-m17/sql/sql_parse.cc:5305 #15 0x0000000000801f58 in dispatch_command (thd=thd@entry=0x7ffd7c000ae0, com_data=com_data@entry=0x7ffdbc9f7e00, command=COM_QUERY) at /export/home2/pb2/build/sb_0-16631638-1443713022.55/mysqlcom-pro-5.8.0-m17/sql/sql_parse.cc:1251 #16 0x0000000000803787 in do_command (thd=thd@entry=0x7ffd7c000ae0) at /export/home2/pb2/build/sb_0-16631638-1443713022.55/mysqlcom-pro-5.8.0-m17/sql/sql_parse.cc:819 #17 0x00000000008af490 in handle_connection (arg=arg@entry=0x2a0e8f0) at /export/home2/pb2/build/sb_0-16631638-1443713022.55/mysqlcom-pro-5.8.0-m17/sql/conn_handler/connection_handler_per_thread.cc:296 #18 0x0000000000ea7bf4 in pfs_spawn_thread (arg=0x28aba70) at /export/home2/pb2/build/sb_0-16631638-1443713022.55/mysqlcom-pro-5.8.0-m17/storage/perfschema/pfs.cc:2211 #19 0x00007ffde5ebedf5 in start_thread () from /lib64/libpthread.so.0 #20 0x00007ffde497e60d in clone () from /lib64/libc.so.6 (gdb) [umshastr@hod03]/export/umesh/server/binaries/mysql-advanced-5.8.0: cat docs/INFO_SRC commit: f1ca5c4badf22b044ad613b5797338b2ec5ec613 date: 2015-10-01 15:53:30 +0200 build-date: 2015-10-01 17:06:11 +0200 short: f1ca5c4 branch: mysql-trunk MySQL source 5.8.0
[5 Oct 2015 10:22]
MySQL Verification Team
// 5.7.10 bin/mysql_install_db --insecure --basedir=/export/umesh/server/binaries/mysql-advanced-5.7.10 --datadir=/export/umesh/server/binaries/mysql-advanced-5.7.10/78497 -v bin/mysqld --no-defaults --basedir=/export/umesh/server/binaries/mysql-advanced-5.7.10 --datadir=/export/umesh/server/binaries/mysql-advanced-5.7.10/78497 --core-file --socket=/tmp/mysql_ushastry.sock --port=15000 --log-error=/export/umesh/server/binaries/mysql-advanced-5.7.10/78497/log.err 2>&1 & (gdb) bt #0 0x00007fd49479c771 in pthread_kill () from /lib64/libpthread.so.0 #1 0x00000000007ae935 in handle_fatal_signal (sig=11) at /export/home2/pb2/build/sb_0-16631979-1443716475.4/mysqlcom-pro-5.7.10/sql/signal_handler.cc:220 #2 <signal handler called> #3 row_upd_sec_index_entry (node=node@entry=0x7fd430025dc8, thr=thr@entry=0x7fd43001c278) at /export/home2/pb2/build/sb_0-16631979-1443716475.4/mysqlcom-pro-5.7.10/storage/innobase/row/row0upd.cc:2030 #4 0x0000000000feccca in row_upd_sec_step (thr=<optimized out>, node=0x7fd430025dc8) at /export/home2/pb2/build/sb_0-16631979-1443716475.4/mysqlcom-pro-5.7.10/storage/innobase/row/row0upd.cc:2273 #5 row_upd (node=node@entry=0x7fd430025dc8, thr=thr@entry=0x7fd43001c278) at /export/home2/pb2/build/sb_0-16631979-1443716475.4/mysqlcom-pro-5.7.10/storage/innobase/row/row0upd.cc:2979 #6 0x0000000000fecec3 in row_upd_step (thr=thr@entry=0x7fd43001c278) at /export/home2/pb2/build/sb_0-16631979-1443716475.4/mysqlcom-pro-5.7.10/storage/innobase/row/row0upd.cc:3096 #7 0x0000000000fb5857 in row_update_for_mysql_using_upd_graph (prebuilt=prebuilt@entry=0x7fd430025298, mysql_rec=0x7fd430020720 "\370\060\001\060\001") at /export/home2/pb2/build/sb_0-16631979-1443716475.4/mysqlcom-pro-5.7.10/storage/innobase/row/row0mysql.cc:2507 #8 0x0000000000fb63e0 in row_update_for_mysql (mysql_rec=mysql_rec@entry=0x7fd430020720 "\370\060\001\060\001", prebuilt=prebuilt@entry=0x7fd430025298) at /export/home2/pb2/build/sb_0-16631979-1443716475.4/mysqlcom-pro-5.7.10/storage/innobase/row/row0mysql.cc:2704 #9 0x0000000000ed4c17 in ha_innobase::delete_row (this=0x7fd430020430, record=<optimized out>) at /export/home2/pb2/build/sb_0-16631979-1443716475.4/mysqlcom-pro-5.7.10/storage/innobase/handler/ha_innodb.cc:7920 #10 0x00000000008045ef in handler::ha_delete_row (this=0x7fd430020430, buf=0x7fd430020720 "\370\060\001\060\001") at /export/home2/pb2/build/sb_0-16631979-1443716475.4/mysqlcom-pro-5.7.10/sql/handler.cc:7838 #11 0x0000000000de1d76 in Sql_cmd_delete::mysql_delete (this=this@entry=0x7fd430006438, thd=thd@entry=0x7fd430000ae0, limit=18446744073709551615) at /export/home2/pb2/build/sb_0-16631979-1443716475.4/mysqlcom-pro-5.7.10/sql/sql_delete.cc:458 #12 0x0000000000de249f in Sql_cmd_delete::execute (this=0x7fd430006438, thd=0x7fd430000ae0) at /export/home2/pb2/build/sb_0-16631979-1443716475.4/mysqlcom-pro-5.7.10/sql/sql_delete.cc:1365 #13 0x0000000000c88c30 in mysql_execute_command (thd=thd@entry=0x7fd430000ae0, first_level=first_level@entry=true) at /export/home2/pb2/build/sb_0-16631979-1443716475.4/mysqlcom-pro-5.7.10/sql/sql_parse.cc:4645 #14 0x0000000000c8ee0d in mysql_parse (thd=thd@entry=0x7fd430000ae0, parser_state=parser_state@entry=0x7fd46b2db7b0) at /export/home2/pb2/build/sb_0-16631979-1443716475.4/mysqlcom-pro-5.7.10/sql/sql_parse.cc:5357 #15 0x0000000000c8f7d2 in dispatch_command (thd=thd@entry=0x7fd430000ae0, com_data=com_data@entry=0x7fd46b2dbe00, command=COM_QUERY) at /export/home2/pb2/build/sb_0-16631979-1443716475.4/mysqlcom-pro-5.7.10/sql/sql_parse.cc:1284 #16 0x0000000000c91067 in do_command (thd=thd@entry=0x7fd430000ae0) at /export/home2/pb2/build/sb_0-16631979-1443716475.4/mysqlcom-pro-5.7.10/sql/sql_parse.cc:852 #17 0x0000000000d48798 in handle_connection (arg=arg@entry=0x27e6cd0) at /export/home2/pb2/build/sb_0-16631979-1443716475.4/mysqlcom-pro-5.7.10/sql/conn_handler/connection_handler_per_thread.cc:295 #18 0x00000000011b0ba4 in pfs_spawn_thread (arg=0x28da430) at /export/home2/pb2/build/sb_0-16631979-1443716475.4/mysqlcom-pro-5.7.10/storage/perfschema/pfs.cc:2192 #19 0x00007fd494797df5 in start_thread () from /lib64/libpthread.so.0 #20 0x00007fd49325760d in clone () from /lib64/libc.so.6 (gdb) [umshastr@hod03]/export/umesh/server/binaries/mysql-advanced-5.7.10: cat docs/INFO_SRC commit: a814c74e87b4ef1a81c59f10805bdd9f9ff903d4 date: 2015-10-01 15:51:16 +0200 build-date: 2015-10-01 18:03:36 +0200 short: a814c74 branch: mysql-5.7 MySQL source 5.7.10
[14 Oct 2015 9:05]
Olav Sandstå
Slightly simplified test case: CREATE TEMPORARY TABLE t1 ( a INTEGER NOT NULL, b INTEGER GENERATED ALWAYS AS (a+1) VIRTUAL ); INSERT INTO t1 (a) VALUES (0), (0), (0); ALTER TABLE t1 ADD INDEX idx (b); DELETE FROM t1; DROP TABLE t1;
[14 Oct 2015 11:05]
Olav Sandstå
Initial analysis of the bug: ============================ When executing the "DELETE FROM t1" statement, the server asks InnoDB to delete the rows in the table. In addition to delete the rows from the table, InnoDB also needs to delete the entries from the secondary index. Since this is an index on a virtual column, InnoDB uses the handler::my_eval_gcolumn_expr() to get the value for the virtual column. Since the table t1 is a temporary table, handler::my_eval_gcolumn_expr() calls find_temporary_table() to get the TABLE object for this table. In the case of this bug, find_temporary_table() does not find any TABLE object and we return an error value to InnoDB without having evaluated the values for the virtual column. This is an error situation that eventually causes a debug assert to hit inside InnoDB. The reason for not finding the TABLE object for this table seems to be that in this case there is an inconsistency for what is that table name for this table. When InnoDB calls handler::my_eval_gcolumn_expr() the table name is given as "#sql-3bb8_3" while the only temporary table that find_temporary_table() is able to find is named "t1". If I change the test case slightly to avoid the separate ALTER TABLE statement by adding the index definition in the table definition: CREATE TEMPORARY TABLE t1 ( a INTEGER NOT NULL, b INTEGER GENERATED ALWAYS AS (a+1) VIRTUAL, INDEX idx (b) ); INSERT INTO t1 (a) VALUES (0), (0), (0); DELETE FROM t1; DROP TABLE t1; the bug no longer occurs. In this case, InnoDB calls handler::my_eval_gcolumn_expr() with the original name for the table "t1". If I to this test case add a new ALTER TABLE statement which is not on the virtual column, eg.: ALTER TABLE t1 ADD INDEX idx2 (a); the assert is again hit due to InnoDB now again calls handler::my_eval_gcolumn_expr() with a table name starting as "#sql-.....". So it seems like running an ALTER TABLE statement on a temporary table causes InnoDB to start using a new generated name for the table. This name is not the same as the table has when find_temporary_table() tries to locate it. My initial understanding is that running an ALTER TABLE statement should not change the name that the storage engine has for the table. It seems that the root cause for this bug is that ALTER TABLE statements on temporary tables changes table names in the storage engine.
[17 Feb 2016 8:17]
Erlend Dahl
Fixed under the heading of Bug#22070021 CHANGE VIRTUAL INDEX CALLBACK FUNCTION TO AVOID THE UNINTENDED TABLE OBJECT. [21 Dec 2015 5:26] Daniel T Price Fixed as of the upcoming 5.7.11, 5.8.0 release, and here's the changelog entry: The wrong table object was used to compute virtual column values for a query that accessed multiple instances of the same table.
[18 Jun 2016 21:28]
Omer Barnir
Posted by developer: Reported version value updated to reflect release name change from 5.8 to 8.0