MySQL Bugs: #49155: mysql doesn't start normaly after altering innodb table to be compressed

Bug #49155	mysql doesn't start normaly after altering innodb table to be compressed
Submitted:	27 Nov 2009 3:30	Modified:	2 Feb 2010 3:41
Reporter:	Goki Honjo	Email Updates:
Status:	No Feedback	Impact on me:	None
Category:	MySQL Server: InnoDB Plugin storage engine	Severity:	S1 (Critical)
Version:	5.4.3-0	OS:	Linux (CentOS 4.8)
Assigned to:		CPU Architecture:	Any
Tags:	compression, innodb

Description:
The mysql daemon quits unexpectedly as soon as it starts. 

Environment:
MySQL is installed on VPS (OpenVZ). 
Hardware node and guest node are CentOS 5.4 and CentOS 4.8

What happened:
Originally InnoDB table `item` was created on MySQL 5.1.28-0 and mysql daemon was running smoothly.
I installed MySQL 5.4.3-0, and at this time mysql daemon was running.
I executed following command from cli.
    ALTER TABLE `item` ROW_FORMAT=COMPRESSED KEY_BLOCK_SIZE=8;
The transaction spent too much time, so I checked daemon log file. Then I found the daemon was in endless loop:
    daemon quits unexpectedly -> daemon reboot -> innodb table recovery -> daemon started normally -> daemon quits unexpectedly ...

Daemon log:
I replaced some texts with *** for privacy.
-----log file begins-----
091127  9:55:55  InnoDB: Assertion failure in thread 1189390688 in file fsp/fsp0fsp.c
line 3404
InnoDB: Failing assertion: not_full_n_used >= descr_n_used
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.1/en/forcing-recovery.html
InnoDB: about forcing recovery.
091127  9:55:55 - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help diagnose
the problem, but since we have already crashed, something is definitely wrong
and this may fail.

key_buffer_size=1073741824
read_buffer_size=4194304
max_used_connections=0
max_threads=64
threads_connected=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 2359947 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = (nil) thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x85078e]
/usr/sbin/mysqld(handle_segfault+0x31d)[0x5bdc8d]
/lib64/tls/libpthread.so.0[0x2b8bb375a5b0]
/lib64/tls/libc.so.6(gsignal+0x3d)[0x2b8bb3d6b26d]
/lib64/tls/libc.so.6(abort+0xfe)[0x2b8bb3d6ca6e]
/usr/sbin/mysqld[0x7f10ea]
/usr/sbin/mysqld(fseg_free_step+0x1e1)[0x7f1751]
/usr/sbin/mysqld(btr_free_but_not_root+0xdc)[0x7a87cc]
/usr/sbin/mysqld(dict_drop_index_tree+0xc4)[0x7d1514]
/usr/sbin/mysqld(row_upd_step+0x8a5)[0x7833e5]
/usr/sbin/mysqld(que_run_threads+0x2d0)[0x762220]
/usr/sbin/mysqld(que_eval_sql+0xb9)[0x762709]
/usr/sbin/mysqld(row_drop_table_for_mysql+0x360)[0x772790]
/usr/sbin/mysqld(trx_rollback_or_clean_all_recovered+0x672)[0x799452]
/lib64/tls/libpthread.so.0[0x2b8bb3754137]
/lib64/tls/libc.so.6(__clone+0x73)[0x2b8bb3e06f03]
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
091127 09:55:55 mysqld_safe Number of processes running now: 0
091127 09:55:55 mysqld_safe mysqld restarted
091127  9:55:55 [Note] Plugin 'FEDERATED' is disabled.
InnoDB: The InnoDB memory heap is disabled
InnoDB: Neither mutexes nor rw_locks use GCC atomic builtins.
091127  9:55:56  InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 3988098206852
091127  9:55:56  InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
InnoDB: Doing recovery: scanned up to log sequence number 3988103449600
InnoDB: Doing recovery: scanned up to log sequence number 3988108692480
InnoDB: Doing recovery: scanned up to log sequence number 3988113935360
InnoDB: Doing recovery: scanned up to log sequence number 3988119178240
InnoDB: Doing recovery: scanned up to log sequence number 3988124421120
InnoDB: Doing recovery: scanned up to log sequence number 3988126901873
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 1 row operations to undo
InnoDB: Trx id counter is 6842F9A00
091127  9:55:58  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22
23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52
53 54 55 56 57 58 59 60 61 62 6
3 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92
93 94 95 96 97 98 99
InnoDB: Apply batch completed
091127  9:56:56 InnoDB Plugin 1.0.4 started; log sequence number 3988126901873
InnoDB: Starting in background the rollback of uncommitted transactions
091127  9:56:56  InnoDB: Rolling back trx with id 6842F9857, 1 rows to undo
InnoDB: Dropping table with id 0 44 in recovery if it exists
InnoDB: Table found: dropping table "***"."#sql2-6639-a" in recovery
091127  9:56:56 [Note] Event Scheduler: Loaded 0 events
091127  9:56:56 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.4.3-beta-community'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MySQL
Community Server (GPL)
091127  9:56:56  InnoDB: Assertion failure in thread 1197001056 in file fsp/fsp0fsp.c
line 3404
-----log file ends-----
 ... endless loop

my.cnf:
[mysqld]
skip-locking
key_buffer = 1024M
max_allowed_packet = 8M
table_cache = 1024
sort_buffer_size = 16M
join_buffer_size = 16M
read_buffer_size = 4M
read_rnd_buffer_size = 4M
thread_cache_size = 50
query_cache_size = 256M
innodb_buffer_pool_size = 1024M
innodb_additional_mem_pool_size = 64M
innodb_log_file_size = 128M
innodb_log_buffer_size = 8M
innodb_flush_log_at_trx_commit = 0
innodb_lock_wait_timeout = 300
innodb_file_per_table = 1
innodb_mirrored_log_groups = 1
innodb_log_files_in_group = 2
innodb_file_format = Barracuda
innodb_flush_method=O_DIRECT

How to repeat:
I'm not sure because I executed same command "ALTER TABLE ...." to another table in the same way and in that time altering table was successful.

Thank you for the problem report. Please, send complete CREATE TABLE statement for the problematic table.

Here's the CREATE TABLE statement executed when originally the table was created.

CREATE TABLE IF NOT EXISTS `item` (
  `item_id` int(10) unsigned NOT NULL AUTO_INCREMENT,
  `itemNumber` int(8) unsigned zerofill NOT NULL DEFAULT '00000000',
  `itemPrice` int(10) unsigned NOT NULL DEFAULT '0',
  `imageFlag` tinyint(1) NOT NULL DEFAULT '0',
  `shop_id` mediumint(9) unsigned NOT NULL DEFAULT '0',
  `genreId` int(11) NOT NULL DEFAULT '0',
  `get_date` int(10) NOT NULL DEFAULT '0',
  `get_date_micro` mediumint(6) NOT NULL DEFAULT '0',
  PRIMARY KEY (`item_id`),
  UNIQUE KEY `itemNumber` (`itemNumber`,`shop_id`),
  KEY `item_genreId` (`genreId`),
  KEY `itemPrice` (`itemPrice`),
  KEY `get_date` (`get_date`),
  KEY `shopCode` (`shop_id`)
) ENGINE=InnoDB DEFAULT CHARSET=ujis AUTO_INCREMENT=1 ;

Thank you for the feedback.

I can not repeat problem with just create/alter statements.

You wrote you originally created table in version 5.1.28-0, but InnoDB Plugin is only included into MySQL releases since version 5.1.38.

Did you install InnoDB Plugin with version 5.1.28 yourself? Did you use Barracuda format originally? If yes, please, indicate packages of MySQL server and InnoDB you used.

When I made the table in MySQL 5.1.28, I used InnoDB not as Plugin. 
Installed packages were downloaded from mysql.com download page.

I created the table as InnoDB in 5.1.28, inserted records into it.
Then, I upgraded to MySQL 5.4.3.
5.4.3 recognized innodb data file (*.ibd, *.frm, ib_data and ib_logfile) created in 5.1.28, so the upgrading was completed without dumping the table and importing.

Thank you for the feedback.

Moving ib* files, then use another format is not recommended. Although I can not repeat described behavior with dummy data and crash is not good anyway.

Please send us minimal dump of data problem is repeatable with, so we can repeat the problem on our side.

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".

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".