Bug #42516 Maria assertion at ma_key_recover.c:68: _ma_unpin_all_pages()
Submitted: 1 Feb 2009 14:10 Modified: 26 May 2010 17:51
Reporter: Philip Stoev Email Updates:
Status: Unsupported Impact on me:
None 
Category:MySQL Server: Maria storage engine Severity:S2 (Serious)
Version:6.0-maria OS:Any
Assigned to: CPU Architecture:Any

[1 Feb 2009 14:10] Philip Stoev
Description:
When executing a concurrent workload involving large fields and numerous indexes, Maria asserted as follows:

mysqld: ma_key_recover.c:68: _ma_unpin_all_pages: Assertion `!pinned_page->changed || undo_lsn != ((LSN)0) || !info->s->now_transactional' failed.

#6  0x000000315a42bec9 in __assert_fail () from /lib64/libc.so.6
#7  0x0000000000b9840d in _ma_unpin_all_pages (info=0x270c878, undo_lsn=0) at ma_key_recover.c:67
#8  0x0000000000bb2cac in _ma_unpin_all_pages_and_finalize_row (info=0x270c878, undo_lsn=0) at ma_key_recover.h:109
#9  0x0000000000bb388f in _ma_update_block_record2 (info=0x270c878, record_pos=12037, oldrec=0x26dabc8 "ЪЪФЪ", record=0x26d8370 "ЪЪФЪ", undo_lsn=1)
    at ma_blockrec.c:3666
#10 0x0000000000bb3d96 in _ma_update_block_record (info=0x270c878, record_pos=12037, orig_rec=0x26dabc8 "ЪЪФЪ", new_rec=0x26d8370 "ЪЪФЪ")
    at ma_blockrec.c:3803
#11 0x0000000000bc15a4 in maria_update (info=0x270c878, oldrec=0x26dabc8 "ЪЪФЪ", newrec=0x26d8370 "ЪЪФЪ") at ma_update.c:160
#12 0x0000000000b79861 in ha_maria::update_row (this=0x26a4a00, old_data=0x26dabc8 "ЪЪФЪ", new_data=0x26d8370 "ЪЪФЪ") at ha_maria.cc:1830
#13 0x000000000080c4a4 in handler::ha_update_row (this=0x26a4a00, old_data=0x26dabc8 "ЪЪФЪ", new_data=0x26d8370 "ЪЪФЪ") at handler.cc:5462
#14 0x000000000078e020 in mysql_update (thd=0x7ff73ceb3128, table_list=0x26acea8, fields=@0x7ff73ceb5258, values=@0x7ff73ceb5660, conds=0x26ad958,
    order_num=0, order=0x0, limit=18446744073709551504, handle_duplicates=DUP_ERROR, ignore=false) at sql_update.cc:649
#15 0x00000000006d4400 in mysql_execute_command (thd=0x7ff73ceb3128) at sql_parse.cc:3005
#16 0x00000000006d9f57 in mysql_parse (thd=0x7ff73ceb3128,
    inBuf=0x26aca50 "UPDATE `table10_int_autoinc` SET `char_255_utf8` = REPEAT( _LATIN1 x'A4AB' , 218 ) WHERE `varchar_255_utf8` IS  NULL", length=116,
    found_semicolon=0x7ff72e0bcf00) at sql_parse.cc:5735
#17 0x00000000006dab42 in dispatch_command (command=COM_QUERY, thd=0x7ff73ceb3128,
    packet=0x7ff73cebd9f9 "UPDATE `table10_int_autoinc` SET `char_255_utf8` = REPEAT( _LATIN1 x'A4AB' , 218 ) WHERE `varchar_255_utf8` IS  NULL ",
    packet_length=117) at sql_parse.cc:1007
#18 0x00000000006dc06b in do_command (thd=0x7ff73ceb3128) at sql_parse.cc:690
#19 0x00000000006ca181 in handle_one_connection (arg=0x7ff73ceb3128) at sql_connect.cc:1145
#20 0x000000315b0073da in start_thread () from /lib64/libpthread.so.0
#21 0x000000315a4e627d in clone () from /lib64/libc.so.6

(gdb) list
62            Note this assert fails if we got a disk error or the record file
63            is corrupted, which means we should have this enabled only in debug
64            builds.
65          */
66      #ifdef EXTRA_DEBUG
67          DBUG_ASSERT(!pinned_page->changed ||
68                      undo_lsn != LSN_IMPOSSIBLE || !info->s->now_transactional);
69      #endif
70          pagecache_unlock_by_link(info->s->pagecache, pinned_page->link,
71                                   pinned_page->unlock, PAGECACHE_UNPIN,

(gdb) print pinned_page->changed
$1 = 1 '\001'
(gdb) print undo_lsn
$2 = 0
(gdb) print info->s->now_transactional
$3 = 1 '\001'

How to repeat:
A test case will be uploaded shortly.
[1 Feb 2009 14:12] Philip Stoev
YY file

Attachment: bug42516.yy (application/octet-stream, text), 920 bytes.

[1 Feb 2009 14:13] Philip Stoev
ZZ file for this bug

Attachment: bug42516.zz (text/plain), 385 bytes.

[1 Feb 2009 14:15] Philip Stoev
To reproduce, please run:

$ perl runall.pl \
  --basedir=/build/bzr/6.0-maria/ \
  --bug42516.yy \
  --gendata=bug42516.zz \
  --queries=10000 \
  --threads=1 \
  --vardir1=/tmp/vardir1 --mysqld1=--default-storage-engine=Maria

The workload is not concurrent. Recovery after the crash fails with:

# 16:14:56 090201 16:14:56 [Note] mysqld: Maria engine: starting recovery
# 16:14:57 recovered pages: 0%090201 16:14:57 [ERROR] mysqld: Got error 127 when executing record redo_insert_row_head
# 16:14:57 090201 16:14:57 [ERROR] mysqld: Maria engine: Redo phase failed
# 16:14:57 090201 16:14:57 [ERROR] mysqld: Maria recovery failed. Please run maria_chk -r on all maria tables and delete all maria_log.######## files
# 16:14:57 090201 16:14:57 [ERROR] Plugin 'MARIA' init function returned error.
# 16:14:57 090201 16:14:57 [ERROR] Plugin 'MARIA' registration as a STORAGE ENGINE failed.
# 16:14:57 mysqld: ma_close.c:138: maria_close: Assertion `share->now_transactional == share->base.born_transactional' failed.