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 (OCA) 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
Triage: Triaged: D1 (Critical)

[17 Jun 2009 0:29] Roel Van de Paar
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
[17 Jun 2009 0:47] Roel Van de Paar
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.
[17 Jun 2009 5:32] Roel Van de Paar
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.
[17 Jun 2009 5:40] Sveta Smirnova
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`
[17 Jun 2009 6:16] Roel Van de Paar
> 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): 
----------
[17 Jun 2009 7:46] Shane Bester
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..
[17 Jun 2009 7:51] Sveta Smirnova
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
[17 Jun 2009 8:07] Sveta Smirnova
This can be duplicate of bug #25433, but I'd say this feature request is "Gratefully finish OPTIMIZE/REPAIR when shutdown server"
[17 Jun 2009 18:23] James Day
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.
[16 Nov 2010 9:14] Roel Van de Paar
Any updates?
[14 Jun 2013 5:09] Shane Bester
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?