Aria recovery assertion page_offset >= keypage_header && page_offset <= page_length

[Philip Stoev]

when recovering from a KILL -9 after a DML workload involving numerous indexes, Aria 5.1 asserted as follows:

recovered pages: 0%mysqld: ma_key_recover.c:913: _ma_apply_redo_index: Assertion `page_offset >= keypage_header && page_offset <= page_length' failed.

backtrace:

#8 0x00897de8 in __assert_fail () from /lib/libc.so.6
#9 0x0853431c in _ma_apply_redo_index (info=0xb2dd4c8, lsn=4308011413, header=0xb2eb777 "\002\001\001\003\377", head_length=281) at ma_key_recover.c:913
#10 0x0859cf20 in exec_REDO_LOGREC_REDO_INDEX (rec=0xbfcd2950) at ma_recovery.c:1613
#11 0x0859aa4d in display_and_apply_record (log_desc=0x9262880, rec=0xbfcd2950) at ma_recovery.c:549
#12 0x0859f4c4 in run_redo_phase (lsn=4294975495, lsn_end=0, apply=MARIA_LOG_APPLY) at ma_recovery.c:2560
#13 0x0859a3be in maria_apply_log (from_lsn=4294975495, end_lsn=0, apply=MARIA_LOG_APPLY, trace_file=0xb26ae38, should_run_undo_phase=1 '\001',
    skip_DDLs_arg=1 '\001', take_checkpoints=1 '\001', warnings_count=0xbfcd54f4) at ma_recovery.c:324
#14 0x0859a070 in maria_recovery_from_log () at ma_recovery.c:221
#15 0x0851e0e5 in ha_maria_init (p=0xb2660c8) at ha_maria.cc:3259
#16 0x08397599 in ha_initialize_handlerton (plugin=0xb24c7f8) at handler.cc:430
#17 0x084526a7 in plugin_initialize (plugin=0xb24c7f8) at sql_plugin.cc:1039
#18 0x08452ec9 in plugin_init (argc=0x8a4b8d8, argv=0xb219870, flags=0) at sql_plugin.cc:1267
#19 0x0826be7b in init_server_components () at mysqld.cc:4131
#20 0x0826c937 in main (argc=14, argv=0xbfcd5ae4) at mysqld.cc:4603

bzr version-info:

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

[Michael Widenius (monty)]

I have tried to repeat this but without success.

The issue is that there is some wrong data in the maria recovery log file. I have pinpointed the code that generated the log file entry but can't find anything wrong with it.

To help find the bug I would need one or more of the following:
- A general log file of the queries issued
- The command that caused the failure.

What I have done in the mean time is adding some new asserts into the log generating code so that mysqld will assert if Aria attempts to generated such a wrong log entry. (Should make testing much easier).

[Philip Stoev (pstoev-askmonty)]

The query log is available in the .ZIP file under vardir3/log/master.log

[Philip Stoev (pstoev-askmonty)]

This is still repeatable even after the latest recovery fixes. RQG command line:

# 2010-09-07T15:00:28 # /home/buildbot/randgen/runall.pl \
# 2010-09-07T15:00:28 # --queries=1M \
# 2010-09-07T15:00:28 # --engine=Maria \
# 2010-09-07T15:00:28 # --mysqld=--log-output=file \
# 2010-09-07T15:00:28 # --reporters=ErrorLog,Backtrace,Recovery,Shutdown \
# 2010-09-07T15:00:28 # --duration=240 \
# 2010-09-07T15:00:28 # --threads=1 \
# 2010-09-07T15:00:28 # --rows=100 \
# 2010-09-07T15:00:28 # --mask-level=1 \
# 2010-09-07T15:00:28 # --mysqld=--maria-repair-threads=2 \
# 2010-09-07T15:00:28 # --mysqld=--loose-maria-group-commit=soft \
# 2010-09-07T15:00:28 # --mysqld=--loose-maria_group_commit_interval=0 \
# 2010-09-07T15:00:28 # --mysqld=--maria-checkpoint-interval=120 \
# 2010-09-07T15:00:28 # --mysqld=--maria-block-size=4K \
# 2010-09-07T15:00:28 # --grammar=conf/engines/varchar.yy \
# 2010-09-07T15:00:28 # --gendata=conf/engines/varchar.zz \
# 2010-09-07T15:00:28 # --mask=54181 \
# 2010-09-07T15:00:28 # --queries=100000000 \
# 2010-09-07T15:00:28 # --mask=54181 \
# 2010-09-07T15:00:28 # --basedir=. \
# 2010-09-07T15:00:28 # --seed=1283860832 \
# 2010-09-07T15:00:28 # --vardir=/home/buildbot/rqg-buildbot-slave/rqg-weekend/vardir-maria_recovery_weekend/current

[Michael Widenius (monty)]

Have now run the test in a loop for 16 hours and no failures, so I think it's safe to assume that this bug was fixed with my previous recovery fixes.