Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
5.5.36, 10.0.8
-
None
-
Debian 7.4 (Wheezy), Linux mysql06 3.2.0-4-amd64 #1 SMP Debian 3.2.54-2 x86_64 GNU/Linux
deb http://mariadb.mirror.nucleus.be//repo/10.0/debian wheezy main
deb-src http://mariadb.mirror.nucleus.be//repo/10.0/debian wheezy main
Description
When using mysqldump -uroot, this initiates a very, very resource intensive recursive check of every single database and table on the system.
On a system with some 12k databases and 540k .frm files, this takes a long, long time.
(The following output has substituted "censored" for the real username.)
Using mysqldump -ucensored takes next to no time at all, and does not last for long enough that I can even see the query running.
The issue does not appear to be present in MySQL 5.5.36 server as delivered by Oracle, but it occurs also when using mysqldump from that version, and therefore seems like it is in the server code, not the client code.
Someone else have asked this as a question on serverfault.com also, so I'm not the only one experiencing the issue:
http://serverfault.com/questions/574646/mariadb-10-0-slow-work-mysqldump
Here is the relevant excerpt from SHOW FULL PROCESSLIST for my use case:
| 292 | root | localhost | NULL | Query | 265 | Opening tables | SELECT LOGFILE_GROUP_NAME, FILE_NAME, TOTAL_EXTENTS, INITIAL_SIZE, ENGINE, EXTRA FROM INFORMATION_SCHEMA.FILES WHERE FILE_TYPE = 'UNDO LOG' AND FILE_NAME IS NOT NULL AND LOGFILE_GROUP_NAME IN (SELECT DISTINCT LOGFILE_GROUP_NAME FROM INFORMATION_SCHEMA.FILES WHERE FILE_TYPE = 'DATAFILE' AND TABLESPACE_NAME IN (SELECT DISTINCT TABLESPACE_NAME FROM INFORMATION_SCHEMA.PARTITIONS WHERE TABLE_SCHEMA IN ('censored'))) GROUP BY LOGFILE_GROUP_NAME, FILE_NAME, ENGINE ORDER BY LOGFILE_GROUP_NAME | 0.000 |
|
And here is some sample output from strace, showing what's going on:
[pid 37289] getcwd("/var/lib/mysql", 4096) = 15
|
[pid 37289] lstat("/var/lib/mysql/CENSORED", {st_mode=S_IFDIR|0700, st_size=8192, ...}) = 0
|
[pid 37289] read(1449, "\376\1\n\f\22\0V\0\1\0\37\10\0\0\371\0010\3\0\0\0\0\0\0\0\0\0\2!\0\t\0"..., 64) = 64
|
[pid 37289] read(1449, "\0\20\2539\2215\232.\21\343\217\221\270\312:d\362\200\217\5\0\0\1\1\0\0\n\0\0\0\4\0"..., 2015) = 2015
|
[pid 37289] close(1449) = 0
|
[pid 37289] time(NULL) = 1393234684
|
[pid 37289] access("./CENSORED/flabber_updates.TRG", F_OK) = -1 ENOENT (No such file or directory)
|
[pid 37289] stat("./CENSORED/flabber_updates.frm", {st_mode=S_IFREG|0660, st_size=2079, ...}) = 0
|
[pid 37289] open("./CENSORED/flabber_user_notes.frm", O_RDONLY) = 1449
|
[pid 37289] getcwd("/var/lib/mysql", 4096) = 15
|
[pid 37289] lstat("/var/lib/mysql/CENSORED", {st_mode=S_IFDIR|0700, st_size=8192, ...}) = 0
|
[pid 37289] read(1449, "\376\1\n\f\22\0V\0\1\0t\n\0\0\313\5\201\1\0\0\0\0\0\0\0\0\0\2_\0\t\0"..., 64) = 64
|
[pid 37289] read(1449, "\0\20\253B\364\376\232.\21\343\217\221\270\312:d\362\200\262\7\0\0\3\3\0\0&\0\0\0\4\0"..., 2612) = 2612
|
[pid 37289] close(1449) = 0
|
[pid 37289] time(NULL) = 1393234684
|
[pid 37289] access("./CENSORED/flabber_user_notes.TRG", F_OK) = -1 ENOENT (No such file or directory)
|
[pid 37289] stat("./CENSORED/flabber_user_notes.frm", {st_mode=S_IFREG|0660, st_size=2676, ...}) = 0
|
[pid 37289] open("./CENSORED/flabber_user_profiles.frm", O_RDONLY) = 1449
|
Attachments
Activity
Did investigation of optimizer behavior:
1. Old optimizer (before semi-join subquery optimizations)
The query ran instantly on older versions, because they only supported top-to-bottom execution. The top-level select is "SELECT ... FROM INFORMATION_SCHEMA.FILES", which typically produces no rows and the subquery is never invoked (I_S tables are populated in JOIN::exec(), see get_schema_tables_result() call)
2. Semi-join optimizer, MariaDB
Semi-join optimizer merges the subquery into top-level query. The decision to use SJ-Materialization is essentially a random choice: I_S tables provide bogus data to the optimizer (each I_S table has 2 rows, table->scan_time() =2).
The problem is that JOIN::exec()/get_schema_tables_result() will attempt to populate all tables before executing the join. Populating I_S.PARTITIONS table will cause all tables in the database of interest to be opened.
3. Semi-join optimizer, MySQL 5.6
They have MySQL BUG# 71914 . They never populate I_S.PARTITIONS which causes them to run fast.
Fixing I_S tables to provide sane data to the optimizer is a big project.
For now, we will:
- Fix MariaDB 10.0 to only open tables/databases of interest (already committed)
- To get a bit of extra performance, fix mysqldump in 5.5/10.0 to run the query with 'semijoin=off' to speed it up.
Fixed as described in the previous comment.
frettled, thanks alot for taking time to report this issue. We really appreciate such input.
And thank you very much, elenst and psergey, for the detailed analysis and, as far as I can tell from following the comments, exactly the correct fix for the problem!
Committed a patch that makes MariaDB 10.0 be as fast as MariaDB 5.5. It will not scan unneeded databases anymore.