Bug #42519 Maria: RESTORE leads to corrupted table and assertion
Submitted: 1 Feb 2009 15:36 Modified: 7 May 2009 8:29
Reporter: Philip Stoev Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Maria storage engine Severity:S2 (Serious)
Version:6.0-maria OS:Any
Assigned to: Guilhem Bichot CPU Architecture:Any
Triage: Triaged: D1 (Critical)

[1 Feb 2009 15:36] Philip Stoev
Description:
When executing BACKUP and RESTORE in the face of very simple concurrent workload on very simple tables, Maria tables become corrupt:

1034 Incorrect key file for table 'AAA'; try to repair it

the error log contains:

090201 18:34:02 [ERROR] Got an error from thread_id=14, ma_write.c:387
090201 18:34:02 [ERROR] MySQL thread id 11, query id 8282 localhost 127.0.0.1 root Table lock
INSERT INTO `AAA` ( `datetime_key` ) VALUES ( 2 )
090201 18:34:02 [ERROR] MySQL thread id 14, query id 8278 localhost 127.0.0.1 root update
INSERT INTO `AAA` ( `time_key` ) VALUES ( 9 )
090201 18:34:02 [ERROR] Got an error from thread_id=11, ma_write.c:387
090201 18:34:02 [ERROR] MySQL thread id 11, query id 8282 localhost 127.0.0.1 root update
INSERT INTO `AAA` ( `datetime_key` ) VALUES ( 2 )
090201 18:34:02 [Note] Restore: Restore completed
090201 18:34:02 [ERROR] Got an error from thread_id=7, ma_write.c:387
090201 18:34:02 [ERROR] MySQL thread id 7, query id 8290 localhost 127.0.0.1 root update
INSERT INTO `AA` ( `time_key` ) VALUES ( 7 )
090201 18:34:02 [ERROR] mysqld: Table './test/AAA' is marked as crashed and should be repaired
090201 18:34:02 [ERROR] Couldn't repair table: test.AAA
090201 18:34:02 [ERROR] Got an error from thread_id=6, ma_update.c:239
090201 18:34:02 [ERROR] MySQL thread id 6, query id 8281 localhost 127.0.0.1 root Updating
UPDATE `A` SET `pk` = 1 WHERE `datetime_nokey` < 9 LIMIT 2
090201 18:34:02 [ERROR] Got an error from thread_id=14, ma_write.c:387
090201 18:34:02 [ERROR] MySQL thread id 14, query id 8291 localhost 127.0.0.1 root update
INSERT INTO `AA` ( `datetime_nokey` ) VALUES ( 4 )
090201 18:34:02 [ERROR] mysqld: Table './test/AAA' is marked as crashed and should be repaired
090201 18:34:02 [ERROR] Couldn't repair table: test.AAA
090201 18:34:02 [ERROR] mysqld: Table './test/AAA' is marked as crashed and should be repaired
090201 18:34:02 [ERROR] Couldn't repair table: test.AAA
090201 18:34:02 [ERROR] Got an error from thread_id=13, ma_write.c:387
090201 18:34:02 [ERROR] MySQL thread id 13, query id 8306 localhost 127.0.0.1 root update
INSERT INTO `AA` ( `date_key` ) VALUES ( 6 )
090201 18:34:02 [ERROR] Got an error from thread_id=10, ma_delete.c:141
090201 18:34:02 [ERROR] MySQL thread id 10, query id 8311 localhost 127.0.0.1 root updating
DELETE FROM `A` WHERE `date_nokey` < 1 LIMIT 2
090201 18:34:02 [ERROR] mysqld: Table './test/AAA' is marked as crashed and should be repaired
090201 18:34:02 [ERROR] Couldn't repair table: test.AAA
090201 18:34:02 [ERROR] Got an error from thread_id=11, ma_write.c:387
090201 18:34:02 [ERROR] MySQL thread id 11, query id 8320 localhost 127.0.0.1 root update
INSERT INTO `AA` ( `varchar_nokey` ) VALUES ( 8 )
090201 18:34:02 [ERROR] mysqld: Table './test/AAA' is marked as crashed and should be repaired
090201 18:34:02 [ERROR] Couldn't repair table: test.AAA
090201 18:34:03 [ERROR] mysqld: Table './test/AAA' is marked as crashed and should be repaired
090201 18:34:03 [ERROR] Couldn't repair table: test.AAA
090201 18:34:03 [ERROR] Got an error from thread_id=8, ma_delete.c:141
090201 18:34:03 [ERROR] MySQL thread id 8, query id 8342 localhost 127.0.0.1 root updating
DELETE FROM `A` WHERE `datetime_nokey` < 9 LIMIT 8
090201 18:34:03 [ERROR] mysqld: Table './test/AAA' is marked as crashed and should be repaired
090201 18:34:03 [ERROR] Couldn't repair table: test.AAA
mysqld: ma_page.c:374: _ma_new: Assertion `key_del_current != share->state.key_del && (key_del_current != 0) && ((key_del_current == (~ (my_off_t) 0)) || (key_del_current <= (share->state.state.key_file_length - block_size)))' failed.

How to repeat:
A test case will be uploaded shortly.
[1 Feb 2009 15:40] Philip Stoev
YY file for bug42519.yy

Attachment: bug42519.yy (application/octet-stream, text), 428 bytes.

[1 Feb 2009 15:44] Philip Stoev
To reproduce with the RQG:

$ perl runall.pl \
  --basedir=/build/bzr/6.0-maria/ \
  --engine=Maria \
  --grammar=conf/42519.yy \
  --queries=100000

This grammar is set up so that the BACKUP+RESTORE are not concurrent. They are executed sequentially only on connection #1 and there is a 1 second SLEEP() before each BACKUP and RESTORE.

The rest of the workload is standard INSERT/UPDATE/DELETE statements.
[1 Feb 2009 15:49] Philip Stoev
MyISAM also has issues with this test, however its MTBF is larger and the table is less likely to become permanently corrupted.
[3 Feb 2009 15:09] Guilhem Bichot
Got this same assertion, but sometimes other ones (corrupted tables).
[6 Feb 2009 9:44] Guilhem Bichot
The root cause is the non-atomicity of RESTORE (time window between recreating the table empty and filling it with data), exactly the same as BUG#41716.
I am attaching a testcase for MyISAM which is similar to the one I posted in BUG#41716 and gives corruption.
Here is the patch to enable sync points:
=== modified file 'sql/backup/kernel.cc'
--- sql/backup/kernel.cc        2009-02-03 07:48:09 +0000
+++ sql/backup/kernel.cc        2009-02-06 09:13:32 +0000
@@ -1324,10 +1324,14 @@
   close_thread_tables(m_thd);                   // Never errors
   m_thd->stmt_da->reset_diagnostics_area();     // Never errors

+  DEBUG_SYNC(m_thd, "before_restore_locks_tables");
+
   err= lock_tables_for_restore();               // logs errors
   if (err)
     DBUG_RETURN(fatal_error(err));

+  DEBUG_SYNC(m_thd, "after_restore_locks_tables");
+
   /*
    Here restore drivers are created to restore table data. Data is being
    (potentially) changed so we set m_data_changed flag.

The testcase provokes corruption because (see attached test):
- BACKUP backs up empty table
- RESTORE first creates the table (by executing CREATE TABLE); it is empty; before it locks the table (time window), the following happens:
- other client's INSERT opens and locks table, inserts to it; this puts a new key page in the key cache, at unlock this page is flushed to disk; so the index file grows beyond 1024 bytes; the data file also grows as it's not empty anymore (not 0 bytes anymore)
- RESTORE locks table, MyISAM driver does no write to the data file, and a 1024-byte write to the index file (table was empty when it was backed up)
- RESTORE updates state-in-memory from the restored state-on-disk.
- So we have a state-on-disk which says "0 records, 0-byte data file, 1024-byte index file", and so CHECK TABLE says that this is inconsistent with the reality in the data and index file:
Table   Op      Msg_type        Msg_text
mysqltest.t1    check   warning Size of indexfile is: 2048      Should be: 1024
mysqltest.t1    check   warning Size of datafile is: 20       Should be: 0
mysqltest.t1    check   error   Record-count is not ok; is 1   Should be: 0
mysqltest.t1    check   warning Found 1 key parts. Should be: 0
mysqltest.t1    check   error   Corrupt

The corruption observed in the first post of this bug report in Maria has the same cause.
[6 Feb 2009 9:45] Guilhem Bichot
repeatable test for MyISAM

Attachment: bug42519_myisam.test (application/octet-stream, text), 984 bytes.

[10 Feb 2009 14:52] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/65758

2721 Guilhem Bichot	2009-02-10
      Maria online backup: BUG#42519 "Maria: RESTORE leads to corrupted table and assertion":
      * working around deficiencies of the restore kernel
      (occuring also in
      BUG 41716 "Backup Error when sending data (for table #1) to Default/Snapshot restore driver"
      BUG 40944 "Backup: crash after myisampack"); this fixes BUG#42519.
      * same workaround for MyISAM (which suffered from a bug similar to BUG#42519).
      * fixing a Maria restore driver bug found during debugging this ("DELETE FROM <table>;" was
      not handled during backup).
      modified:
        mysql-test/suite/backup/r/backup_maria.result
        mysql-test/suite/backup/t/backup_maria.test
        sql/backup/kernel.cc
        storage/maria/ma_bitmap.c
        storage/maria/ma_check.c
        storage/maria/ma_delete_all.c
        storage/maria/ma_examine_non_trans_log.c
        storage/maria/ma_non_trans_log.c
        storage/maria/maria_backup_engine.cc
        storage/maria/maria_def.h
        storage/myisam/myisam_backup_engine.cc
[13 Feb 2009 16:54] Guilhem Bichot
queued to 6.0-maria
[17 Feb 2009 11:46] Bugs System
Pushed into 6.0.10-alpha (revid:serg@mysql.com-20090217113558-vpsqsyjule7nz0gk) (version source revid:guilhem@mysql.com-20090210150451-kabqw9gbnmieoho7) (merge vers: 6.0.10-alpha) (pib:6)
[7 May 2009 8:29] MC Brown
A note has been added to the 6.0.10 changelog: 

Performing a BACKUP and RESTORE on a Maria table while an existing workload is in progress could lead to a corrupted table and possible crash.
[4 Jan 2010 15:46] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/95896

3023 Ingo Struewing	2010-01-04
      WL#5101 - MySQL Backup back port - MS09
      Merged (part of) revid:guilhem@mysql.com-20090210145140-wc5aohc1ucqo64ua
        Maria online backup: BUG#42519 "Maria: RESTORE leads to corrupted table and assertion":
        * working around deficiencies of the restore kernel
        (occuring also in
        BUG 41716 "Backup Error when sending data (for table #1) to Default/Snapshot restore driver"
        BUG 40944 "Backup: crash after myisampack"); this fixes BUG#42519.
        * same workaround for MyISAM (which suffered from a bug similar to BUG#42519).
        * fixing a Maria restore driver bug found during debugging this ("DELETE FROM <table>;" was
        not handled during backup).
      
      Only included the changes in storage/myisam/myisam_backup_engine.cc.
      The changes from sql/backup/kernel.cc.
      Left away all maria changes.
      
      original changeset: 2617.26.9
     @ storage/myisam/myisam_backup_engine.cc
        WL#5101 - MySQL Backup back port - MS09
            Same changes as in maria_backup_engine.cc (though simplified).
        Comments from storage/maria/maria_backup_engine.cc:
            * Working around a deficiency of the restore kernel:
             - it leaves a window between creating the table empty and locking it; in this window,
            another thread can do an update to the table (which conflicts with what the restore
            driver will put into files).
             - it does not always really close tables at end of restore, so restore driver has to
            make sure to invalidate any cached info before table is unlocked.
            - see this file's comments for more details about the two problems above;
            they were the causes of BUG#42519 (various corruptions or assertion failures
            in the first DMLs after RESTORE, depending on concurrency).
            * The same logic is needed independently of rebuilding the index or not.
            * keep MARIA_SHARE::close_lock when iterating over states of table,
            to protect against a concurrent checkpoint (safer).
[14 Dec 2010 20:06] Roel Van de Paar
See bug #58927