Bug #37343 Assertion in IndexNode::parseNode, ASSERT(key - (UCHAR*) indexNode < 14);
Submitted: 11 Jun 2008 13:42 Modified: 30 Sep 2008 19:49
Reporter: Philip Stoev Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Falcon storage engine Severity:S1 (Critical)
Version:6.0-falcon OS:Any
Assigned to: Ann Harrison CPU Architecture:Any
Triage: D1 (Critical)

[11 Jun 2008 13:42] Philip Stoev
Description:
When executing a concurrent DML workload, Falcon crashed as follows:

#0  0x00110416 in __kernel_vsyscall ()
#1  0x00581c78 in pthread_kill () from /lib/libpthread.so.0
#2  0x0843eda3 in write_core (sig=6) at stacktrace.c:302
#3  0x0829b228 in handle_segfault (sig=6) at mysqld.cc:2626
#4  <signal handler called>
#5  0x00110416 in __kernel_vsyscall ()
#6  0x00584fe0 in raise () from /lib/libpthread.so.0
#7  0x0850fd4c in Error::debugBreak () at Error.cpp:90
#8  0x0850fda9 in Error::error (string=0x88c4744 "assertion failed at line %d in file %s\n") at Error.cpp:67
#9  0x0850fe4c in Error::assertionFailed (fileName=0x88c6048 "IndexNode.h", line=109) at Error.cpp:74
#10 0x08523dbb in IndexNode::parseNode (this=0xb60324c8, indexNode=0xb729b90b) at IndexNode.h:109
#11 0x08523e4d in IndexNode::getNext (this=0xb60324c8, end=0xb729b947) at IndexNode.h:132
#12 0x0859e181 in WalkIndex::getNextNode (this=0xb602cff0) at WalkIndex.cpp:94
#13 0x0859e247 in WalkIndex::getNext (this=0xb602cff0, lockForUpdate=false) at WalkIndex.cpp:65
#14 0x084aef38 in StorageDatabase::nextIndexed (this=0xb6f1b130, storageTable=0xb72905f8, indexWalker=0xb602cff0, lockForUpdate=false)
    at StorageDatabase.cpp:481
#15 0x084b589c in StorageTable::nextIndexed (this=0xb72905f8, recordNumber=0, lockForUpdate=false) at StorageTable.cpp:180
#16 0x084a8485 in StorageInterface::index_next (this=0x91d5318, buf=0x91d54e0 "Ъ") at ha_falcon.cpp:1585
#17 0x084a1b4c in StorageInterface::index_first (this=0x91d5318, buf=0x91d54e0 "Ъ") at ha_falcon.cpp:1572
#18 0x08312738 in join_read_first (tab=0x9124fd8) at sql_select.cc:14219
#19 0x08315d89 in sub_select (join=0x915c5e0, join_tab=0x9124fd8, end_of_records=false) at sql_select.cc:13341
#20 0x08322d70 in do_select (join=0x915c5e0, fields=0x915d93c, table=0x0, procedure=0x0) at sql_select.cc:13092
#21 0x08335655 in JOIN::exec (this=0x915c5e0) at sql_select.cc:2740
#22 0x0824f73b in subselect_single_select_engine::exec (this=0x9124ac0) at item_subselect.cc:2277
#23 0x0824c10e in Item_subselect::exec (this=0x9124a20) at item_subselect.cc:280
#24 0x0824c41a in Item_singlerow_subselect::val_decimal (this=0x9124a20, decimal_value=0xa9461ce4) at item_subselect.cc:658
#25 0x081dda91 in Item::save_in_field (this=0x9124a20, field=0x91e5dd8, no_conversions=false) at item.cc:4878
#26 0x082ea7c9 in fill_record (thd=0xa91089c8, fields=@0xa910a038, values=@0x9123e58, ignore_errors=false) at sql_base.cc:7964
#27 0x082ea8d1 in fill_record_n_invoke_before_triggers (thd=0xa91089c8, fields=@0xa910a038, values=@0x9123e58, ignore_errors=false, triggers=0x0,
    event=TRG_EVENT_INSERT) at sql_base.cc:8009
#28 0x0833fec9 in mysql_insert (thd=0xa91089c8, table_list=0x9123b00, fields=@0xa910a038, values_list=@0xa910a05c, update_fields=@0xa910a050,
    update_values=@0xa910a044, duplic=DUP_ERROR, ignore=false) at sql_insert.cc:754
#29 0x082ae991 in mysql_execute_command (thd=0xa91089c8) at sql_parse.cc:2951
#30 0x082b4ec6 in mysql_parse (thd=0xa91089c8,
    inBuf=0x9123978 "INSERT INTO C ( int_key , int_nokey ) VALUES ( ( SELECT AVG( int_nokey ) FROM A AS X WHERE X . int_nokey < 48 GROUP BY pk LIMIT 1 ) , 55 )", length=138, found_semicolon=0xa9463260) at sql_parse.cc:5782
#31 0x082b590f in dispatch_command (command=COM_QUERY, thd=0xa91089c8,
    packet=0xa910a3c1 "INSERT INTO C ( int_key , int_nokey ) VALUES ( ( SELECT AVG( int_nokey ) FROM A AS X WHERE X . int_nokey < 48 GROUP BY pk LIMIT 1 ) , 55 )", packet_length=138) at sql_parse.cc:1059
#32 0x082b6b75 in do_command (thd=0xa91089c8) at sql_parse.cc:732
#33 0x082a4385 in handle_one_connection (arg=0xa91089c8) at sql_connect.cc:1134
#34 0x0057d32f in start_thread () from /lib/libpthread.so.0
#35 0x0049a27e in clone () from /lib/libc.so.6

The assertion in question is:

104
105                             if (c & 0x80)
106                                     break;
107                             }
108
109             ASSERT(key - (UCHAR*) indexNode < 14);
110             nextNode = (Btn*) (key + length);

The participating variables are:

(gdb) print key
$10 = (UCHAR *) 0xb729b948 'л' <repeats 200 times>...
(gdb) print key[0]
$12 = 204 'л'
(gdb) print indexNode
$13 = (Btn *) 0xb729b90b
(gdb) print (UCHAR*) indexNode
$17 = (unsigned char *) 0xb729b90b ""
(gdb) print (UCHAR) indexNode
$18 = 11 '\v'

How to repeat:
A simplifed test case will hopefully follow...
[11 Jun 2008 18:00] Philip Stoev
This is all that is required to reproduce this bug:

CREATE TABLE t1 (
	pk INTEGER AUTO_INCREMENT,
	int_key INTEGER,
	PRIMARY KEY (pk),
	KEY (int_key)
) ENGINE=Falcon;

SELECT * FROM t1 WHERE int_key < 5 ORDER BY int_key LIMIT 1;
[11 Jun 2008 22:06] Ann Harrison
The problem is that the index walking code doesn't handle the case
where the starting value is higher than any stored value.  This shows
up when there are no records and (I suspect) when all values are
lower than the starting value.

The fix is simple.  In WalkIndex::nextNode, check for END_LEVEL
[11 Jun 2008 22:55] Kevin Lewis
Ann has a fix and will create a patch tomorrow.
[30 Jun 2008 19:28] Philip Stoev
The fix provided by Ann appears to fix the crash:

<quote>
in WalkIndex::getNextNode(void)
you need to add the "else" statement shown below:

if (first)
{
first = false;
recordNumber = node.getNumber();

if (recordNumber >= 0)
return recordNumber;
else if (recordNumber == END_LEVEL)
return -1;
}
</quote>
[4 Jul 2008 12:33] Philip Stoev
The same assertion was hit when coming from WalkIndex::getNextNode . Here is the backtrace:

#0  0x00110416 in __kernel_vsyscall ()
#1  0x00581c78 in pthread_kill () from /lib/libpthread.so.0
#2  0x085b0d94 in my_write_core (sig=6) at stacktrace.c:307
#3  0x08213e88 in handle_segfault (sig=6) at mysqld.cc:2638
#4  <signal handler called>
#5  0x00110416 in __kernel_vsyscall ()
#6  0x00584fe0 in raise () from /lib/libpthread.so.0
#7  0x08441fd0 in Error::debugBreak () at Error.cpp:94
#8  0x0844203d in Error::error (string=0x86c6234 "assertion (%s) failed at line %d in file %s\n") at Error.cpp:71
#9  0x084420b3 in Error::assertionFailed (text=0x86c7d2c "key - (UCHAR*) indexNode < 14", fileName=0x86c7d20 "IndexNode.h", line=109) at Error.cpp:78
#10 0x084a94eb in WalkIndex::getNextNode (this=0xb74eefb8) at IndexNode.h:109
#11 0x084a95fa in WalkIndex::getNext (this=0xb74eefb8, lockForUpdate=false) at WalkIndex.cpp:65
#12 0x083f9a7d in StorageDatabase::nextIndexed (this=0xb7110130, storageTable=0xb74a63d0, indexWalker=0xb74eefb8, lockForUpdate=false)
    at StorageDatabase.cpp:481
#13 0x083fe453 in StorageTable::nextIndexed (this=0x1242, recordNumber=0, lockForUpdate=<value optimized out>) at StorageTable.cpp:180
#14 0x083f63b7 in StorageInterface::index_next (this=0x9b7b560, buf=0x9b7b718 "©Ъ") at ha_falcon.cpp:1589
#15 0x083efc6e in StorageInterface::index_first (this=0x9b7b560, buf=0x9b7b718 "©Ъ") at ha_falcon.cpp:1576
#16 0x0827fac0 in join_read_first (tab=0x9bc2258) at sql_select.cc:14515
#17 0x08281605 in sub_select (join=0x9bc0b58, join_tab=0x9bc2258, end_of_records=false) at sql_select.cc:13636
#18 0x0828b5a9 in do_select (join=0x9bc0b58, fields=0x9bc1e98, table=0x0, procedure=0x0) at sql_select.cc:13387
#19 0x0828d751 in JOIN::exec (this=0x9bc0b58) at sql_select.cc:2811
#20 0x081d26c4 in subselect_single_select_engine::exec (this=0x9bd8a48) at item_subselect.cc:2277
#21 0x081d0c4a in Item_subselect::exec (this=0x9bd8980) at item_subselect.cc:280
#22 0x081d42fc in Item_in_subselect::exec (this=0x9bd8980) at item_subselect.cc:330
#23 0x081d1363 in Item_in_subselect::val_bool (this=0x9bd8980) at item_subselect.cc:899
#24 0x0817cd6d in Item::val_bool_result (this=0x9bd8980) at ../item.h:742
#25 0x081a17e1 in Item_in_optimizer::val_int (this=0x9bd9428) at item_cmpfunc.cc:1595
#26 0x0816f04b in Item::val_bool (this=0x9bd9428) at item.cc:184
#27 0x081a1976 in Item_func_not::val_int (this=0x9bd8a70) at item_cmpfunc.cc:275
#28 0x0816f04b in Item::val_bool (this=0x9bd8a70) at item.cc:184
#29 0x081a0d5f in Item_cond_or::val_int (this=0x9bd1e50) at item_cmpfunc.cc:4273
#30 0x08281324 in evaluate_join_record (join=0x9bd09e8, join_tab=0x9bd9db0, error=<value optimized out>) at sql_select.cc:13775
#31 0x08281610 in sub_select (join=0x9bd09e8, join_tab=0x9bd9db0, end_of_records=false) at sql_select.cc:13637
#32 0x0828b5a9 in do_select (join=0x9bd09e8, fields=0x0, table=0x9bd6178, procedure=0x0) at sql_select.cc:13387
#33 0x0828bfe0 in JOIN::exec (this=0x9bd09e8) at sql_select.cc:2399
#34 0x0828e1ea in mysql_select (thd=0xa8816d38, rref_pointer_array=0xa881821c, tables=0x9c0c5f8, wild_num=0, fields=@0xa88181ac, conds=0x9bd8d18, og_num=1,
    order=0x0, group=0x9bd8ea8, having=0x9bd8fc8, proc_param=0x0, select_options=2147764736, result=0x9bd9120, unit=0xa8817e88, select_lex=0xa8818118)
    at sql_select.cc:3001
#35 0x082910cc in handle_select (thd=0xa8816d38, lex=0xa8817e2c, result=0x9bd9120, setup_tables_done_option=0) at sql_select.cc:302
#36 0x082201d2 in execute_sqlcom_select (thd=0xa8816d38, all_tables=0x9c0c5f8) at sql_parse.cc:4847
#37 0x08220f51 in mysql_execute_command (thd=0xa8816d38) at sql_parse.cc:2015
#38 0x0822a01e in mysql_parse (thd=0xa8816d38,
    inBuf=0x9c0bf48 "SELECT OUTR . `int_key` AS X FROM B AS OUTR WHERE OUTR . `datetime_key` NOT IN ( SELECT MIN( INNR . `datetime_nokey` ) FROM BB AS INNR2 LEFT JOIN AA AS INNR ON ( INNR2 . `datetime_key` = INNR . `datet"..., length=402, found_semicolon=0xa876c314) at sql_parse.cc:5811
#39 0x0822a911 in dispatch_command (command=COM_QUERY, thd=0xa8816d38,
---Type <return> to continue, or q <return> to quit---
    packet=0xa8818751 "SELECT OUTR . `int_key` AS X FROM B AS OUTR WHERE OUTR . `datetime_key` NOT IN ( SELECT MIN( INNR . `datetime_nokey` ) FROM BB AS INNR2 LEFT JOIN AA AS INNR ON ( INNR2 . `datetime_key` = INNR . `datet"..., packet_length=403) at sql_parse.cc:1051
#40 0x0822ba39 in do_command (thd=0xa8816d38) at sql_parse.cc:724
#41 0x0821bee0 in handle_one_connection (arg=0xa8816d38) at sql_connect.cc:1153
#42 0x0057d32f in start_thread () from /lib/libpthread.so.0
#43 0x0049a27e in clone () from /lib/libc.so.6

The query involves date/time columns:

SELECT OUTR . `int_key` AS X
FROM B AS OUTR
WHERE OUTR . `datetime_key` NOT IN (
 SELECT MIN( INNR . `datetime_nokey` ) FROM BB AS INNR2
 LEFT JOIN AA AS INNR ON ( INNR2 . `datetime_key` = INNR . `datetime_nokey` )
 WHERE INNR . `time_key` = INNR . `datetime_key`
 AND NOT INNR . `time_nokey` <> 35
 GROUP BY INNR . `datetime_key`
)
OR OUTR . `date_key` >= 17
GROUP BY OUTR . `datetime_key`
HAVING X >= 172

Please let me know if a simplifed test case is required.
[4 Jul 2008 13:12] Philip Stoev
This last backtrace was obtained using the mysql-6.0 tree, which does not contain Ann's fix.
[10 Jul 2008 15:27] Ann Harrison
Fix has been pushed to the shared mysql-6.0-falcon tree.
[22 Aug 2008 20:49] Kevin Lewis
This fix is in version 6.0.6
[28 Sep 2008 13:06] Philip Stoev
This bug was observed again in 6.0-falcon-team . Note that the server was started with --falcon-page-size=2K and that the WHERE clause contains a relatively long predicate on an utf8 column.

#9  0x0858b987 in Error::assertionFailed (text=0x8977cd4 "key - (UCHAR*) indexNode < 14", fileName=0x8977cc8 "IndexNode.h", line=109) at Error.cpp:78
#10 0x0859fa23 in IndexNode::parseNode (this=0xb4e771f4, indexNode=0xb4e7f7d0) at IndexNode.h:109
#11 0x0859fab5 in IndexNode::getNext (this=0xb4e771f4, end=0xb4e7f80c) at IndexNode.h:132
#12 0x0861b3a4 in WalkIndex::getNextNode (this=0xb4e71d18) at WalkIndex.cpp:96
#13 0x0861b46b in WalkIndex::getNext (this=0xb4e71d18, lockForUpdate=false) at WalkIndex.cpp:65
#14 0x08529ca6 in StorageDatabase::nextIndexed (this=0xb701b130, storageTable=0xb4e7ff78, indexWalker=0xb4e71d18, lockForUpdate=false)
    at StorageDatabase.cpp:485
#15 0x08530452 in StorageTable::nextIndexed (this=0xb4e7ff78, recordNumber=0, lockForUpdate=false) at StorageTable.cpp:169
#16 0x08521da2 in StorageInterface::index_next (this=0xb13de48, buf=0xb13e230 "ЪЪЪ", ' ' <repeats 197 times>...) at ha_falcon.cpp:1629
#17 0x08521183 in StorageInterface::read_range_first (this=0xb13de48, start_key=0xb13dedc, end_key=0x0, eq_range_arg=false, sorted=true)
    at ha_falcon.cpp:1597
#18 0x083d9f96 in handler::multi_range_read_next (this=0xb13de48, range_info=0xa7270c30) at handler.cc:4258
#19 0x083ba4fb in QUICK_RANGE_SELECT::get_next (this=0xb0fd4e0) at opt_range.cc:8522
#20 0x083d3f3f in rr_quick (info=0xb0ddd64) at records.cc:317
#21 0x0832a115 in join_init_read_record (tab=0xb0ddd20) at sql_select.cc:14537
#22 0x0832da5a in sub_select (join=0xb175af0, join_tab=0xb0ddd20, end_of_records=false) at sql_select.cc:13703
#23 0x0833aec7 in do_select (join=0xb175af0, fields=0xa7e92f80, table=0x0, procedure=0x0) at sql_select.cc:13450
#24 0x0834e0b0 in JOIN::exec (this=0xb175af0) at sql_select.cc:2826
#25 0x08348eca in mysql_select (thd=0xa7e91ae8, rref_pointer_array=0xa7e92ff0, tables=0xb0dcea0, wild_num=0, fields=@0xa7e92f80, conds=0xb0dd558, og_num=1,
    order=0xb0dd740, group=0x0, having=0x0, proc_param=0x0, select_options=2148289024, result=0xb0dd7d8, unit=0xa7e92c54, select_lex=0xa7e92eec)
    at sql_select.cc:3016
#26 0x0834e3c0 in handle_select (thd=0xa7e91ae8, lex=0xa7e92bf8, result=0xb0dd7d8, setup_tables_done_option=0) at sql_select.cc:300
#27 0x082c04f1 in execute_sqlcom_select (thd=0xa7e91ae8, all_tables=0xb0dcea0) at sql_parse.cc:4886
#28 0x082c1e86 in mysql_execute_command (thd=0xa7e91ae8) at sql_parse.cc:2107
#29 0x082cacd5 in mysql_parse (thd=0xa7e91ae8,
    inBuf=0xb0dc958 "SELECT `set_latin1` FROM `table100_falcon_int_autoinc` WHERE `char_130_key_utf8` > REPEAT( '14:15:54' , 69 ) ORDER BY `char_130_key_utf8` LIMIT 3", length=145, found_semicolon=0xa7272270) at sql_parse.cc:5856
#30 0x082cb71f in dispatch_command (command=COM_QUERY, thd=0xa7e91ae8, packet=0xa7e93ba9 "", packet_length=145) at sql_parse.cc:1120
#31 0x082cca32 in do_command (thd=0xa7e91ae8) at sql_parse.cc:807
#32 0x082ba473 in handle_one_connection (arg=0xa7e91ae8) at sql_connect.cc:1153
#33 0x0057d32f in start_thread () from /lib/libpthread.so.0
#34 0x0049a27e in clone () from /lib/libc.so.6
[30 Sep 2008 19:49] Jon Stephens
Documented as follows in the 6.0.6 changelog:

        Queries with complex conditions in the WHERE clause on Falcon tables
        when falcon_page_size was set to a low value could cause the server to
        crash.