Bug #49154 mysql doesn't start normaly after altering innodb table to be compressed
Submitted: 27 Nov 2009 2:48 Modified: 27 Nov 2009 3:31
Reporter: Goki Honjo Email Updates:
Status: Duplicate Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S1 (Critical)
Version:5.4.3-0 OS:Linux (CentOS 5.4)
Assigned to: CPU Architecture:Any
Tags: compress, innodb

[27 Nov 2009 2:48] Goki Honjo
Description:
The mysql daemon quits unexpectedly as soon as it starts. 

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

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.
[27 Nov 2009 3:31] Goki Honjo
I'm sorry but I duplicated bug report.