InnoDB: Failing assertion: mtr_memo_contains_page(mtr, page, 2) || mtr_memo_contains_page(mtr, page, 1) in file btr0btr.ic line 169

[Roel Van de Paar]

InnoDB: Error: the age of the oldest untracked record exceeds the log group capacity!
InnoDB: Error: stopping the log tracking thread at LSN 204650236
2013-06-20 03:48:53 27439 [ERROR] InnoDB: log tracking bitmap write failed, stopping log tracking thread!
2013-06-20 03:56:08 7fa9503f7700 InnoDB: Assertion failure in thread 140365172537088 in file btr0btr.ic line 169
InnoDB: Failing assertion: mtr_memo_contains_page(mtr, page, 2) || mtr_memo_contains_page(mtr, page, 1)
InnoDB: We intentionally generate a memory trap.

Thread 1 (LWP 31022):
+bt
#0 0x0000003fde20c69c in pthread_kill () from /lib64/libpthread.so.0
#1 0x000000000068302e in handle_fatal_signal (sig=6) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/signal_handler.cc:251
#2 <signal handler called>
#3 0x0000003fdde328a5 in raise () from /lib64/libc.so.6
#4 0x0000003fdde34085 in abort () from /lib64/libc.so.6
#5 0x0000000000b34632 in btr_page_get_next (page=0x7fa9466ac000 "_\330", <incomplete sequence \355\240>, mtr=0x7fa9503f4550) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/include/btr0btr.ic:168
#6 0x0000000000b39529 in btr_cur_latch_leaves (page=0x7fa9468bc000 "f\340hs", space=8, zip_size=0, page_no=740, latch_mode=<optimized out>, cursor=0x7fa9503f4d40, mtr=0x7fa9503f4550) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/btr/btr0cur.cc:296
#7 0x0000000000b40977 in btr_cur_search_to_nth_level (index=0x7fa90c067478, level=0, tuple=0x7fa94c067808, mode=4, latch_mode=37, cursor=0x7fa9503f4d40, has_search_latch=0, file=0xdc5250 "/bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/row/row0ins.cc", line=2348, mtr=0x7fa9503f4550) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/btr/btr0cur.cc:798
#8 0x0000000000a9709e in row_ins_clust_index_entry_low (flags=0, mode=37, index=0x7fa90c067478, n_uniq=0, entry=0x7fa94c067808, n_ext=0, thr=0x7fa94c084250) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/row/row0ins.cc:2348
#9 0x0000000000a9a075 in row_ins_clust_index_entry (index=0x7fa90c067478, entry=0x7fa94c067808, thr=0x7fa94c084250, n_ext=0) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/row/row0ins.cc:2887
#10 0x0000000000a9b7f7 in row_ins_index_entry (thr=0x7fa94c084250, entry=0x7fa94c067808, index=0x7fa90c067478) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/row/row0ins.cc:2981
#11 row_ins_index_entry_step (thr=0x7fa94c084250, node=0x7fa94c083d88) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/row/row0ins.cc:3058
#12 row_ins (thr=0x7fa94c084250, node=0x7fa94c083d88) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/row/row0ins.cc:3198
#13 row_ins_step (thr=0x7fa94c084250) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/row/row0ins.cc:3323
#14 0x0000000000aae1ec in row_insert_for_mysql (mysql_rec=<optimized out>, prebuilt=<optimized out>) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/row/row0mysql.cc:1312
#15 0x00000000009ea39e in ha_innobase::write_row (this=0x7fa94c0745d0, record=0x7fa94c076300 "\177\377") at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/innobase/handler/ha_innodb.cc:6929
#16 0x00000000005b7b04 in handler::ha_write_row (this=0x7fa94c0745d0, buf=0x7fa94c076300 "\177\377") at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/handler.cc:7414
#17 0x00000000006f8540 in write_record (thd=0x1dd9d90, table=0x7fa94c07ed40, info=0x7fa9503f5390, update=0x7fa9503f5310) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/sql_insert.cc:1905
#18 0x00000000007002d1 in mysql_insert (thd=0x1dd9d90, table_list=0x7fa94c02bdd0, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/sql_insert.cc:1054
#19 0x000000000071806e in mysql_execute_command (thd=0x1dd9d90) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/sql_parse.cc:3634
#20 0x000000000071b8b8 in mysql_parse (thd=0x1dd9d90, rawbuf=0x1ddc148 "p\234\065\001", length=<optimized out>, parser_state=<optimized out>) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/sql_parse.cc:6451
#21 0x000000000071c923 in dispatch_command (command=COM_QUERY, thd=0x1dd9d90, packet=0x1dddd01 " INSERT INTO v ( `c21` ) VALUES ( 10566570625718026240 )", packet_length=56) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/sql_parse.cc:1376
#22 0x000000000071d86b in do_command (thd=0x1dd9d90) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/sql_parse.cc:1051
#23 0x00000000006e261f in do_handle_one_connection (thd_arg=<optimized out>) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/sql_connect.cc:1615
#24 0x00000000006e2707 in handle_one_connection (arg=0x1dd9d90) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/sql/sql_connect.cc:1526
#25 0x00000000009beb49 in pfs_spawn_thread (arg=0x1dd7e00) at /bzr/5.6_dbg/Percona-Server-5.6.11-rc60.3/storage/perfschema/pfs.cc:1853
#26 0x0000003fde207851 in start_thread () from /lib64/libpthread.so.0
#27 0x0000003fddee890d in clone () from /lib64/libc.so.6

[Roel Van de Paar (roel11)]

[roel@qaserver 934394]$ cat cmd9
ps -ef | grep 'cmdrun_9' | grep -v grep | awk '{print $2}' | xargs sudo kill -9
rm -Rf /ssd2/934394/cmdrun_9
mkdir /ssd2/934394/cmdrun_9
cd /ssd2/randgen
bash -c "set -o pipefail; perl runall.pl --queries=100000000 --seed=14638 --duration=300 --querytimeout=60 --short_column_names --reporter=Shutdown,Backtrace,QueryTimeout,ErrorLog,ErrorLogAlarm --mysqld=--log-output=none --mysqld=--sql_mode=ONLY_FULL_GROUP_BY --grammar=conf/percona_qa/5.6/5.6.yy --gendata=conf/percona_qa/5.6/5.6.zz --basedir=/ssd2/Percona-Server-5.6.11-rc60.3-383-debug.Linux.x86_64 --threads=25 --no-mask --views --notnull --validator=Transformer --mysqld=--innodb_track_changed_pages=1 --mysqld=--innodb_max_bitmap_file_size=9223372036854775807 --mysqld=--innodb_changed_pages=FORCE --mysqld=--innodb_max_changed_pages=100 --mysqld=--innodb_log_file_size=1048576 --mysqld=--innodb_log_files_in_group=2 --mysqld=--innodb_log_buffer_size=1048576 --mysqld=--innodb_log_block_size=512 --mysqld=--innodb_fast_shutdown=2 --mysqld=--innodb_log_group_home_dir=/ssd2/934394/_epoch/1371688599002818017 --mysqld=--innodb_use_global_flush_log_at_trx_commit=0 --mysqld=--userstat --mysqld=--innodb_flush_method=O_DIRECT --mysqld=--innodb_file_per_table=1 --mtr-build-thread=790 --mask=34062 --vardir1=/ssd2/934394/cmdrun_9 > /ssd2/934394/cmdrun9.log 2>&1"

[Roel Van de Paar (roel11)]

Adding another occurrence

[Roel Van de Paar (roel11)]

RQG Revno: 900 Revision-Id: <email address hidden>

Seen in 5.6 GA QA tree @ revid Percona-Server-5.6.12-rc60.4-416-debug-valgrind.Linux.x86_64

[Roel Van de Paar (roel11)]

Adding qablock as it's seen regularly also. Not highest prio.

[Roel Van de Paar (roel11)]

Actually, it is seen in many runs. High prio also.

[Laurynas Biveinis (laurynas-biveinis)]

This is a bug 1059738 regression, UNIV_BTR_DEBUG only. The fix is trivial: make btr_page_get_next() cope with buffer-fixed pages too.

[Laurynas Biveinis (laurynas-biveinis)]

A 5.1 testcase. Useful not only for this relatively minor bug, but for testing sibling prefetch on pessimistic B tree update code path too.

--source include/have_innodb_plugin.inc

CREATE TABLE t1 (a BIGINT UNSIGNED PRIMARY KEY,
                 b CHAR(255) NOT NULL,
                 c CHAR(255) NOT NULL,
                 d CHAR(255) NOT NULL,
                 e CHAR(255) NOT NULL) ENGINE=InnoDB;

SET @t1_space_id= (SELECT SPACE FROM INFORMATION_SCHEMA.INNODB_SYS_TABLES
                                WHERE
                                INFORMATION_SCHEMA.INNODB_SYS_TABLES.SCHEMA='test' AND
                                INFORMATION_SCHEMA.INNODB_SYS_TABLES.NAME='T1');

# Fill the root leaf
INSERT INTO t1 (a, b, c, d, e) VALUES (1, REPEAT("b", 255), REPEAT("c", 255), REPEAT("d", 255), REPEAT("e", 255));
INSERT INTO t1 (a, b, c, d, e) VALUES (2, REPEAT("b", 255), REPEAT("c", 255), REPEAT("d", 255), REPEAT("e", 255));
INSERT INTO t1 (a, b, c, d, e) VALUES (3, REPEAT("b", 255), REPEAT("c", 255), REPEAT("d", 255), REPEAT("e", 255));
INSERT INTO t1 (a, b, c, d, e) VALUES (4, REPEAT("b", 255), REPEAT("c", 255), REPEAT("d", 255), REPEAT("e", 255));
INSERT INTO t1 (a, b, c, d, e) VALUES (5, REPEAT("b", 255), REPEAT("c", 255), REPEAT("d", 255), REPEAT("e", 255));
INSERT INTO t1 (a, b, c, d, e) VALUES (6, REPEAT("b", 255), REPEAT("c", 255), REPEAT("d", 255), REPEAT("e", 255));
INSERT INTO t1 (a, b, c, d, e) VALUES (7, REPEAT("b", 255), REPEAT("c", 255), REPEAT("d", 255), REPEAT("e", 255));
INSERT INTO t1 (a, b, c, d, e) VALUES (8, REPEAT("b", 255), REPEAT("c", 255), REPEAT("d", 255), REPEAT("e", 255));
INSERT INTO t1 (a, b, c, d, e) VALUES (9, REPEAT("b", 255), REPEAT("c", 255), REPEAT("d", 255), REPEAT("e", 255));
INSERT INTO t1 (a, b, c, d, e) VALUES (10, REPEAT("b", 255), REPEAT("c", 255), REPEAT("d", 255), REPEAT("e", 255));
INSERT INTO t1 (a, b, c, d, e) VALUES (11, REPEAT("b", 255), REPEAT("c", 255), REPEAT("d", 255), REPEAT("e", 255));
INSERT INTO t1 (a, b, c, d, e) VALUES (12, REPEAT("b", 255), REPEAT("c", 255), REPEAT("d", 255), REPEAT("e", 255));
INSERT INTO t1 (a, b, c, d, e) VALUES (13, REPEAT("b", 255), REPEAT("c", 255), REPEAT("d", 255), REPEAT("e", 255));
INSERT INTO t1 (a, b, c, d, e) VALUES (14, REPEAT("b", 255), REPEAT("c", 255), REPEAT("d", 255), REPEAT("e", 255));

SELECT COUNT(*) = 1 AS should_be_1 FROM INFORMATION_SCHEMA.INNODB_BUFFER_POOL_PAGES WHERE SPACE_ID=@t1_space_id AND PAGE_TYPE LIKE 'index';

# Split the roof leaf
INSERT INTO t1 (a, b, c, d, e) VALUES (15, REPEAT("b", 255), REPEAT("c", 255), REPEAT("d", 255), REPEAT("e", 255));

SELECT COUNT(*) = 3 AS should_be_1 FROM INFORMATION_SCHEMA.INNODB_BUFFER_POOL_PAGES WHERE SPACE_ID=@t1_space_id AND PAGE_TYPE LIKE 'index';

# Fill the right leaf
INSERT INTO t1 (a, b, c, d, e) VALUES (16, REPEAT("b", 255), REPEAT("c", 255), REPEAT("d", 255), REPEAT("e", 255));
INSERT INTO t1 (a, b, c, d, e) VALUES (17, REPEAT("b", 255), REPEAT("c", 255), REPEAT("d", 255), REPEAT("e", 255));
INSERT INTO t1 (a, b, c, d, e) VALUES (18, REPEAT("b", 255), REPEAT("c", 255), REPEAT("d", 255), REPEAT("e", 255));
INSERT INTO t1 (a, b, c, d, e) VALUES (19, REPEAT("b", ...

[Roel Van de Paar (roel11)]

Another testcase

DROP DATABASE test;CREATE DATABASE test;USE test;
set global innodb_limit_optimistic_insert_debug=2;
CREATE TABLE t1(c1 INT,c2 CHAR(5)) PARTITION BY HASH(c1) PARTITIONS 2;
INSERT INTO t1 VALUES(),(),(),(),(),(),(),(),(),(),(),(),(),(),();
SET innodb_fake_changes=1;
INSERT INTO t1(c1)VALUES(2);

[Roel Van de Paar (roel11)]

Additional testcase will help verify bugfix

[Roel Van de Paar (roel11)]

Laurynas; fixed up bug status (been in progress since 2013) - feel free to revert if not correct

[Krunal Bauskar (krunal-bauskar)]

commit 4005f7eab166a2168f7bf8d9f940b5e25a22d836
Author: Krunal Bauskar <email address hidden>
Date: Mon Sep 14 11:02:36 2015 +0530

    - bug#1192898 : InnoDB: Failing assertion: mtr_memo_contains_page(mtr, page, 2)
      || mtr_memo_contains_page(mtr, page, 1) in file btr0btr.ic line 169

      In case of fake change operational mode, locking is less restricting.
      For example: If pessmisitic insert is operating in fake-change mode
      sibilings are not locked/latched as the flow doesn't plan to change
      the perform the change action but this contradict with existing validation
      assert that are not meant to handle this situation.

      Relaxed the assert by || it with special consideration for fake-change
      mode operation.

PR#166 - 5.5
PR#167 - 5.6

[Shahriyar Rzayev (rzayev-sehriyar)]

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