MySQL database drop insanely slow

innodbMySQL

I just installed MySQL 5.0.45-log Source distribution on my Debian 6.0.6 server.

I installed it under my user home directory like I'm used to doing.

But this time the queries are extremely slow to run.

Running a create table or a database drop takes ages. I can literally watch tv in the meantime.

So I did a profiling of the database drop statement.

mysql> SHOW PROFILES;
+----------+--------------+------------------------------+
| Query_ID | Duration     | Query                        |
+----------+--------------+------------------------------+
|        1 | 369.54719400 | drop database db_madeintouch | 
|        2 |   0.00004600 | SELECT DATABASE()            | 
+----------+--------------+------------------------------+
2 rows in set (0.00 sec)

mysql> SHOW PROFILE FOR QUERY 1;
+----------------------+-----------+
| Status               | Duration  |
+----------------------+-----------+
| (initialization)     | 0.000001  | 
| checking permissions | 369.54705 | 
| Opening table        | 0.000103  | 
| System lock          | 0.000003  | 
| Table lock           | 0.000018  | 
| query end            | 0.000004  | 
| freeing items        | 0.000004  | 
| logging slow query   | 0.000002  | 
+----------------------+-----------+
8 rows in set (0.00 sec)

We can see the time it takes for the checking of permissions is of 369 seconds.

I also did a show status of the InnoDB engine.

mysql> show engine innodb status\G
*************************** 1. row ***************************
Status: 
=====================================
130415 23:11:27 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 9 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 781, signal count 781
Mutex spin waits 0, rounds 8629, OS waits 231
RW-shared spins 379, OS waits 190; RW-excl spins 380, OS waits 342
------------
TRANSACTIONS
------------
Trx id counter 0 7599
Purge done for trx's n:o < 0 7430 undo n:o < 0 0
History list length 3
Total number of lock structs in row lock hash table 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 0, not started, process no 14133, OS thread id 140617364518656
MySQL thread id 16, query id 1305 localhost stephane checking permissions
drop database db_madeintouch
---TRANSACTION 0 0, not started, process no 14133, OS thread id 140617364383488
MySQL thread id 13, query id 1307 localhost stephane
show engine innodb status
---TRANSACTION 0 7597, COMMITTED IN MEMORY, process no 14133, OS thread id 140617364518656 dropping table
COMMITTING , undo log entries 16
MySQL thread id 16, query id 1305 localhost stephane checking permissions
drop database db_madeintouch
--------
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: 1; buffer pool: 0
174 OS file reads, 3781 OS file writes, 2099 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 17393, used cells 122, node heap has 1 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 0 7801057
Log flushed up to   0 7798962
Last checkpoint at  0 7798962
1 pending log writes, 0 pending chkp writes
1535 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 22136914; in additional pool allocated 1048576
Buffer pool size   512
Free buffers       2
Database pages     509
Modified db pages  18
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages read 183, created 1444, written 6980
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. 14133, id 140617334142720, 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
============================

1 row in set (0.00 sec)

And here is my environment.

mysql> SHOW VARIABLES;

+———————————+——————————————————————–+ | Variable_name | Value
|
+———————————+——————————————————————–+ | auto_increment_increment | 1
| | auto_increment_offset | 1
| | automatic_sp_privileges | ON
| | back_log | 50
| | basedir |
/home/stephane/programs/mysql-5.0.45/install/ |
| binlog_cache_size | 32768
| | bulk_insert_buffer_size | 8388608
| | character_set_client | latin1
| | character_set_connection | latin1
| | character_set_database | latin1
| | character_set_filesystem | binary
| | character_set_results | latin1
| | character_set_server | latin1
| | character_set_system | utf8
| | character_sets_dir |
/home/stephane/programs/mysql-5.0.45/install/share/mysql/charsets/ |
| collation_connection | latin1_swedish_ci
| | collation_database | latin1_swedish_ci
| | collation_server | latin1_swedish_ci
| | completion_type | 0
| | concurrent_insert | 1
| | connect_timeout | 5
| | datadir |
/home/stephane/programs/mysql/install/data/ |
| date_format | %Y-%m-%d
| | datetime_format | %Y-%m-%d %H:%i:%s
| | default_week_format | 0
| | delay_key_write | ON
| | delayed_insert_limit | 100
| | delayed_insert_timeout | 300
| | delayed_queue_size | 1000
| | div_precision_increment | 4
| | engine_condition_pushdown | OFF
| | expire_logs_days | 0
| | flush | OFF
| | flush_time | 0
| | ft_boolean_syntax | + -><()~*:""&|
| | ft_max_word_len | 84
| | ft_min_word_len | 4
| | ft_query_expansion_limit | 20
| | ft_stopword_file | (built-in)
| | group_concat_max_len | 1024
| | have_archive | NO
| | have_bdb | NO
| | have_blackhole_engine | NO
| | have_compress | YES
| | have_crypt | YES
| | have_csv | NO
| | have_dynamic_loading | YES
| | have_example_engine | NO
| | have_federated_engine | NO
| | have_geometry | YES
| | have_innodb | YES
| | have_isam | NO
| | have_merge_engine | YES
| | have_ndbcluster | NO
| | have_openssl | NO
| | have_ssl | NO
| | have_query_cache | YES
| | have_raid | NO
| | have_rtree_keys | YES
| | have_symlink | YES
| | hostname | server1
| | init_connect |
| | init_file |
| | init_slave |
| | innodb_additional_mem_pool_size | 1048576
| | innodb_autoextend_increment | 8
| | innodb_buffer_pool_awe_mem_mb | 0
| | innodb_buffer_pool_size | 8388608
| | innodb_checksums | ON
| | innodb_commit_concurrency | 0
| | innodb_concurrency_tickets | 500
| | innodb_data_file_path | ibdata1:10M:autoextend
| | innodb_data_home_dir |
| | innodb_doublewrite | ON
| | innodb_fast_shutdown | 1
| | innodb_file_io_threads | 4
| | innodb_file_per_table | OFF
| | innodb_flush_log_at_trx_commit | 1
| | innodb_flush_method |
| | innodb_force_recovery | 0
| | innodb_lock_wait_timeout | 50
| | innodb_locks_unsafe_for_binlog | OFF
| | innodb_log_arch_dir |
| | innodb_log_archive | OFF
| | innodb_log_buffer_size | 1048576
| | innodb_log_file_size | 5242880
| | innodb_log_files_in_group | 2
| | innodb_log_group_home_dir | ./
| | innodb_max_dirty_pages_pct | 90
| | innodb_max_purge_lag | 0
| | innodb_mirrored_log_groups | 1
| | innodb_open_files | 300
| | innodb_rollback_on_timeout | OFF
| | innodb_support_xa | ON
| | innodb_sync_spin_loops | 20
| | innodb_table_locks | ON
| | innodb_thread_concurrency | 8
| | innodb_thread_sleep_delay | 10000
| | interactive_timeout | 28800
| | join_buffer_size | 131072
| | key_buffer_size | 16384
| | key_cache_age_threshold | 300
| | key_cache_block_size | 1024
| | key_cache_division_limit | 100
| | language |
/home/stephane/programs/mysql-5.0.45/install/share/mysql/english/ |
| large_files_support | ON
| | large_page_size | 0
| | large_pages | OFF
| | lc_time_names | en_US
| | license | GPL
| | local_infile | ON
| | locked_in_memory | OFF
| | log | ON
| | log_bin | OFF
| | log_bin_trust_function_creators | OFF
| | log_error |
/home/stephane/programs/mysql/install/mysql.error.log |
| log_queries_not_using_indexes | OFF
| | log_slave_updates | OFF
| | log_slow_queries | ON
| | log_warnings | 1
| | long_query_time | 10
| | low_priority_updates | OFF
| | lower_case_file_system | OFF
| | lower_case_table_names | 0
| | max_allowed_packet | 1047552
| | max_binlog_cache_size | 18446744073709551615
| | max_binlog_size | 1073741824
| | max_connect_errors | 10
| | max_connections | 100
| | max_delayed_threads | 20
| | max_error_count | 64
| | max_heap_table_size | 16777216
| | max_insert_delayed_threads | 20
| | max_join_size | 18446744073709551615
| | max_length_for_sort_data | 1024
| | max_prepared_stmt_count | 16382
| | max_relay_log_size | 0
| | max_seeks_for_key | 18446744073709551615
| | max_sort_length | 1024
| | max_sp_recursion_depth | 0
| | max_tmp_tables | 32
| | max_user_connections | 0
| | max_write_lock_count | 18446744073709551615
| | multi_range_count | 256
| | myisam_data_pointer_size | 6
| | myisam_max_sort_file_size | 9223372036854775807
| | myisam_recover_options | OFF
| | myisam_repair_threads | 1
| | myisam_sort_buffer_size | 8388608
| | myisam_stats_method | nulls_unequal
| | net_buffer_length | 2048
| | net_read_timeout | 30
| | net_retry_count | 10
| | net_write_timeout | 60
| | new | OFF
| | old_passwords | OFF
| | open_files_limit | 1024
| | optimizer_prune_level | 1
| | optimizer_search_depth | 62
| | pid_file |
/home/stephane/programs/mysql/install/data/server1.pid |
| port | 3306
| | preload_buffer_size | 32768
| | profiling | OFF
| | profiling_history_size | 15
| | protocol_version | 10
| | query_alloc_block_size | 8192
| | query_cache_limit | 1048576
| | query_cache_min_res_unit | 4096
| | query_cache_size | 0
| | query_cache_type | ON
| | query_cache_wlock_invalidate | OFF
| | query_prealloc_size | 8192
| | range_alloc_block_size | 2048
| | read_buffer_size | 258048
| | read_only | OFF
| | read_rnd_buffer_size | 258048
| | relay_log_purge | ON
| | relay_log_space_limit | 0
| | rpl_recovery_rank | 0
| | secure_auth | OFF
| | secure_file_priv |
| | server_id | 1
| | skip_external_locking | ON
| | skip_networking | OFF
| | skip_show_database | OFF
| | slave_compressed_protocol | OFF
| | slave_load_tmpdir | /tmp/
| | slave_net_timeout | 3600
| | slave_skip_errors | OFF
| | slave_transaction_retries | 10
| | slow_launch_time | 2
| | socket | /tmp/mysql.sock
| | sort_buffer_size | 65528
| | sql_big_selects | ON
| | sql_mode |
| | sql_notes | ON
| | sql_warnings | OFF
| | ssl_ca |
| | ssl_capath |
| | ssl_cert |
| | ssl_cipher |
| | ssl_key |
| | storage_engine | MyISAM
| | sync_binlog | 0
| | sync_frm | ON
| | system_time_zone | MSK
| | table_cache | 4
| | table_lock_wait_timeout | 50
| | table_type | MyISAM
| | thread_cache_size | 0
| | thread_stack | 131072
| | time_format | %H:%i:%s
| | time_zone | SYSTEM
| | timed_mutexes | OFF
| | tmp_table_size | 33554432
| | tmpdir | /tmp/
| | transaction_alloc_block_size | 8192
| | transaction_prealloc_size | 4096
| | tx_isolation | REPEATABLE-READ
| | updatable_views_with_limit | YES
| | version | 5.0.45-log
| | version_comment | Source distribution
| | version_compile_machine | x86_64
| | version_compile_os | unknown-linux-gnu
| | wait_timeout | 28800
|
+———————————+——————————————————————–+ 225 rows in set (43.41 sec)

Best Answer

I hate the checking permissions issue.

You may have to disable key checks before the DROP DATABASE

SET unique_checks = 0;
SET foreign_key_checks = 0;
SET GLOBAL innodb_stats_on_metadata = 0;
DROP DATABASE db_madeintouch;
SET GLOBAL innodb_stats_on_metadata = 1;
SET foreign_key_checks = 1;
SET unique_checks = 1;

UPDATE 2013-04-15 18:04 EDT

I just noticed you have innodb_file_per_table OFF. What gives ?

  • You currently have all the InnoDB data and the corresponding index sitting in a single file.
  • Any CREATE TABLE statement must make data dictionary updates and look for space (small but annoying in this instance)
  • Internal Fragmentation of ibdata1
  • Dropping a table means scanning the table and its indexes for availability to lock. With data and index pages possibly fragmented, this takes spindles, seek time, and latency.
  • See Pictorial Representation of ibdata1 to see everything that goes into ibdata1

Recommendation : Remove all Data and Index Pages from ibdata1

This will give ibdata1 a breather to handle just data dictionary and MVCC management. In addition, ibdata1 will stay rather lean and mean and can be read more quickly.

You will need to perform the InnoDB Infrastructure Cleanup. I wrote out all the steps back on October 29, 2010 in StackOverflow.

UPDATE 2013-04-22 08:10 EDT

Three suggestions

SUGGESTION 1 : I just noticed something else. You are using an ancient version of MySQL (5.0.45). You should think about upgrading to MySQL 5.6.11 as it performs significantly faster that MySQL 5.5 and way faster than MySQL 5.0.

SUGGESTION 2 : You should also go ahead and implement the InnoDB Infrastructure Cleanup.

SUGGESTION 3 : You should also check the disk itself. If the data is sitting on a RAID10 set, one of the disks may have an issues. Check the disk controller's battery as well because it can slow down disk caching and affect read performance.

Related Question