Bug #35077 Very slow DROP TABLE (ALTER TABLE, OPTIMIZE TABLE) on compressed tables
Submitted: 5 Mar 2008 12:13 Modified: 19 Jun 2010 0:25
Reporter: Philip Stoev Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB Plugin storage engine Severity:S3 (Non-critical)
Version:5.1.42 OS:Any
Assigned to: Marko Mäkelä CPU Architecture:Any
Tags: buf_LRU_invalidate_tablespace

[5 Mar 2008 12:13] Philip Stoev
Description:
Innodb deadlocks on concurrent DDL statements. CPU usage remains at 100% (one core out of two occupied).

How to repeat:
Simpler testcase will follow shortly.
[5 Mar 2008 12:27] Philip Stoev
Test case for bug 35077

Attachment: bug35077.zip (application/x-zip-compressed, text), 1.62 KiB.

[5 Mar 2008 12:30] Philip Stoev
To run the test case, please place the .txt files in mysql-test and the .test files in mysql-test/t. Then run:

$ perl ./mysql-test-run.pl --stress --stress-init-file=bug35077_init.txt \
--stress-test-file=bug35077_run.txt --stress-test-duration=60000 \
--stress-threads=10  --skip-ndb --mysqld=--innodb --mysqld=--log-output=file

Ignore any errors reported by the test script. Within a few hundred iterations, you will observe that the test stalls. At that point, you can issue SHOW processlist to confirm that there is a constant set of queries which are not going anywhere and are not affected by the 50-second innodb timeout.
[5 Mar 2008 12:43] Heikki Tuuri
Philip,

since the deadlock is not resolve in 50 seconds, this is probably a deadlock in MySQL's table locks, or an infinite loop.

Please print SHOW INNODB STATUS\G and SHOW PROCESSLIST; during the deadlock.

Regards,

Heikki
[5 Mar 2008 13:04] Philip Stoev
Here is the processlist. The threads sometimes change status, however make no real progress.

mysql> show processlist\G
*************************** 1. row ***************************
     Id: 252
   User: root
   Host: localhost
     db: test
Command: Query
   Time: 90
  State: rename result table
   Info: ALTER TABLE inter1 ADD KEY k1 (t1_uuid)
*************************** 2. row ***************************
     Id: 253
   User: root
   Host: localhost
     db: test
Command: Query
   Time: 90
  State: rename result table
   Info: ALTER TABLE inter1 ADD KEY k1 (t1_uuid)
*************************** 3. row ***************************
     Id: 256
   User: root
   Host: localhost
     db: test
Command: Query
   Time: 90
  State: Waiting for table
   Info: ALTER TABLE inter1 DROP COLUMN filler
*************************** 4. row ***************************
     Id: 257
   User: root
   Host: localhost
     db: test
Command: Query
   Time: 90
  State: Waiting for table
   Info: ALTER TABLE inter1 DROP COLUMN filler
*************************** 5. row ***************************
     Id: 259
   User: root
   Host: localhost
     db: test
Command: Query
   Time: 90
  State: Waiting for table
   Info: ALTER TABLE inter1 DROP COLUMN filler
*************************** 6. row ***************************
     Id: 260
   User: root
   Host: localhost
     db: test
Command: Query
   Time: 90
  State: Waiting for table
   Info: ALTER TABLE inter1 DROP COLUMN filler
*************************** 7. row ***************************
     Id: 261
   User: root
   Host: localhost
     db: test
Command: Query
   Time: 90
  State: Waiting for table
   Info: ALTER TABLE inter1 DROP COLUMN filler
*************************** 8. row ***************************
     Id: 262
   User: root
   Host: localhost
     db: test
Command: Query
   Time: 90
  State: Waiting for table
   Info: ALTER TABLE inter1 ADD COLUMN filler TINYTEXT
*************************** 9. row ***************************
     Id: 263
   User: root
   Host: localhost
     db: test
Command: Query
   Time: 89
  State: Waiting for table
   Info: ALTER TABLE inter1 DROP COLUMN filler
*************************** 10. row ***************************
     Id: 264
   User: root
   Host: localhost
     db: test
Command: Query
   Time: 89
  State: Waiting for table
   Info: ALTER TABLE inter1 ADD COLUMN filler TINYTEXT
[5 Mar 2008 13:05] Philip Stoev
mysql> SHOW ENGINE INNODB STATUS\G
*************************** 1. row ***************************
  Type: InnoDB
  Name:
Status:
=====================================
080305 15:05:13 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 25 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 162, signal count 162
Mutex spin waits 0, rounds 4859, OS waits 77
RW-shared spins 113, OS waits 58; RW-excl spins 48, OS waits 24
------------
TRANSACTIONS
------------
Trx id counter 0 6661
Purge done for trx's n:o < 0 6659 undo n:o < 0 0
History list length 13
Total number of lock structs in row lock hash table 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 0, not started, process no 10563, OS thread id 2990336912
MySQL thread id 265, query id 1747 localhost root
SHOW ENGINE INNODB STATUS
---TRANSACTION 0 0, not started, process no 10563, OS thread id 2992003984
MySQL thread id 256, query id 1702 localhost root Waiting for table
ALTER TABLE inter1 DROP COLUMN filler
---TRANSACTION 0 0, not started, process no 10563, OS thread id 2992405392
MySQL thread id 257, query id 1700 localhost root Waiting for table
ALTER TABLE inter1 DROP COLUMN filler
---TRANSACTION 0 6660, not started, process no 10563, OS thread id 2992204688
mysql tables in use 1, locked 2
MySQL thread id 253, query id 1701 localhost root rename result table
ALTER TABLE inter1 ADD KEY k1 (t1_uuid)
---TRANSACTION 0 6652, not started, process no 10563, OS thread id 2991803280
mysql tables in use 1, locked 2
MySQL thread id 252, query id 1699 localhost root rename result table
ALTER TABLE inter1 ADD KEY k1 (t1_uuid)
--------
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
0 OS file reads, 2532 OS file writes, 2494 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 0, seg size 2,
0 inserts, 0 merged recs, 0 merges
Hash table size 34679, used cells 69, node heap has 1 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 0 4123244
Log flushed up to   0 4123244
Last checkpoint at  0 4123244
0 pending log writes, 0 pending chkp writes
2481 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 19910426; in additional pool allocated 897664
Dictionary memory allocated 36616
Buffer pool size   512
Free buffers       247
Database pages     264
Modified db pages  0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages read 0, created 264, written 313
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 process no. 10563, id 3005029264, state: waiting for server activity
Number of rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
[5 Mar 2008 13:43] Heikki Tuuri
Looks like two ALTERs were allowed to proceed:

*************************** 1. row ***************************
     Id: 252
   User: root
   Host: localhost
     db: test
Command: Query
   Time: 90
  State: rename result table
   Info: ALTER TABLE inter1 ADD KEY k1 (t1_uuid)
*************************** 2. row ***************************
     Id: 253
   User: root
   Host: localhost
     db: test
Command: Query
   Time: 90
  State: rename result table
   Info: ALTER TABLE inter1 ADD KEY k1 (t1_uuid)
*************************** 3. row ***************************

All threads apparently are waiting for MySQL table or name locks. This is probably a MySQL server bug and not an InnoDB bug.
[5 Mar 2008 13:51] Philip Stoev
Please reassign as you see fit.
[5 Mar 2008 14:06] Heikki Tuuri
IF this is an InnoDB bug, then the bug probably is that the following code in ha_innodb.cc ::store_lock() weakens the ALTER table locks. The comment below says that MySQL uses TL_WRITE_ALLOW_READ, which is not weakened. But if that has changed...

ha_innodb.cc in 5.1:

                /* If we are not doing a LOCK TABLE, DISCARD/IMPORT
                TABLESPACE or TRUNCATE TABLE then allow multiple
                writers. Note that ALTER TABLE uses a TL_WRITE_ALLOW_READ
                < TL_WRITE_CONCURRENT_INSERT.

                We especially allow multiple writers if MySQL is at the
                start of a stored procedure call (SQLCOM_CALL) or a
                stored function call (MySQL does have in_lock_tables
                TRUE there). */

                if ((lock_type >= TL_WRITE_CONCURRENT_INSERT
                     && lock_type <= TL_WRITE)
                    && !(in_lock_tables
                         && sql_command == SQLCOM_LOCK_TABLES)
                    && !thd_tablespace_op(thd)
                    && sql_command != SQLCOM_TRUNCATE
                    && sql_command != SQLCOM_OPTIMIZE
                    && sql_command != SQLCOM_CREATE_TABLE) {

                        lock_type = TL_WRITE_ALLOW_WRITE;
                }

                /* In queries of type INSERT INTO t1 SELECT ... FROM t2 ...
                MySQL would use the lock TL_READ_NO_INSERT on t2, and that
                would conflict with TL_WRITE_ALLOW_WRITE, blocking all inserts
                to t2. Convert the lock to a normal read lock to allow
                concurrent inserts to t2.

                We especially allow concurrent inserts if MySQL is at the
                start of a stored procedure call (SQLCOM_CALL)
                (MySQL does have thd_in_lock_tables() TRUE there). */

                if (lock_type == TL_READ_NO_INSERT
                    && sql_command != SQLCOM_LOCK_TABLES) {

                        lock_type = TL_READ;
                }

                lock.type = lock_type;
[14 Mar 2008 14:29] Philip Stoev
The test case also hangs with Falcon. For both engines, the CPU continues to run at 100% (one core occupied). Therefore it is a livelock and it is not Innodb-specific.
[2 Oct 2008 15:34] Konstantin Osipov
I disagree with the impact. This is a regression!
[3 Feb 2009 12:36] Philip Stoev
This bug is no longer reproducible on 5.1 with Innodb and/or 6.0 with Falcon and Innodb.
[10 Jun 2009 12:46] Chris DiMartino
I disagree that this is fixed.  I am running multiple table alters on different databases (with different disks for each).  The alters move along smoothly until one of the processes is ready to rename the result table.  At that point, all file io hangs and all processes get stuck in their current state until thread that is renaming the result table completes.  This thread takes a very long time to complete (30 minutes+).  During that time, 1 processor is at 100%, all others are idle.  File io is non-existent.

+-----+------+-----------+---------------+---------+------+---------------------+-------------------------------------------+
| Id  | User | Host      | db            | Command | Time | State               | Info                                      |
+-----+------+-----------+---------------+---------+------+---------------------+-------------------------------------------+
| 79  | root | localhost |               | Query   | 0    |                     | show processlist                          |
| 100 | root | localhost | common_files  | Query   | 7873 | copy to tmp table   | OPTIMIZE TABLE `geoname`                  |
| 101 | root | localhost | stats_test    | Query   | 7574 | copy to tmp table   | OPTIMIZE TABLE `scans`                    |
| 113 | root | localhost | international | Query   | 2606 | rename result table | OPTIMIZE TABLE `manifest_transport_table` |
| 116 | root | localhost |               | Query   | 1034 |                     | show innodb status                        |
+-----+------+-----------+---------------+---------+------+---------------------+-------------------------------------------+

top - 08:45:16 up 74 days, 11:45,  8 users,  load average: 1.01, 1.02, 1.02
Tasks: 144 total,   1 running, 143 sleeping,   0 stopped,   0 zombie
Cpu0  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu1  :  0.0%us,  0.3%sy,  0.0%ni, 99.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu2  :100.0%us,  0.0%sy,  0.0%ni,  0.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu3  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:  16423052k total, 15578132k used,   844920k free,   937924k buffers
Swap:  2096376k total,    11760k used,  2084616k free,  1827220k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
22633 mysql     15   0 12.4g  11g 4572 S  100 76.0   1039:32 mysqld
    1 root      15   0 10332  548  516 S    0  0.0   0:02.46 init
    2 root      RT  -5     0    0    0 S    0  0.0   0:32.38 migration/0
    3 root      34  19     0    0    0 S    0  0.0   2:47.08 ksoftirqd/0
    4 root      RT  -5     0    0    0 S    0  0.0   0:00.00 watchdog/0
    5 root      RT  -5     0    0    0 S    0  0.0   0:24.21 migration/1
    6 root      34  19     0    0    0 S    0  0.0   0:01.22 ksoftirqd/1
    7 root      RT  -5     0    0    0 S    0  0.0   0:00.00 watchdog/1
    8 root      RT  -5     0    0    0 S    0  0.0   0:08.62 migration/2
    9 root      34  19     0    0    0 S    0  0.0   1:42.73 ksoftirqd/2
   10 root      RT  -5     0    0    0 S    0  0.0   0:00.00 watchdog/2
   11 root      RT  -5     0    0    0 S    0  0.0   0:03.04 migration/3

Show innodb status does not complete.

This is in:

mysql> select version();
+--------------------------------+
| version()                      |
+--------------------------------+
| 5.1.34-enterprise-gpl-advanced |
+--------------------------------+
1 row in set (0.00 sec)
[20 Jan 2010 14:13] Vojtech Kurka
I'm experiencing this on 5.1.42 with innodb plugin 1.0.6. Only compressed tables are affected.

The ALTER TABLE  gets stuck in "rename result table", however the old table has been already renamed and looks like "#sql2-37ec-3b585.ibd". I see it on the FS, I use innodb_file_per_table.

FS doesn't matter, both EXT3 and XFS are affected. CPU usage 100%, i/o activity is zero. Server is running a s a slave with active slave thread (reading and executing transactions from master). Sometimes, the ALTER TABLE proceeds after for example 20 seconds in "rename result table". Sometimes it gets stuck in this state and the only way is killing-9  mysqld. It seems like a race condition to me, the more data the table has (1GB+), the higher is the probability of this deadlock.

In error log, I see this:

InnoDB: Warning: a long semaphore wait:
--Thread 1231960384 has waited at buf/buf0buf.c line 1613 for 241.00 seconds the semaphore:
Mutex at 0xd3e3c0 '&LRU_list_mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 1197029696 has waited at buf/buf0buf.c line 3012 for 241.00 seconds the semaphore:
Mutex at 0xd3e3c0 '&LRU_list_mutex', lock var 1
waiters flag 1
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending preads 0, pwrites 0

=====================================
100120 14:56:58 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 64 seconds
----------
BACKGROUND THREAD
----------
srv_master_thread loops: 49029 1_second, 49029 sleeps, 4897 10_second, 1764 background, 1729 flush
srv_master_thread log flush and writes: 50150
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 4394676, signal count 19638024
--Thread 1231960384 has waited at buf/buf0buf.c line 1613 for 247.00 seconds the semaphore:
Mutex at 0xd3e3c0 '&LRU_list_mutex', lock var 1
waiters flag 1
--Thread 1197029696 has waited at buf/buf0buf.c line 3012 for 247.00 seconds the semaphore:
Mutex at 0xd3e3c0 '&LRU_list_mutex', lock var 1
waiters flag 1
--Thread 1228499264 has waited at buf/buf0buf.c line 2209 for 241.00 seconds the semaphore:
S-lock on RW-latch at 0xd3e440 '&page_hash_latch'
a writer (thread id 1229830464) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf/buf0buf.c line 2209
Last time write locked in file buf/buf0lru.c line 367
Mutex spin waits 3955352, rounds 41246365, OS waits 802987
RW-shared spins 11680120, OS waits 2740120; RW-excl spins 983806, OS waits 678449
Spin rounds per wait: 10.43 mutex, 11.02 RW-shared, 62.64 RW-excl
--------
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 (read thread)
I/O thread 4 state: waiting for i/o request (read thread)
I/O thread 5 state: waiting for i/o request (read thread)
I/O thread 6 state: waiting for i/o request (write thread)
I/O thread 7 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
7595363 OS file reads, 9772129 OS file writes, 328120 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 149, free list len 3820, seg size 3970,
885478 inserts, 849235 merged recs, 268928 merges
Hash table size 84999127, node heap has 166751 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 4031433450741
Log flushed up to   4031433450741
Last checkpoint at  4031139301340
Max checkpoint age    434154333
Checkpoint age target 420587011
Modified age          280707380
Checkpoint age        294149401
0 pending log writes, 0 pending chkp writes
7546531 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 44019220480; in additional pool allocated 0
Internal hash tables (constant factor + variable factor)
    Adaptive hash index 3412045608 	(679993016 + 2732052592)
    Page hash           42500456
    Dictionary cache    173652720 	(169999664 + 3653056)
    File system         302304 	(82672 + 219632)
    Lock system         106255000 	(106249768 + 5232)
    Recovery system     0 	(0 + 0)
    Threads             408536 	(406936 + 1600)
Dictionary memory allocated 3653056
InnoDB: ###### Diagnostic info printed to the standard error stream
InnoDB: Warning: a long semaphore wait:
--Thread 1231960384 has waited at buf/buf0buf.c line 1613 for 272.00 seconds the semaphore:
Mutex at 0xd3e3c0 '&LRU_list_mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 1197029696 has waited at buf/buf0buf.c line 3012 for 272.00 seconds the semaphore:
Mutex at 0xd3e3c0 '&LRU_list_mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 1228499264 has waited at buf/buf0buf.c line 2209 for 266.00 seconds the semaphore:
S-lock on RW-latch at 0xd3e440 '&page_hash_latch'
a writer (thread id 1229830464) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf/buf0buf.c line 2209
Last time write locked in file buf/buf0lru.c line 367
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending preads 0, pwrites 0
InnoDB: ###### Diagnostic info printed to the standard error stream
InnoDB: Warning: a long semaphore wait:
--Thread 1231960384 has waited at buf/buf0buf.c line 1613 for 303.00 seconds the semaphore:
Mutex at 0xd3e3c0 '&LRU_list_mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 1197029696 has waited at buf/buf0buf.c line 3012 for 303.00 seconds the semaphore:
Mutex at 0xd3e3c0 '&LRU_list_mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 1228499264 has waited at buf/buf0buf.c line 2209 for 297.00 seconds the semaphore:
S-lock on RW-latch at 0xd3e440 '&page_hash_latch'
a writer (thread id 1229830464) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf/buf0buf.c line 2209
Last time write locked in file buf/buf0lru.c line 367
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending preads 0, pwrites 0
InnoDB: ###### Diagnostic info printed to the standard error stream
[20 Jan 2010 14:24] Philip Stoev
Setting back to open in light of the recent comments.
[20 Jan 2010 14:27] Vojtech Kurka
It looks I'm not alone:

http://forums.innodb.com/read.php?3,1012,1012#msg-1012
[21 Jan 2010 12:08] Marko Mäkelä
Vojtech,
can you please attach gdb to the hung mysqld or tell the system to generate a core dump before you kill the mysqld process? I would appreciate seeing a stack trace of the hang. In gdb, you would get that with the following commands:

set log on
set height 0
thread apply all backtrace
set log off
[22 Jan 2010 15:07] Mathias Walter
I run into the same problem with MySQL 5.1.37 and InnoDB plugin 1.04. I thougth it is already fixed and upgraded to MySQL 5.1.42 and InnoDB plugin 1.06. But the problem still exists.

I got exactly the same error log output and behavious as Vojtech Kurka.

I never saw this problem with the builtin InnoDB. I also tried the precompiled version of MySQL 5.1.42 and Perconna XtraDB (MySQL-server-percona-5.1.42-9.rhel5.x86_64.rpm) without any luck.
[22 Jan 2010 23:05] Vojtech Kurka
gdb output

Attachment: gdb.txt (text/plain), 12.91 KiB.

[22 Jan 2010 23:16] Vojtech Kurka
Marko, gdb output is posted above.

I have done this:

mysql> create table test.descr like mydb.descr;
Query OK, 0 rows affected (1.16 sec)

mysql> insert into test.descr select * from mydb.descr;
Query OK, 3083399 rows affected (12 min 5.39 sec)
Records: 3083399  Duplicates: 0  Warnings: 0

mysql> optimize table test.descr;
+------------+----------+----------+-------------------------------------------------------------------+
| Table      | Op       | Msg_type | Msg_text                                                          |
+------------+----------+----------+-------------------------------------------------------------------+
| test.descr | optimize | note     | Table does not support optimize, doing recreate + analyze instead |
| test.descr | optimize | status   | OK                                                                |
+------------+----------+----------+-------------------------------------------------------------------+
2 rows in set (7 min 11.20 sec)

mysql> optimize table test.descr;

The second optimize never completes (stays in "rename result table"), the first one proceeded successfully.
Table structure:

 CREATE TABLE `descr` (
  `col0` int(10) unsigned NOT NULL,
  `col1` text COLLATE utf8_czech_ci NOT NULL,
  `col2` tinyint(1) unsigned NOT NULL DEFAULT '1' COMMENT 'some comment',
  `col3` int(10) unsigned NOT NULL,
  `col4` smallint(5) unsigned DEFAULT NULL COMMENT 'some comment',
  PRIMARY KEY (`col0`),
  KEY `col3` (`col3`),
  KEY `col4` (`col4`),
  KEY `col2` (`col2`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8 COLLATE=utf8_czech_ci ROW_FORMAT=COMPRESSED KEY_BLOCK_SIZE=8;

Table size on disk is 897581056 Bytes
[27 Jan 2010 9:15] Marko Mäkelä
Vojtech,
thank you very much for the stack traces. My suspicions are on this thread:

Thread 2 (Thread 0x49ae4940 (LWP 23320)):
#0  buf_LRU_invalidate_tablespace (id=296071) at ./include/sync0sync.ic:185
#1  0x00000000007d7a87 in fil_delete_tablespace (id=296071) at fil/fil0fil.c:2249
#2  0x00000000007592d8 in row_drop_table_for_mysql (name=0x2ab6943c8440 "test/#sql2-3eb9-83ba1", trx=0x2ab694097070, drop_db=<value optimized out>) at row/row0mysql.c:3318
#3  0x000000000070b97e in ha_innobase::delete_table (this=<value optimized out>, name=0x49adfc70 "./test/#sql2-3eb9-83ba1") at handler/ha_innodb.cc:6870

Unfortunately, the code has been inlined. If you can repeat this bug easily, can you please recompile with inlining disabled, e.g., -DUNIV_MUST_NOT_INLINE? Also, if you enable UNIV_DEBUG and UNIV_SYNC_DEBUG in include/univ.i, do you get any assertion failures?

If I am seeing the same source code, sync0sync.ic:185 should be within mutex_exit():

		mutex_signal_object(mutex);

There are several mutex_exit() calls in buf_LRU_invalidate_tablespace(). If you have the core dump for the gdb.txt you posted, please print the mutex there by executing the following:

(gdb) thread 2
(gdb) frame 0
(gdb) print *mutex
[27 Jan 2010 9:45] Marko Mäkelä
I downloaded http://dev.mysql.com/get/Downloads/MySQL-5.1/mysql-5.1.42.tar.gz/from/http://ftp.sunet.se/... and verified that sync0sync.ic:185 is the statement mutex_signal_object(mutex) in mutex_exit().

Further questions:

* What does InnoDB Plugin report about atomic operations at startup?
* On which processor and operating system does the bug occur?
[27 Jan 2010 10:00] Vojtech Kurka
* What does InnoDB Plugin report about atomic operations at startup?

100125 23:31:05 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
100125 23:31:05 [Note] Plugin 'FEDERATED' is disabled.
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
100125 23:31:10  InnoDB: highest supported file format is Barracuda.

* On which processor and operating system does the bug occur?

AMD Opteron 2220, Centos 5.4, Linux 2.6.18-164.9.1.el5.centos.plus

One more thing to note: currently, we use XtraDB 1.0.6-9. Therefore the source code might be slightly different. However, I don't think it's XtraDB-only issue, we have been hitting this bug also on standard InnoDB plugin 1.0.3 and 1.0.4.

We have installed this release from using RPM:
http://www.percona.com/mysql/xtradb/5.1.42-9/
[27 Jan 2010 10:16] Marko Mäkelä
As far as I can understand, the original bug (hang on concurrent DDL) has been fixed, but users are running into another issue with the InnoDB Plugin, not the built-in InnoDB. These hangs have also been discussed on the InnoDB forum at http://forums.innodb.com/read.php?3,1012,1012

I suspect that the bug is in the software or hardware implementation of InnoDB mutexes with atomic memory accesses. The built-in InnoDB uses the operating system primitives for mutexes and rw-locks, but the InnoDB Plugin uses atomic memory operations where available. The function buf_LRU_invalidate_tablespace() is causing a burst of mutex_enter/mutex_exit operations that is apparently triggering the bug.

Please report your processor and operating system.
[27 Jan 2010 10:18] Vojtech Kurka
AMD Opteron 2220, Centos 5.4, Linux 2.6.18-164.9.1.el5.centos.plus
[27 Jan 2010 11:03] Vojtech Kurka
Marko,

is this informatin sufficient for you? I'm sorry, I don't have enough resources to recompile mysql at now. It would be possible in few weeks.

We have two machines with AMD 2220, both suffer from this bug. I'll try to simulate this on our local testing machine with Intel CPU.
[27 Jan 2010 13:23] Marko Mäkelä
Thanks Vojtech, your information is enough for now.

In case you run into this issue again, please enable core dumps and try to preserve the core dump and the corresponding executable. Whether it is XtraDB or InnoDB, it should not matter. I do not remember reading anything about changes in this area, but then again, I have not followed XtraDB closely.

It would be very helpful if you could try to repeat this on different types of processors and report the outcome. Different processors may implement memory barriers differently, and there could be a bug in a cache coherence protocol that we could hopefully work around in software.
[27 Jan 2010 13:30] Mikhail Izioumtchenko
Vojtech, could you provide the output of

cat /proc/cpuinfo

on the machine you experience the hang?
[27 Jan 2010 13:34] Vojtech Kurka
processor	: 0
vendor_id	: AuthenticAMD
cpu family	: 15
model		: 65
model name	: Dual-Core AMD Opteron(tm) Processor 2220
stepping	: 3
cpu MHz		: 2800.000
cache size	: 1024 KB
physical id	: 0
siblings	: 2
core id		: 0
cpu cores	: 2
apicid		: 0
fpu		: yes
fpu_exception	: yes
cpuid level	: 1
wp		: yes
flags		: fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ht syscall nx mmxext fxsr_opt rdtscp lm 3dnowext 3dnow pni cx16 lahf_lm cmp_legacy svm extapic cr8_legacy
bogomips	: 5629.02
TLB size	: 1024 4K pages
clflush size	: 64
cache_alignment	: 64
address sizes	: 40 bits physical, 48 bits virtual
power management: ts fid vid ttp tm stc

processor	: 1
vendor_id	: AuthenticAMD
cpu family	: 15
model		: 65
model name	: Dual-Core AMD Opteron(tm) Processor 2220
stepping	: 3
cpu MHz		: 2800.000
cache size	: 1024 KB
physical id	: 0
siblings	: 2
core id		: 1
cpu cores	: 2
apicid		: 1
fpu		: yes
fpu_exception	: yes
cpuid level	: 1
wp		: yes
flags		: fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ht syscall nx mmxext fxsr_opt rdtscp lm 3dnowext 3dnow pni cx16 lahf_lm cmp_legacy svm extapic cr8_legacy
bogomips	: 5629.02
TLB size	: 1024 4K pages
clflush size	: 64
cache_alignment	: 64
address sizes	: 40 bits physical, 48 bits virtual
power management: ts fid vid ttp tm stc

processor	: 2
vendor_id	: AuthenticAMD
cpu family	: 15
model		: 65
model name	: Dual-Core AMD Opteron(tm) Processor 2220
stepping	: 3
cpu MHz		: 2800.000
cache size	: 1024 KB
physical id	: 1
siblings	: 2
core id		: 0
cpu cores	: 2
apicid		: 2
fpu		: yes
fpu_exception	: yes
cpuid level	: 1
wp		: yes
flags		: fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ht syscall nx mmxext fxsr_opt rdtscp lm 3dnowext 3dnow pni cx16 lahf_lm cmp_legacy svm extapic cr8_legacy
bogomips	: 5629.02
TLB size	: 1024 4K pages
clflush size	: 64
cache_alignment	: 64
address sizes	: 40 bits physical, 48 bits virtual
power management: ts fid vid ttp tm stc

processor	: 3
vendor_id	: AuthenticAMD
cpu family	: 15
model		: 65
model name	: Dual-Core AMD Opteron(tm) Processor 2220
stepping	: 3
cpu MHz		: 2800.000
cache size	: 1024 KB
physical id	: 1
siblings	: 2
core id		: 1
cpu cores	: 2
apicid		: 3
fpu		: yes
fpu_exception	: yes
cpuid level	: 1
wp		: yes
flags		: fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ht syscall nx mmxext fxsr_opt rdtscp lm 3dnowext 3dnow pni cx16 lahf_lm cmp_legacy svm extapic cr8_legacy
bogomips	: 5629.02
TLB size	: 1024 4K pages
clflush size	: 64
cache_alignment	: 64
address sizes	: 40 bits physical, 48 bits virtual
power management: ts fid vid ttp tm stc
[27 Jan 2010 13:46] Mikhail Izioumtchenko
Do you compile from source? In particular when you saw this with Plugin
1.0.3 or 1.0.4 did you compile the plugin from source, if so, was it a static
or dynamic compilation? Just in case, you are using gcc that comes with
the OS distribution, no local changhes?
[27 Jan 2010 13:54] Marko Mäkelä
Bug #26081 was an AMD bug that was worked around in the Linux kernel.
[27 Jan 2010 13:59] Vojtech Kurka
The current install is done using RPM package, as mentioned above.
As far as InnoDB Plugin 1.0.3 and 1.0.4 is concerned, I don't remember.

On the second machine, we currently have XtraDB 7, installed from RPM:
MySQL-shared-percona-5.1.37-7.rhel5.x86_64.rpm

XtraDB 7 is based on InnoDB plugin 1.0.3
[27 Jan 2010 14:17] Vojtech Kurka
cpu family      : 15
model           : 65

Model is not <= 63, therefore this CPU should not be affected by AMD bug described here:

http://bugzilla.kernel.org/show_bug.cgi?id=11305
[27 Jan 2010 15:38] Mikhail Izioumtchenko
Vojtech, could you confirm that in your testcase with test.descr
there is no other activity on the mysqld process. otoh, does the problem occur
during other activity on those machines or is it limited to the
OPTIMIZE test case?
[27 Jan 2010 15:47] Vojtech Kurka
Before the test I run STOP SLAVE on both nodes (master-master).

During the test, I used SHOW [FULL] PROCESSLIST, SHOW STATUS (mtop).
Also there were some nagios checks trying to connect and execute SHOW MASTER STATUS and SHOW SLAVE STATUS.
No other DML/DDL queries were used.
[27 Jan 2010 21:18] Mathias Walter
My machine (Dual-Core AMD Opteron(tm) Processor 2216 HE) is very similar to Vojtech' machine. It only differ in MHz.

The OS is openSUSE 10.3 (X86-64) and the kernel version is 2.6.22.19-0.4.

I never compiled MySQL by my self. Currently MySQL-server-percona-5.1.42-9.rhel5.x86_64.rpm is installed. Before MySQL-server-community-5.1.37-0.sles10.x86_64.rpm and innodb_plugin-1.0.4-linux-x86_64-glibc23 was installed. The problem exists in both versions.
But in my opinion the server did not stop working. It just takes a very very long time to finish the ALTER operation. In my case it took more than five hours.
But there was one other DDL running. I was copying databases in Baracuda format from a different server to this server.

I'm not able to use gdb because I never did this.
[27 Jan 2010 21:32] Vojtech Kurka
Mathias says the ALTER TABLE always finished - this might be true also in my case. Sometimes it really finishes after several dozen minutes in "renaming result table". However, the maximum I tested was about 20 hours and I could not wait more.

If this is a problem of atomic mutex on AMD 2xxx processors, why the COMPACT tables are not affected? I see this only when working with COMPRESSED tables. Is the codebase different for Barracuda format and COMPACT tables stay in Antelope?
[28 Jan 2010 9:38] Marko Mäkelä
This is an interesting case. Mathias, could you generate stack traces with pstack? I would like to confirm that you are experiencing the slowdown in the same place. Are you using compressed tables?

This could also be a scheduler fairness issue, if it is just taking a long time. It would be useful to dump several stack traces during the hang.

I believe that we can rule out mutex contention, because Vojtech was not running a single InnoDB user thread (the OPTIMIZE TABLE). Nevertheless, I believe that buf_LRU_invalidate_tablespace() can be rewritten so that it acquires and releases fewer mutexes.
[28 Jan 2010 13:15] Mathias Walter
Hi Marko,

I'll attach a stack trace from gstack right after this comment.

I tried to repeat the problem w/o load and w/o compressed tables.

I could never repeat it without load or without compressed tables. Even if I convert a table to a compressed table under load, the problem does not occur.

It did also not occur with relatively small tables (about 60 MB), even under load (about 25% I/O wait and 200% cpu).

The hang only occur for one large table (> 1 GB) and during load.
[28 Jan 2010 13:25] Mathias Walter
error log file during the three gstack traces

Attachment: mysql.err (application/octet-stream, text), 26.29 KiB.

[28 Jan 2010 13:26] Mathias Walter
1st stack trace from 12:27 AM

Attachment: gstack_1.txt (text/plain), 10.47 KiB.

[28 Jan 2010 13:27] Mathias Walter
2nd stack trace from 12:29 AM

Attachment: gstack_2.txt (text/plain), 11.55 KiB.

[28 Jan 2010 13:27] Mathias Walter
3rd stack trace from 12:30 AM

Attachment: gstack_3.txt (text/plain), 15.19 KiB.

[28 Jan 2010 13:32] Mathias Walter
I think I have to correct myself regarding to the not occurrence of the hang without load. If you have a look in mysql.err, you'll find the first long running semaphore warning at 11:52:16. I did not recognize any hang at this time.

I just used SHOW FULL PROCESSLIST to see if the rename table hangs. Maybe I run this command not to often.
[28 Jan 2010 13:39] Heikki Tuuri
A general advice about diagnostics. Please print SHOW INNODB STATUS\G several times during the hang and post the results. We can observe from the output if the server is genuinely hung or just running some very long procedure.

If InnoDB prints to the .err log, please post several iterations of the InnoDB Monitor output in the .err log; for the same reason as above.
[28 Jan 2010 13:44] Heikki Tuuri
I see that Mathias Walter HAD posted several iterations from the .err log:

Attachment: mysql.err (application/octet-stream, text), 26.29 KiB.

The output shows that there was no genuine hang. InnoDB was busy processing an ALTER TABLE. Marko can find out why does that cause starvation on a mutex.
[28 Jan 2010 13:57] Heikki Tuuri
Inaam suspects that there is an O(n^2) algorithm introduced in  buf_LRU_invalidate_tablespace() in a bug fix, which is too slow. That has to be fixed to remove the contention on the mutex.
[28 Jan 2010 14:27] Marko Mäkelä
I just committed a patch that reduces the number of block mutex operations in buf_LRU_invalidate_tablespace(). Next, I will see how to avoid the O(n²) scans.
[28 Jan 2010 16:40] Vojtech Kurka
I have repeated this behaviour on  Intel(R) Xeon(R) CPU           E5502  @ 1.87GHz

It is a clean install + import from mysqldump file. XtraDB 9 is used.
Binlog is ON, row-level format. I could not repeat this with binlog off yet.

mysql> optimize table test_table;
+-------------------------------+----------+----------+-------------------------------------------------------------------+
| Table                         | Op       | Msg_type | Msg_text                                                          |
+-------------------------------+----------+----------+-------------------------------------------------------------------+
| test.test_table | optimize | note     | Table does not support optimize, doing recreate + analyze instead |
| test.test_table | optimize | status   | OK                                                                |
+-------------------------------+----------+----------+-------------------------------------------------------------------+
2 rows in set (13 min 54.56 sec)

mysql> optimize table test_table;
+-------------------------------+----------+----------+-------------------------------------------------------------------+
| Table                         | Op       | Msg_type | Msg_text                                                          |
+-------------------------------+----------+----------+-------------------------------------------------------------------+
| test.test_table | optimize | note     | Table does not support optimize, doing recreate + analyze instead |
| test.test_table | optimize | status   | OK                                                                |
+-------------------------------+----------+----------+-------------------------------------------------------------------+
2 rows in set (47 min 3.72 sec)

See the error log in the attached file.
[28 Jan 2010 16:41] Vojtech Kurka
mysqld error log with innodb status output

Attachment: mysqld_errlog.txt (text/plain), 38.34 KiB.

[29 Jan 2010 9:01] Vojtech Kurka
Today I reproduced this with binlog off. However, the stall seems to be much shorter, about 30 seconds, and nothing is written to the error log. I just see the "renaming result table" in show processlist.

Simple testcase:
- enable binlog
- take 5GB innodb compressed table
- run a script with show status and show processlist every second (i.e. mtop)
- run optimize table in cycle
[31 Jan 2010 22:03] Alan Kasindorf
Hi,

I wrote the report at: http://forums.innodb.com/read.php?3,1012,1012#msg-1012

See that two other folks are saying "me too!" but the symptoms are a little different?

In my report it's noted that 'SHOW ENGINE INNODB STATUS' hangs and does not return. The error log did not accumulate any entries either, after waiting 30+ minutes. No concurrent DDL, but other queries were occasionally running.

Stack for all running threads is in the report. It's certainly different from OP, potentially related to the other ones, but behavior seems different.
[1 Feb 2010 11:06] Marko Mäkelä
The source of this slowness is the “goto rescan” in buf_LRU_invalidate_tablespace(). The effect is worst when the buffer pool is filled with the compressed pages of the table, but no uncompressed pages, such as after OPTIMIZE TABLE or a table-copying ALTER of a huge compressed table.

I have posted a patch for our internal testing. It ensures that prev_bpage cannot be relocated while the current block is being freed, and thus avoids the rescan. The complexity of the algorithm becomes mostly O(n) instead of O(n²) again.

There is a similar issue when the adaptive hash index comprises many pages in the tablespace. Every time when an indexed page is dropped, the LRU list will be rescanned. But it might not be that bad as dropping compressed tables, because the buffer pool mutex will be released for a while.
[2 Feb 2010 15:11] Vojtech Kurka
Marko, is there any workaround how to remove these compressed pages from the buffer pool before I run the DDL statment? The only one I can think of is mysqld restart.
[2 Feb 2010 15:53] Mikhail Izioumtchenko
the workarounds are limited and not pleasant: either avoid DROPping of a compressed
table altogether, or do it with cold cache immediately after mysqld restart.
Since in the case of OPTIMIZE or generally ALTER the table is temporary
the workaround is to avoid using a temporary table.
For example, compressing a table, normally done with
ALTER TABLE X row_format=compressed ...
can be done with a dump - insert into compressed table with a different name - drop the original table [uncompressed tables are not affected by the bug] - and rename the compressed one.
[2 Feb 2010 16:23] Vojtech Kurka
Thank you!

One more complaint: When mysqld hangs during the OPTIMIZE and I kill -9 mysqld, there remains a temporary table like "#sql2-423d-2996c26.ibd". It is the old one, which has been renamed during the OPTIMIZE process. However, after startup innodb doesn't know what to do with it and a warning occurs in the error log:

InnoDB: Error: table 'mydb/#sql2-423d-2996c26'
InnoDB: in InnoDB data dictionary has tablespace id 23915,
InnoDB: but tablespace with that id or name does not exist. Have
InnoDB: you deleted or moved .ibd files?

I think innoDB should drop this table automatically, if possible.
[3 Feb 2010 13:04] Marko Mäkelä
Vojtech,
InnoDB deliberately does not drop the #sql* tables, because they can be useful for recovering from unexpected bugs. It is better to be safe than sorry. You can drop the table by copying the missing .frm file from a similar table first.
[7 Feb 2010 2:24] Alan Kasindorf
Marko,

Did you see my note in the forum post where the .frm trick didn't work in allowing me to drop the stuck temp table? It changed the error message but didn't seem to work.

Does the table you copy the .frm from need to have an identical name? Was not able to enter #sql as a table name in recent versions of mysql.
[8 Feb 2010 11:30] Marko Mäkelä
Alan, you should be able to bypass the “filename-safe” table name encoding of MySQL 5.1 by prefixing the name with #mysql50#.  Something like this: 
DROP TABLE '#mysql50##sql…';
[10 Feb 2010 14:19] Vojtech Kurka
I have created similar table with exactly same structure, copied it to a file 
#sql2-4947-72390.frm

Then I run:

mysql> DROP TABLE `#mysql50##sql2-4947-72390`;
ERROR 1051 (42S02): Unknown table '#mysql50##sql2-4947-72390'

The .frm file was successfully deleted, but the .ibd file not.

In errorlog I see:

100210 15:12:02  InnoDB: Error: table 100210 15:12:02 [Warning] Invalid (old?) table or database name '#sql2-4947-72390'
`mydb`.<result 2 when explaining filename '#sql2-4947-72390'> does not exist in the InnoDB internal
InnoDB: data dictionary though MySQL is trying to drop it.

So I assume I can now delete the ibd file from filesystem and everything is OK.

By the way, when I read this http://www.innodb.com/support/tips/fic-recovery/, I don't see #mysql50# mentioned anywhere. Maybe it should be better documented?
[10 Feb 2010 14:29] Vojtech Kurka
No, it's not OK, after restart mysqld prints:

100210 15:27:20  InnoDB: Operating system error number 2 in a file operation.
InnoDB: The error means the system cannot find the path specified.
InnoDB: If you are installing InnoDB, remember that you must create
InnoDB: directories yourself, InnoDB does not create them.
100210 15:27:20  InnoDB: Error: trying to open a table, but could not
InnoDB: open the tablespace file './mydb/#sql2-4947-72390.ibd'!
InnoDB: Have you moved InnoDB .ibd files around without using the
InnoDB: commands DISCARD TABLESPACE and IMPORT TABLESPACE?
InnoDB: It is also possible that this is a temporary table #sql...,
InnoDB: and MySQL removed the .ibd file for this.
[10 Feb 2010 15:03] Marko Mäkelä
Vojtech,
the problem is that the table still exists in InnoDB’s internal data dictionary (SYS_TABLES and related tables). Unfortunately there are two data dictionaries at play: the MySQL one in the .frm file and the InnoDB dictionary. You should be able to delete the InnoDB table by creating a .frm file with a matching name and by issuing a DROP TABLE statement.
[10 Feb 2010 15:06] Vojtech Kurka
Marko, you probably missed my comment from [10 Feb 15:19]
[10 Feb 2010 15:10] Marko Mäkelä
Vojtech, it appears that you copied the .frm file to 'mydb/#sql2-4947-72390'. If you dump the InnoDB data dictionary by creating a table innodb_table_monitor, waiting until something is dumped to the error log, and dropping the table, which table name do you see there?

The #mysql50# prefix is badly documented indeed. And it appears that there is a bug in explain_filename: it is not displaying the #mysql50# prefix as InnoDB used to. I will update Bug #32430.
[10 Feb 2010 16:12] Vojtech Kurka
I've created innodb_table_monitor table. Dropped that missing table:

mysql> DROP TABLE `#mysql50##sql2-4947-72390`;
ERROR 1051 (42S02): Unknown table '#mysql50##sql2-4947-72390'

And immediately after DROP TABLE mysqld outputs:

InnoDB: Error: trying to load index PRIMARY for table mydb/#sql2-4947-72390
InnoDB: but the index tree has been freed!
100210 16:57:57  InnoDB: Error: table 100210 16:57:57 [Warning] Invalid (old?) table or database name '#sql2-4947-72390'
`mydb`.<result 2 when explaining filename '#sql2-4947-72390'> does not exist in the InnoDB internal
InnoDB: data dictionary though MySQL is trying to drop it.
InnoDB: Have you copied the .frm file of the table to the
InnoDB: MySQL database directory from another database?
InnoDB: You can look for further help from
InnoDB: http://dev.mysql.com/doc/refman/5.1/en/innodb-troubleshooting.html
===========================================
100210 16:57:58 INNODB TABLE MONITOR OUTPUT
===========================================
--------------------------------------
TABLE: name SYS_FOREIGN, id 0 11, flags 0, columns 7, indexes 3, appr.rows 232
  COLUMNS: ID: DATA_VARCHAR prtype 2162692 len 0; FOR_NAME: DATA_VARCHAR prtype 2162692 len 0; REF_NAME: DATA_VARCHAR prtype 2162692 len 0;
N_COLS: DATA_INT len 4; DB_ROW_ID: DATA_SYS prtype 256 len 6; DB_TRX_ID: DATA_SYS prtype 257 len 6; DB_ROLL_PTR: DATA_SYS prtype 258 len 7;
  INDEX: name ID_IND, id 0 11, fields 1/6, uniq 1, type 3
   root page 46, appr.key vals 232, leaf pages 3, size pages 4
   FIELDS:  ID DB_TRX_ID DB_ROLL_PTR FOR_NAME REF_NAME N_COLS
  INDEX: name FOR_IND, id 0 12, fields 1/2, uniq 2, type 0
   root page 47, appr.key vals 161, leaf pages 2, size pages 3
   FIELDS:  FOR_NAME ID
  INDEX: name REF_IND, id 0 13, fields 1/2, uniq 2, type 0
   root page 48, appr.key vals 71, leaf pages 2, size pages 3
   FIELDS:  REF_NAME ID
--------------------------------------
TABLE: name SYS_FOREIGN_COLS, id 0 12, flags 0, columns 7, indexes 1, appr.rows 251
n 7;
  INDEX: name ID_IND, id 0 14, fields 2/6, uniq 2, type 3
   root page 49, appr.key vals 251, leaf pages 2, size pages 3
   FIELDS:  ID POS DB_TRX_ID DB_ROLL_PTR FOR_COL_NAME REF_COL_NAME

InnoDB: Error: trying to load index PRIMARY for table mydb/#sql2-4947-72390
InnoDB: but the index tree has been freed!
InnoDB: Failed to load table 100210 16:57:58 [Warning] Invalid (old?) table or database name '#sql2-4947-72390'
"mydb".<result 2 when explaining filename '#sql2-4947-72390'>

[HERE IS DESCRIPTION OF ALL OTHER TABLES]

-----------------------------------
END OF INNODB TABLE MONITOR OUTPUT
==================================
[10 Feb 2010 21:13] Mathias Walter
Hi Vojtech,

I run into a similar problem. See http://forums.innodb.com/read.php?3,1012,1045#msg-1045 and Markos follow up.

But your and my case is not related to this bug anymore. I suggest to move the discussion to the InnoDB forum.
[1 Mar 2010 8:10] Marko Mäkelä
Bug #51325 is a duplicate of this one.
[17 Mar 2010 0:00] bhushan uparkar
I am using 5.1.43 with Innodb plugin 1.0.6 on debian Linux 2.6.26-2-amd64 . I am using pilot  setup to compare the innodb plugin performance with / without compression . I setup first servers , I use innodb plugin with compression and while other I use innodb plugin but no compression. I use default setting for innodb plugin, with innodb buffer set to 36GB out of total 64GB on server. For compression I use key_block_size=8K . The test tables are order or 20GB and are range partitioned on day. 

 With compression I was able to save more than 50% on space, I like that. But when I went for "Alter table ", it took more 3 hours and 30 minutes on server with compression turned on. While on other server where compression is turned off, it took only 15 minutes for "Alter table". Also the server with compression was unresponsive for 80% of time, I was not able to run any query on other tables or show engine innodb status . For all the time when server was unresponsive I thought "Innodb hung", but that was not the case. Once the "Alter table" finished, the server started working normally after that.

One other thing, I was only doing one alter on the server, i.e. no other ddl going on during the time.
[1 Apr 2010 11:28] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/104821

3469 Sergey Vojtovich	2010-04-01
      Applying InnoDB snapshot, fixes BUG#35077.
      
      Detailed revision comments:
      
      r6525 | marko | 2010-01-28 16:23:15 +0200 (Thu, 28 Jan 2010) | 11 lines
      branches/zip: buf_LRU_invalidate_tablespace(): Do not unnecessarily
      acquire the block_mutex for every block in the LRU list. Only acquire
      it when holding buf_pool_mutex is not sufficient. This should speed up
      the function and considerably reduce traffic on the memory bus and
      caches.
      
      I noticed this deficiency when working on Issue #157.
      This deficiency popped up again in Issue #449 (Bug #35077),
      which this fix does not fully address.
      
      rb://78 revision 1 approved by Heikki Tuuri.
[1 Apr 2010 11:37] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/104832

3478 Sergey Vojtovich	2010-04-01
      Applying InnoDB snapshot, fixes BUG#35077.
      
      Detailed revision comments:
      
      r6548 | marko | 2010-02-03 15:01:39 +0200 (Wed, 03 Feb 2010) | 11 lines
      branches/zip: buf_LRU_invalidate_tablespace(): Ensure that prev_bpage
      is not relocated when freeing a compressed block.  This avoids the
      costly rescan of the LRU list.  (Bug #35077, Issue #449)
      
      At most one buffer-fix will be active at a time, affecting two blocks:
      the buf_page_t and the compressed page frame. This should not block
      the memory defragmentation in buf0buddy.c too much.  In fact, it may
      avoid unnecessary copying if also prev_bpage belongs to the tablespace
      that is being invalidated.
      
      rb://240
[6 Apr 2010 8:00] Bugs System
Pushed into 5.1.46 (revid:sergey.glukhov@sun.com-20100405111026-7kz1p8qlzglqgfmu) (version source revid:svoj@sun.com-20100401151005-c6re90vdvutln15d) (merge vers: 5.1.46) (pib:16)
[28 Apr 2010 4:12] James Day
The fix for this is in the InnoDB Plugin version 1.0.7 which was included with MySQL 5.1.46.
[5 May 2010 15:23] Bugs System
Pushed into 5.1.47 (revid:joro@sun.com-20100505145753-ivlt4hclbrjy8eye) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[5 May 2010 15:32] Vojtech Kurka
Why is there push for 5.1.47? Previous comment says "Pushed to 5.1.46". Which version includes the fix?
[8 May 2010 17:23] Paul DuBois
Push resulted from incorporation of InnoDB tree. No changes pertinent to this bug.
[10 May 2010 14:34] Paul DuBois
Noted in 5.1.46, 5.5.4 changelogs.

InnoDB Plugin page-freeing operations were made faster for compressed
blocks, speeding up ALTER TABLE, DROP TABLE, and other operations on
compressed tables that free compressed blocks. One symptom of the
older behavior could be 100% CPU use during these operations.
[28 May 2010 5:53] Bugs System
Pushed into mysql-next-mr (revid:alik@sun.com-20100524190136-egaq7e8zgkwb9aqi) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (pib:16)
[28 May 2010 6:22] Bugs System
Pushed into 6.0.14-alpha (revid:alik@sun.com-20100524190941-nuudpx60if25wsvx) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[28 May 2010 6:50] Bugs System
Pushed into 5.5.5-m3 (revid:alik@sun.com-20100524185725-c8k5q7v60i5nix3t) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[30 May 2010 0:16] Paul DuBois
Push resulted from incorporation of InnoDB tree. No changes pertinent to this bug.
Re-closing.
[15 Jun 2010 8:19] Bugs System
Pushed into 5.5.5-m3 (revid:alik@sun.com-20100615080459-smuswd9ooeywcxuc) (version source revid:mmakela@bk-internal.mysql.com-20100415070122-1nxji8ym4mao13ao) (merge vers: 5.1.47) (pib:16)
[15 Jun 2010 8:36] Bugs System
Pushed into mysql-next-mr (revid:alik@sun.com-20100615080558-cw01bzdqr1bdmmec) (version source revid:mmakela@bk-internal.mysql.com-20100415070122-1nxji8ym4mao13ao) (pib:16)
[17 Jun 2010 11:54] Bugs System
Pushed into 5.1.47-ndb-7.0.16 (revid:martin.skold@mysql.com-20100617114014-bva0dy24yyd67697) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[17 Jun 2010 12:31] Bugs System
Pushed into 5.1.47-ndb-6.2.19 (revid:martin.skold@mysql.com-20100617115448-idrbic6gbki37h1c) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[17 Jun 2010 13:19] Bugs System
Pushed into 5.1.47-ndb-6.3.35 (revid:martin.skold@mysql.com-20100617114611-61aqbb52j752y116) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)