MySQL Bugs: #41330: Myisam table open count set to zero before index blocks are written.

Bug #41330	Myisam table open count set to zero before index blocks are written.
Submitted:	9 Dec 2008 15:39	Modified:	13 May 2009 23:34
Reporter:	David Crimmins	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: MyISAM storage engine	Severity:	S2 (Serious)
Version:	5.0/5.1/6.0	OS:	Any
Assigned to:	Satya B	CPU Architecture:	Any

Description:
When using the DELAY_KEY_WRITE option, index updates are not applied until flush tables command is issued or mysqld shutdown. If mysqld is killed before the index updates are completely written to disk the index file is likely to be corrupt. However the table is not marked as crashed. If mysqld is killed before the index flush begins the table is marked as crashed and, providing the myisam-recover option is specified, will be automatically repaired when next opened. 

We use key_buffer_size > 1Gb and delay-key-write=ALL. We suffer this problem whenever windows is shutdown because insufficent time is given for mysqld to flush its cache.

How to repeat:
-- create test db
create database test;
use test;

-- increase size of key buffer
SET GLOBAL key_buffer_size=1000000000;

-- create tables used in test case 
CREATE TABLE dest (
  c1 char(18), c2 char(18),
  PRIMARY KEY  (`c1`,`c2`),
  KEY `c2` (`c2`)
) DELAY_KEY_WRITE = 1;

-- create and populate table used as row source
CREATE TABLE src ( c1 int);
INSERT INTO src values (0), (1), (2), (3), (4), (5), (6), (7), (8), (9);

-- insert 5 million rows
REPLACE INTO dest SELECT rand(), rand() FROM src a, src b, src c, src d, src e, src f;
REPLACE INTO dest SELECT rand(), rand() FROM src a, src b, src c, src d, src e, src f;
REPLACE INTO dest SELECT rand(), rand() FROM src a, src b, src c, src d, src e, src f;
REPLACE INTO dest SELECT rand(), rand() FROM src a, src b, src c, src d, src e, src f;
REPLACE INTO dest SELECT rand(), rand() FROM src a, src b, src c, src d, src e, src f;

-- verify there unwritten index blocks
SHOW GLOBAL STATUS LIKE 'Key_blocks%';

-- If mysqld is killed at this point dest table will have open count > 0 and considered crashed. 
-- With appropriate options mysqld will check and repair table when next opened.

flush tables;

-- If mysqld is killed at this point BEFORE flush is complete (YOU MUST BE QUICK), dest table will have
--  open count = 0 and NOT considered crashed.
-- On restart expect to see "Incorrect key file for table" errors when attempting to use dest table.
-- mysqld will not automatically repair the table.
 

Suggested fix:
Update open_count in myi header after index blocks are flushed.

Thank you for the bug report. Could you please try the latest released version 5.0.22 is quite older. Thanks in advance.

Problem also exists on version 5.0.54a-classic-nt-log.
Is this version new enough, if not please suggest version to try as I will have to download and install.
Thanks

Please try version 5.0.67. I did the first test of your test case and I was unable to repeat with 5.0.74 source server running on Windows. Thanks in advance.

Problem is reproducible using 5.0.67-community-nt. (NB we usually use enterprise versions, but community one was easier to download).
When reproducing this, timing is critical. mysqld-nt must be killed after flush has started and before it completes. Use task manager or some other tool to kill mysqld-nt do not perform normal DB shutdown. If “flush tables” completes too quickly insert more rows into table “dest”, if necessary increase size of key_buffer_size.

Below is sample output where mysqld-nt was killed approx 3 seconds after flush tables commenced and restarted before select statement.

mysql> REPLACE INTO dest SELECT rand(), rand() FROM src a, src b, src c, src d, src e, src f; REPLACE INTO dest SELECT rand(), rand() FROM src a, src b, src c,
src d, src e, src f; REPLACE INTO dest SELECT rand(), rand() FROM src a, src b, src c, src d, src e, src f; REPLACE INTO dest SELECT rand(), rand() FROM src a,
src b, src c, src d, src e, src f; REPLACE INTO dest SELECT rand(), rand() FROM src a, src b, src c, src d, src e, src f;
Query OK, 1000000 rows affected, 1784 warnings (16.78 sec)
Records: 1000000  Duplicates: 0  Warnings: 1784

Query OK, 1000000 rows affected, 1772 warnings (20.92 sec)
Records: 1000000  Duplicates: 0  Warnings: 1772

Query OK, 1000000 rows affected, 1790 warnings (21.78 sec)
Records: 1000000  Duplicates: 0  Warnings: 1790

Query OK, 1000000 rows affected, 1801 warnings (23.28 sec)
Records: 1000000  Duplicates: 0  Warnings: 1801

Query OK, 1000000 rows affected, 1840 warnings (22.83 sec)
Records: 1000000  Duplicates: 0  Warnings: 1840

mysql> SHOW GLOBAL STATUS LIKE 'Key_blocks%';
+------------------------+--------+
| Variable_name          | Value  |
+------------------------+--------+
| Key_blocks_not_flushed | 331306 |
| Key_blocks_unused      | 523323 |
| Key_blocks_used        | 331306 |
+------------------------+--------+
3 rows in set (0.00 sec)

mysql> flush tables;
ERROR 2013 (HY000): Lost connection to MySQL server during query
mysql> select * from dest
    -> limit 3;
ERROR 2006 (HY000): MySQL server has gone away
No connection. Trying to reconnect...
Connection id:    1
Current database: test

ERROR 126 (HY000): Incorrect key file for table '.\test\dest.MYI'; try to repair it

Looking in the code:

int mi_close(register MI_INFO *info)
{
<cut>
if (share->reopen == 1 && share->kfile >= 0)
    _mi_decrement_open_count(info);
<cut>
  if (flag)
  {
    if (share->kfile >= 0 &&
	flush_key_blocks(share->key_cache, share->kfile,
			 share->temporary ? FLUSH_IGNORE_CHANGED :
			 FLUSH_RELEASE))
<cut>

}

So I guess adding a sleep(120) between these two statements could make the problem alot easier to repeat.

Now I was able to repeat using a way to kill the process quick than before:

g:\share\dbs>pslist | findstr mysqld

pslist v1.28 - Sysinternals PsList
Copyright ® 2000-2004 Mark Russinovich
Sysinternals

mysqld             4416   8  11 32702  30232     0:00:00.218     0:00:16.052

g:\share\dbs>pskill 4416

PsKill v1.12 - Terminates processes on local or remote systems
Copyright (C) 1999-2005  Mark Russinovich
Sysinternals - www.sysinternals.com

Process 4416 killed.

mysql 5.0 > -- If mysqld is killed at this point dest table will have open count > 0 and considered crashed.
mysql 5.0 > -- With appropriate options mysqld will check and repair table when next opened.
mysql 5.0 >
mysql 5.0 > flush tables;
ERROR 2013 (HY000): Lost connection to MySQL server during query
mysql 5.0 >
mysql 5.0 > select * from dest limit 3;
ERROR 2006 (HY000): MySQL server has gone away
No connection. Trying to reconnect...
Connection id:    1
Current database: test

ERROR 126 (HY000): Incorrect key file for table '.\test\dest.MYI'; try to repair it
mysql 5.0 >

I will test 5.1/6.0.

Thank you for the feedback. Verified as described:

090115 12:57:10 [Note] g:\share\dbs\6.0\bin\mysqld: ready for connections.
Version: '6.0.10-alpha-nt-log'  socket: ''  port: 3600  Source distribution
090115 12:57:12 [ERROR] mysqld: Incorrect key file for table '.\test\dest.MYI'; try to repair it
090115 12:57:12 [ERROR] Got error 126 when reading table '.\test\dest'

090115 13:04:34 [Note] g:\share\dbs\5.1\bin\mysqld: ready for connections.
Version: '5.1.31-nt-log'  socket: ''  port: 3510  Source distribution
090115 13:04:59 [ERROR] g:\share\dbs\5.1\bin\mysqld: Incorrect key file for table '.\test\dest.MYI'; try to repair it
090115 13:04:59 [ERROR] Got error 126 when reading table '.\test\dest'

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/69419

2775 Satya B	2009-03-17
      Fix for BUG#41330 -Myisam table open count set to zero before index blocks 
                         are written.
      
      When we have a myisam table with DELAY_KEY_WRITE option, index updates
      are not applied until the flush tables command is issued or until the
      server is shutdown. If server gets killed before the index updates are 
      written to disk, the index file is corrupted as expected but the table 
      is not marked as crashed. So when we start server with myisam-recover,
      table is not repaired leaving the table unusable.
      
      The problem is when we try to write the index updates to index file,
      we decrement the open_count even before the flushing the keys to index
      file.
      
      Fixed by moving the decrement operation after flushing the keys to the
      index file. So we always have non zero open count if the flush table
      operation is killed and when the server is started with mysiam-recover
      option, it marks the table as crashed and repairs it
      
      Note: No testcase added as we need to kill the server and start the 
            server with different set of options and other non trivial
            operations involved.
      modified:
        myisam/mi_close.c

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/69892

2745 Satya B	2009-03-20
      Fix for BUG#41330 -Myisam table open count set to zero before index blocks 
                         are written.
            
      When we have a myisam table with DELAY_KEY_WRITE option, index updates
      are not applied until the flush tables command is issued or until the
      server is shutdown. If server gets killed before the index updates are 
      written to disk, the index file is corrupted as expected but the table 
      is not marked as crashed. So when we start server with myisam-recover,
      table is not repaired leaving the table unusable.
            
      The problem is when we try to write the index updates to index file,
      we decrement the open_count even before the flushing the keys to index
      file.
            
      Fixed by moving the decrement operation after flushing the keys to the
      index file. So we always have non zero open count if the flush table
      operation is killed and when the server is started with mysiam-recover
      option, it marks the table as crashed and repairs it.
            
      Note: No testcase for added as we need to kill the server and start the 
            server with different set of options and other non trivial
            operations involved.
      modified:
        myisam/mi_close.c

Pushed into 5.0.82 (revid:davi.arnaut@sun.com-20090505184158-dvmedh8n472y8np5) (version source revid:davi.arnaut@sun.com-20090505184158-dvmedh8n472y8np5) (merge vers: 5.0.82) (pib:6)

Pushed into 5.1.35 (revid:davi.arnaut@sun.com-20090505190206-9xmh7dlc6kom8exp) (version source revid:davi.arnaut@sun.com-20090505190206-9xmh7dlc6kom8exp) (merge vers: 5.1.35) (pib:6)

Pushed into 6.0.12-alpha (revid:svoj@sun.com-20090506125450-yokcmvqf2g7jhujq) (version source revid:joro@sun.com-20090407141908-9lgfo0xj3c6guaes) (merge vers: 6.0.11-alpha) (pib:6)

Noted in 5.0.82, 5.1.35, 6.0.12 changelogs.

For a MyISAM table with DELAY_KEY_WRITE enabled, the index file could
be corrupted without the table being marked as crashed if the server
was killed.

Pushed into 5.1.35-ndb-6.3.26 (revid:jonas@mysql.com-20090615074202-0r5r2jmi83tww6sf) (version source revid:jonas@mysql.com-20090615070837-9pccutgc7repvb4d) (merge vers: 5.1.35-ndb-6.3.26) (pib:6)

Pushed into 5.1.35-ndb-7.0.7 (revid:jonas@mysql.com-20090615074335-9hcltksp5cu5fucn) (version source revid:jonas@mysql.com-20090615072714-rmfkvrbbipd9r32c) (merge vers: 5.1.35-ndb-7.0.7) (pib:6)

Pushed into 5.1.35-ndb-6.2.19 (revid:jonas@mysql.com-20090615061520-sq7ds4yw299ggugm) (version source revid:jonas@mysql.com-20090615054654-ebgpz7elwu1xj36j) (merge vers: 5.1.35-ndb-6.2.19) (pib:6)