InnoDB: Assertion failure in thread <nr> in file buf0buf.cc line 4362 after corruption (possibly caused by sql) | abort (sig=6) in buf_page_io_complete

[Roel Van de Paar]

InnoDB: Ending processing because of a corrupt database page.
2014-10-20 05:07:54 7fb1d6223700 InnoDB: Assertion failure in thread 140401778505472 in file buf0buf.cc line 4362
[...]
Query (7fb184004e90): SELECT * FROM INFORMATION_SCHEMA.INNODB_SYS_FOREIGN_COLS
Connection ID (thread ID): 4

Single threaded run, single mysqld involved. Corruption possibly caused by sql.

Thread 1 (Thread 0x7fb1d6223700 (LWP 21820)):
+bt
#0 0x00007fb1ef6fc771 in pthread_kill () from /lib64/libpthread.so.0
#1 0x0000000000ab7586 in my_write_core (sig=6) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/mysys/stacktrace.c:422
#2 0x000000000072f9ff in handle_fatal_signal (sig=6) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/sql/signal_handler.cc:236
#3 <signal handler called>
#4 0x00007fb1ee3005c9 in raise () from /lib64/libc.so.6
#5 0x00007fb1ee301cd8 in abort () from /lib64/libc.so.6
#6 0x0000000000cbf2da in buf_page_io_complete (bpage=0x7fb1dbfddee0) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/storage/innobase/buf/buf0buf.cc:4362
#7 0x0000000000cdc6ac in buf_read_page_low (err=0x7fb1d621fa6c, sync=true, mode=132, space=0, zip_size=0, unzip=0, tablespace_version=1, offset=305, trx=0x7fb1880033b8) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/storage/innobase/buf/buf0rea.cc:258
#8 0x0000000000cdcaf7 in buf_read_page (space=0, zip_size=0, offset=305, trx=0x7fb1880033b8) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/storage/innobase/buf/buf0rea.cc:462
#9 0x0000000000cbb528 in buf_page_get_gen (space=0, zip_size=0, offset=305, rw_latch=3, guess=0x0, mode=10, file=0x10b6eb8 "/mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/storage/innobase/include/btr0pcur.ic", line=518, mtr=0x7fb1d6220110) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/storage/innobase/buf/buf0buf.cc:2710
#10 0x0000000000c97c12 in btr_cur_open_at_index_side_func (from_left=true, index=0x2991988, latch_mode=1, cursor=0x7fb1d6220030, level=0, file=0x10b6eb8 "/mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/storage/innobase/include/btr0pcur.ic", line=518, mtr=0x7fb1d6220110) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/storage/innobase/btr/btr0cur.cc:964
#11 0x0000000000d03e9c in btr_pcur_open_at_index_side (from_left=true, index=0x2991988, latch_mode=1, pcur=0x7fb1d6220030, init_pcur=true, level=0, mtr=0x7fb1d6220110) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/storage/innobase/include/btr0pcur.ic:518
#12 0x0000000000d04a56 in dict_startscan_system (pcur=0x7fb1d6220030, mtr=0x7fb1d6220110, system_id=SYS_FOREIGN_COLS) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/storage/innobase/dict/dict0load.cc:286
#13 0x0000000000b0adfc in i_s_sys_foreign_cols_fill_table (thd=0x22c1cf0, tables=0x7fb184005198) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/storage/innobase/handler/i_s.cc:7622
#14 0x0000000000840c9b in do_fill_table (thd=0x22c1cf0, table_list=0x7fb184005198, join_table=0x7fb188079ea0) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/sql/sql_show.cc:7902
#15 0x000000000084106a in get_schema_tables_result (join=0x7fb184005d48, executed_place=PROCESSED_BY_JOIN_EXEC) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/sql/sql_show.cc:8003
#16 0x0000000000813522 in JOIN::prepare_result (this=0x7fb184005d48, columns_list=0x7fb1d62208e0) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/sql/sql_select.cc:823
#17 0x00000000007b050b in JOIN::exec (this=0x7fb184005d48) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/sql/sql_executor.cc:116
#18 0x000000000081401b in mysql_execute_select (thd=0x22c1cf0, select_lex=0x22c4950, free_join=true) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/sql/sql_select.cc:1100
#19 0x0000000000814317 in mysql_select (thd=0x22c1cf0, tables=0x7fb184005198, wild_num=1, fields=..., conds=0x0, order=0x22c4b18, group=0x22c4a50, having=0x0, select_options=2686345728, result=0x7fb184005d20, unit=0x22c4308, select_lex=0x22c4950) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/sql/sql_select.cc:1221
#20 0x00000000008123a6 in handle_select (thd=0x22c1cf0, result=0x7fb184005d20, setup_tables_done_option=0) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/sql/sql_select.cc:110
#21 0x00000000007ea892 in execute_sqlcom_select (thd=0x22c1cf0, all_tables=0x7fb184005198) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/sql/sql_parse.cc:5597
#22 0x00000000007e2de9 in mysql_execute_command (thd=0x22c1cf0) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/sql/sql_parse.cc:2958
#23 0x00000000007ed193 in mysql_parse (thd=0x22c1cf0, rawbuf=0x7fb184004e90 "SELECT * FROM INFORMATION_SCHEMA.INNODB_SYS_FOREIGN_COLS", length=56, parser_state=0x7fb1d6221d50) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/sql/sql_parse.cc:6773
#24 0x00000000007df5fc in dispatch_command (command=COM_QUERY, thd=0x22c1cf0, packet=0x2ab5931 "SELECT * FROM INFORMATION_SCHEMA.INNODB_SYS_FOREIGN_COLS;", packet_length=57) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/sql/sql_parse.cc:1432
#25 0x00000000007de528 in do_command (thd=0x22c1cf0) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/sql/sql_parse.cc:1049
#26 0x00000000008c2c30 in threadpool_process_request (thd=0x22c1cf0) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/sql/threadpool_common.cc:311
#27 0x00000000008c5572 in handle_event (connection=0x2945820) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/sql/threadpool_unix.cc:1553
#28 0x00000000008c57a2 in worker_main (param=0x1898400 <all_groups+2048>) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/sql/threadpool_unix.cc:1606
#29 0x0000000000dc5bac in pfs_spawn_thread (arg=0x7fb184004ba0) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/storage/perfschema/pfs.cc:1860
#30 0x00007fb1ef6f7df3 in start_thread () from /lib64/libpthread.so.0
#31 0x00007fb1ee3c101d in clone () from /lib64/libc.so.6

[Ramesh Sivaraman (rameshvs02)]

***** Testcase

DROP DATABASE test;CREATE DATABASE test;USE test;
SET GLOBAL innodb_buffer_pool_dump_at_shutdown=ON;
SET GLOBAL innodb_corrupt_table_action='warn';
CREATE TABLE t0(s0 INT)ENGINE=InnoDB;
SET GLOBAL innodb_checksum_algorithm=1;
DROP DATABASE test;

[Laurynas Biveinis (laurynas-biveinis)]

5.1/5.5 might be affected if innodb_checksum_algorithm is replaced with innodb_fast_checksum

[Ramesh Sivaraman (rameshvs02)]

Could not reproduce with 5.5 build after replacing innodb_checksum_algorithm with innodb_fast_checksum.

[Ramesh Sivaraman (rameshvs02)]

Got another assertion and looks like similar bug.

** Testcase

DROP DATABASE test;CREATE DATABASE test;USE test;
SET GLOBAL innodb_buffer_pool_dump_at_shutdown=ON;
SET @orig=@@global.innodb_buffer_pool_dump_at_shutdown;
SET GLOBAL innodb_checksum_algorithm=@orig;
CREATE TABLE sys_foreign SELECT 1;

** GDB info

+bt
#0 0x00007f41c6ada771 in pthread_kill () from /lib64/libpthread.so.0
#1 0x00000000006772cd in handle_fatal_signal (sig=6) at /mnt/workspace/percona-server-5.6-binaries-opt-yassl/label_exp/centos6-64/percona-server-5.6.22-71.0
/sql/signal_handler.cc:236
#2 <signal handler called>
#3 0x00007f41c56de5c9 in raise () from /lib64/libc.so.6
#4 0x00007f41c56dfcd8 in abort () from /lib64/libc.so.6
#5 0x0000000000a36f6f in buf_page_io_complete (bpage=bpage@entry=0x7f41b5846a80) at /mnt/workspace/percona-server-5.6-binaries-opt-yassl/label_exp/centos6-6
4/percona-server-5.6.22-71.0/storage/innobase/buf/buf0buf.cc:4377
#6 0x0000000000a4ce88 in buf_read_page_low (trx=0x0, offset=9, tablespace_version=<optimized out>, unzip=0, zip_size=0, space=0, mode=132, sync=true, err=0x
7f41c7084140) at /mnt/workspace/percona-server-5.6-binaries-opt-yassl/label_exp/centos6-64/percona-server-5.6.22-71.0/storage/innobase/buf/buf0rea.cc:258
#7 buf_read_page (space=space@entry=0, zip_size=zip_size@entry=0, offset=offset@entry=9, trx=trx@entry=0x0) at /mnt/workspace/percona-server-5.6-binaries-op
t-yassl/label_exp/centos6-64/percona-server-5.6.22-71.0/storage/innobase/buf/buf0rea.cc:462
#8 0x0000000000a31696 in buf_page_get_gen (space=space@entry=0, zip_size=<optimized out>, offset=offset@entry=9, rw_latch=rw_latch@entry=3, guess=<optimized
 out>, guess@entry=0x0, mode=mode@entry=10, file=file@entry=0xc8ac30 "/mnt/workspace/percona-server-5.6-binaries-opt-yassl/label_exp/centos6-64/percona-serve
r-5.6.22-71.0/storage/innobase/row/row0ins.cc", line=line@entry=2672, mtr=mtr@entry=0x7f41c70849d0) at /mnt/workspace/percona-server-5.6-binaries-opt-yassl/l
abel_exp/centos6-64/percona-server-5.6.22-71.0/storage/innobase/buf/buf0buf.cc:2721
#9 0x0000000000a145f8 in btr_cur_search_to_nth_level (index=index@entry=0x7f41c4c272e8, level=level@entry=0, tuple=tuple@entry=0x7f418fc6c988, mode=mode@ent
ry=4, latch_mode=2, latch_mode@entry=514, cursor=cursor@entry=0x7f41c7084870, has_search_latch=has_search_latch@entry=0, file=file@entry=0xc8ac30 "/mnt/works
pace/percona-server-5.6-binaries-opt-yassl/label_exp/centos6-64/percona-server-5.6.22-71.0/storage/innobase/row/row0ins.cc", line=line@entry=2672, mtr=mtr@en
try=0x7f41c70849d0) at /mnt/workspace/percona-server-5.6-binaries-opt-yassl/label_exp/centos6-64/percona-server-5.6.22-71.0/storage/innobase/btr/btr0cur.cc:6
52
#10 0x0000000000998acd in row_ins_sec_index_entry_low (flags=flags@entry=0, mode=mode@entry=2, index=index@entry=0x7f41c4c272e8, offsets_heap=offsets_heap@en
try=0x7f418fcaa400, heap=heap@entry=0x7f418fcaa900, entry=entry@entry=0x7f418fc6c988, trx_id=trx_id@entry=0, thr=thr@entry=0x7f418fcca730) at /mnt/workspace/
percona-server-5.6-binaries-opt-yassl/label_exp/centos6-64/percona-server-5.6.22-71.0/storage/innobase/row/row0ins.cc:2672
#11 0x000000000099b14b in row_ins_sec_index_entry (index=index@ent...

[Laurynas Biveinis (laurynas-biveinis)]

Neither a testcase in the comment #2 nor #5 crashes with the current trunk. Please check

[Ramesh Sivaraman (rameshvs02)]

Tested with latest build and able to reproduce the issue.

Server Version : Percona-Server-5.6.22-rel72.0-739.Linux.x86_64

*** Startup options

--plugin-load=audit_log=audit_log.so\;tokudb=ha_tokudb.so --init-file=/sda/percona-qa/TokuDB.sql --event-scheduler=ON --maximum-bulk_insert_buffer_size=1M --maximum-join_buffer_size=1M --maximum-max_heap_table_size=1M --maximum-max_join_size=1M --maximum-myisam_max_sort_file_size=1M --maximum-myisam_mmap_size=1M --maximum-myisam_sort_buffer_size=1M --maximum-optimizer_trace_max_mem_size=1M --maximum-preload_buffer_size=1M --maximum-query_alloc_block_size=1M --maximum-query_prealloc_size=1M --maximum-range_alloc_block_size=1M --maximum-read_buffer_size=1M --maximum-read_rnd_buffer_size=1M --maximum-sort_buffer_size=1M --maximum-tmp_table_size=1M --maximum-transaction_alloc_block_size=1M --maximum-transaction_prealloc_size=1M --log-output=none --sql_mode=ONLY_FULL_GROUP_BY

Please find the attached testcase reduction files.

[Roel Van de Paar (roel11)]

mysql> SET GLOBAL innodb_checksum_algorithm=1;
Query OK, 0 rows affected (0.00 sec)

mysql> show global variables like '%innodb_checksum_algorithm%';
+---------------------------+--------------+
| Variable_name | Value |
+---------------------------+--------------+
| innodb_checksum_algorithm | strict_crc32 |
+---------------------------+--------------+
1 row in set (0.00 sec)

[Roel Van de Paar (roel11)]

The testcase in #2 crashes both PS 5.7 and MS 5.7. Reduced testcase;

DROP DATABASE test;CREATE DATABASE test;USE test;
CREATE TABLE t (f INT) ENGINE=InnoDB;
SET GLOBAL innodb_checksum_algorithm=strict_crc32;
DROP DATABASE test;

[Roel Van de Paar (roel11)]

2015-02-12 08:34:56 0x7f9b55804700 InnoDB: Assertion failure in thread 140305131128576 in file ut0ut.cc line 981

[Roel Van de Paar (roel11)]

Assertion is same on both MS and PS.

[Roel Van de Paar (roel11)]

The strict_* forms work the same as innodb, crc32, and none, except that InnoDB halts if it encounters a mix of checksum values in the same tablespace. You can only use these options in a completely new instance, to set up all tablespaces for the first time. The strict_* settings are somewhat faster, because they do not need to compute both new and old checksum values to accept both during disk reads.

http://dev.mysql.com/doc/refman/5.6/en/innodb-parameters.html#sysvar_innodb_checksum_algorithm

[Roel Van de Paar (roel11)]

Testcase in #5 is similar/same;

mysql> SELECT @@global.innodb_buffer_pool_dump_at_shutdown;
+----------------------------------------------+
| @@global.innodb_buffer_pool_dump_at_shutdown |
+----------------------------------------------+
| 0 |
+----------------------------------------------+
1 row in set (0.00 sec)

mysql> SET GLOBAL innodb_buffer_pool_dump_at_shutdown=ON;
Query OK, 0 rows affected (0.00 sec)

mysql> SELECT @@global.innodb_buffer_pool_dump_at_shutdown;
+----------------------------------------------+
| @@global.innodb_buffer_pool_dump_at_shutdown |
+----------------------------------------------+
| 1 |
+----------------------------------------------+
1 row in set (0.00 sec)

mysql> SET GLOBAL innodb_buffer_pool_dump_at_shutdown=OFF;
Query OK, 0 rows affected (0.00 sec)

mysql> SELECT @@global.innodb_buffer_pool_dump_at_shutdown;
+----------------------------------------------+
| @@global.innodb_buffer_pool_dump_at_shutdown |
+----------------------------------------------+
| 0 |
+----------------------------------------------+
1 row in set (0.00 sec)

mysql> SET GLOBAL innodb_checksum_algorithm=1;
Query OK, 0 rows affected (0.00 sec)

mysql> show global variables like '%innodb_checksum_algorithm%';
+---------------------------+--------------+
| Variable_name | Value |
+---------------------------+--------------+
| innodb_checksum_algorithm | strict_crc32 |
+---------------------------+--------------+
1 row in set (0.00 sec)

mysql> CREATE TABLE sys_foreign SELECT 1;
ERROR 2013 (HY000): Lost connection to MySQL server during query

[Roel Van de Paar (roel11)]

Thus, the following testcase also crashes.

DROP DATABASE test;CREATE DATABASE test;USE test;
SET GLOBAL innodb_checksum_algorithm=strict_crc32;
CREATE TABLE t (f INT) ENGINE=InnoDB;

[Roel Van de Paar (roel11)]

Now, there are several (individually) interesting items;

1) PS 5.6.22 does NOT (!) crash on these two reduced testcases. (MS and PS 5.7 both do...)
2) PS 5.6.22 crashes on testcase in #5 (buf0buf.cc line 4377, ~expected page corruption) but not on the one in #2 even after many repeats
3) MS 5.6.22 crashes on testcase in #14 and #9 immediately. Sometimes it seems to need a bit of forcing (execute testcase 2-3x). One time I could not get it to crash on #14 at all. It's messy allright.

Current thoughts; there is some sporadic element that sometimes causes the issue to trigger, but not always. Maybe the check for corruption is not present in all codepaths or is not always called or maybe data is not always accessed immediately, or something.

Laurynas, can you check further on what may be happening with the code here? There may or may not be a connection with innodb_buffer_pool_dump_at_shutdown=1 and there is some sporadic element present, which may be clearer from code.

Data dirs were wiped (./init) each time during runs.

[Laurynas Biveinis (laurynas-biveinis)]

Is there any valid testcase then at all? Or shall we close the bug as Invalid? You cannot set strict_* on an existing instance.

"You can only use these options in a completely new instance, to set up all tablespaces for the first time."

[Roel Van de Paar (roel11)]

Laurynas, as per #17, there are sporadic issues here. This looks buggy.

[Roel Van de Paar (roel11)]

For example, why does PS 5.6.22 not fail in spite of running the testcase many times? This should not be the case...

[Roel Van de Paar (roel11)]

(That in itself is a reverse logic testcase)

[Laurynas Biveinis (laurynas-biveinis)]

The testcases should crash on buffer pool I/O, which is async except for reading in non-present data pages. This makes the current testcases non-deterministic, and is a probable cause for what you see.

[Krunal Bauskar (krunal-bauskar)]

Was just hovering around this bug and thought of trying it.

I couldn't get any of the TC to crash PS-5.6 server.

Interesting fact is

mysql> USE test;
mysql> SET GLOBAL innodb_checksum_algorithm=strict_crc32;
mysql> CREATE TABLE t (f INT) ENGINE=InnoDB;

generates following warning:

Version: '5.6.26-73.2-debug' socket: '/opt/projects/codebase/installed/5.6/mysql.sock' port: 29993 Source distribution
2015-09-21 10:33:45 7718 [Warning] InnoDB: innodb_checksum_algorithm is set to "strict_crc32" but the page [page id: space=0, page number=9] contains a valid checksum "innodb". Accepting the page as valid. C
hange innodb_checksum_algorithm to "crc32" to silently accept such pages or rewrite all pages so that they contain "crc32" checksum.

................

Seems like the issue is fixed by the bug that is addressed below.
As per the commit message mis-matching checksum use to crash the server before.

commit 0bf409d175fe674e73c92492a68af9dd69278377
Author: Thirunarayanan Balathandayuthapani <email address hidden>
Date: Wed Apr 8 13:38:21 2015 +0530

    Fix Bug#20568464 MITIGATE THE STRICTNESS OF STRICT_* MODES
                        OF INNODB_CHECKSUM_ALGORITHM

[Launchpad Janitor (janitor)]

[Expired for Percona Server 5.5 because there has been no activity for 60 days.]

[Launchpad Janitor (janitor)]

[Expired for Percona Server 5.6 because there has been no activity for 60 days.]

[Launchpad Janitor (janitor)]

[Expired for Percona Server 5.1 because there has been no activity for 60 days.]

[Roel Van de Paar (roel11)]

Will consider it 'fixed' and remove from filter list.

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-838