MySQL Bugs: #27577: ALTER TABLE .. TYPE=InnoDB causes uninterruptable hang

Bug #27577	ALTER TABLE .. TYPE=InnoDB causes uninterruptable hang
Submitted:	2 Apr 2007 1:13	Modified:	22 May 2007 16:05
Reporter:	Chris Elsworth	Email Updates:
Status:	Can't repeat	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S2 (Serious)
Version:	5.1.16-beta	OS:	Linux (Linux 2.6.17 x86_64 (Ubuntu))
Assigned to:	Inaam Rana	CPU Architecture:	Any

Description:
I can reproducably hang mysqld 5.1.16-beta when attempting to convert the MyISAM table (FileGroup) provided in the tarfile [below] to InnoDB, using
ALTER TABLE FileGroup TYPE=InnoDB;

CHECK TABLE produces no errors. I've tried REPAIR TABLE prior to the ALTER TABLE anyway, with no effect.

To reduce the chances of the particular datafile/indexfile I was trying to convert being corrupt, I tried:

CREATE TABLE t2 LIKE FileGroup;
INSERT INTO t2 SELECT * FROM FileGroup;
ALTER TABLE t2 TYPE=InnoDB;

This also hung. CPU usage falls to zero in the middle of the operation, and all disk access ceases. There is no indication of why in any of the server logs.

This occurs with both the Linux/amd64 binary, and a build from source using:
./configure --prefix=/usr/local/mysql --with-debug --with-plugin-partition --with-plugin-innobase

I believe this to be a problem in InnoDB, as this works:
ALTER TABLE FileGroup TYPE=MyISAM;

It is basically a null-op, but it proves the entire table can be read and re-written into a new set of files without issue. It's only when I try to convert it to InnoDB that I see a hang.

Attaching gdb to the debug build also hangs; I'm unable to get a backtrace.
The mysqld process is unkillable, SIGTERM does absolutely nothing, SIGKILL causes the process to end up a zombie.

my.cnf:

[mysqld]
pid-file        = /db/mysql/mysqld.pid
port            = 3306
socket          = /tmp/mysql.sock

basedir         = /usr/local/mysql
datadir         = /db/mysql
tmpdir          = /db/tmp

key_buffer_size         = 256M
sort_buffer_size        = 16M
read_buffer_size        = 1M
read_rnd_buffer_size    = 1M
max_allowed_packet      = 16M
thread_cache            = 16
table_cache             = 1024
query_prealloc_size     = 32768
max_connections         = 256
tmp_table_size          = 512M
max_heap_table_size     = 256M

myisam-recover          = BACKUP,FORCE

slave_net_timeout       = 30
skip_slave_start

myisam_max_sort_file_size=1024M
myisam_max_extra_sort_file_size=1024M

query_cache_size        = 16M

log-slow-queries        = /db/mysql/mysql-slow.log
server-id               = 104
slave-skip-errors       = 1062,1053

innodb_data_file_path = ibdata1:1024M:autoextend
innodb_buffer_pool_size = 1024M
innodb_additional_mem_pool_size = 24M
innodb_log_file_size = 256M
innodb_log_buffer_size = 16M
innodb_flush_log_at_trx_commit = 0
innodb_flush_method = O_DIRECT
innodb_file_per_table

Please let me know if I missed anything/you need anything else.

How to repeat:
Unpack the MyISAM table provided, and try to convert it to InnoDB.
http://spork.qfe3.net/~chris/FileGroup.tar.bz2 [469MB - figured I'd better just leave it as a link unless you want something this big attached]

MD5s:
0dcb209171067650db8c3de10cf01cd3  FileGroup.frm
174589419e2cd0700ed951f967045d23  FileGroup.MYD
94029c1badc19f68a1578dc9fd65e731  FileGroup.MYI
7a5e464d092cfaa3f16176440786e21b  FileGroup.tar.bz2

ALTER TABLE FileGroup TYPE=InnoDB;

Chris,

what do SHOW INNODB STATUS\G and SHOW PROCESSLIST print during the hang?

How long does it take to hang?

Regards,

Heikki

Heikki,

SHOW PROCESSLIST / SHOW INNODB STATUS do not respond after the hang; the entire server seems to go into some kind of deadlock. It doesn't accept any new connections, and any existing connections that were open, don't return to any commands.

After executing the ALTER TABLE it varies on time to deadlock but is between 2 and 15 minutes. For comparison, the "null-op" ALTER TABLE FileGroup TYPE=MyISAM I did as a test took 6 minutes.

Did you manage to recreate the hang?

Heikki,

After some more experimentation, it appears as though the order of the rows in the MyISAM table I tarred up may have some bearing.

This works:
ALTER TABLE FileGroup ORDER BY FileID;
ALTER TABLE FileGroup TYPE=InnoDB;

That is, ordering the rows by FileID before converting makes the conversion work. I have repeated this several times with 100% success. I have not yet tried ordering by other columns.

Chris,

I will try to repeat this.

I assume that after the hang, InnoDB did not start within 10 minutes to print diagnostics to the .err log? If the hang happens on an InnoDB semaphore, that is what normally happens.

Regards,

Heikki

Heikki,

I haven't seen any information dumped to the error log yet. I've just done it again and realised that only SHOW INNODB STATUS does not return; I can still do SHOW FULL PROCESSLIST etc:

     Id: 1
   User: root
   Host: localhost
     db: test
Command: Query
   Time: 2997
  State: copy to tmp table
   Info: alter table FileGroup type=innodb

As you can see this one has been hung nearly an hour.
Apologies for the earlier misinformation that the entire server seemed to deadlock, that was wrong. Only the ALTER TABLE and SHOW INNODB STATUS seem to be hanging for me with this test.

Heikki,

Just one more bit of evidence to add to this; after the first conversion hangs, if I then try to start another one on an unrelated table, even in an unrelated database, in the same server, that hangs too, in state 'creating table'.

Since there is no output in the .err log, it is probably hanging on some MySQL mutex.

I hope I have time to test this.

Could it be this critical binlog hang bug that is fixed in 5.1.17:

http://bugs.mysql.com/bug.php?id=26079

?

Regards,

Heikki

Heikki,

I don't think so - binary logging is disabled on this host. It is a replication slave so does relay logging, but for the purposes of this test I disabled replication with skip-slave-start (see config above). So there should be nothing written to any form of binary log.

Assigning this mystical hang to Inaam. Please compile MySQL with:

./BUILD/compile-pentium64-debug-max

and try to repeat this inside gdb so that we get the stack trace from the hang place.

--Heikki

Chris,

Inaam is not able to repeat the hang. I guess the only way to find the bug is that you compile mysqld with:

CFLAGS="-g" CXXFLAGS="-g" ./configure ...

and run inside gdb. When it hangs, kill -11 the mysqld process, so that gdb breaks execution. Then look at all threads and their stack traces.

Regards,

Heikki

This seems to be Linux-specific; we've been unable to reproduce the problem on 2 different FreeBSD systems.

We've been unable to get much of use out of gdb so far; it hangs enumerating threads inside wait4(), and killing MySQL just results in a zombie.

I wonder if we need a kernel debugger or so...

Thomas,

you do not need a kernel debugger. mysqld is a perfectly normal user process.

I have not seen such gdb hangs on 2.6.18-4-amd64 #1 SMP Mon Mar 26 11:36:53 CEST 2007 x86_64 GNU/Linux.

When I have a hung mysqld process, I attach witg gdb to it. Then I send kill -11 to the mysqld process. Then execution breaks inside gdb, and I can query the threads and print their stack traces.

Regards,

Heikki

That's the problem Heikki, mysqld does not stop execution and hand control to gdb. We get this:

root@db9:~# ps auxw | grep mysqld
root      8425  0.0  0.0   2772   568 pts/0    S    13:40   0:00 /bin/sh /usr/local/mysql/bin/mysqld_safe
mysql     8462 52.3 33.2 1120612 683456 pts/0  Sl   13:40  10:16 /usr/local/mysql/bin/mysqld --basedir=/usr/local/mysql --datadir=/db/mysql --user=mysql --pid-file=/db/mysql/mysqld.pid --skip-external-locking --port=3306 --socket=/tmp/mysql.sock
root      8600  0.0  0.0   3908   808 pts/1    S+   13:59   0:00 grep mysqld
root@db9:~# gdb /usr/local/mysql/bin/mysqld 8462
GNU gdb 6.4.90-debian
Copyright (C) 2006 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you are
welcome to change it and/or distribute copies of it under certain conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB.  Type "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu"...(no debugging symbols found)
Using host libthread_db library "/lib/libthread_db.so.1".

Attaching to program: /usr/local/mysql-5.0.37-linux-x86_64-glibc23/bin/mysqld, process 8462
Reading symbols from /lib/librt.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib/librt.so.1
Reading symbols from /lib/libdl.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib/libdl.so.2
Reading symbols from /lib/libpthread.so.0...
(no debugging symbols found)...done.
[Thread debugging using libthread_db enabled]
[New Thread 47087960752640 (LWP 8462)]
[New Thread 1133554000 (LWP 8481)]
[New Thread 1133287760 (LWP 8476)]

There is no further output. I then issue the kill:
root@db9:~# kill -11 8462

gdb does absolutely nothing - no more output. I inspect the process again:

root@db9:~# ps auxw | grep mysqld
root      8425  0.0  0.0   2772   568 pts/0    S    13:40   0:00 /bin/sh /usr/local/mysql/bin/mysqld_safe
mysql     8462 45.8  0.0      0     0 pts/0    Zl   13:40  10:16 [mysqld] <defunct>
root      8610  0.0  0.7  24092 14920 pts/1    S+   14:00   0:00 gdb /usr/local/mysql/bin/mysqld 8462
root      8636  0.0  0.0   3908   812 pts/2    S+   14:02   0:00 grep mysqld
root@db9:~#

mysqld appears to now be a zombie. So you see the problem we're having debugging this :)

For this reason we now think we may be tickling a Linux kernel bug. Especially as we are unable to reproduce the hang in FreeBSD.

Chris,

thank you. I put this to the 'Can't repeat' status until someone is able to get gdb to work on this bug.

Regards,

Heikki

Chris,

thank you. I put this to the 'Can't repeat' status until someone is able to get gdb to work on this bug.

Regards,

Heikki

We've repeated this on FreeBSD 7-CURRENT, and managed to get a coredump using gcore.  Very similar behavior to Linux; attaching gdb hangs in wait4(), MySQL won't die and still accepts connections, etc.  gcore left the process in state STOP, looks like we'll need to reboot.

Backtrace from the core:

#0  0x000000080122cc9c in _umtx_op () from /lib/libc.so.7
#1  0x0000000800cb318b in pthread_cleanup_pop () from /lib/libthr.so.2
#2  0x0000000800cb1cda in pthread_cond_destroy () from /lib/libthr.so.2
#3  0x00000000004c1a75 in one_thread_per_connection_end ()
#4  0x00000000004ca6b0 in handle_one_connection ()
#5  0x0000000800cac124 in pthread_create () from /lib/libthr.so.2

This was with our own build of 5.1.19 and FreeBSD 7.0-CURRENT/AMD64 built on the 8th of June.  The hang happened on shutdown after a "difficult repair" of another table, as described at http://dev.mysql.com/doc/refman/5.1/en/repair.html

Here's an excerpt from SHOW ENGINE INNODB MUTEX

| InnoDB | buf0buf.c:545    | os_waits=0 |
| InnoDB | buf0buf.c:547    | os_waits=0 |
| InnoDB | buf0buf.c:545    | os_waits=0 |
| InnoDB | buf0buf.c:547    | os_waits=0 |
| InnoDB | buf0buf.c:545    | os_waits=0 |
| InnoDB | buf0buf.c:547    | os_waits=0 |
| InnoDB | buf0buf.c:545    | os_waits=0 |
| InnoDB | buf0buf.c:597    | os_waits=0 |
| InnoDB | fil0fil.c:1313   | os_waits=0 |
| InnoDB | srv0start.c:1227 | os_waits=0 |
| InnoDB | srv0start.c:1220 | os_waits=0 |
| InnoDB | srv0start.c:1198 | os_waits=0 |
| InnoDB | dict0mem.c:90    | os_waits=0 |
| InnoDB | dict0mem.c:90    | os_waits=0 |
| InnoDB | srv0srv.c:860    | os_waits=0 |
| InnoDB | srv0srv.c:858    | os_waits=0 |
| InnoDB | thr0loc.c:227    | os_waits=0 |
| InnoDB | mem0pool.c:206   | os_waits=0 |
| InnoDB | sync0sync.c:1302 | os_waits=0 |
+--------+------------------+------------+
1311116 rows in set (11.77 sec)

The list bounces between buf0buf.c:545 and buf0buf.c:547 about 1311104 times.

Here's SHOW INNODB STATUS:

=====================================
070610 22:25:39 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 3 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 2359, signal count 2359
Mutex spin waits 0, rounds 0, OS waits 0
RW-shared spins 2921, OS waits 1025; RW-excl spins 6388, OS waits 1334
------------
TRANSACTIONS
------------
Trx id counter 0 60951690
Purge done for trx's n:o < 0 60951670 undo n:o < 0 0
History list length 8
Total number of lock structs in row lock hash table 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 0, not started, OS thread id 34381767264
MySQL thread id 26, query id 510990 admin0-mgt.newzbin.com 192.168.201.105 root
show innodb status
--------
FILE I/O
--------
I/O thread 0 state: waiting for i/o request (insert buffer thread)
I/O thread 1 state: waiting for i/o request (log thread)
I/O thread 2 state: waiting for i/o request (read thread)
I/O thread 3 state: waiting for i/o request (write thread)
Pending normal aio reads: 0, aio writes: 0,
 ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
52541 OS file reads, 29073 OS file writes, 3814 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 617, seg size 619,
38891 inserts, 38891 merged recs, 13668 merges
Hash table size 21249871, used cells 1131661, node heap has 1717 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 13 2404484002
Log flushed up to   13 2404484002
Last checkpoint at  13 2404484002
0 pending log writes, 0 pending chkp writes
1426 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 11488937550; in additional pool allocated 11610112
Dictionary memory allocated 496584
Buffer pool size   655360
Free buffers       592304
Database pages     61339
Modified db pages  0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages read 57986, created 3393, written 51661
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Main thread id 34381765792, state: waiting for server activity
Number of rows inserted 89005, updated 794676, deleted 95871, read 3124944
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

And the thread states via top(1):

  995 mysql      4    0 11637M 11642M sbwait 2   2:59  1.22% mysqld
  995 mysql     96    0 11637M 11642M ucond  3   2:59  0.24% mysqld
  995 mysql     96    0 11637M 11642M ucond  3   2:59  0.00% mysqld
  995 mysql     96    0 11637M 11642M ucond  2   2:59  0.00% mysqld
  995 mysql     96    0 11637M 11642M ucond  3   2:59  0.00% mysqld
  995 mysql     96    0 11637M 11642M ucond  2   2:59  0.00% mysqld
  995 mysql     96    0 11637M 11642M select 0   2:59  0.00% mysqld
  995 mysql     96    0 11637M 11642M ucond  0   2:59  0.00% mysqld
  995 mysql     96    0 11637M 11642M select 2   2:59  0.00% mysqld
  995 mysql     96    0 11637M 11642M ucond  2   2:59  0.00% mysqld
  995 mysql     96    0 11637M 11642M select 1   2:59  0.00% mysqld
  995 mysql     20    0 11637M 11642M sigwai 3   2:59  0.00% mysqld
  995 mysql      4    0 11637M 11642M sbwait 2   2:59  0.00% mysqld

After comparing with our slaves, this looks normal; we have a lot of InnoDB buffers, and thus a lot of buffer pool objects and their associated pair of mutexes, as per our InnoDB config:

innodb_data_file_path = ibdata1:500M:autoextend
innodb_buffer_pool_size = 10240M
innodb_additional_mem_pool_size = 24M
innodb_log_file_size = 256M
innodb_log_buffer_size = 16M
innodb_flush_log_at_trx_commit = 0
innodb_lock_wait_timeout = 50
innodb_flush_method = O_DIRECT
innodb_file_per_table