Assertion range_end >= range_start fails in log0online.c on select from I_S.INNODB_CHANGED_PAGES

[Elena Stepanova]

https://mariadb.atlassian.net/browse/MDEV-4791

SELECT * FROM INFORMATION_SCHEMA.INNODB_CHANGED_PAGES WHERE start_lsn < 10 AND end_lsn > 20 ;

Version: '5.5.32-debug-log'
130717 18:19:09 InnoDB: Assertion failure in thread 139931363571456 in file log0online.c line 1284
InnoDB: Failing assertion: range_end >= range_start

#4 0x00007f445a6bf425 in __GI_raise (sig=<optimized out>) at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
#5 0x00007f445a6c2b8b in __GI_abort () at abort.c:91
#6 0x0000000000addbb1 in log_online_setup_bitmap_file_range (bitmap_files=0x7f444f37beb8, range_start=20, range_end=10) at Percona-Server/storage/innobase/log/log0online.c:1284
#7 0x0000000000ade58c in log_online_bitmap_iterator_init (i=0x7f444f37beb0, min_lsn=20, max_lsn=10) at Percona-Server/storage/innobase/log/log0online.c:1566
#8 0x000000000098f229 in i_s_innodb_changed_pages_fill (thd=0x28646d0, tables=0x7f4444004e68, cond=0x7f444403e9b0) at Percona-Server/storage/innobase/handler/i_s.cc:7494
#9 0x00000000006681a2 in do_fill_table (thd=0x28646d0, table_list=0x7f4444004e68, join_table=0x7f444403e4e0) at Percona-Server/sql/sql_show.cc:7462
#10 0x00000000006685c0 in get_schema_tables_result (join=0x7f444403ca70, executed_place=PROCESSED_BY_JOIN_EXEC) at Percona-Server/sql/sql_show.cc:7568
#11 0x00000000006205d8 in JOIN::exec (this=0x7f444403ca70) at Percona-Server/sql/sql_select.cc:1960
#12 0x0000000000622a91 in mysql_select (thd=0x28646d0, rref_pointer_array=0x2866b98, tables=0x7f4444004e68, wild_num=1, fields=..., conds=0x7f4444005988, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2684619520, result=0x7f4444006038, unit=0x2866390, select_lex=0x28669b0) at Percona-Server/sql/sql_select.cc:2645
#13 0x000000000061abca in handle_select (thd=0x28646d0, lex=0x28662d0, result=0x7f4444006038, setup_tables_done_option=0) at Percona-Server/sql/sql_select.cc:313
#14 0x00000000005f61ff in execute_sqlcom_select (thd=0x28646d0, all_tables=0x7f4444004e68) at Percona-Server/sql/sql_parse.cc:4819
#15 0x00000000005eec86 in mysql_execute_command (thd=0x28646d0) at Percona-Server/sql/sql_parse.cc:2322
#16 0x00000000005f8452 in mysql_parse (thd=0x28646d0, rawbuf=0x7f4444004bd0 "SELECT * FROM INFORMATION_SCHEMA.INNODB_CHANGED_PAGES WHERE start_lsn < 10 AND end_lsn > 20", length=91, parser_state=0x7f444f37dff0) at Percona-Server/sql/sql_parse.cc:5889
#17 0x00000000005ebfab in dispatch_command (command=COM_QUERY, thd=0x28646d0, packet=0x28f0c81 "SELECT * FROM INFORMATION_SCHEMA.INNODB_CHANGED_PAGES WHERE start_lsn < 10 AND end_lsn > 20 ", packet_length=92) at Percona-Server/sql/sql_parse.cc:1079
#18 0x00000000005eb1eb in do_command (thd=0x28646d0) at Percona-Server/sql/sql_parse.cc:789
#19 0x00000000006d4713 in do_handle_one_connection (thd_arg=0x28646d0) at Percona-Server/sql/sql_connect.cc:1487
#20 0x00000000006d413f in handle_one_connection (arg=0x28646d0) at Percona-Server/sql/sql_connect.cc:1402
#21 0x00000000008e917c in pfs_spawn_thread (arg=0x28d3b20) at Percona-Server/storage/perfschema/pfs.cc:1015
#22 0x00007f445b488e9a in start_thread (arg=0x7f444f37f700) at pthread_create.c:308
#23 0x00007f445a77ccbd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#24 0x0000000000000000 in ?? ()

bzr version-info
revision-id: <email address hidden>
date: 2013-07-12 09:17:29 +0000
build-date: 2013-07-17 19:20:13 +0400
revno: 555
branch-nick: percona-server-5.5

[Valerii Kravchuk (valerii-kravchuk)]

Thank you for the bug report. Same with 5.6.12:

openxs@debian7:~/bzr/percona-5.5/Percona-Server-5.5.32-rel31.0$ mysql -uroot -proot test
Warning: Using a password on the command line interface can be insecure.
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 40
Server version: 5.6.12-rc60.4-debug-log MySQL Community Server (GPL)

Copyright (c) 2009-2013 Percona Ireland Ltd.
Copyright (c) 2000, 2013, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> SELECT * FROM INFORMATION_SCHEMA.INNODB_CHANGED_PAGES WHERE start_lsn < 10 AND end_lsn > 20 ;
ERROR 2013 (HY000): Lost connection to MySQL server during query
mysql> exit

...
2013-07-17 18:51:31 4800 [Note] /usr/sbin/mysqld-debug: ready for connections.
Version: '5.6.12-rc60.4-debug-log' socket: '/var/run/mysqld/mysqld.sock' port: 3306 MySQL Community Server (GPL)
2013-07-17 18:52:04 8faffb70 InnoDB: Assertion failure in thread 2410675056 in file log0online.cc line 1280
InnoDB: Failing assertion: range_end >= range_start
InnoDB: We intentionally generate a memory trap.

[Valerii Kravchuk (valerii-kravchuk)]

Same code in 5.1.x:

[openxs@centos percona-5.1]$ grep -rn 'range_end >= range_start' *
Percona-Server/storage/innodb_plugin/log/log0online.c:1277: ut_ad(range_end >= range_start);
...

[Valerii Kravchuk (valerii-kravchuk)]

It seems there is no assertion for 5.1.70-debug, at least built from sources:

[openxs@centos p5.1]$ bin/mysql -uroot test
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.1.70-debug Source distribution

Copyright (c) 2009-2013 Percona Ireland Ltd.
Copyright (c) 2000, 2013, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> SELECT * FROM INFORMATION_SCHEMA.INNODB_CHANGED_PAGES WHERE start_lsn < 10 AND end_lsn > 20 ;
Empty set (0.00 sec)

[Roel Van de Paar (roel11)]

Adding another occurrence on this query:

Query (7f9540004c60): SELECT * FROM INFORMATION_SCHEMA . `INNODB_CHANGED_PAGES` AS table1 WHERE ( ( (NOT ( ( ( ( (NOT ( table1 . `page_id` <> table1 . `start_lsn` AND table1 . `space_id` <> 8) AND table1 . `page_id` >= table1 . `end_lsn`) OR table1 . `end_lsn` = table1 . `space_id`) AND table1 . `end_lsn` <> table1 . `page_id`) OR table1 . `end_lsn` < 8) AND table1 . `space_id` >= '2000-06-10 11:33:07.046821') AND table1 . `end_lsn` >= 5) AND table1 . `start_lsn` < 'mm') OR table1 . `end_lsn` != table1 . `end_lsn`) HAVING ( table1 . `start_lsn` < '2005-09-09 01:34:19.012946' OR table1 . `page_id` < 6) ORDER BY table1 . `start_lsn`
LIMIT 3
Connection ID (thread ID): 56

[Roel Van de Paar (roel11)]

[roel@qaserver 209184]$ cat cmd249
ps -ef | grep 'cmdrun_249' | grep -v grep | awk '{print $2}' | xargs sudo kill -9
rm -Rf /ssd/209184/cmdrun_249
mkdir /ssd/209184/cmdrun_249
cd /ssd/randgen
bash -c "set -o pipefail; perl /ssd/randgen/runall.pl --queries=100000000 --seed=11534 --duration=300 --querytimeout=60 --reporter=Shutdown,Backtrace,QueryTimeout,ErrorLog,ErrorLogAlarm --mysqld=--log-output=none --mysqld=--sql_mode=ONLY_FULL_GROUP_BY --mysqld=--slow_query_log --mysqld=--userstat --threads=25 --notnull --basedir=/ssd/Percona-Server-5.6.12-rc60.4-405-debug.Linux.x86_64 --grammar=/tmp/976291/29.yy --gendata=/ssd/randgen/conf/temporal/temporal_ranges.zz --mtr-build-thread=778 --mask=3382 --vardir1=/ssd/209184/cmdrun_249 > /ssd/209184/cmdrun249.log 2>&1"

[Roel Van de Paar (roel11)]

2013-08-24 05:46:55 7fb02955a700 InnoDB: Assertion failure in thread 140394584450816 in file log0online.cc line 1280
InnoDB: Failing assertion: range_end >= range_start

The testcase from bug 1045231 also now produces this bug in the 5.6 QA tree @ revid 410 (latest as at 24/8/13)

[roel@qaserver randgen]$ ./runall.pl --queries=100000000 --seed=random --duration=3600 --reporter=Shutdown,Backtrace,Deadlock,ErrorLog --threads=80 --basedir=/sde/Percona-Server-5.6.12-rc60.4-410-debug.Linux.x86_64/ --grammar=/ssd/randgen/conf/runtime/information_schema.yy --mask=46021 --vardir1=/ssd/bug1/

[Jan Lindström (jplindst)]

Simple fix for assertion for 5.5 based XtraDB.

[Jan Lindström (jplindst)]

Simple fix for assertion on 5.6 based XtraDB.

[Jan Lindström (jplindst)]

Better fix would be to use range optimizer instead doing the range condition extraction on a storage engine.

[Laurynas Biveinis (laurynas-biveinis)]

Debug-only crash, not fixing on 5.1 unless requested.

[Laurynas Biveinis (laurynas-biveinis)]

Discussion on the contributed patch on https://mariadb.atlassian.net/browse/MDEV-4791

[Roel Van de Paar (roel11)]

Another testcase (possibly reducible to same original one)

SELECT * FROM (INFORMATION_SCHEMA.INNODB_SYS_FOREIGN AS t1 JOIN INFORMATION_SCHEMA.INNODB_CHANGED_PAGES AS t2 ON (t2.start_lsn=t1.REF_NAME)) WHERE NOT (((t2.end_lsn>='2005-05-25 06:28:02.028009' OR t1.REF_NAME<t1.TYPE) OR t2.space_id<'w') OR t2.start_lsn<='2007-06-10 17:28:40.010864') ;

[Shahriyar Rzayev (rzayev-sehriyar)]

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