Bug #16618 mysql breaks tables at normal shutdown
Submitted: 18 Jan 2006 21:28 Modified: 7 Mar 2006 13:41
Reporter: Andrew Sitnikov Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server Severity:S1 (Critical)
Version:4.1.14 OS:Linux (SuSE 10)
Assigned to: CPU Architecture:Any

[18 Jan 2006 21:28] Andrew Sitnikov
Description:
We have high loaded mysql server (~2.5K Req/sec). 
After normal shutdown it breaks some tables. 

How to repeat:
[root@mysql] /data/db/rate>mysqladmin -p shutdown                                                                           [23:02]
Enter password: 
STOPPING server from pid file /data/logs/mysqld.pid
060118 23:02:54  mysqld ended
[root@mysql] /data/db/rate>/usr/local/mysql/start.sh                                                                          [23:02]
[root@mysql] /data/db/rate>Starting mysqld daemon with databases from /data/db [23:02]

[root@mysql] /data/db/rate>tf /data/logs/mysqld-err.log                                                                              [23:02]
060118 23:03:02 [ERROR] /usr/local/mysql/bin/mysqld: Can't open file: 'users_info.MYI' (errno: 145)
060118 23:03:02 [ERROR] /usr/local/mysql/bin/mysqld: Can't open file: 'users_info.MYI' (errno: 145)
060118 23:03:02 [ERROR] /usr/local/mysql/bin/mysqld: Can't open file: 'users_info.MYI' (errno: 145)
060118 23:03:02 [ERROR] /usr/local/mysql/bin/mysqld: Can't open file: 'users_info.MYI' (errno: 145)
[19 Jan 2006 17:46] Valeriy Kravchuk
Thank you for a problem report. Why do you think it is a bug and not a hardware failure? perror 145 will give you:

MySQL error code 145: Table was marked as crashed and should be repaired

Have you tried to CHECK the tables that usually crash upon startup before the shutdown?

Please, send the df -k results from your server also.
[19 Jan 2006 19:03] Andrew Sitnikov
Before shutdown all tables in normal state, after shutdown this table crash. i repair it, try to shutdown - it crash again.

Filesystem            Size  Used Avail Use% Mounted on
/dev/cciss/c0d0p1     977M  184M  793M  19% /
/dev/cciss/c0d0p8     8.7G   59M  8.6G   1% /home
/dev/cciss/c0d0p7     953M   34M  919M   4% /tmp
/dev/cciss/c0d0p5     2.8G  912M  2.0G  32% /usr
/dev/cciss/c0d0p6     1.9G  236M  1.7G  13% /var
/dev/cciss/c0d1p1     103G   33G   71G  32% /data
[20 Jan 2006 9:51] Valeriy Kravchuk
OK. If it fails regularly on that table, please, send the results of SHOW CREATE TABLE users_info and SHOW TABLE STATUS LIKE 'users_info'.
[20 Jan 2006 13:37] Andrew Sitnikov
mysql> SHOW CREATE TABLE users_info\G
*************************** 1. row ***************************
       Table: users_info
Create Table: CREATE TABLE `users_info` (
  `id` mediumint(8) unsigned NOT NULL auto_increment,
  `location` varchar(100) default NULL,
  `occupation` varchar(60) default NULL,
  `firstname` varchar(80) default NULL,
  `lastname` varchar(80) default NULL,
  `realname` varchar(80) default NULL,
  `phone` varchar(60) default NULL,
  `hide_phone` tinyint(3) unsigned NOT NULL default '0',
  `info` text,
  `info_friends` text,
  `changed2` datetime default NULL,
  PRIMARY KEY  (`id`),
  KEY `lastname` (`lastname`(5)),
  KEY `firstname` (`firstname`(5)),
  FULLTEXT KEY `location` (`location`),
  FULLTEXT KEY `occupation` (`occupation`),
  FULLTEXT KEY `realname` (`realname`),
  FULLTEXT KEY `info` (`info`),
  FULLTEXT KEY `info_friends` (`info_friends`)
) ENGINE=MyISAM DEFAULT CHARSET=latin1
1 row in set (0.00 sec)

mysql> SHOW TABLE STATUS LIKE 'users_info'\G
*************************** 1. row ***************************
           Name: users_info
         Engine: MyISAM
        Version: 9
     Row_format: Dynamic
           Rows: 395001
 Avg_row_length: 847
    Data_length: 334980312
Max_data_length: 4294967295
   Index_length: 185021440
      Data_free: 47956
 Auto_increment: 1285990
    Create_time: 2005-09-19 01:18:53
    Update_time: 2006-01-20 15:37:00
     Check_time: 2006-01-19 10:52:27
      Collation: latin1_swedish_ci
       Checksum: NULL
 Create_options: 
        Comment: 
1 row in set (0.00 sec)
[1 Feb 2006 16:47] Valeriy Kravchuk
Sorry, but I was not able to repeat the behaviout you described with a similar table containing random data on 4.1.19-BK on SuSE 9.3:

mysql> show table status like 'users%'\G
*************************** 1. row ***************************
           Name: users_info
         Engine: MyISAM
        Version: 9
     Row_format: Dynamic
           Rows: 524288
 Avg_row_length: 68
    Data_length: 36117060
Max_data_length: 4294967295
   Index_length: 30381056
      Data_free: 0
 Auto_increment: 524289
    Create_time: 2006-01-29 22:20:00
    Update_time: 2006-01-29 22:23:54
     Check_time: NULL
      Collation: latin1_swedish_ci
       Checksum: NULL
 Create_options:
        Comment:
1 row in set (0.01 sec)

mysql> exit
Bye
openxs@suse:~/dbs/4.1> bin/mysqladmin -uroot shutdown
STOPPING server from pid file /home/openxs/dbs/4.1/var/suse.pid
060129 22:24:11  mysqld ended

[1]+  Done                    bin/mysqld_safe
openxs@suse:~/dbs/4.1> bin/mysqld_safe &
[1] 21096
openxs@suse:~/dbs/4.1> Starting mysqld daemon with databases from /home/openxs/dbs/4.1/var

openxs@suse:~/dbs/4.1> bin/mysql -uroot test
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1 to server version: 4.1.19

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> check table users_info;
+-----------------+-------+----------+----------+
| Table           | Op    | Msg_type | Msg_text |
+-----------------+-------+----------+----------+
| test.users_info | check | status   | OK       |
+-----------------+-------+----------+----------+
1 row in set (4.03 sec)

mysql> exit
Bye
openxs@suse:~/dbs/4.1> tail var/suse.err
060129 22:24:09  InnoDB: Starting shutdown...
060129 22:24:11  InnoDB: Shutdown completed; log sequence number 0 43634
060129 22:24:11 [Note] /home/openxs/dbs/4.1/libexec/mysqld: Shutdown complete

060129 22:24:11  mysqld ended

060129 22:24:15  mysqld started
060129 22:24:15  InnoDB: Started; log sequence number 0 43634
/home/openxs/dbs/4.1/libexec/mysqld: ready for connections.
Version: '4.1.19'  socket: '/tmp/mysql.sock'  port: 3306  Source distribution
[1 Feb 2006 17:06] Andrew Sitnikov
My server high loaded (~2000-3000 Req/sec) and has 8G RAM. When i stop mysqld without requests (stop apache before) it shutdown properly.
[2 Feb 2006 10:57] Valeriy Kravchuk
So, I need a test case with (or, at least, a description of) tipical SQL statements for this table. How many concurrent sessions are working with it while you are trying to shut down MySQL? Send (upload) the SHOW PROCESSLIST results just before the shutdown.
[6 Feb 2006 2:40] [ name withheld ]
Hi, I've experienced a similar problem using MySQL 4.1.7 and Red Hat EL 4.

A client noticed that they were not able to perform a search on their Web site, so I investigated the problem and found one of the tables (coleman) in the database unresponsive.  Whether my response was correct or not, is a separate debate, but here are the actions that I performed:

1. Restarted MySQL (no visible change)
2. Rebuilt the database from a backup taken earlier in the day (problem solved)

Here is the log file from the MySQL server restart:
060203 23:58:46  mysqld ended

060203 23:58:47  mysqld started
060203 23:58:48  InnoDB: Started; log sequence number 0 198534194
/usr/libexec/mysqld: ready for connections.
Version: '4.1.7'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  Source distribution
060203 23:59:20 [ERROR] /usr/libexec/mysqld: Can't open file: 'coleman.MYI' (errno: 145)
060203 23:59:25 [ERROR] /usr/libexec/mysqld: Can't open file: 'coleman.MYI' (errno: 145)

[continues for 10 minutes, about 25 messages]

060204  0:09:22 [ERROR] /usr/libexec/mysqld: Can't open file: 'coleman.MYI' (errno: 145)
060204  0:09:22 [ERROR] /usr/libexec/mysqld: Can't open file: 'coleman.MYI' (errno: 145)

[errors stopped after I rebuilt the database]

Before the rebuild, I located the file /var/lib/mysql/bciusa/coleman.MYI but didn't notice anything strange about it's permissions, date, or data size.  After rebuilding the database it looked about the same (I can get the exact size later if needed.)  The corrupted table theory sounds the closest to my problem.

As requested in the original post here are some system / MySQL stats:
# df -hT
Filesystem    Type    Size  Used Avail Use% Mounted on
/dev/mapper/VolGroup00-LogVol00
              ext3    273G   72G  189G  28% /
/dev/sda1     ext3     99M   13M   82M  13% /boot
none         tmpfs   1014M     0 1014M   0% /dev/shm

mysql> SHOW CREATE TABLE coleman\G
*************************** 1. row ***************************
       Table: coleman
Create Table: CREATE TABLE `coleman` (
  `primary_id` int(11) NOT NULL auto_increment,
  `img_number` varchar(20) NOT NULL default '',
  `sysnum` varchar(20) NOT NULL default '',
  `lb` text NOT NULL,
  `main_head` text NOT NULL,
  `short_caption` varchar(255) NOT NULL default '',
  `fc` text NOT NULL,
  `long_caption` varchar(255) NOT NULL default '',
  `where` text NOT NULL,
  `genus` text NOT NULL,
  `photographer` varchar(200) NOT NULL default '',
  `scode` text NOT NULL,
  `keywords` text NOT NULL,
  `cd_volume` varchar(20) NOT NULL default '',
  `site` varchar(30) NOT NULL default 'Coleman',
  `url` varchar(255) NOT NULL default '',
  `status` int(2) NOT NULL default '0',
  `date_added` timestamp NOT NULL default CURRENT_TIMESTAMP,
  PRIMARY KEY  (`primary_id`),
  KEY `img_number` (`img_number`),
  FULLTEXT KEY `keywords` (`keywords`)
) ENGINE=MyISAM DEFAULT CHARSET=utf8
1 row in set (0.00 sec)

mysql> SHOW TABLE STATUS LIKE 'coleman'\G
*************************** 1. row ***************************
           Name: coleman
         Engine: MyISAM
        Version: 9
     Row_format: Dynamic
           Rows: 122288
 Avg_row_length: 372
    Data_length: 45549840
Max_data_length: 4294967295
   Index_length: 28665856
      Data_free: 0
 Auto_increment: 128613
    Create_time: 2006-02-04 00:10:25
    Update_time: 2006-02-05 10:58:31
     Check_time: 2006-02-04 00:11:03
      Collation: utf8_general_ci
       Checksum: NULL
 Create_options:
        Comment:
1 row in set (0.00 sec)

Lastly, I use phpMyAdmin to view and manipulate the DB from time to time.  When looking at the table structure through phpMyAdmin I noticed that the line cooresponding to the 'coleman' table was very irregular.

Rather than a typical line that looks like this:
[checkbox]  	  coleman    	 Browse  	 Search  	  Insert   	  Structure   	 Empty  	  Drop   	 122,288  	  MyISAM   	  utf8_general_ci   	    70.8 MB   	

I got:
[checkbox]  	  coleman    	 Browse  	 Search  	  Insert   	  Structure   	 Empty  	  Drop   	 In Use
(The last four cells had merged into one that had the phrase 'In Use' in it.)

Of course, I could not browse the table or use it in any way.  At that time I was given the error message that appears in the log file: Can't open file: 'coleman.MYI' (errno: 145).

I hope this helps troubleshoot the problem and nail down if this is a bug or not.
[7 Feb 2006 13:41] Valeriy Kravchuk
In both test cases presented here there are FULLTEXT indexes on some columns. So, I think, it can be a duplicate of bug #16489, fixed in 4.1.18. So, please, wait for 4.1.18 to be officially released (really soon), check with that version and inform about the results.
[8 Mar 2006 0:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".