Aria recovery assertion block->org_bitmap_value == _ma_bitmap_get_page_bits(info, &info->s->bitmap, page) in _ma_update_at_original_place

[Philip Stoev]

When recovering from a kill -9 of a DML workload, Aria asserted as follows:

recovered pages: 0% 10% 20% 30% 40% 50% 60% 70% 80% 90% 100% (26.1 seconds); transactions to roll back: 1mysqld: ma_blockrec.c:3820: _ma_update_at_original_place: Assertion `block->org_bitmap_value == _ma_bitmap_get_page_bits(info, &info->s->bitmap, page)' failed.

backtrace:

#6 0x000000307b62b945 in __assert_fail (assertion=0xd56538 "block->org_bitmap_value == _ma_bitmap_get_page_bits(info, &info->s->bitmap, page)",
    file=<value optimized out>, line=3820, function=<value optimized out>) at assert.c:81
#7 0x00000000009892c1 in _ma_update_at_original_place (info=0x392e658, page=10, rownr=66, length_on_head_page=35, extent_count=0,
    extent_info=0x397bf2b "\002\002\004\003", oldrec=0x394e938 "\341\377\377\377\177", record=0x394e95d "\341\377\377\377\177\003", undo_lsn=4304625274)
    at ma_blockrec.c:3819
#8 0x000000000099267f in _ma_apply_undo_row_update (info=0x392e658, undo_lsn=4304625274, header=0x397bf32 "", header_length=17) at ma_blockrec.c:7144
#9 0x00000000009dcdd6 in exec_UNDO_LOGREC_UNDO_ROW_UPDATE (rec=0x7fffbd354210, trn=0x389f338) at ma_recovery.c:2230
#10 0x00000000009de50c in run_undo_phase (uncommitted=0) at ma_recovery.c:2805
#11 0x00000000009d88ab in maria_apply_log (from_lsn=4294975495, end_lsn=0, apply=MARIA_LOG_APPLY, trace_file=0x38c2150, should_run_undo_phase=1 '\001',
    skip_DDLs_arg=1 '\001', take_checkpoints=1 '\001', warnings_count=0x7fffbd354990) at ma_recovery.c:394
#12 0x00000000009d8494 in maria_recovery_from_log () at ma_recovery.c:221
#13 0x00000000009574d0 in ha_maria_init (p=0x38a9148) at ha_maria.cc:3259
#14 0x00000000007b7f04 in ha_initialize_handlerton (plugin=0x386e558) at handler.cc:430
#15 0x0000000000882e58 in plugin_initialize (plugin=0x386e558) at sql_plugin.cc:1039
#16 0x00000000008836ff in plugin_init (argc=0xd10df1, argv=0x0, flags=0) at sql_plugin.cc:1267
#17 0x000000000066edda in init_server_components () at mysqld.cc:4131
#18 0x000000000066f8fc in main (argc=14, argv=0x7fffbd355178) at mysqld.cc:4603

bzr version-info:

revision-id: <email address hidden>
date: 2010-08-11 13:55:54 +0300
build-date: 2010-08-12 08:56:32 +0300
revno: 2901
branch-nick: 5.1

[Philip Stoev (pstoev-askmonty)]

RQG command line:

/home/buildbot/randgen/gentest.pl \
--gendata=/home/buildbot/randgen//conf/engines/engine_stress.zz \
--engine=Maria \
--reporter=ErrorLog \
--reporter=Backtrace \
--reporter=Recovery \
--reporter=Shutdown \
--threads=5 \
--queries=100000000 \
--duration=240 \
--dsn=dbi:mysql:host=127.0.0.1:port=19300:user=root:database=test \
--grammar=/home/buildbot/randgen//conf/engines/engine_stress.yy \
--seed=1281590806 \
--mask=37836 \
--mask-level=1 \
--rows=1000

[Philip Stoev (pstoev-askmonty)]

The RQG command line above would not start the initial server. Here is the command line that includes starting the initial server:

/home/buildbot/randgen/runall.pl \
--grammar=conf/engines/engine_stress.yy \
--gendata=conf/engines/engine_stress.zz \
--queries=1M \
--engine=Maria \
--mysqld=--log-output=file \
--mysqld=--log-bin \
--reporters=ErrorLog,Backtrace,Recovery,Shutdown \
--duration=240 \
--threads=5 \
--rows=1000 \
--mask-level=1 \
--mysqld=--loose-maria-group-commit=soft \
--mysqld=--loose-maria_group_commit_interval=100000000 \
--mysqld=--maria-checkpoint-interval=0 \
--mysqld=--maria-block-size=16K \
--mask=37836 \
--queries=100000000 \
--basedir=. \
--seed=1281590806

[Michael Widenius (monty)]

It's very likely this bug is fixed in the current 5.1 release

I did also try to run the last RQG script for 10 hours, but didn't get any failures.