Aria assertion "!pinned_page->changed || undo_lsn != ((LSN)0) || !info->s->now_transactional

[Philip Stoev]

When executing a DML workload with multiple indexes, aria asserted as follows:

#2 0x00000000006729f7 in handle_segfault (sig=6) at mysqld.cc:2728
#3 <signal handler called>
#4 0x000000307b6329c5 in raise (sig=6)
    at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
#5 0x000000307b6341a5 in abort () at abort.c:92
#6 0x000000307b62b945 in __assert_fail (
    assertion=0xd763b8 "!pinned_page->changed || undo_lsn != ((LSN)0) || !info->s->now_transactional", file=<value optimized out>, line=68,
    function=<value optimized out>) at assert.c:81
#7 0x00000000009823cb in _ma_unpin_all_pages (info=0x7f910004ec68,
    undo_lsn=0) at ma_key_recover.c:67
#8 0x0000000000996620 in _ma_unpin_all_pages_and_finalize_row (
    info=0x7f910004ec68, undo_lsn=0) at ma_key_recover.h:102
#9 0x000000000099f3cd in _ma_update_block_record2 (info=0x7f910004ec68,
    record_pos=1545, oldrec=0x7f91000413f0 "\367\237\377",
    record=0x7f910003ffb0 "\367\233\377", undo_lsn=1) at ma_blockrec.c:3713
#10 0x000000000099f9a6 in _ma_update_block_record (info=0x7f910004ec68,
    record_pos=1545, orig_rec=0x7f91000413f0 "\367\237\377",
    new_rec=0x7f910003ffb0 "\367\233\377") at ma_blockrec.c:3850
#11 0x00000000009ae79d in maria_update (info=0x7f910004ec68,
    oldrec=0x7f91000413f0 "\367\237\377",
    newrec=0x7f910003ffb0 "\367\233\377") at ma_update.c:160
#12 0x000000000096a103 in ha_maria::update_row (this=0x7f9100012230,
    old_data=0x7f91000413f0 "\367\237\377",
    new_data=0x7f910003ffb0 "\367\233\377") at ha_maria.cc:2113
#13 0x00000000007cee75 in handler::ha_update_row (this=0x7f9100012230,
    old_data=0x7f91000413f0 "\367\237\377",
    new_data=0x7f910003ffb0 "\367\233\377") at handler.cc:4869
#14 0x00000000007d7eba in ha_partition::update_row (this=0x7f91000114e0,
    old_data=0x7f91000413f0 "\367\237\377",
    new_data=0x7f910003ffb0 "\367\233\377") at ha_partition.cc:3162
#15 0x00000000007cee75 in handler::ha_update_row (this=0x7f91000114e0,
    old_data=0x7f91000413f0 "\367\237\377",
    new_data=0x7f910003ffb0 "\367\233\377") at handler.cc:4869
#16 0x0000000000742a62 in mysql_update (thd=0x3ab8b18,
    table_list=0x7f911c014ec8, fields=..., values=..., conds=0x7f911c0159d0,
    order_num=0, order=0x0, limit=18446744073709551511,
    handle_duplicates=DUP_ERROR, ignore=false) at sql_update.cc:652
#17 0x000000000068849e in mysql_execute_command (thd=0x3ab8b18)
    at sql_parse.cc:3120
#18 0x000000000069151e in mysql_parse (thd=0x3ab8b18,
    inBuf=0x7f911c014bf0 "UPDATE `table100_maria_key_pk_parts_2_int_autoinc` SET `col_varchar_255_utf8_key` = REPEAT( _LATIN1 0x176 , 190 ) WHERE `col_varchar_255_ucs2_key` <> REPEAT( _UCS2 0x55 , 50 )", length=175,
    found_semicolon=0x7f912bffec88) at sql_parse.cc:6055
#19 0x00000000006834e2 in dispatch_command (command=COM_QUERY, thd=0x3ab8b18,
    packet=0x3b581e9 "UPDATE `table100_maria_key_pk_parts_2_int_autoinc` SET `col_varchar_255_utf8_key` = REPEAT( _LATIN1 0x176 , 190 ) WHERE `col_varchar_255_ucs2_key` <> REPEAT( _UCS2 0x55 , 50 ) ", packet_length=176)
    at sql_parse.cc:1204
#20 0x00000000006828a8 in do_command (thd=0x3ab8b18) at sql_parse.cc:898
#21 0x000000000067f898 in handle_one_connection (arg=0x3ab8b18)
    at sql_connect.cc:1154
#22 0x000000307ba07761 in start_thread (arg=0x7f912bfff710)
    at pthread_create.c:301
#23 0x000000307b6e150d in clone ()

rqg command line:

 /home/buildbot/randgen/runall.pl \
 --basedir=. \
 --vardir=../../vardir-maria_many_indexes \
 --grammar=/home/buildbot/randgen/conf/engines/many_indexes.yy \
 --gendata=/home/buildbot/randgen/conf/engines/many_indexes.zz \
 --rows=10000 \
 --reporter=Backtrace,ErrorLog,Recovery,Shutdown \
 --duration=240 \
 --queries=1M \
 --engine=Maria \
 --rows=10000 \
 --mysqld=--maria-checkpoint-interval=0 \
 --mysqld=--log-output=file \
 --seed=time

[Philip Stoev (pstoev-askmonty)]

Core binary, vardir, etc

bzr version-info:

revision-id: <email address hidden>
date: 2010-08-11 01:04:46 +0300
build-date: 2010-08-11 11:30:03 +0300
revno: 2846
branch-nick: 5.2

[Philip Stoev (pstoev-askmonty)]

This RQG command line reproduces this crash within 220 seconds

perl runall.pl --basedir=/home/philips/bzr/maria-5.1 --vardir=/home/philips/vardir-recovery$i --grammar=conf/engines/many_indexes.yy --gendata=conf/engines/many_indexes.zz --rows=10000 --reporter=Backtrace,ErrorLog,Recovery,Shutdown --duration=240 --queries=1M --engine=Maria --rows=10000 --mysqld=--maria-checkpoint-interval=0 --mysqld=--log-output=file --seed=time

[Philip Stoev (pstoev-askmonty)]

This assertion is also seen on recovery, with the following backtrace:

#8 0x00897de8 in __assert_fail () from /lib/libc.so.6
#9 0x08531ca3 in _ma_unpin_all_pages (info=0x97cd528, undo_lsn=0) at ma_key_recover.c:67
#10 0x08544bd4 in _ma_unpin_all_pages_and_finalize_row (info=0x97cd528, undo_lsn=0) at ma_key_recover.h:102
#11 0x0854cbbb in _ma_update_at_original_place (info=0x97cd528, page=16, rownr=12, length_on_head_page=502, extent_count=0,
    extent_info=0x97c1b43 "\001\377\356\377\375", '\003' <repeats 76 times>, oldrec=0x9837da0 "n\377\375", '\b' <repeats 197 times>...,
    record=0x98391df "\356\377\375", '\b' <repeats 197 times>..., undo_lsn=4334155267) at ma_blockrec.c:3840
#12 0x085550f1 in _ma_apply_undo_row_update (info=0x97cd528, undo_lsn=4334155267, header=0x97c1b48 '\003' <repeats 76 times>, header_length=15)
    at ma_blockrec.c:7144
#13 0x0859e799 in exec_UNDO_LOGREC_UNDO_ROW_UPDATE (rec=0xbfa1e888, trn=0x97b5b78) at ma_recovery.c:2230
#14 0x0859fe23 in run_undo_phase (uncommitted=0) at ma_recovery.c:2805
#15 0x0859a517 in maria_apply_log (from_lsn=4294975495, end_lsn=0, apply=MARIA_LOG_APPLY, trace_file=0x9763e38, should_run_undo_phase=1 '\001',
    skip_DDLs_arg=1 '\001', take_checkpoints=1 '\001', warnings_count=0xbfa1eff4) at ma_recovery.c:394
#16 0x0859a070 in maria_recovery_from_log () at ma_recovery.c:221
#17 0x0851e0e5 in ha_maria_init (p=0x975f0c8) at ha_maria.cc:3259
#18 0x08397599 in ha_initialize_handlerton (plugin=0x97457f8) at handler.cc:430
#19 0x084526a7 in plugin_initialize (plugin=0x97457f8) at sql_plugin.cc:1039
#20 0x08452ec9 in plugin_init (argc=0x8a4b8d8, argv=0x9712870, flags=0) at sql_plugin.cc:1267
#21 0x0826be7b in init_server_components () at mysqld.cc:4131
#22 0x0826c937 in main (argc=14, argv=0xbfa1f5e4) at mysqld.cc:4603

[Michael Widenius (monty)]

This was fixed by my previous commit into 5.1.
I didn't include the bug number in the push as I found and fixed the bug independently and didn't know about this bug report.

[Philip Stoev (pstoev-askmonty)]

I can confirm this is fixed.