Mysql – Slow “CREATE TABLE” and “TRUNCATE” on MySQL / MariaDB

mariadbMySQLperformance

I am fighting with performance issues on a local MariaDB instance.

Fun thing: I previously had problems with all my INSERT and UPDATE and DELETE queries. This got signigicantly faster (~40ms -> less than 1ms) by changing the innodb_flush_method from O_DIRECT to ALL_O_DIRECT (undoing a previous change), following a suggestion on stackexchange. This is contrary to all other advice I found on the web, that suggests to use O_DIRECT.

EDIT: Not sure anymore about the above. Seen slow INSERT and UPDATE queries again.

What still remains is TRUNCATE and CREATE TABLE being very slow:
~150ms to CREATE TABLE, with a quite simple table structure (InnoDB).
~150ms to TRUNCATE this table, while it is already empty.

All of that in an otherwise empty database, and after purging all the ibdata1 and stuff, as suggested here: https://stackoverflow.com/a/3456885/246724.

The same queries are significantly faster (mysql says 0.00 seconds) on a different machine (my webserver).

Profiling results

Using the awesome profiling feature, I found that the bottleneck is in the 'creating table' step for CREATE, and in the 'After table lock' step for TRUNCATE.

TRUNCATE:

+------------------------------+----------+
| Status                       | Duration |
+------------------------------+----------+
| starting                     | 0.000038 |
| checking permissions         | 0.000042 |
| Opening tables               | 0.000093 |
| After opening tables         | 0.000007 |
| System lock                  | 0.000005 |
| Table lock                   | 0.000003 |
| After table lock             | 0.116224 |
| Waiting for query cache lock | 0.000007 |
| After table lock             | 0.000004 |
| query end                    | 0.000011 |
| closing tables               | 0.000011 |
| freeing items                | 0.000004 |
| updating status              | 0.000010 |
| cleaning up                  | 0.000003 |
+------------------------------+----------+

CREATE TABLE:

+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.000093 |
| checking permissions | 0.000013 |
| Opening tables       | 0.000013 |
| After opening tables | 0.000004 |
| System lock          | 0.000002 |
| Table lock           | 0.000002 |
| After table lock     | 0.000016 |
| creating table       | 0.155836 |
| After create         | 0.000006 |
| query end            | 0.000003 |
| closing tables       | 0.000005 |
| freeing items        | 0.000003 |
| updating status      | 0.000007 |
| cleaning up          | 0.000002 |
+----------------------+----------+

When using SHOW PROFILE ALL FOR QUERY 10, I get a lot of zeros in CPU_*, Context_*, Block_ops_*, Messages_*, Page_faults_*, Swaps.

But the non-zero table cells are:

TRUNCATE:
"After table lock" + "Context_voluntary" -> 10
"After table lock" + "Block_ops_out" -> 269

CREATE TABLE:
"creating table" + "Context_voluntary" -> 10
"creating table" + "Block_ops_out" -> 276

Source:
TRUNCATE "After table lock" -> mysql_lock_tables lock.cc 326
CREATE TABLE "creating table" -> create_table_impl sql_table.cc 4775

Table structure

The table structure is:

CREATE TABLE `cache_bootstrap` (
`cid` varchar(255) NOT NULL DEFAULT '' COMMENT 'Primary Key: Unique cache ID.',
`data` longblob COMMENT 'A collection of data to cache.',
`expire` int(11) NOT NULL DEFAULT '0' COMMENT 'A Unix timestamp indicating when the cache entry should expire, or 0 for never.',
`created` int(11) NOT NULL DEFAULT '0' COMMENT 'A Unix timestamp indicating when the cache entry was created.',
`serialized` smallint(6) NOT NULL DEFAULT '0' COMMENT 'A flag to indicate whether content is serialized (1) or not (0).',
PRIMARY KEY (`cid`),
KEY `expire` (`expire`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8 COMMENT='Cache table for data required to bootstrap Drupal, may be...';

Simplifying this to just one column, either string key or auto-increment, still leaves me with ~100ms for CREATE TABLE and TRUNCATE. But the Context_voluntary changes to 2, and the Block_ops_out changes to 16.

System specs on desktop, where this issue occurs

MySQL version:
mysql Ver 15.1 Distrib 10.0.15-MariaDB, for Linux (x86_64) using readline 5.1

OS: Manjaro / Arch Linux.

Memory: 16 GB
CPU: Intel(R) Core(TM) i5-4570 CPU @ 3.20GHz
Board: ASRock H97 Pro4
HDD (/dev/sda): WDC WD30EZRX-00DC0B0, 3TB, connected with SATA
HDD Partitions:
/dev/sda5 mounted to /, 33% full, 52.1GB total, ext4
/dev/sda4 mounted to /home, 34% full, 524GB total, ext4
Other partitions probably not relevant here.. /var/lib/mysql is on /dev/sda5.
Second HDD probably not relevant here.

System spec on webserver, where these queries are much faster

mysql Ver 14.14 Distrib 5.1.73, for debian-linux-gnu (x86_64) using readline 6.1

Memory: 1GB
CPU: Intel(R) Xeon(R) CPU E5520 @ 2.27GHz

Since this is a virtual machine provided by a hosting company, it won't let me see info about harddrives.

Best Answer

I experimented with this and found something very interesting.

Running Fedora release 20 (Heisenbug) 3.11.10-301.fc20.x86_64, 2GB RAM (I know!), 2 processor Intel centrino.

If you enable the Performance Schema (P_S), the times seem to drop dramatically. Why this is, I simply don't know - the P_S is for monitoring, and not changing anything. I have put what I put in my my.cnf at the end.

Could you test this for your 3 scenarios (CREATE, TRUNCATE & DELETE) running your server using the new my.cnf. If you obtain similar results to mine, then we can investigate further.

Strangely, as far as I can see, the client reports a time of approx 0.3 seconds for me for all of my experiments - but the results from the profiling seem very different. Still puzzling through this one.

Below are my results just for the CREATE table statement before and after enabling the performance schema.

Before enabling P_S.

mysql> show profile for CREATE TABLE cache_bootstrap;
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.000290 |
| checking permissions | 0.000021 |
| Opening tables       | 0.000141 |
| creating table       | 0.365769 |  <<====
| After create         | 0.000037 |
| query end            | 0.000023 |
| closing tables       | 0.000018 |
| freeing items        | 0.000114 |
| cleaning up          | 0.000030 |
+----------------------+----------+
9 rows in set, 1 warning (0.00 sec)

After enabling P_S

mysql> show profile for CREATE TABLE cache_bootstrap;
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.000188 |
| checking permissions | 0.000131 |
| query end            | 0.000015 |
| closing tables       | 0.000020 |
| freeing items        | 0.000068 |
| cleaning up          | 0.000052 |
+----------------------+----------+
6 rows in set, 1 warning (0.00 sec)

MariaDB

Before enabling P_S

Query OK, 0 rows affected (0.33 sec)

MariaDB [test]> show profile for CREATE TABLE cache_bootstrap;
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.000321 |
| checking permissions | 0.000024 |
| Opening tables       | 0.000073 |
| After opening tables | 0.000017 |
| System lock          | 0.000011 |
| Table lock           | 0.000019 |
| After opening tables | 0.000056 |
| creating table       | 0.328769 |  <<======
| After create         | 0.000043 |
| query end            | 0.000026 |
| closing tables       | 0.000022 |
| freeing items        | 0.000043 |
| updating status      | 0.000050 |
| cleaning up          | 0.000039 |
+----------------------+----------+
14 rows in set (0.00 sec)

After enabling P_S on MariaDB

MariaDB [test]> show profile for CREATE TABLE cache_bootstrap
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.000311 |
| checking permissions | 0.000024 |
| Opening tables       | 0.000044 |
| After opening tables | 0.000038 |
| System lock          | 0.000014 |
| Table lock           | 0.000012 |
| After opening tables | 0.000347 |
| After create         | 0.000015 |
| query end            | 0.000014 |
| closing tables       | 0.000021 |
| freeing items        | 0.000014 |
| updating status      | 0.000026 |
| cleaning up          | 0.000034 |
+----------------------+----------+
13 rows in set (0.00 sec)

To be added in the [mysqld] section of my.cnf

[mysqld]

performance_schema
performance_schema_instrument = '%=on'
performance_schema_consumer_events_stages_current = ON
performance_schema_consumer_events_stages_history = ON
performance_schema_consumer_events_stages_history_long = ON
performance_schema_consumer_events_statements_history = ON
performance_schema_consumer_events_statements_history_long = ON
performance_schema_consumer_events_waits_current = ON
performance_schema_consumer_events_waits_history = ON
performance_schema_consumer_events_waits_history_long = ON

YOUR QUERY

SELECT post.postid, post.attach FROM newbb_innopost AS post WHERE post.threadid = 51506;

At first glance, that query should only touches 1.1597% (62510 out of 5390146) of the table. It should be fast given the key distribution of threadid 51506.

REALITY CHECK

No matter which version of MySQL (Oracle, Percona, MariaDB) you use, none of them can fight to one enemy they all have in common : The InnoDB Architecture.

InnoDB Architecture

CLUSTERED INDEX

Please keep in mind that the each threadid entry has a primary key attached. This means that when you read from the index, it must do a primary key lookup within the ClusteredIndex (internally named gen_clust_index). In the ClusteredIndex, each InnoDB page contains both data and PRIMARY KEY index info. See my post Best of MyISAM and InnoDB for more info.

REDUNDANT INDEXES

You have a lot of clutter in the table because some indexes have the same leading columns. MySQL and InnoDB has to navigate through the index clutter to get to needed BTREE nodes. You should reduced that clutter by running the following:

ALTER TABLE newbb_innopost
    DROP INDEX threadid,
    DROP INDEX threadid_2,
    DROP INDEX threadid_visible_dateline,
    ADD INDEX threadid_visible_dateline_index (`threadid`,`visible`,`dateline`,`userid`)
;

Why strip down these indexes ?

The first three indexes start with threadid
threadid_2 and threadid_visible_dateline start with the same three columns
threadid_visible_dateline does not need postid since it's the PRIMARY KEY and it's embedded

BUFFER CACHING

The InnoDB Buffer Pool caches data and index pages. MyISAM only caches index pages.

Just in this area alone, MyISAM does not waste time caching data. That's because it's not designed to cache data. InnoDB caches every data page and index page (and its grandmother) it touches. If your InnoDB Buffer Pool is too small, you could be caching pages, invalidating pages, and removing pages all in one query.

TABLE LAYOUT

You could shave of some space from the row by considering importthreadid and importpostid. You have them as BIGINTs. They take up 16 bytes in the ClusteredIndex per row.

You should run this

SELECT importthreadid,importpostid FROM newbb_innopost PROCEDURE ANALYSE();

This will recommend what data types these columns should be for the given dataset.

CONCLUSION

MyISAM has a lot less to contend with than InnoDB, especially in the area of caching.

While you revealed the amount of RAM (32GB) and the version of MySQL (Server version: 10.0.12-MariaDB-1~trusty-wsrep-log mariadb.org binary distribution, wsrep_25.10.r4002), there are still other pieces to this puzzle you have not revealed

The InnoDB settings
The Number of Cores
Other settings from my.cnf

If you can add these things to the question, I can further elaborate.

UPDATE 2014-08-28 11:27 EDT

You should increase threading

innodb_read_io_threads = 64
innodb_write_io_threads = 16
innodb_log_buffer_size = 256M

I would consider disabling the query cache (See my recent post Why query_cache_type is disabled by default start from MySQL 5.6?)

query_cache_size = 0

I would preserve the Buffer Pool

innodb_buffer_pool_dump_at_shutdown=1
innodb_buffer_pool_load_at_startup=1

Increase purge threads (if you do DML on multiple tables)

innodb_purge_threads = 4