MySQL Bugs: #45541: OPTIMIZE + server shutdown may damage a MyISAM table (due to thread kill)

Bug #45541	OPTIMIZE + server shutdown may damage a MyISAM table (due to thread kill)
Submitted:	17 Jun 2009 0:29	Modified:	17 Jun 2009 7:51
Reporter:	Roel Van de Paar	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: MyISAM storage engine	Severity:	S1 (Critical)
Version:	5.0.68, 5.1	OS:	Any (MS Windows, Mac OS X, all)
Assigned to:		CPU Architecture:	Any

Description:
Issue seen:

[Changes made to log for privacy purposes: xx instead of day/time, 'Customer' instead of 2 customer name subdirs, 'table' and 'TaBle' instead of actual table name, though likely not important - notice the case difference,'database' instead of actual database name]

---------
0905xx xx:xx:xx InnoDB: Started; log sequence number 0 1330352629
0905xx xx:xx:xx [Note] C:\Program Files\Customer\server\mysql\bin\mysqld-nt.exe: ready for connections.
Version: '5.0.68-enterprise-nt-log' socket: '' port: 3908 MySQL Enterprise Server (Commercial)
0905xx xx:xx:xx [Note] C:\Program Files\Customer\server\mysql\bin\mysqld-nt.exe: Normal shutdown

0905xx xx:xx:xx [Warning] C:\Program Files\Customer\server\mysql\bin\mysqld-nt.exe: Forcing close of thread 6 user: 'Administrator'

0905xx xx:xx:xx [Warning] C:\Program Files\Customer\server\mysql\bin\mysqld-nt.exe: Forcing close of thread 5 user: 'Administrator'

0905xx xx:xx:xx [Warning] Warning: Optimize table got errno 120 on database.TaBle, retrying
0905xx xx:xx:xx [Note] Retrying repair of: './database/table' failed. Please try REPAIR EXTENDED or myisamchk
0905xx xx:xx:xx InnoDB: Starting shutdown...
0905xx xx:xx:xx InnoDB: Shutdown completed; log sequence number 0 1330355282
0905xx xx:xx:xx [Note] C:\Program Files\Customer\server\mysql\bin\mysqld-nt.exe: Shutdown complete

0905xx xx:xx:xx InnoDB: Started; log sequence number 0 1330355282
0905xx xx:xx:xx [Note] C:\Program Files\Customer\server\mysql\bin\mysqld-nt.exe: ready for connections.
Version: '5.0.68-enterprise-nt-log' socket: '' port: 3908 MySQL Enterprise Server (Commercial)
0905xx xx:xx:xx [ERROR] C:\Program Files\Customer\server\mysql\bin\mysqld-nt.exe: Table '.\database\table' is marked as crashed and last (automatic?) repair
failed
0905xx xx:xx:xx [ERROR] C:\Program Files\Customer\server\mysql\bin\mysqld-nt.exe: Table '.\database\table' is marked as crashed and last (automatic?) repair
failed
---------

Note the 120 error:
0905xx xx:xx:xx [Warning] Warning: Optimize table got errno 120 on database.TaBle, retrying

perror 120:
MySQL error code 120: Didn't find key on read or update
Win32 error code 120: This function is not supported on this system.

o Table was *not* defined with DELAY_KEY_WRITE (see bug #41330) 
o Customer is using myisam-recover=BACKUP,FORCE in my.ini
o No antivirus software

How to repeat:
Unknown, happened twice now.

Suggested fix:
Unknown

Besides reviewing bug #41330 (even though it seems not related, as per the above), also note bug's #8067, #10767 (especially the last remark), and #25433.

Researching some related bugs brought up some interesting information:

'Killing a REPAIR TABLE or OPTIMIZE TABLE operation on a MyISAM table results in a table that is corrupted and unusable. Any reads or writes to such a table fail until you optimize or repair it again (without interruption).'
http://dev.mysql.com/doc/refman/5.0/en/kill.html

And:

'Some threads might refuse to be killed. For example, REPAIR TABLE, CHECK TABLE, and OPTIMIZE TABLE cannot be killed before MySQL 4.1 and run to completion. This is changed: REPAIR TABLE and OPTIMIZE TABLE can be killed as of MySQL 4.1.0, as can CHECK TABLE as of MySQL 4.1.3. However, killing a REPAIR TABLE or OPTIMIZE TABLE operation on a MyISAM table results in a table that is corrupted and is unusable (reads and writes to it fail) until you optimize or repair it again (without interruption).'
http://dev.mysql.com/doc/refman/4.1/en/kill.html

And:

'For each thread that is associated with a client connection, the connection to the client is broken and the thread is marked as killed.'
http://dev.mysql.com/doc/refman/5.0/en/server-shutdown.html

So, it looks like when an OPTIMIZE is started by a user and then the server is shutdown, it may damage the table in question.

Thank you for the report.

Do you know circumstances needs to repeat this failure? Do they have 2 tables table and TaBle? Please provide output of `dir datadir\database`

> Do you know circumstances needs to repeat this failure? 

Yes, as per the bug report: shutdown server at the right time during an OPTIMIZE. Also see other bugs linked.

> Do they have 2 tables table and TaBle?

This is not possible since it's Windows (Windows is not case-sensitive):

----------
C:\mysql5.1.31\data\roelt>copy con test.MYD
test
^Z
        1 file(s) copied.

C:\mysql5.1.31\data\roelt>copy con Test.MYD
test
Overwrite Test.MYD? (Yes/No/All): 
----------

I discussed this with ingo once. there's simply no worthwhile way to fix it, and it was agreed to not fix it.  same with repair table.  see bug #25433 for those comments..

Thank you for the report.

Verified as described.

To repeat:

1. Modify source as following:

=== modified file 'storage/myisam/mi_check.c'
--- storage/myisam/mi_check.c   2009-02-13 16:41:47 +0000
+++ storage/myisam/mi_check.c   2009-06-17 07:24:36 +0000
@@ -1979,6 +1979,8 @@
   /* Flush key cache for this file if we are calling this outside myisamchk */
   flush_key_blocks(share->key_cache,share->kfile, FLUSH_IGNORE_CHANGED);
 
+  sleep(20);
+
   share->state.version=(ulong) time((time_t*) 0);
   old_state= share->state;                     /* save state if not stored */
   r_locks=   share->r_locks;

2. Run attached test case with --manual-gdb option.

3. In gdb:

Version: '5.1.37-debug-log'  socket: '/Users/apple/bzr/mysql-5.1/mysql-test/var/tmp/mysqld.1.sock'  port: 13000  Source distribution
[Switching to process 2991 thread 0x2103]

Breakpoint 1, mysql_parse (thd=<incomplete type>, inBuf=0x606a828 "create table t1(f1 int, f2 varchar(255), KEY (f2))", length=50, found_semicolon=0xb0061dc4) at sql_parse.cc:5865
5865      DBUG_ENTER("mysql_parse");
(gdb) b mi_sort_index
Breakpoint 2 at 0x3e7715: file mi_check.c, line 1934.
(gdb) c
Continuing.

Breakpoint 2, mi_sort_index (param=0xb005bfcc, info=0x6074418, name=0xb005bd00 "./test/t1") at mi_check.c:1934
1934      MYISAM_SHARE *share=info->s;
(gdb) b flush_key_blocks
Breakpoint 3 at 0x4b673d: file mf_keycache.c, line 4005.
Current language:  auto; currently c
(gdb) c
Continuing.

Breakpoint 3, flush_key_blocks (keycache=0x6006c18, file=30, type=FLUSH_IGNORE_CHANGED) at mf_keycache.c:4005
4005      int res= 0;
(gdb) c

4. In another shell session:

mysqladmin shutdown -S /path/to/mysql-5.1/mysql-test/var/tmp/mysqld.1.sock

5. In gdb:

Continuing.
090617 11:46:19 [Note] /Users/apple/bzr/mysql-5.1/sql/mysqld: Normal shutdown

090617 11:46:19 [Note] Event Scheduler: Purging the queue. 0 events
090617 11:46:19 [Note] Got signal 15 to shutdown mysqld

Breakpoint 3, flush_key_blocks (keycache=0x6006c18, file=30, type=FLUSH_KEEP) at mf_keycache.c:4005
4005      int res= 0;
(gdb) c
Continuing.
090617 11:46:22 [Warning] /Users/apple/bzr/mysql-5.1/sql/mysqld: Forcing close of thread 1  user: 'root'

Breakpoint 3, flush_key_blocks (keycache=0x6006c18, file=30, type=FLUSH_RELEASE) at mf_keycache.c:4005
4005      int res= 0;
(gdb) clear
Deleted breakpoint 3 
(gdb) c
Continuing.
090617 11:46:27 [Warning] Forcing shutdown of 3 plugins
090617 11:46:27 [Note] /Users/apple/bzr/mysql-5.1/sql/mysqld: Shutdown complete

Program exited normally.
(gdb) q

6. In another shell session:

$myisamchk var/log/main.bug45541/mysqld.1/data/test/t1.MYI
Checking MyISAM file: var/log/main.bug45541/mysqld.1/data/test/t1.MYI
Data records:    8192   Deleted blocks:       0
myisamchk: warning: Table is marked as crashed and last repair failed
- check file-size
- check record delete-chain
- check key delete-chain
- check index reference
- check data record references index: 1
- check record links
MyISAM-table 'var/log/main.bug45541/mysqld.1/data/test/t1.MYI' is usable but should be fixed

This can be duplicate of bug #25433, but I'd say this feature request is "Gratefully finish OPTIMIZE/REPAIR when shutdown server"

The optimize can't be gracefully completed because the index will be incomplete and the table has to be marked as crashed to force a repair so it will be rebuilt after the restart. The feature request to use a copy instead of modifying the original index is a good one.

Any updates?

It is expected that killing optimize on myisam will leave the table in marked as crashed state.  To prevent that, a copy of the index can be made first.  But then folks will complain about excessive disk space being used, and it taking longer.
In short, I don't see any way to please all.   If we make the optimize thread unkillable, people will complain too, then kill -9 their server, and then complain again that all open tables are marked as corrupt.

So I think this is a *feature request*.  Can you tell me what the requested feature is exactly?  How do you want to handle this situation?