| Bug #61188 | DROP TABLE extremely slow | ||
|---|---|---|---|
| Submitted: | 16 May 2011 16:43 | Modified: | 2 Nov 2011 16:32 |
| Reporter: | Jonathan Stimmel | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Server: InnoDB storage engine | Severity: | S3 (Non-critical) |
| Version: | 5.5.12-log | OS: | Linux (CentOS release 5.3 (Final)) |
| Assigned to: | Inaam Rana | CPU Architecture: | Any |
[16 May 2011 16:54]
Valeriy Kravchuk
Please, send your my.cnf file content and the results of: show engine innodb status\G while this slow DROP TABLE is running.
[16 May 2011 17:24]
Jonathan Stimmel
$ cat /etc/my.cnf # $Id$ [mysqld_safe] pid-file = /var/lib/mysql/mysqld.pid [mysqld] user = mysql socket = /var/lib/mysql/mysql.sock datadir = /var/lib/mysql tmpdir = /var/tmp performance_schema tmp_table_size = 256MB max_heap_table_size = 256MB log-output = TABLE slow_query_log = ON innodb_file_per_table innodb_stats_on_metadata = OFF innodb_strict_mode = ON innodb_file_format = Barracuda innodb_data_file_path = ibdata1:1G innodb_buffer_pool_size = 32G innodb_buffer_pool_instances = 8 innodb_log_buffer_size = 64M innodb_log_files_in_group = 3 innodb_log_file_size = 1G innodb_io_capacity = 20000 innodb_write_io_threads = 4 innodb_read_io_threads = 4 innodb_open_files = 750 innodb_flush_log_at_trx_commit = 2 innodb_flush_method = O_DIRECT innodb_max_dirty_pages_pct = 1 innodb_purge_threads = 1
[16 May 2011 17:25]
Jonathan Stimmel
Note that it took several minutes to get innodb status. The thread "Waiting for table metadata lock" is a mysql client I accidentally started without -A after the drop was in progress.
[16 May 2011 20:17]
Jonathan Stimmel
The performance appears to degrade with the number of partitions. Dropping an empty table with 2 partitions takes around 5 seconds, while the same table with 50 partitions takes takes about a minute and a half. Not surprisingly the problem disappears with MyISAM.
I've reproduced this bug on two hosts (5.5.10 and 5.5.12), but not a third (also 5.5.12). I'm still investigating what the key difference is in that third host.
Here's my test script:
#!/bin/bash
set -o errexit -o nounset
PARTITIONS=50
MYSQL="mysql -vvv --database=test -Ee"
$MYSQL "SELECT VERSION()"
$MYSQL "CREATE TABLE t (i INT) ENGINE innodb ROW_FORMAT=COMPRESSED KEY_BLOCK_SIZE=4"
$MYSQL "ALTER TABLE t PARTITION BY RANGE COLUMNS(i) (PARTITION pNULL VALUES LESS THAN (0))"
for i in `seq $PARTITIONS`; do
$MYSQL "ALTER TABLE t ADD PARTITION (PARTITION p$i VALUES LESS THAN ($i))"
done
$MYSQL "DROP TABLE t"
[16 May 2011 22:45]
Jonathan Stimmel
(Changing Category to InnoDB) I misspoke in my previous comment - the script I posted reproduced the problem on one host (5.5.10), but not another (5.5.12). After several hours, the original server eventually finished dropping its tables, so I ran my test script on that host, and was unable to reproduce the problem (<100ms to drop the test table). As that server has no user tables, I'm now suspecting that the performance hit is also related to the size of innodb data outside of the table being dropped. In particular, I suspect innodb may be scanning all data pages in the buffer pool - perhaps to free those pages which belong to the table being dropped. To test this theory I took the empty host and did the following: 0. ran my script, which takes <100ms to drop the test table 1. recreated the tables 2. inserted 20-30M rows 3. let the database idle 4. ran my script, which now takes 2-3 seconds to drop 5. restarted mysql 6. ran the script again on the cold, idle database - drop is again <100ms Note that at step 0 InnoDB's has 32GB of pages allocated, but very few are in use since all tables have been dropped. As a further test, I restarted the host which took over a minute to run the test script. After restart, dropping the test table takes <100ms. At this point, I suspect that dropping tables causes InnoDB to scan all active pages in the buffer pool(s). This scan becomes much more expensive due to the need to decompress most pages. Finally, I suspect this process is repeated for each partition. With a 32 GB buffer pool and 200 large, compressed partitions, it's easy to see how this could degrade to a time scale of hours.
[17 May 2011 7:22]
Valeriy Kravchuk
I think this is a duplicate of/related to known Bug #51325. Please, check.
[17 May 2011 7:23]
Valeriy Kravchuk
See http://www.mysqlperformanceblog.com/2011/02/03/performance-problem-with-innodb-and-drop-ta... also.
[19 May 2011 19:23]
Jonathan Stimmel
Agreed, this is most likely a duplicate of bug 51325.
[19 May 2011 20:16]
MySQL Verification Team
Duplicate of http://bugs.mysql.com/bug.php?id=51325.
[4 Jun 2011 0:48]
Mark Callaghan
I suspect the slow DROP TABLE problem for compressed InnoDB tables is not 51325. I just had a test server crash because of long lock wait while doing "DROP DATABASE" on a db with 6 compressed InnoDB tables and a 60G buffer pool. I use 5.1.52 + the facebook patch. I always consider that I created the bug in the facebook patch, so I am still investigating and will try to reproduce with 5.1.52 unmodified. I think http://bugs.mysql.com/bug.php?id=59727 might be related because of buf_LRU_block_remove_hashed_page The call stack from MySQL 5.1.52 + Facebook patch is: buf_buddy_free_low,buf_LRU_block_remove_hashed_page,buf_LRU_invalidate_tablespace,fil_delete_tablespace,row_drop_table_for_mysql,row_drop_tables_for_mysql_in_background,srv_master_thread,start_thread,clone The first long lock wait message is: InnoDB: Warning: a long semaphore wait: --Thread 1201695040 has waited at buf/buf0buf.c line 1671 for 247.00 seconds the semaphore: Mutex at 0x37fcc00 created file buf/buf0buf.c line 1050, lock var 0 waiters flag 0 wait has ended Thread 13 (Thread 1246906688 (LWP 31166)): #0 buf_buddy_free_low (buf=0x2ab7c4382600, i=2) at buf/buf0buddy.c:575 #1 0x0000000000832594 in buf_LRU_block_remove_hashed_page (bpage=0x2ab7c4382700, zip=1) at ./include/buf0buddy.ic:121 #2 0x000000000083467c in buf_LRU_invalidate_tablespace (id=96) at buf/buf0lru.c:469 #3 0x000000000085352f in fil_delete_tablespace (id=96) at fil/fil0fil.c:2401 #4 0x00000000007d300d in row_drop_table_for_mysql (name=0x2ab93809d1d8 "test/purchases_index6", trx=0x2ab97af3daf0, drop_db=<value optimized out>, delayed_drop=0) at row/row0mysql.c:3409 #5 0x00000000007d3f24 in row_drop_tables_for_mysql_in_background (wait=0) at row/row0mysql.c:2153 #6 0x00000000007e9a57 in srv_master_thread (arg=<value optimized out>) at srv/srv0srv.c:3080 #7 0x00000031c6c062f7 in start_thread () from /lib64/libpthread.so.0 #8 0x00000031c64d1e3d in clone () from /lib64/libc.so.6
[4 Jun 2011 2:25]
Mark Callaghan
All of the time is in buf_buddy_free_low. That is only called for compressed pages. Thus I am more certain that this problem is much worse for compressed tables. And there is a for loop in buf_buddy_free_low over buf_pool->zip_free[] which is probably the problem.
for (bpage = UT_LIST_GET_FIRST(buf_pool->zip_free[i]); bpage; ) {
UNIV_MEM_VALID(bpage, BUF_BUDDY_LOW << i);
ut_ad(buf_page_get_state(bpage) == BUF_BLOCK_ZIP_FREE);
if (bpage == buddy) {
buddy_free:
/* The buddy is free: recombine */
buf_buddy_remove_from_free(bpage, i);
buddy_free2:
ut_ad(buf_page_get_state(buddy) == BUF_BLOCK_ZIP_FREE);
ut_ad(!buf_pool_contains_zip(buddy));
i++;
buf = ut_align_down(buf, BUF_BUDDY_LOW << i);
goto recombine;
}
ut_a(bpage != buf);
{
buf_page_t* next = UT_LIST_GET_NEXT(list, bpage);
UNIV_MEM_ASSERT_AND_FREE(bpage, BUF_BUDDY_LOW << i);
bpage = next;
}
}
[4 Jun 2011 3:08]
Mark Callaghan
On unmodified mysql 5.1.52: * drop of 6 uncompressed tables --> 21 seconds * drop of 6 compressed tables --> 53 minutes buffer pool is 55GB and warm as the tables were just loaded. Tables should be fully cached in the buffer pool. I used a modified version of the insert benchmark and will attach my files. Ignore duplicate settings in this, but my.cnf was: [mysqld] plugin-load=innodb=ha_innodb_plugin.so;innodb_trx=ha_innodb_plugin.so;innodb_locks=ha_innodb_plugin.so;innodb_lock_waits=ha_innodb_plugin.so;innodb_cmp=ha_innodb_plugin.so;innodb_cmp_reset=ha_innodb_plugin.so;innodb_cmpmem=ha_innodb_plugin.so;innodb_cmpmem_reset=ha_innodb_plugin.so innodb_buffer_pool_size=16G innodb_log_file_size=1900M innodb_flush_log_at_trx_commit=1 innodb_doublewrite=1 innodb_flush_method=O_DIRECT innodb_thread_concurrency=0 innodb_max_dirty_pages_pct=80 innodb_file_format=barracuda innodb_file_per_table max_connections=2000 table_cache=2000 key_buffer_size=200M innodb_io_capacity=1000 innodb_thread_concurrency=128 log_bin sync_binlog=1 innodb_read_io_threads=8 innodb_io_capacity=2000 skip_log_bin innodb_buffer_pool_size=55G
[4 Jun 2011 3:15]
Mark Callaghan
modified insert benchmark test
Attachment: iibench.py (text/x-python-script), 15.60 KiB.
[4 Jun 2011 3:15]
Mark Callaghan
shell script to run iibench
Attachment: rp.sh (application/octet-stream, text), 993 bytes.
[4 Jun 2011 3:17]
Mark Callaghan
I added a test case. To run it for compressed tables: bash rp.sh 20000000 yes yes yes 6 time mysql -A -e 'drop database test; create database test' And for uncompressed tables: bash rp.sh 20000000 yes yes no 6 time mysql -A -e 'drop database test; create database test'
[5 Jun 2011 15:06]
Mark Callaghan
The DROP command holds critical InnoDB mutexes while running which blocks most activity until done. SHOW INNODB STATUS hangs. In some cases there are long-lock wait timeouts on internal InnoDB mutexes and InnoDB crashes when that occurs. I wonder if LOCK_open is also held. I can't use compressed InnoDB tables until this is fixed.
[6 Jun 2011 19:14]
Inaam Rana
I agree that this is not a duplicate of bug 51325. That bug is about general code path of drop table where buffer pool mutex may become a contention point. This is compression specific. Agree with Mark that buf_buddy_free_low() looks heavy duty. Depends on how long zip_free[] lists can be. If we are coalescing aggressively, as we seem to do. then these lists should not be very long. I am assigning it to our buf_buddy author Marko and resetting the state from duplicate to analyzing. Marko, if you have too much on your plate and you want me to look into it, please let me know and I'll give it a stab.
[7 Jun 2011 13:16]
Marko Mäkelä
It looks like the buddy allocator is combining blocks too aggressively. The recombination is not needed for correctness; it is only needed for avoiding fragmentation in the buddy allocator, that is, to minimize INFORMATION_SCHEMA.INNODB_CMPMEM.pages_free. To make the matter worse, sizeof(buf_page_t) is much smaller than typical compressed page size. We should consider allocating the buf_page_t from a separate pool, which should be easier, because the block size is always fixed.
[7 Jun 2011 13:19]
Inaam Rana
grab it
[8 Jun 2011 13:07]
Marko Mäkelä
Grabbing back. I have a patch that reduces the recombination efforts in buf_buddy_free_low() and makes bpage->state trustable for blocks shorter than PAGE_ZIP_MIN_SIZE.
[8 Jun 2011 15:08]
Inaam Rana
Mark, I tried reproducing the test you reported. I had to work on a smaller box with 16G RAM therefore I reduced the table size to 2 million instead of 20 million. Worked with 6 tables still. The drop database took 3 seconds. Maybe because tables are too small. I'll see if I can get my hands on a box that has more than 16G RAM. Meanwhile if you get a chance can you get "select * from information_schema.innodb_cmpmem" before and after drop database and also LRU and unzip_LRU length from innodb status? In my case, it looked like: before DROP DATABASE (just after load of tables) mysql> select * from information_schema.innodb_cmpmem; +-----------+------------+------------+----------------+-----------------+ | page_size | pages_used | pages_free | relocation_ops | relocation_time | +-----------+------------+------------+----------------+-----------------+ | 128 | 0 | 0 | 0 | 0 | | 256 | 0 | 0 | 0 | 0 | | 512 | 0 | 0 | 0 | 0 | | 1024 | 0 | 0 | 0 | 0 | | 2048 | 0 | 0 | 0 | 0 | | 4096 | 0 | 0 | 0 | 0 | | 8192 | 319966 | 0 | 18 | 0 | | 16384 | 0 | 0 | 0 | 0 | +-----------+------------+------------+----------------+-----------------+ 8 rows in set (0.00 sec) LRU len: 319989, unzip_LRU len: 319966 after DROP DATABASE mysql> select * from information_schema.innodb_cmpmem; +-----------+------------+------------+----------------+-----------------+ | page_size | pages_used | pages_free | relocation_ops | relocation_time | +-----------+------------+------------+----------------+-----------------+ | 128 | 0 | 0 | 0 | 0 | | 256 | 0 | 0 | 0 | 0 | | 512 | 0 | 0 | 0 | 0 | | 1024 | 0 | 0 | 0 | 0 | | 2048 | 0 | 0 | 0 | 0 | | 4096 | 0 | 0 | 0 | 0 | | 8192 | 0 | 0 | 155729 | 0 | | 16384 | 0 | 0 | 0 | 0 | +-----------+------------+------------+----------------+-----------------+ 8 rows in set (0.00 sec) As you mentioned all your data is cached. Assuming you are doing test on a freshly started server i.e.: no other data in the buffer pool. If this is the case, then the hypothesis that Marko and I were working on may not resolve this issue. The above tells us that buf_page_t structs are not allocated from buf_buddy because we don't have any compressed only pages in the buffer pool. And we both tried in our own way to reduce heavy work when coalescing freed buf_page_t structs.
[8 Jun 2011 15:14]
Mark Callaghan
Before drop: 'select * from innodb_cmpmem' +-----------+------------+------------+----------------+-----------------+ | page_size | pages_used | pages_free | relocation_ops | relocation_time | +-----------+------------+------------+----------------+-----------------+ | 128 | 30463 | 1 | 7 | 0 | | 256 | 0 | 0 | 0 | 0 | | 512 | 0 | 0 | 0 | 0 | | 1024 | 0 | 0 | 0 | 0 | | 2048 | 0 | 0 | 0 | 0 | | 4096 | 0 | 0 | 0 | 0 | | 8192 | 2422533 | 1 | 0 | 0 | | 16384 | 0 | 0 | 0 | 0 | +-----------+------------+------------+----------------+-----------------+ select * from innodb_cmp' +-----------+--------------+-----------------+---------------+------------------+----------------+-----------------+ | page_size | compress_ops | compress_ops_ok | compress_time | compress_ok_time | uncompress_ops | uncompress_time | +-----------+--------------+-----------------+---------------+------------------+----------------+-----------------+ | 1024 | 0 | 0 | 0 | 0 | 0 | 0 | | 2048 | 0 | 0 | 0 | 0 | 0 | 0 | | 4096 | 0 | 0 | 0 | 0 | 0 | 0 | | 8192 | 9471628 | 9468137 | 1460 | 1460 | 1369 | 0 | | 16384 | 0 | 0 | 0 | 0 | 0 | 0 | ---------------------- BUFFER POOL AND MEMORY ---------------------- Total memory allocated 60411084800; in additional pool allocated 0 Dictionary memory allocated 91454 Buffer pool size 3604480 Free buffers 0 Database pages 2422546 Old database pages 435281 Modified db pages 0 Read ahead: 0 Evicted after read ahead without access: 0 Percent pages dirty: 0.00 Pending reads 0 Pending writes: LRU 0, flush list 0, single page 0 Total writes: 0 LRU, 50754271 flush list, 0 single page Write sources: fg free margin 0, bg free margin 0, bg dirty 34014, preflush 49576988, adaptive 77157, other 0, bg checkpoint 2708971, fg checkpoint 46868017 Neighbor pages flushed: 49815512 from list, 0 from LRU Pages made young 809367, not young 7 0.00 youngs/s, 0.00 non-youngs/s Pages read 19, created 2431200, written 50754271 0.00 reads/s, 0.00 creates/s, 0.00 writes/s No buffer pool page gets since the last printout Pages read ahead 0.00/s, evicted without access 0.00/s LRU len: 2422546, unzip_LRU len: 2392070 I/O sum[0]:cur[0], unzip sum[0]:cur[0]
[8 Jun 2011 15:14]
Mark Callaghan
Innodb variables before drop ignore_builtin_innodb OFF innodb_adaptive_flushing ON innodb_adaptive_hash_index ON innodb_adaptive_hash_latch_cache ON innodb_additional_mem_pool_size 20971520 innodb_aio_old_usecs 2000000 innodb_auto_lru_dump 0 innodb_autoextend_increment 8 innodb_autoinc_lock_mode 1 innodb_background_checkpoint ON innodb_background_drop_table ON innodb_background_thread_interval_usecs 1000000 innodb_buffer_pool_size 59055800320 innodb_change_buffering inserts innodb_checksums ON innodb_commit_concurrency 0 innodb_compression_level 6 innodb_compression_method quicklz innodb_concurrency_tickets 500 innodb_data_file_path ibdata1:512M:autoextend innodb_data_home_dir /data/mysql innodb_deadlock_detect OFF innodb_doublewrite ON innodb_expand_import OFF innodb_fast_checksums ON innodb_fast_free_list OFF innodb_fast_shutdown 1 innodb_file_format Barracuda innodb_file_format_check Barracuda innodb_file_per_table ON innodb_flush_log_at_trx_commit 1 innodb_flush_method O_DIRECT innodb_flush_neighbors_for_lru ON innodb_flush_neighbors_on_checkpoint ON innodb_force_recovery 0 innodb_ibuf_max_iops_when_below_limit 10 innodb_ibuf_max_pct_of_buffer_pool 20 innodb_ibuf_max_pct_of_io_capacity 50 innodb_io_capacity 2000 innodb_lock_wait_timeout 2 innodb_locks_unsafe_for_binlog OFF innodb_log_buffer_size 4194304 innodb_log_compressed_pages OFF innodb_log_file_size 536870912 innodb_log_files_in_group 2 innodb_log_group_home_dir /data/mysql innodb_lru_dump_old_pages OFF innodb_lru_load_max_entries 524288 innodb_max_dirty_pages_pct 75 innodb_max_purge_lag 0 innodb_merge_sort_block_size 1048576 innodb_mirrored_log_groups 1 innodb_old_blocks_pct 18 innodb_old_blocks_time 1000 innodb_open_files 10240 innodb_prepare_commit_mutex ON innodb_read_ahead_linear OFF innodb_read_ahead_threshold 56 innodb_read_io_threads 8 innodb_release_locks_early OFF innodb_replication_delay 0 innodb_retry_io_on_error OFF innodb_rollback_on_timeout OFF innodb_spin_wait_delay 6 innodb_stats_on_metadata ON innodb_stats_sample_pages 8 innodb_strict_mode OFF innodb_support_xa ON innodb_sync_checkpoint_limit 0 innodb_sync_spin_loops 30 innodb_table_locks ON innodb_thread_concurrency 128 innodb_thread_lifo OFF innodb_thread_sleep_delay 10000 innodb_use_purge_thread 0 innodb_use_sys_malloc ON innodb_version 1.0.13 innodb_write_io_threads 4 storage_engine InnoDB table_type InnoDB
[8 Jun 2011 15:16]
Mark Callaghan
Only the tables to be dropped are in the buffer pool
[8 Jun 2011 15:18]
Mark Callaghan
After the drop. This drop seemed to be fast, but I did not time it. 'select * from innodb_cmpmem' +-----------+------------+------------+----------------+-----------------+ | page_size | pages_used | pages_free | relocation_ops | relocation_time | +-----------+------------+------------+----------------+-----------------+ | 128 | 0 | 0 | 13601 | 0 | | 256 | 0 | 0 | 0 | 0 | | 512 | 0 | 0 | 0 | 0 | | 1024 | 0 | 0 | 0 | 0 | | 2048 | 0 | 0 | 0 | 0 | | 4096 | 0 | 0 | 0 | 0 | | 8192 | 0 | 0 | 1196168 | 3 | | 16384 | 0 | 0 | 0 | 0 | select * from innodb_cmp' +-----------+--------------+-----------------+---------------+------------------+----------------+-----------------+ | page_size | compress_ops | compress_ops_ok | compress_time | compress_ok_time | uncompress_ops | uncompress_time | +-----------+--------------+-----------------+---------------+------------------+----------------+-----------------+ | 1024 | 0 | 0 | 0 | 0 | 0 | 0 | | 2048 | 0 | 0 | 0 | 0 | 0 | 0 | | 4096 | 0 | 0 | 0 | 0 | 0 | 0 | | 8192 | 9471628 | 9468137 | 1460 | 1460 | 1369 | 0 | | 16384 | 0 | 0 | 0 | 0 | 0 | 0 |
[8 Jun 2011 15:26]
Mark Callaghan
I am rerunning the repro cases now on two servers -- one that loads 6 X 15M rows and one that loads 6 X 20M rows. It does the IS queries and drop table immediately after the loads are done so there will be dirty pages in the buffer pool. I don't know if the presence of dirty pages has an impact.
[8 Jun 2011 16:39]
Inaam Rana
The following line is of interest: +-----------+------------+------------+----------------+-----------------+ | page_size | pages_used | pages_free | relocation_ops | relocation_time | +-----------+------------+------------+----------------+-----------------+ | 128 | 0 | 0 | 13601 | 0 | What this tells us is that though your data probably fits in the buffer pool but LRU eviction has started and we have some compressed only pages in the buffer pool. 128 byte allocations are for buf_page_t struct. When dealing with compression things get a little tricky in terms of what we mean by 'in-memory'. Say, your compressed data is 20G in size. Assuming 8K compressed page size, we can think of 'in-memory' data in two ways: * if buffer pool is bigger than 60G then you'll be able to cache both compressed pages and the uncompressed version of the pages in the buffer pool. You'll know this because you'll probably not see any 128 byte allocations for buf_page_t structs which are used for compressed only pages. * if buffer pool is roughly bigger than 24GB (10% slack for IO bound workloads) but less that 60GB then you'll still be able to cache all your on disk data in the buffer pool and won't see any significant IO activity but within buffer pool most of your pages will be in compressed only form meaning lots of decompression and buf_page_t allocations. From a user perspective this will still be an in-memory workload but the buffer pool logic will follow the extra code path of allocating/deallocating buf_page_t structs which can become a bottleneck.
[8 Jun 2011 16:42]
Inaam Rana
The following line is of interest: +-----------+------------+------------+----------------+-----------------+ | page_size | pages_used | pages_free | relocation_ops | relocation_time | +-----------+------------+------------+----------------+-----------------+ | 128 | 0 | 0 | 13601 | 0 | What this tells us is that though your data probably fits in the buffer pool but LRU eviction has started and we have some compressed only pages in the buffer pool. 128 byte allocations are for buf_page_t struct. When dealing with compression things get a little tricky in terms of what we mean by 'in-memory'. Say, your compressed data is 20G in size. Assuming 8K compressed page size, we can think of 'in-memory' data in two ways: * if buffer pool is bigger than 60G then you'll be able to cache both compressed pages and the uncompressed version of the pages in the buffer pool. You'll know this because you'll probably not see any 128 byte allocations for buf_page_t structs which are used for compressed only pages. * if buffer pool is roughly bigger than 24GB (10% slack for IO bound workloads) but less that 60GB then you'll still be able to cache all your on disk data in the buffer pool and won't see any significant IO activity but within buffer pool most of your pages will be in compressed only form meaning lots of decompression and buf_page_t allocations. From a user perspective this will still be an in-memory workload but the buffer pool logic will follow the extra code path of allocating/deallocating buf_page_t structs which can become a bottleneck.
[8 Jun 2011 19:38]
Inaam Rana
Mark, I believe we have nailed it down. The problem is indeed with buf_page_t allocation/deallocation. We're able to reduce drop database time to 8 seconds from unpatched version where it took upward of 20 minutes before choking on semaphore waits. We have two different approaches to resolve this issue. We are going to decide shortly which one to pick.
[8 Jun 2011 23:54]
Mark Callaghan
Let me know when there is a patch I can try
[24 Jun 2011 5:23]
James Day
For a similar issue not involving compressed tables see Bug #51325.
[12 Jul 2011 19:30]
James Day
The expected solution for this is under test at the moment. We expect to release it more generally once the testers have confirmed that the problem is solved or at least greatly improved.
[23 Jul 2011 8:02]
Simon Mudd
Does anyone have a _simple_ reproducible test case I can run for this that generates a noticeable delay in DROP TABLE (10+ minutes)? [ ideally shell script generated ] I've made workarounds and thus on the production systems I'm using I no longer experience the issue. Trying some simple test cases does not seem to be triggering the issue.
[15 Aug 2011 22:14]
James Day
The fix for this is in MySQL 5.5.15 and is expected to be in 5.1.59. At the time of writing it hasn't yet been added to the release notes but that should happen soon.
[7 Oct 2011 0:46]
John Russell
Added to changelog: The DROP TABLE command for an InnoDB table could be very slow, in a configuration with a combination of table compression, partitioning, and a large buffer pool.
[2 Nov 2011 0:42]
James Day
If still suffering from slower than desirable drops, see MySQL bug #51325 (Oracle bug #11759044) for work on improving another part of dropping tables.
[2 Nov 2011 16:32]
Jonathan Stimmel
I recently had a chance to recreate the conditions from my original report. I upgraded to 5.5.15, then let it run normally for a few days before dropping all tables. This operation ran many times faster than in my original case, and I assume that any remaining performance issues are due to other issues.
[2 Nov 2011 22:14]
James Day
Thanks. Good to have confirmation that the performance improvement works!
Description: In "recent" minor releases of 5.5, DROP TABLE can be incredibly slow. As I file this, I've been waiting almost 45 minutes to drop a moderately sized, compressed/partitioned InnoDB table: mysql> show processlist \G *************************** 1. row *************************** Id: 2352 User: dbuser Host: localhost db: db Command: Query Time: 2573 State: checking permissions Info: DROP TABLE `A` Thr DROP is proceeding (some of the partitions have been unlinked in the filesystem), it's just exceedingly slow. MySQL is almost entirely idle, aside from a select against INFORMATION_SCHEMA.GLOBAL_STATUS and a cheap query against another table (both run once every 60s). MySQL has a CPU-bound thread: $ pgrep -x mysqld | xargs -r ps -L -o pid,lwp,pcpu,comm PID LWP %CPU COMMAND 8740 8740 0.0 mysqld 8740 8746 0.0 mysqld 8740 8747 0.0 mysqld 8740 8748 0.0 mysqld 8740 8749 0.0 mysqld 8740 8750 0.0 mysqld 8740 8751 0.0 mysqld 8740 8752 0.1 mysqld 8740 8753 0.1 mysqld 8740 8754 0.1 mysqld 8740 8755 0.1 mysqld 8740 8870 0.0 mysqld 8740 8871 0.0 mysqld 8740 8872 0.0 mysqld 8740 8873 4.3 mysqld 8740 8874 0.8 mysqld 8740 8877 0.0 mysqld 8740 25068 99.9 mysqld 8740 25143 0.0 mysqld 8740 25314 0.0 mysqld 8740 26445 0.0 mysqld 8740 26838 0.0 mysqld while the local disks are virtually idle: $ date Mon May 16 12:03:19 EDT 2011 $ sar -b -s 11:30:00 Linux 2.6.32.15-asl.1.pf.el5.x86_64 (ita1avsdb1) 05/16/11 20110516 11:30:01 tps rtps wtps bread/s bwrtn/s 20110516 11:40:01 0.86 0.03 0.83 0.32 10.15 20110516 11:50:01 1.70 0.03 1.67 2.11 17.91 20110516 12:00:01 2.09 0.19 1.91 1.57 55.82 Average: 1.55 0.08 1.47 1.33 27.97 I have performance_schema enabled: mysql> select * from threads where processlist_id=2352; +-----------+----------------+---------------------------+ | THREAD_ID | PROCESSLIST_ID | NAME | +-----------+----------------+---------------------------+ | 2368 | 2352 | thread/sql/one_connection | +-----------+----------------+---------------------------+ 1 row in set (0.00 sec) mysql> truncate events_waits_summary_by_thread_by_event_name mysql> select sleep(60); mysql> select * from events_waits_summary_by_thread_by_event_name where thread_id=2368 and COUNT_STAR>0 \G *************************** 1. row *************************** THREAD_ID: 2368 EVENT_NAME: wait/synch/mutex/innodb/buf_pool_zip_mutex COUNT_STAR: 48329 SUM_TIMER_WAIT: 1935086400 MIN_TIMER_WAIT: 16800 AVG_TIMER_WAIT: 40039 MAX_TIMER_WAIT: 3224400 1 row in set (0.00 sec) mysql> select SOURCE, EVENT_NAME, sum(TIMER_WAIT), count(*) from events_waits_history_long where thread_id=2368 group by SOURCE, EVENT_NAME \G *************************** 1. row *************************** SOURCE: buf0buddy.c:376 EVENT_NAME: wait/synch/mutex/innodb/buf_pool_zip_mutex sum(TIMER_WAIT): 139258800 count(*): 1765 *************************** 2. row *************************** SOURCE: buf0buddy.c:485 EVENT_NAME: wait/synch/mutex/innodb/buf_pool_zip_mutex sum(TIMER_WAIT): 25796400 count(*): 1314 *************************** 3. row *************************** SOURCE: buf0lru.c:377 EVENT_NAME: wait/synch/mutex/innodb/buf_pool_zip_mutex sum(TIMER_WAIT): 75835200 count(*): 3431 *************************** 4. row *************************** SOURCE: buf0lru.c:477 EVENT_NAME: wait/synch/mutex/innodb/buf_pool_zip_mutex sum(TIMER_WAIT): 159886800 count(*): 3431 4 rows in set (0.04 sec) Finally, here's the table definition: CREATE TABLE A ( B smallint(6) NOT NULL, C datetime NOT NULL, D smallint(6) NOT NULL, E smallint(6) NOT NULL, F decimal(5,0) NOT NULL, G date NOT NULL, H smallint(6) NOT NULL, I smallint(6) NOT NULL, PRIMARY KEY (B,C,D,E,F,G,H,I), KEY J (E,F,G,B,C,D), KEY K (E,G,B,C,D) ) ENGINE=InnoDB DEFAULT CHARSET=latin1 ROW_FORMAT=COMPRESSED KEY_BLOCK_SIZE=4 /*!50500 PARTITION BY RANGE COLUMNS(G) (PARTITION pNULL VALUES LESS THAN ('0000-00-00') ENGINE = InnoDB, PARTITION p201001 VALUES LESS THAN ('2010-02-01') ENGINE = InnoDB, PARTITION p201002 VALUES LESS THAN ('2010-03-01') ENGINE = InnoDB, PARTITION p201003 VALUES LESS THAN ('2010-04-01') ENGINE = InnoDB, PARTITION p201004 VALUES LESS THAN ('2010-05-01') ENGINE = InnoDB, PARTITION p201005 VALUES LESS THAN ('2010-06-01') ENGINE = InnoDB, PARTITION p201006 VALUES LESS THAN ('2010-07-01') ENGINE = InnoDB, PARTITION p201007 VALUES LESS THAN ('2010-08-01') ENGINE = InnoDB, PARTITION p201008 VALUES LESS THAN ('2010-09-01') ENGINE = InnoDB, PARTITION p201009 VALUES LESS THAN ('2010-10-01') ENGINE = InnoDB, PARTITION p201010 VALUES LESS THAN ('2010-11-01') ENGINE = InnoDB, PARTITION p201011 VALUES LESS THAN ('2010-12-01') ENGINE = InnoDB, PARTITION p201012 VALUES LESS THAN ('2011-01-01') ENGINE = InnoDB, PARTITION p201101 VALUES LESS THAN ('2011-02-01') ENGINE = InnoDB, PARTITION p201102 VALUES LESS THAN ('2011-03-01') ENGINE = InnoDB, PARTITION p201103 VALUES LESS THAN ('2011-04-01') ENGINE = InnoDB, PARTITION p201104 VALUES LESS THAN ('2011-05-01') ENGINE = InnoDB, PARTITION p201105 VALUES LESS THAN ('2011-06-01') ENGINE = InnoDB, PARTITION p201106 VALUES LESS THAN ('2011-07-01') ENGINE = InnoDB, PARTITION p201107 VALUES LESS THAN ('2011-08-01') ENGINE = InnoDB, PARTITION p201108 VALUES LESS THAN ('2011-09-01') ENGINE = InnoDB, PARTITION p201109 VALUES LESS THAN ('2011-10-01') ENGINE = InnoDB, PARTITION p201110 VALUES LESS THAN ('2011-11-01') ENGINE = InnoDB, PARTITION p201111 VALUES LESS THAN ('2011-12-01') ENGINE = InnoDB, PARTITION p201112 VALUES LESS THAN ('2012-01-01') ENGINE = InnoDB, PARTITION p201201 VALUES LESS THAN ('2012-02-01') ENGINE = InnoDB, PARTITION p201202 VALUES LESS THAN ('2012-03-01') ENGINE = InnoDB, PARTITION p201203 VALUES LESS THAN ('2012-04-01') ENGINE = InnoDB, PARTITION p201204 VALUES LESS THAN ('2012-05-01') ENGINE = InnoDB, PARTITION p201205 VALUES LESS THAN ('2012-06-01') ENGINE = InnoDB, PARTITION p201206 VALUES LESS THAN ('2012-07-01') ENGINE = InnoDB, PARTITION p201207 VALUES LESS THAN ('2012-08-01') ENGINE = InnoDB, PARTITION p201208 VALUES LESS THAN ('2012-09-01') ENGINE = InnoDB, PARTITION p201209 VALUES LESS THAN ('2012-10-01') ENGINE = InnoDB, PARTITION p201210 VALUES LESS THAN ('2012-11-01') ENGINE = InnoDB) The table had over 600 million rows, mostly concentrated in the first few partitions How to repeat: Although I've witness this a few times, I don't yet have a repeatable test case. If I'm able to produce one, I will add it to the bug. I suspect the problem is related to InnoDB partitioning and/or compression and the size of the table.