MySQL Bugs: #28351: Falcon: Crash recovery failure if the crash is during an alter table.

Bug #28351	Falcon: Crash recovery failure if the crash is during an alter table.
Submitted:	10 May 2007 13:53	Modified:	31 Aug 2007 12:29
Reporter:	Peter Gulutzan	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Falcon storage engine	Severity:	S3 (Non-critical)
Version:	6.0.1-alpha-debug	OS:	Linux (SUSE 10 64-bit)
Assigned to:	Kevin Lewis	CPU Architecture:	Any

Description:
I create a procedure which creates a table,
inserts 20 rows, then goes into a loop,
updating the rows randomly and altering
character sets.

I now encounter a 'recovery failure' problem using this procedure.

This procedure was originally described in
Bug#26433 Falcon: crash in procedure after error 1025
Here the procedure is causing a recovery failure
rather than an immediate crash, so at the request
of Kevin Lewis I report it as a separate bug.

How to repeat:
Start with a fresh install, e.g. clear datadir and run mysql_install_db.

Create a procedure, and call it, thus:

delimiter //
drop table tq//
drop procedure p2//
create procedure p2 ()
begin
  declare v int default 0;
  declare v10000 int;
  declare v999 int;
  declare v255 int;
  declare v9999 int;
  declare continue handler for sqlexception
  begin
    declare vx int;
    select 'error, probably 1025';
    drop table tq;
    select '1';
    create table tq (
    s0 int, s1 varchar(1000) character set latin1,
    s2 varchar(1000) character set latin2)
    engine=falcon;
    set vx = 0;
    while vx < 20 do
      insert into tq values (vx,null,null);
      set vx = vx + 1;
      end while;
    select '2';
    create index itq1 on tq (s1,s0);
    create index itq2 on tq (s2,s0);
    select '3';
    end;
  select 'a';
  create table tq (s0 int, s1 varchar(1000) character set latin1, s2
varchar(1000) character set latin2) engine=falcon;
  select 'b';
  set v = 0;
  while v < 20 do
    insert into tq values (v,null,null);
    set v = v + 1;
    end while;
  select 'c';
  create index itq1 on tq (s1,s0);
  create index itq2 on tq (s2,s0);
  select 'd';
  set v = 0;
  while v < 100000 do
    set v10000 = rand()*10000;
    set v999 = rand()*999;
    set v255 = rand()*255;
    set v9999 = rand()*9999;
    set @x = concat('update tq set s1 = repeat(0x', hex(v10000),',',v999,'), s0
=', v,', s2 = repeat(0x', hex(v255), ',',v9999,')');
    select v,@x;
    prepare stmt1 from @x;
    execute stmt1;
    if v mod 2 = 0 then
      alter table tq modify column s1 varchar(1000) character set latin2;
      alter table tq modify column s2 varchar(1000) character set latin1;
    else
      alter table tq modify column s1 varchar(1000) character set latin1;
      alter table tq modify column s2 varchar(1000) character set latin2;
      end if;
    set v = v + 1;
    end while;
  end//
call p2()//

Create procedure and call it as originally described.
Let it run for at least 5 seconds.

Elsewhere, find out the mysqld process number and kill it, e.g.
"
linux:/home/pgulutzan # ps -A | grep mysqld
12471 pts/1    00:00:02 mysqld
linux:/home/pgulutzan # kill -9 12471
"

Restart mysqld.

Restart mysql client. Say 'use (databasename)' and/or 'select * from tq;'.

I tried that 3 times, and got a crash 3 times.

There are already bugs about recovery failure, e.g. Bug#25017,
but I like this example because I think/hope it will be easy to reproduce.

Thank you for the bug report. Verified on FC 6.0 32-bit.

(gdb) bt full
#0  0x006c4402 in __kernel_vsyscall ()
No symbol table info available.
#1  0x00bb40d1 in raise () from /lib/libpthread.so.0
No symbol table info available.
#2  0x08512008 in Error::debugBreak () at Error.cpp:92
No locals.
#3  0x08512069 in Error::error (string=0x890050c "read error on page %d of \"%s\": %s (%d)") at Error.cpp:69
        buffer = "read error on page 8913152 of \"/home/miguel/dbs/5.1f/var/test.fts\": No such file or directory (2)\000\000\000````\002```\000\000\000\000````ô¿¤\000\002\000\000\000\b¥Å\n\224Àx´#a\223\000\021$£\000Ô%£", '\0' <repeats 13 times>, "\005\000\000\000ô¿¤\000ÔÀx´9ô\227\000\021$£\000Ô%£\000\005\000\000\000àÀx´à:\220\000\200\b\221\000HÎý·\001\000\000"...
        args = 0xb478c104 ""
#4  0x0852abbf in IO::readPage (this=0xb7c062dc, bdb=0xb7f3aabc) at IO.cpp:168
<cut>

I can reproduce this easily on Windows. debugging...

I have reproduced a crash during recovery every time I have killed the engine while running this stored procedure.  The procedure creates a file with 20 records.  Then in a loop, it updates each record with random data, and does two alter tables.  Most of the time is spent in the alter table code, so that every time I crash it, the call stack is somewhere in the alter table code.  The error 1025 does not happen in my tests and has nothing to do with the failure to recover.  

The recovery crash happens in various places;  Sometimes the page read is the wrong page type, sometimes the serial log record is invalid, yeilding wrong page numbers which cause asserts later.

I am renaming the synopsis to reflect the true situation and raising the priority since this seems to indicate that a Falcon database is unrecoverable if the crash occurs during an alter table.

After several days of improving debug logging of the serial log so that I could see what was in it, I finally have the information I need to understand why this problem occurs.  I have tracked it down to a difference between Section::insertStub() and Section::reInsertStub().  

Section::insertStub takes into account two levels of section pages, the lower level is filled with RecordIndex entries and has 510 slots in a 4k page.  The upper level is finnled with four-byte page numbers and contains 1020 slots in a 4k page.  

Section::reInsertStub() however seems to think it is inserting directly into a lower level SectionPage.  It does not handle the upper level.  Section::reInsertStub() is only called during recovery and happens after a section page is 'bumped' to a new incarnation during a drop table, which always happens during an AlterTable.  Whenever I kill this test, it is always during an  alter table since the 2 AlterTables take much longer than the updates in the test. 

So I need to make sure Section::reInsertStub() works on the same SectionPage structure as Section::insertStub()

Well, the last synopsys of the problem was not correct! Section::reInsertStub is working correctly(). It turns out that the upper level section page slot which contains the page number of the lower level section page (the RecordLocatorPage) was set to zero after the first record in the transaction was redone.  That is because Section::storeRecord() decided that;

/* Record doesn't fit on last used data page, make another */

So during recovery, the records are put onto different pages than originally done, and the section pages can have different contents.  This bug may have something to do with the test using very large varchar fields. Still looking for the smoking gun, but I smell gunpowder...

Pushed a set of changes that prevent this crash from occurring.  The crash was due to a section page that was redone during recovery, and then allocated as another data page.  The reason it was re-allocated is because the page was marked as a free page in the PageInventoryPage.  The problem was that Section::redoSectionPage() is called in pass 2 of the recovery, but SerialLog::redoFreePage() is called in pass 3 (the redo pass).  The the section page was redone before it was freed.

This changeset calls SerialLog::redoFreePage() in pass 2 instead of pass 3 and adds PageInventoryPage::markPageInUse() to Section::redoSectionPage() so that the page is no longer marked free.

There are still problems encountered when Falcon is crashed during an alter table.  I have seen both missing tables and missing indexes after the recovery.  But these are mentioned in a similar bug (Bug#25017).  Let's let this bug track the crash that occurs during recovery of a crashed alter table, and let Bug#25017 track missing indexes and tables.

Another part of this changeset allows prevents a crash from occurring when the index is missing after recovery.  The missing index is still a problem, which will be tracked by Bug#25017

If not, another alloc make use that page thinking it is free.

I confirm that I can no longer reproduce the bug behaviour.

A note has been added to the 6.0.2 changelog: 

Under certain situations the Falcon tables and log could become corrupt and prevent recovery from a crashed version of the files.