MySQL Bugs: #38375: Falcon crash in Record::isNull

Bug #38375	Falcon crash in Record::isNull
Submitted:	25 Jul 2008 14:28	Modified:	26 May 2010 17:46
Reporter:	Alexey Stroganov	Email Updates:
Status:	Unsupported	Impact on me:	None
Category:	MySQL Server: Falcon storage engine	Severity:	S1 (Critical)
Version:	6.0.6-alpha,6.0.8-falcon-team,6.0.11-falcon-team	OS:	Any
Assigned to:	Christopher Powers	CPU Architecture:	Any
Tags:	F_CHILL THAW

Description:
6.0.6/falcon crashes in sysbench test while executing query below.

SELECT name FROM phptest WHERE country_id = ? limit 5

For the same query there is already another report BUG#36734 but with different backtrace.

bt:

Version: '6.0.6-alpha'  socket: '/tmp/mysqld-sysbench-phptest.sock'  port: 3306  MySQL Community Server (GPL)
080725 14:34:45 - mysqld got signal 11 ;
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.
We will try our best to scrape up some info that will hopefully help diagnose
the problem, but since we have already crashed, something is definitely wrong
and this may fail.

key_buffer_size=8388600
read_buffer_size=131072
max_used_connections=64
max_threads=1600
thread_count=64
connection_count=64
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 324660 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0x1bb3a90
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...
stack_bottom = 0x403dd190 thread_stack 0x20000
/data0/ranger/mysql-6.0.6-alpha-linux-x86_64-glibc23//bin/mysqld(my_print_stacktrace+0x2e)[0xa64a5e]
/data0/ranger/mysql-6.0.6-alpha-linux-x86_64-glibc23//bin/mysqld(handle_segfault+0x33b)[0x6412fb]
/lib64/libpthread.so.0[0x2b3944dce140]
/data0/ranger/mysql-6.0.6-alpha-linux-x86_64-glibc23//bin/mysqld(Record::isNull(int)+0xcd)[0x894a1d]
/data0/ranger/mysql-6.0.6-alpha-linux-x86_64-glibc23//bin/mysqld(StorageTable::compareKey(unsigned char const*, int)+0x140)[0x822cc0]
/data0/ranger/mysql-6.0.6-alpha-linux-x86_64-glibc23//bin/mysqld(StorageInterface::index_read(unsigned char*, unsigned char const*, unsigned int, ha_rkey_function)+0xb8)[0x817a68]
/data0/ranger/mysql-6.0.6-alpha-linux-x86_64-glibc23//bin/mysqld[0x6b7435]
/data0/ranger/mysql-6.0.6-alpha-linux-x86_64-glibc23//bin/mysqld(sub_select(JOIN*, st_join_table*, bool)+0xd7)[0x6abce7]
/data0/ranger/mysql-6.0.6-alpha-linux-x86_64-glibc23//bin/mysqld[0x6ac11d]
/data0/ranger/mysql-6.0.6-alpha-linux-x86_64-glibc23//bin/mysqld(JOIN::exec()+0x8e4)[0x6c1a94]
/data0/ranger/mysql-6.0.6-alpha-linux-x86_64-glibc23//bin/mysqld(mysql_select(THD*, Item***, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*)+0x1b0)[0x6c3630]
/data0/ranger/mysql-6.0.6-alpha-linux-x86_64-glibc23//bin/mysqld(handle_select(THD*, st_lex*, select_result*, unsigned long)+0x169)[0x6c4009]
/data0/ranger/mysql-6.0.6-alpha-linux-x86_64-glibc23//bin/mysqld[0x64c519]
/data0/ranger/mysql-6.0.6-alpha-linux-x86_64-glibc23//bin/mysqld(mysql_execute_command(THD*)+0x1480)[0x650de0]
/data0/ranger/mysql-6.0.6-alpha-linux-x86_64-glibc23//bin/mysqld(Prepared_statement::execute(String*, bool)+0x3b8)[0x6ced48]
/data0/ranger/mysql-6.0.6-alpha-linux-x86_64-glibc23//bin/mysqld(Prepared_statement::execute_loop(String*, bool, unsigned char*, unsigned char*)+0x80)[0x6d1140]
/data0/ranger/mysql-6.0.6-alpha-linux-x86_64-glibc23//bin/mysqld(mysql_stmt_execute(THD*, char*, unsigned int)+0x19d)[0x6d14dd]
/data0/ranger/mysql-6.0.6-alpha-linux-x86_64-glibc23//bin/mysqld(dispatch_command(enum_server_command, THD*, char*, unsigned int)+0x498)[0x6561c8]
/data0/ranger/mysql-6.0.6-alpha-linux-x86_64-glibc23//bin/mysqld(do_command(THD*)+0xc6)[0x657106]
/data0/ranger/mysql-6.0.6-alpha-linux-x86_64-glibc23//bin/mysqld(handle_one_connection+0xf4)[0x6499c4]
/lib64/libpthread.so.0[0x2b3944dc7193]
/lib64/libc.so.6(__clone+0x6d)[0x2b39453fa45d]
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 0x1bc44b8 = SELECT name FROM phptest WHERE country_id = ? limit 5
thd->thread_id=18
thd->killed=NOT_KILLED
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.

How to repeat:
See BUG#36734

corrected version of simulator program

Attachment: sysbench_limit.py (text/plain), 1.32 KiB.

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

Ranger,

can you still reproduce this bug?

Got the crash with similar backtrace while testing the recent falcon tree with sysbench:

Using host libthread_db library "/lib64/libthread_db.so.1".
Core was generated by `/data0/ranger/mysql-6.0.8-alpha-pb130-linux-x86_64/bin/mysqld --no-defaults --p'.
Program terminated with signal 11, Segmentation fault.
#0  0x00002ab3ca7574c5 in pthread_kill () from /lib64/libpthread.so.0
#0  0x00002ab3ca7574c5 in pthread_kill () from /lib64/libpthread.so.0
#1  0x000000000068524e in handle_segfault (sig=11) at mysqld.cc:2671
#2  <signal handler called>
#3  Record::isNull (this=0x2aaaf48dd6e8, fieldId=-192030893) at EncodedDataStream.h:350
#4  0x00000000008a1f13 in StorageTable::compareKey (this=0x2aaae5343960, key=<value optimized out>,
    keyLength=<value optimized out>) at StorageTable.cpp:432
#5  0x000000000089551b in StorageInterface::index_next_same (this=0x2aaae5029088, buf=0x2aaae5029468 "\001",
    key=0x2aaae4f50038 "\002", key_len=2) at ha_falcon.cpp:1715
#6  0x0000000000700a7f in join_read_next_same (info=<value optimized out>) at sql_select.cc:14476
#7  0x00000000006f2dfc in sub_select (join=0x2aaae5244698, join_tab=0x2aaae4f4fd98, end_of_records=<value optimized out>)
    at sql_select.cc:13726
#8  0x00000000006f33b4 in do_select (join=0x2aaae5244698, fields=0x2aaae4f3f210, table=0x0, procedure=0x0)
    at sql_select.cc:13455
#9  0x000000000070ac55 in JOIN::exec (this=0x2aaae5244698) at sql_select.cc:2829
#10 0x000000000070c840 in mysql_select (thd=0x1e8e070, rref_pointer_array=0x2aaae4f3f2f0, tables=0x2aaae4f3fdc8,
    wild_num=0, fields=@0x2aaae4f3f210, conds=0x2aaae4f40a70, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0,
    select_options=2416200192, result=0x2aaae4f40be8, unit=0x2aaae4f3eca8, select_lex=0x2aaae4f3f108) at sql_select.cc:3019
#11 0x000000000070d219 in handle_select (thd=0x1e8e070, lex=0x2aaae4f3ec08, result=0x2aaae4f40be8,
    setup_tables_done_option=0) at sql_select.cc:301
#12 0x0000000000690c99 in execute_sqlcom_select (thd=0x1e8e070, all_tables=0x2aaae4f3fdc8) at sql_parse.cc:4644
#13 0x0000000000695ead in mysql_execute_command (thd=0x1e8e070) at sql_parse.cc:2064
#14 0x0000000000717ff8 in Prepared_statement::execute (this=0x2aaae4f37490, expanded_query=<value optimized out>,
    open_cursor=false) at sql_prepare.cc:3577
#15 0x000000000071a440 in Prepared_statement::execute_loop (this=0x2aaae4f37490, expanded_query=0x40bef3d0,
    open_cursor=false, packet=<value optimized out>, packet_end=<value optimized out>) at sql_prepare.cc:3244
#16 0x000000000071a7dd in mysql_stmt_execute (thd=0x1e8e070, packet_arg=0x1e90a61 "4", packet_length=17)
    at sql_prepare.cc:2465
#17 0x000000000069a59d in dispatch_command (command=COM_STMT_EXECUTE, thd=0x1e8e070, packet=0x1e90a61 "4", packet_length=17)
    at sql_parse.cc:960
#18 0x000000000069aa86 in do_command (thd=0x1e8e070) at sql_parse.cc:689
#19 0x000000000068def4 in handle_one_connection (arg=0x1e8e070) at sql_connect.cc:1156
#20 0x00002ab3ca753193 in start_thread () from /lib64/libpthread.so.0
#21 0x00002ab3cad8645d in clone () from /lib64/libc.so.6
#22 0x0000000000000000 in ?? ()

The issue is still here(6.0.11pre falcon-team tree):

(gdb) bt
#0  0x00002ae2364514c5 in pthread_kill () from /lib64/libpthread.so.0
#1  0x000000000069175e in handle_segfault (sig=11) at mysqld.cc:2690
#2  <signal handler called>
#3  Record::isNull (this=0x2aaaed757710, fieldId=-308591173) at EncodedDataStream.h:350
#4  0x00000000008c5157 in StorageTable::compareKey (this=0x2aaaeae5a240, key=<value optimized out>, keyLength=<value optimized out>) at StorageTable.cpp:459
#5  0x00000000008b77ab in StorageInterface::index_next_same (this=0x2aaaea7303f8, buf=0x2aaaea7307d8 "\001", key=0x1d46dc8 "#", key_len=2) at ha_falcon.cpp:1910
#6  0x0000000000717d2f in join_read_next_same (info=<value optimized out>) at sql_select.cc:16957
#7  0x00000000007027c7 in sub_select (join=0x2aaaea0c7638, join_tab=0x1d46b28, end_of_records=<value optimized out>) at sql_select.cc:16245
#8  0x000000000070ee93 in do_select (join=0x2aaaea0c7638, fields=0x1d94f48, table=0x0, procedure=0x0) at sql_select.cc:15786
#9  0x000000000072331d in JOIN::exec (this=0x2aaaea0c7638) at sql_select.cc:2881
#10 0x0000000000724c3b in mysql_select (thd=0x2aaaea417770, rref_pointer_array=0x1d95028, tables=0x1d95b48, wild_num=0, fields=@0x1d94f48, conds=0x2aaaea508f28, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2417248768, result=0x1d96800, unit=0x1d949d8, select_lex=0x1d94e40) at sql_select.cc:3062
#11 0x000000000072563f in handle_select (thd=0x2aaaea417770, lex=0x1d94938, result=0x1d96800, setup_tables_done_option=0) at sql_select.cc:314
#12 0x000000000069d559 in execute_sqlcom_select (thd=0x2aaaea417770, all_tables=0x1d95b48) at sql_parse.cc:4768
#13 0x00000000006a350c in mysql_execute_command (thd=0x2aaaea417770) at sql_parse.cc:2069
#14 0x0000000000731157 in Prepared_statement::execute (this=0x1d81aa0, expanded_query=<value optimized out>, open_cursor=false) at sql_prepare.cc:3764
#15 0x00000000007339af in Prepared_statement::execute_loop (this=0x1d81aa0, expanded_query=0x407283b0, open_cursor=false, packet=<value optimized out>, packet_end=<value optimized out>) at sql_prepare.cc:3394
#16 0x0000000000733fab in mysql_stmt_execute (thd=0x2aaaea417770, packet_arg=0x2aaaea41ab71 "", packet_length=17) at sql_prepare.cc:2542
#17 0x00000000006a7770 in dispatch_command (command=COM_STMT_EXECUTE, thd=0x2aaaea417770, packet=0x2aaaea41ab71 "", packet_length=17) at sql_parse.cc:963
#18 0x00000000006a7de2 in do_command (thd=0x2aaaea417770) at sql_parse.cc:691
#19 0x000000000069a9b4 in handle_one_connection (arg=0x2aaaea417770) at sql_connect.cc:1146
#20 0x00002ae23644d193 in start_thread () from /lib64/libpthread.so.0
#21 0x00002ae236a8045d in clone () from /lib64/libc.so.6
#22 0x0000000000000000 in ?? ()

One need to use following test-case to get the latest observed crash.

prepare
-------
mysql -uroot -e'drop database if exists phptest; create database phptest'

sysbench \
--test=/tmp/phptest.lua \
--oltp-table-size=1000000 \
--oltp-table-name=phptest \
--rand-type=uniform \
--mysql-user=root  \
--mysql-table-engine=falcon \
--mysql-db=phptest \
prepare

run
---
sysbench  \
--oltp-table-size=1000000  \
--oltp-table-name=phptest \
--rand-type=uniform \
--mysql-user=root \
--mysql-socket=/tmp/mysql.sock \
--mysql-table-engine=falcon \
--mysql-db=phptest  \
--trx-mode=0 \
--subtest=READ_KEY_POINT_NO_DATA \
--test=/tmp/phptest.lua \
--max-requests=0 \
--max-time=300 \
--num-threads=128 \
run

Could not reproduce the same crash on Windows.

Instead got

[Falcon] Error: assertion (vector[index] < size) failed at line 679 in file .\Record.cpp

with the callstack. 
000000013FC24EC5    mysqld.exe!Error::debugBreak()[error.cpp:94]
000000013FC24FC8    mysqld.exe!Error::error()[error.cpp:73]
000000013FC25006    mysqld.exe!Error::assertionFailed()[error.cpp:78]
000000013FC488F9    mysqld.exe!Record::getEncodedValue()[record.cpp:679]
000000013FC499E5    mysqld.exe!Record::getValue()[record.cpp:335]
000000013FC24801    mysqld.exe!StorageTable::compareKey()[storagetable.cpp:467]
000000013FC18C66    mysqld.exe!StorageInterface::index_next_same()[ha_falcon.cpp:1912]
000000013F9E8FEF    mysqld.exe!join_read_next_same()[sql_select.cc:16959]
000000013FA08554    mysqld.exe!sub_select()[sql_select.cc:16245]
000000013FA09779    mysqld.exe!do_select()[sql_select.cc:15786]
000000013FA0F122    mysqld.exe!JOIN::exec()[sql_select.cc:2882]
000000013FA127C1    mysqld.exe!mysql_select()[sql_select.cc:3064]
000000013FA12D26    mysqld.exe!handle_select()[sql_select.cc:314]
000000013F9BFDD3    mysqld.exe!execute_sqlcom_select()[sql_parse.cc:4768]
000000013F9C281A    mysqld.exe!mysql_execute_command()[sql_parse.cc:2069]
000000013F9DC78B    mysqld.exe!Prepared_statement::execute()[sql_prepare.cc:3764]
...

It looks like this call stack shows a code path in which a pending but chilled record is accessed without making a call to Record::hasRecord().

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/69934

3069 Christopher Powers	2009-03-20
      Bug #42131, "falcon_backlog test crashes in Record::getEncodedValue"
      Bug #38375, "Falcon crash in Record::isNull"
      
      For sequential operations such as index and table scans, StorageTable
      caches the current record in StorageTable::record. In rare cases, it is
      possible that StorageTable::record may have been chilled. This is a
      problem if an attempt is made to examine the contents of the record.
      
      Calls from the server directly into the storage interface, such as 
      StorageInterface::rnd_next, bypass the internal checks in Falcon that
      ensure a record is thawed before examining it.To avoid crashes in this
      circumstance, StorageTable::compareKey() now thaws StorageTable::record
      if necessary before examining it.
      
      Note that it is not necessary to always thaw StorageTable::record, e.g. in
      StorageTable::setRecord(), because the contents of the record is not always
      examined as it is in compareKey().
      modified:
        storage/falcon/StorageTable.cpp

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/70771

3085 Christopher Powers	2009-03-28
      Bug #42131, "falcon_backlog test crashes in Record::getEncodedValue"
      Bug #38375, "Falcon crash in Record::isNull"
      
      For sequential operations such as index and table scans, StorageTable
      caches the current record in StorageTable::record. In rare cases, it is
      possible that StorageTable::record may have been chilled. This is a
      problem if an attempt is made to examine the contents of the record.
      
      Calls from the server directly into the storage interface, such as
      StorageInterface::rnd_next, bypass the internal checks in Falcon that
      ensure a record is thawed before examining it.To avoid crashes in this
      circumstance, StorageTable::compareKey() now thaws StorageTable::record
      if necessary before examining it.
      
      Note that it is not necessary to always thaw StorageTable::record, for
      example in StorageTable::setRecord(), because the contents of the
      record is not always examined as it is in compareKey().
      
      If a thaw is necessary, and if the thaw fails, then compareKey() throws
      an INTERNAL_ERROR exception.
      modified:
        storage/falcon/StorageTable.cpp
        storage/falcon/StorageTableShare.h

Pushed into 6.0.11-alpha (revid:hky@sun.com-20090402144811-yc5kp8g0rjnhz7vy) (version source revid:christopher.powers@sun.com-20090328181017-hadhr0dt1a389301) (merge vers: 6.0.11-alpha) (pib:6)