Bug #46738 CREATE TABLE performance issues on Linux/Windows
Submitted: 14 Aug 2009 19:25 Modified: 5 Oct 2010 18:23
Reporter: Chuck Bell Email Updates:
Status: Can't repeat Impact on me:
None 
Category:MySQL Server: General Severity:S3 (Non-critical)
Version:5.4.4 OS:Any
Assigned to: Magne Mæhre CPU Architecture:Any
Tags: regression

[14 Aug 2009 19:25] Chuck Bell
Description:
The table creation process of CREATE TABLE has a severe performance issue on Linux. It is also slow on Windows but that is (somewhat) expected. 

The following are the times as reported by MTR for the simple loop test described below for 1000, 8000, and 16000 tables. 

This was tested on the mysql-6.0-backup tree.

Using 1000 tables
  Mac OS X :    1756
  Windows  :    5241
  Linux    :   11180

Using 8000 tables
  Mac OS X :   21217
  Windows  :   61277
  Linux    : 2008346

Using 16000 tables
  Mac OS X :   67838
  Windows  :  148688
  Linux    : ABORTED after 3 hours...

How to repeat:
Execute this simple test using MTR (be sure to set your timeout parameters very high) -- substitute value for $count for above timings.

--disable_warnings
DROP DATABASE IF EXISTS db1;
--enable_warnings

--echo #
--echo # Create a database for the test.
--echo #
CREATE DATABASE db1;
USE db1;

--echo # 
--echo # Create 16000 tables
--echo #
--disable_query_log
LET $count = 16000;
while ($count)
{
  eval CREATE TABLE t$count (a int) ENGINE=Memory;
  dec $count;
}
--enable_query_log

DROP DATABASE db1;

Note: the test runs and delivers similar results independent of the storage engine chosen although some are slightly slower than others but not significantly so.

Note: this test came about as an effort to produce a regression test for BUG#32499 that creates 16000 tables and performs a backup and restore. The test works fine on Mac and Windows albeit slower on Windows, but runs incredibly slow on Linux.

Note: Mac OS X 10.5, Windows Vista Ultimate 32-bit, Ubuntu 8.04 64-bit
[14 Aug 2009 19:36] Chuck Bell
The test finally finished on Linux. Here is the data for 16000 tables:

Using 16000 tables
  Mac OS X :   67838
  Windows  :  148688
  Linux    : 8510071
[15 Aug 2009 8:26] Peter Laursen
a comment from a non-MySQL person: 

This must be file-system related.  Does the Linux machine run Ext3FS? I that case it is *soemwhat like expected* in my opinion that NTFS performs better than Ext3FS! :-) (and please stop those silly comments on Windoes, if you don't know about it!)

btw: I think I recall a Percona Blog comparing Ext3FS and XFS with such operations (I think is was a huge ammounts of table DROPS they tested) where XFS was many times faster.  A comparison with Ext4FS would be nice too.
[15 Aug 2009 9:06] Peter Laursen
additionally without information about storage engine such report is rather unprecise.  

* notably MyISAM will create more *files* than what other engines will
* with 'file-per_table' option InnoDB will create more *files* than without it

I expect it is file creation efficiency in the file system that is the culprit here.
[15 Aug 2009 9:37] Peter Laursen
and additionally .. only with comparable disk and disk controller hardware it makes sense to compare. Ideally test should be done on one and same box.
[16 Aug 2009 8:53] Sveta Smirnova
Thank you for the report.

Verified as described, although I'd say this is not OS problem, but noticeable regression between MySQL versions.

For example, with 4000 tables:

=====mysql-5.1=====
=====bug46738=====
DROP DATABASE IF EXISTS db1;
#
# Create a database for the test.
#
CREATE DATABASE db1;
USE db1;
# 
# Create 16000 tables
#
select now();
now()
2009-08-16 11:51:25
select now();
now()
2009-08-16 11:52:02
DROP DATABASE db1;

~ 30 seconds

=====mysql-azalea=====
=====bug46738=====
DROP DATABASE IF EXISTS db1;
#
# Create a database for the test.
#
CREATE DATABASE db1;
USE db1;
# 
# Create 16000 tables
#
select now();
now()
2009-08-16 11:40:11
select now();
now()
2009-08-16 11:47:08
DROP DATABASE db1;

~7 minuutes
[17 Aug 2009 12:42] Chuck Bell
The windows and linux machines are on identical hardware.
[18 Aug 2009 16:02] Konstantin Osipov
Known issue in 5.1. A regression in 5.4 that needs attention.
[18 Aug 2009 16:03] Konstantin Osipov
Could you please give some additional information:
- is it IO bound?
- what are the results on optimized binary?
[26 Aug 2009 0:42] shane adams
Hey guys - confirmed this is happening on to me for 5.4 on Centos.  I'm running on top of ext4.  I'm using Innodb tables.
[26 Aug 2009 0:46] shane adams
Konstantin Osipov:

I ran a simple script [sql statements piped into mysql]  that creates 9 tables.  Approx 20 columns a pop.  No blobs.

I ran iostat at the same time the values below were observed for around 5 seconds, which is how long the script took [roughly]

Device:            tps   Blk_read/s   Blk_wrtn/s   Blk_read   Blk_wrtn
sda              22.00         0.00       480.00          0        480
sda1              0.00         0.00         0.00          0          0
sda2              0.00         0.00         0.00          0          0
sda3              0.00         0.00         0.00          0          0
sda4              0.00         0.00         0.00          0          0
sda5             17.00         0.00       480.00          0        480

Shane
[1 Sep 2009 20:55] Sveta Smirnova
Kostja,

> - what are the results on optimized binary?

Same test with 16000 tables:

$cat >51-optim.result
=====mysql-5.1=====
=====bug46738=====
DROP DATABASE IF EXISTS db1;
#
# Create a database for the test.
#
CREATE DATABASE db1;
USE db1;
# 
# Create 16000 tables
#
select now();
now()
2009-09-01 23:27:12
select now();
now()
2009-09-01 23:27:20
DROP DATABASE db1;

$cat >next-optim.result
=====mysql-azalea=====
=====bug46738=====
DROP DATABASE IF EXISTS db1;
#
# Create a database for the test.
#
CREATE DATABASE db1;
USE db1;
# 
# Create 16000 tables
#
select now();
now()
2009-09-01 23:51:54
select now();
now()
2009-09-01 23:52:03
DROP DATABASE db1;
[28 Jan 2010 18:10] John Sivak
Is this issue corrected in a released version of MySQL?

It's unclear to me reading through the notes if the performance on Linux has been improved.
[1 Oct 2010 9:19] Magne Mæhre
I ran the test case with 16.000 tables on Linux (with ext3fs), on optimized builds,and came up with these numbers:

 5.1        63868
 5.5        71767
 "Dahlia"   78721
 "Erica"    71600

The bug report is based on the test running on a 6.0 branch,a codebase that no longer exists.   It would seem that the backports from the 6.0 codebase to Dahlia and Erica did not cause the issue to appear.

Setting the bug report to "Need feedback" awaiting confirmation that the problem is indeed not present any more.
[5 Oct 2010 18:23] Sveta Smirnova
I can not repeat the problem with 5.6.99:

5.0 debug:
real    12m17.052s
user    11m4.070s
sys     0m8.700s
5.1 debug:
real    22m39.157s
user    22m32.495s
sys     0m4.298s
optimized:
real    0m13.608s
user    0m11.513s
sys     0m1.526s
5.6.99 debug:
real    2m4.627s
user    0m45.559s
sys     0m6.574s
[19 Apr 2013 18:52] Len Budney
I am still seeing this problem on MySQL 5.6.10. When can we expect it to be fixed? It is a severe problem for me--it makes every run of my unit tests for my application take almost 15 minutes longer than before.
[18 Jul 2013 16:19] Arnaud Adant
>I am still seeing this problem on MySQL 5.6.10. When can we expect it to be >fixed? It is a severe problem for me--it makes every run of my unit tests for my >application take almost 15 minutes longer than before.

I also noticed this change in 5.6 but it is expected as InnoDB comes with persistent statistics. You should get the same performance in 5.6 as in 5.5 when

http://dev.mysql.com/doc/refman/5.6/en/innodb parameters.html#sysvar_innodb_stats_persistent

 = 0
[24 Aug 2013 9:40] Alexander Velin
Hi,
I'm running Debian wheezy, exact version is

mysql-server-5.5 5.5.31+dfsg-0+wheezy1

I can reproduce the case as follows:

mysql> set profiling =1;
Query OK, 0 rows affected (0.01 sec)

mysql> CREATE TABLE `admin_rule` (
    ->   `rule_id` int(10) unsigned NOT NULL AUTO_INCREMENT COMMENT 'Rule ID',
    ->   `role_id` int(10) unsigned NOT NULL DEFAULT '0' COMMENT 'Role ID',
    ->   `resource_id` varchar(255) DEFAULT NULL COMMENT 'Resource ID',
    ->   `privileges` varchar(20) DEFAULT NULL COMMENT 'Privileges',
    ->   `assert_id` int(10) unsigned NOT NULL DEFAULT '0' COMMENT 'Assert ID',
    ->   `role_type` varchar(1) DEFAULT NULL COMMENT 'Role Type',
    ->   `permission` varchar(10) DEFAULT NULL COMMENT 'Permission',
    ->   PRIMARY KEY (`rule_id`),
    ->   KEY `IDX_ADMIN_RULE_RESOURCE_ID_ROLE_ID` (`resource_id`,`role_id`),
    ->   KEY `IDX_ADMIN_RULE_ROLE_ID_RESOURCE_ID` (`role_id`,`resource_id`),
    ->   CONSTRAINT `FK_ADMIN_RULE_ROLE_ID_ADMIN_ROLE_ROLE_ID` FOREIGN KEY (`role_id`) REFERENCES `admin_role` (`role_id`) ON DELETE CASCADE ON UPDATE CASCADE
    -> ) ENGINE=InnoDB AUTO_INCREMENT=2 DEFAULT CHARSET=utf8 COMMENT='Admin Rule Table';
Query OK, 0 rows affected (0.16 sec)

mysql> set profiling =0;
Query OK, 0 rows affected (0.00 sec)

mysql> show profile all for query 1;
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+----------------------------+--------------+-------------+
| Status               | Duration | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Messages_sent | Messages_received | Page_faults_major | Page_faults_minor | Swaps | Source_function            | Source_file  | Source_line |
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+----------------------------+--------------+-------------+
| starting             | 0.000126 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | NULL                       | NULL         |        NULL |
| checking permissions | 0.000016 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | check_access               | sql_parse.cc |        4751 |
| Opening tables       | 0.000044 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | open_tables                | sql_base.cc  |        4831 |
| System lock          | 0.000029 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_lock_tables          | lock.cc      |         299 |
| creating table       | 0.153939 | 0.036002 |   0.000000 |               233 |                   0 |            0 |           320 |             0 |                 0 |                 0 |                 0 |     0 | mysql_create_table_no_lock | sql_table.cc |        4252 |
| After create         | 0.000040 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_create_table_no_lock | sql_table.cc |        4368 |
| query end            | 0.000008 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_execute_command      | sql_parse.cc |        4440 |
| closing tables       | 0.000012 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_execute_command      | sql_parse.cc |        4492 |
| freeing items        | 0.000019 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_parse                | sql_parse.cc |        5640 |
| logging slow query   | 0.000008 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | log_slow_statement         | sql_parse.cc |        1461 |
| cleaning up          | 0.000008 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | dispatch_command           | sql_parse.cc |        1417 |
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+----------------------------+--------------+-------------+
11 rows in set (0.00 sec)