XtraDB crash in insert / delete load

[Percona]

(gdb) bt
#0 0x00000033d7c30055 in raise () from /lib64/libc.so.6
#1 0x00000033d7c31af0 in abort () from /lib64/libc.so.6
#2 0x0000000000722179 in buf_page_get_zip (space=100062, zip_size=16384, offset=11919)
    at ../../storage/innobase/include/sync0rw.ic:510
#3 0x000000000070c06c in btr_copy_externally_stored_field_prefix_low (buf=0x2aac6bc200b8 "", len=<value optimized out>,
    zip_size=16384, space_id=100062, page_no=0, offset=12) at btr/btr0cur.c:4441
#4 0x000000000070c703 in btr_rec_copy_externally_stored_field (rec=<value optimized out>, offsets=<value optimized out>,
    zip_size=16384, no=<value optimized out>, len=0x45b1d230, heap=<value optimized out>) at btr/btr0cur.c:4692
#5 0x000000000079e0b1 in row_sel_store_mysql_rec (mysql_rec=0x4d35ff0 " c81e728d9d4c2f636f067f89cc14862c\001",
    prebuilt=0x2aac6bbf54b8, rec=0x2aac7f023c5b "c81e728d9d4c2f636f067f89cc14862c", offsets=0x45b1d410) at row/row0sel.c:2761
#6 0x00000000007a02f5 in row_search_for_mysql (buf=0x4d35ff0 " c81e728d9d4c2f636f067f89cc14862c\001", mode=2,
    prebuilt=0x2aac6bbf54b8, match_mode=1, direction=0) at row/row0sel.c:4400
#7 0x00000000007028f2 in ha_innobase::index_read (this=0x4d35e00, buf=0x4d35ff0 " c81e728d9d4c2f636f067f89cc14862c\001",
    key_ptr=<value optimized out>, key_len=34, find_flag=HA_READ_KEY_EXACT) at handler/ha_innodb.cc:4933
#8 0x0000000000664dff in handler::read_range_first (this=0x4d35e00, start_key=<value optimized out>,
    end_key=<value optimized out>, eq_range_arg=<value optimized out>, sorted=<value optimized out>) at handler.cc:4155
#9 0x0000000000666c83 in handler::read_multi_range_first (this=0x4d35e00, found_range_p=0x45b1dd00, ranges=0x4d35970,
    range_count=1, sorted=<value optimized out>, buffer=<value optimized out>) at handler.cc:4029
#10 0x00000000006519fd in QUICK_RANGE_SELECT::get_next (this=0x4d33b80) at opt_range.cc:8446
#11 0x00000000006606ed in rr_quick (info=0x45b1ddd0) at records.cc:313
#12 0x000000000061b453 in mysql_delete (thd=0x4d37550, table_list=0x4d41f78, conds=0x4d424b0, order=<value optimized out>,
    limit=18446744073709551615, options=0, reset_auto_increment=false) at sql_delete.cc:278
#13 0x000000000059a6f7 in mysql_execute_command (thd=0x4d37550) at sql_parse.cc:3216
#14 0x000000000059d0fc in mysql_parse (thd=0x4d37550,
    inBuf=0x4d41e30 "DELETE FROM sessions WHERE ID='c81e728d9d4c2f636f067f89cc14862c'", length=71,
    found_semicolon=0x45b1f8b8) at sql_parse.cc:5809
#15 0x000000000059e0b8 in dispatch_command (command=COM_QUERY, thd=0x4d37550, packet=<value optimized out>,
    packet_length=<value optimized out>) at sql_parse.cc:1216
#16 0x000000000059e616 in do_command (thd=0x4d37550) at sql_parse.cc:857
#17 0x0000000000591884 in handle_one_connection (arg=0x4d37550) at sql_connect.cc:1115
#18 0x00000033d8c062f7 in start_thread () from /lib64/libpthread.so.0
#19 0x00000033d7cce85d in clone () from /lib64/libc.so.6

error.log

090213 19:40:34 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.1.31-percona-log' socket: '/var/lib/mysql/mysql.sock' port: 3306 MySQL Community Server (GPL)
090213 19:43:12 InnoDB: Assertion failure in thread 1169295680 in file ../../storage/innobase/include/sync0rw.ic line 510
InnoDB: Failing assertion: lock->reader_count > 0
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.1/en/forcing-recovery.html
InnoDB: about forcing recovery.
/usr/sbin/mysqld(my_print_stacktrace+0x35)[0x839255]
/usr/sbin/mysqld(handle_segfault+0x31d)[0x58a91d]
/lib64/libpthread.so.0[0x33d8c0de70]
/lib64/libc.so.6(gsignal+0x35)[0x33d7c30055]
/lib64/libc.so.6(abort+0x110)[0x33d7c31af0]
/usr/sbin/mysqld[0x722179]
/usr/sbin/mysqld[0x70c06c]
/usr/sbin/mysqld[0x70c703]
/usr/sbin/mysqld[0x79e0b1]
/usr/sbin/mysqld[0x7a02f5]
/usr/sbin/mysqld[0x7028f2]
/usr/sbin/mysqld(_ZN7handler16read_range_firstEPK12st_key_rangeS2_bb+0xbf)[0x664dff]
/usr/sbin/mysqld(_ZN7handler22read_multi_range_firstEPP18st_key_multi_rangeS1_jbP17st_handler_buffer+0xd3)[0x666c83]
/usr/sbin/mysqld(_ZN18QUICK_RANGE_SELECT8get_nextEv+0x13d)[0x6519fd]
/usr/sbin/mysqld[0x6606ed]
/usr/sbin/mysqld(_Z12mysql_deleteP3THDP10TABLE_LISTP4ItemP11st_sql_listyyb+0x7a3)[0x61b453]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x2f07)[0x59a6f7]
/usr/sbin/mysqld(_Z11mysql_parseP3THDPKcjPS2_+0x1dc)[0x59d0fc]
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0xf98)[0x59e0b8]
/usr/sbin/mysqld(_Z10do_commandP3THD+0xe6)[0x59e616]
/usr/sbin/mysqld(handle_one_connection+0x5b4)[0x591884]
/lib64/libpthread.so.0[0x33d8c062f7]
/lib64/libc.so.6(clone+0x6d)[0x33d7cce85d]

Table definition:
CREATE TABLE `sessions` (
  `ID` varchar(32) NOT NULL DEFAULT '',
  `Last` int(11) NOT NULL DEFAULT '0',
  `C` text NOT NULL,
  PRIMARY KEY (`ID`),
  KEY `Last` (`Last`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1 KEY_BLOCK_SIZE=16

[Percona (percona-team)]

Also there is reported problem with the similar insert / delete workload (replication thread)

090213 9:25:24 InnoDB: Assertion failure in thread 1316211008 in file btr/btr0cur.c line 4231
InnoDB: Failing assertion: fil_page_get_type(page) == FIL_PAGE_TYPE_BLOB
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.1/en/forcing-recovery.html
InnoDB: about forcing recovery.
/usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x819b2e]
/usr/sbin/mysqld(handle_segfault+0x322)[0x5817c2]
/lib64/libpthread.so.0[0x36e700de70]
/lib64/libc.so.6(gsignal+0x35)[0x36e6430155]
/lib64/libc.so.6(abort+0x110)[0x36e6431bf0]
/usr/sbin/mysqld[0x6f3dfc]
/usr/sbin/mysqld[0x77fea3]
/usr/sbin/mysqld[0x76bf27]
/usr/sbin/mysqld[0x799f87]
/usr/sbin/mysqld[0x792df5]
/lib64/libpthread.so.0[0x36e70062f7]
/lib64/libc.so.6(clone+0x6d)[0x36e64d1e3d]
090213 9:25:24 - mysqld got signal 6 ;
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=402653184
read_buffer_size=1048576
max_used_connections=0
max_threads=4000
threads_connected=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 37297841 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0x0
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 = (nil) thread_stack 0x40000
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.

and may be related to http://forums.innodb.com/read.php?3,114,114

I am not sure if it is the same bug or another

[Percona (percona-team)]

Stack trace for second case

Thread with DELETE:

Thread 10 (process 7914):
#0 0x00000036e700d7a8 in pread64 () from /lib64/libpthread.so.0
#1 0x0000000000770f4e in os_file_pread (file=39, buf=0x2aaadced0000, n=16384, offset=<value optimized out>, offset_high=0)
    at os/os0file.c:1998
#2 0x00000000007710a4 in os_file_read (file=39, buf=0x2aaadced0000, offset=1238843392, offset_high=0, n=16384)
    at os/os0file.c:2232
#3 0x0000000000741069 in fil_io (type=<value optimized out>, sync=<value optimized out>, space_id=381, zip_size=0,
---Type <return> to continue, or q <return> to quit---
    block_offset=1238843392, byte_offset=0, len=16384, buf=0x2aaadced0000, message=0x2aaad965d960) at fil/fil0fil.c:4447
#4 0x000000000072b870 in buf_read_page_low (err=0x41b40a20, sync=1, mode=132, space=381, zip_size=0, unzip=<value optimized out>,
    tablespace_version=102, offset=75613) at buf/buf0rea.c:143
#5 0x000000000072c2f7 in buf_read_page (space=381, zip_size=0, offset=75613) at buf/buf0rea.c:353
#6 0x0000000000721abe in buf_page_get_gen (space=381, zip_size=0, offset=75613, rw_latch=1, guess=0x0, mode=10,
    file=0x9257b2 "btr/btr0cur.c", line=<value optimized out>, mtr=0x41b41420) at buf/buf0buf.c:1933
#7 0x000000000070cfa3 in btr_cur_search_to_nth_level (index=0x2aaad910dcb8, level=0, tuple=0x2aaad9387e70, mode=2,
    latch_mode=<value optimized out>, cursor=0x2aaad93890b8, has_search_latch=0, mtr=0x41b41420) at btr/btr0cur.c:465
#8 0x00000000007a0812 in row_search_for_mysql (buf=0xccde510 "", mode=2, prebuilt=0x2aaad9387cb8, match_mode=1, direction=0)
    at ../../storage/innobase/include/btr0pcur.ic:544
#9 0x00000000007028f2 in ha_innobase::index_read (this=0xccde320, buf=0xccde510 "", key_ptr=<value optimized out>, key_len=34,
    find_flag=HA_READ_KEY_EXACT) at handler/ha_innodb.cc:4933
#10 0x0000000000664dff in handler::read_range_first (this=0xccde320, start_key=<value optimized out>,
    end_key=<value optimized out>, eq_range_arg=<value optimized out>, sorted=<value optimized out>) at handler.cc:4155
#11 0x0000000000666c83 in handler::read_multi_range_first (this=0xccde320, found_range_p=0x41b419c0, ranges=0x2aaaac047620,
    range_count=1, sorted=<value optimized out>, buffer=<value optimized out>) at handler.cc:4029
#12 0x00000000006519fd in QUICK_RANGE_SELECT::get_next (this=0x2aaaac00c550) at opt_range.cc:8446
#13 0x00000000006606ed in rr_quick (info=0x41b41a90) at records.cc:313
#14 0x000000000061b453 in mysql_delete (thd=0xcd31520, table_list=0xcd37e98, conds=0xcd383d0, order=<value optimized out>,
    limit=18446744073709551615, options=0, reset_auto_increment=false) at sql_delete.cc:278
#15 0x000000000059a6f7 in mysql_execute_command (thd=0xcd31520) at sql_parse.cc:3216
#16 0x000000000059d0fc in mysql_parse (thd=0xcd31520,
    inBuf=0x2aaaac0078cc "DELETE FROM sessions WHERE ID = 'e2e8cbe26c457db940359cfc7b5c873f'", length=73,
    found_semicolon=0x41b42f78) at sql_parse.cc:5809
#17 0x00000000006455db in Query_log_event::do_apply_event (this=0x2aaaac047540, rli=0xcb75920,
    query_arg=0x2aaaac0078cc "DELETE FROM sessions WHERE ID = 'e2e8cbe26c457db940359cfc7b5c873f'", q_len_arg=73)
    at log_event.cc:3011
...

[Yasufumi Kinoshita (yasufumi-kinoshita)]

I have pushed the new trial branch.

~percona-dev/percona-xtradb/bug-329290-test

I think it may fix the bug.
But I don't reproduce the second and third cases at my server, so I cannot confirm whether it fixes or not...

[Yasufumi Kinoshita (yasufumi-kinoshita)]

Do you use READ_COMMITTED isolation?
Please try all transaction as REPEATABLE_READ or SERIALIZABLE?
Hmm....

[Yasufumi Kinoshita (yasufumi-kinoshita)]

I have got additional information about reproduction of this situation.

It may be compatibility problem between 5.0-innodb and 5.1-innodb and Plugin.
5.0 datafile don't use FIL_PAGE_TYPE_BLOB.
5.1 ignores PAGE_TYPE at btr_free_externally_stored_field().
Plugin has assertion code to check PAGE_TYPE at btr_free_externally_stored_field().

Strictly, I may not be able to recommend to use 5.0 files by InnoDB-Plugin/XtraDB.
Because, we should skip some useful assertion code to work.

fil0fil.h (InnoDB-Plugin):
/* File page types (values of FIL_PAGE_TYPE) */
#define FIL_PAGE_INDEX 17855 /* B-tree node */
#define FIL_PAGE_UNDO_LOG 2 /* Undo log page */
#define FIL_PAGE_INODE 3 /* Index node */
#define FIL_PAGE_IBUF_FREE_LIST 4 /* Insert buffer free list */
/* File page types introduced in MySQL/InnoDB 5.1.7 */
#define FIL_PAGE_TYPE_ALLOCATED 0 /* Freshly allocated page */
#define FIL_PAGE_IBUF_BITMAP 5 /* Insert buffer bitmap */
#define FIL_PAGE_TYPE_SYS 6 /* System page */
#define FIL_PAGE_TYPE_TRX_SYS 7 /* Transaction system data */
#define FIL_PAGE_TYPE_FSP_HDR 8 /* File space header */
#define FIL_PAGE_TYPE_XDES 9 /* Extent descriptor page */
#define FIL_PAGE_TYPE_BLOB 10 /* Uncompressed BLOB page */
#define FIL_PAGE_TYPE_ZBLOB 11 /* First compressed BLOB page */
#define FIL_PAGE_TYPE_ZBLOB2 12 /* Subsequent compressed BLOB page */

(* FIL_PAGE_TYPE_ZBLOB and FIL_PAGE_TYPE_ZBLOB2 is for Plugin only)

[Yasufumi Kinoshita (yasufumi-kinoshita)]

Now it is depend on bug of InnoDB Plugin 1.0.2
http://bugs.mysql.com/bug.php?id=43043

(The comments are invisible?)

[Evgeniy Stepchenko (evgeny-stepchenko)]

fixed in 1.0.3 plugin