MySQL Very Slow for REALLY Simple Operations

MySQL

Something appears to be wrong with my MySQL even with very, very simple operations on almost empty (~100) tables

E.g. DROP TABLE IF EXISTS hookup_gender takes 10+ seconds

mysql> show processlist;
+----+---------------+---------------------+---------------+---------+------+----------------------+--------------------------------------+
| Id | User          | Host                | db            | Command | Time | State                | Info                                 |
+----+---------------+---------------------+---------------+---------+------+----------------------+--------------------------------------+
|  2 | pegpro_hookup | 130.88.149.86:51593 | pegpro_hookup | Sleep   |   43 |                      | NULL                                 |
| 92 | root          | localhost           | NULL          | Query   |    0 | NULL                 | show processlist                     |
| 93 | pegpro_hookup | localhost           | pegpro_hookup | Query   |    7 | checking permissions | DROP TABLE IF EXISTS `hookup_gender` |
+----+---------------+---------------------+---------------+---------+------+----------------------+--------------------------------------+

Whereas a basic table create takes 30+ seconds

mysql> show processlist;
+----+---------------+---------------------+---------------+---------+------+----------------+------------------------------------------------------------------------------------------------------+
| Id | User          | Host                | db            | Command | Time | State          | Info                                                                                                 |
+----+---------------+---------------------+---------------+---------+------+----------------+------------------------------------------------------------------------------------------------------+
|  2 | pegpro_hookup | 130.88.149.86:51593 | pegpro_hookup | Sleep   |   24 |                | NULL                                                                                                 |
| 92 | root          | localhost           | NULL          | Query   |    0 | NULL           | show processlist                                                                                     |
| 93 | pegpro_hookup | localhost           | pegpro_hookup | Query   |   25 | creating table | CREATE TABLE `hookup_message`
(
    `id` INTEGER NOT NULL AUTO_INCREMENT,
    `related_post_id` INTEGER NO |
+----+---------------+---------------------+---------------+---------+------+----------------+------------------------------------------------------------------------------------------------------+

What might be causing this slowdown?

What further information can I provide?

Thanks for your time,

Info:

top - 02:44:33 up  1:15,  2 users,  load average: 1.59, 1.57, 1.05
Tasks:  86 total,   1 running,  85 sleeping,   0 stopped,   0 zombie
Cpu(s):  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:   2097152k total,   398904k used,  1698248k free,        0k buffers
Swap:        0k total,        0k used,        0k free,        0k cached

Error log

root@tent:~$ tail -f /var/lib/mysql/mysql-bin.err
111107  1:29:00 [Note] Event Scheduler: Purging the queue. 0 events
111107  1:29:01  InnoDB: Starting shutdown...
111107 01:29:41 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
111107  1:29:41 [Note] Plugin 'FEDERATED' is disabled.
111107  1:29:41  InnoDB: Initializing buffer pool, size = 8.0M
111107  1:29:41  InnoDB: Completed initialization of buffer pool
111107  1:29:55  InnoDB: Started; log sequence number 0 2618946
111107  1:30:06 [Note] Event Scheduler: Loaded 0 events
111107  1:30:06 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.1.59-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MySQL Community Server (GPL)

iostat:

root@tent:~$ iostat
Linux 2.6.18-274.3.1.el5.028stab094.3   07/11/11

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           0.15    0.05    0.08    2.45    0.00   97.28

Device:            tps   Blk_read/s   Blk_wrtn/s   Blk_read   Blk_wrtn

Thanks for your time,

Best Answer

It appears you are using innodb. During a table drop, the innodb engine locks the entire buffer pool and wipes out any references to the tables, and then drops the tables. This takes a fair bit of time when you have a large buffer pool.

One option is to switch to using the Percona builds of mysql. They have a specific feature to help this out

http://www.percona.com/docs/wiki/percona-server:features:misc_system_variables

When innodb_file_per_table is set to 1, doing a DROP TABLE can take a long time on servers with a large buffer pool, even on an empty InnoDB table. This is because InnoDB has to scan through the buffer pool to purge pages that belong to the corresponding tablespace. Furthermore, no other queries can start while that scan is in progress.

When innodb_lazy_drop_table is ON, XtraDB optimizes that process by only marking the pages corresponding to the tablespace being deleted. It defers the actual work of evicting those pages until it needs to find some free pages in the buffer pool.

When innodb_lazy_drop_table is OFF, the usual behavior for dropping tables is in effect.

Related Solutions

MySQL – Troubleshooting Startup Issues After Increasing innodb_buffer_pool_size

The two answers given from @RickJames and @drogart are essentially the remedies. (+1 for each).

Right from the error log you present, the last two lines say:

InnoDB: Error: log file ./ib_logfile0 is of different size 0 134217728 bytes

InnoDB: than specified in the .cnf file 0 268435456 bytes! `

At that point, it was evident that you set innodb_log_file_size to 256M (268435456) in my.cnf while the InnoDB Transaction Logs (ib_logfile0,ib_logfile1) were respectively 128M (134217728) each. Looking back at the link to my StackOverflow answer in your question, you had to do the following:

Step 01) Add this to my.cnf:

[mysqld]
innodb_buffer_pool_size=4G
innodb_log_file_size=1G

Step 02) Run these command in the OS

mysql -u... -p... -e"SET GLOBAL innodb_fast_shutdown = 1"
service mysql stop
rm -f /var/lib/mysql/ib_logfile*
service mysql start

So as to have confidence in what is happening, run tail -f against the error log. You will see message telling you when each innodb log file is being created.

MySQL InnoDB logfiles resized – review thesql-err.log for potential problems

It is sort of yes and no. Why would I say both?

There are still some transactional data embedded in the old ib_logfiles in conjunction with the ibdata1 file. (See pictorial representation)

What you should have done is this:

mysql -u... -p... -ANe"SET GLOBAL innodb_fast_shutdown = 0"
/etc/init.d/mysql.server stop
mv ib_logfile0 ib_logfile0.OLD
mv ib_logfile0 ib_logfile0.OLD
/etc/init.d/mysql.server start

If you did not know of disabling innodb_fast_shutdown, ther you steps should have been

/etc/init.d/mysql.server stop
/etc/init.d/mysql.server start
/etc/init.d/mysql.server stop
mv ib_logfile0 ib_logfile0.OLD
mv ib_logfile0 ib_logfile0.OLD
/etc/init.d/mysql.server start

Doing either of these coordinate the purging of all uncommitted writes to tables and indexes. Just looking at the error log, I think you dodged a bullet in this instance. In future, please follow this protocol.

If you are not sure either way, you could put back the old log files, set the old size of innodb_log_file_size, restart mysql. Then, start the process over again as I prescribed above.

Best Answer

Related Solutions

MySQL – Troubleshooting Startup Issues After Increasing innodb_buffer_pool_size

MySQL InnoDB logfiles resized – review thesql-err.log for potential problems

Related Question