One problem made me puzzled for couple hours, but it was really interesting to figure out what’s going on.
So let me introduce problem at first. The table is
|
1 |
<br>CREATE TABLE `c` (<br> `tracker_id` int(10) unsigned NOT NULL,<br> `username` char(20) character set latin1 collate latin1_bin NOT NULL,<br> `time_id` date NOT NULL,<br> `block_id` int(10) unsigned default NULL,<br> PRIMARY KEY (`tracker_id`,`username`,`time_id`),<br> KEY `block_id` (`block_id`)<br>) ENGINE=InnoDB<br> |
Table has 11864696 rows and takes Data_length: 698,351,616 bytes on disk
The problem is that after restoring table from mysqldump, the query that scans data by primary key was slow. How slow ? Let me show.
The query in question is (Q1):
|
1 |
SELECT count(distinct username) FROM tracker where TIME_ID >= '2009-07-20 00:00:00' AND TIME_ID <= '2009-10-21 00:00:00' AND (tracker_id=437)<br> |
On cold buffer_pool, it took:
|
1 |
<br>+---------------------------+<br>| count(distinct username) |<br>+---------------------------+<br>| 5856156 | <br>+---------------------------+<br>1 row in set (4 min 13.61 sec)<br> |
However the query (again on cold buffer_pool) (Q2)
|
1 |
SELECT count(distinct username) FROM tracker where TIME_ID >= '2009-07-20 00:00:00' AND TIME_ID <= '2009-10-21 00:00:00' <br> |
|
1 |
<br>+---------------------------+<br>| count(distinct username) |<br>+---------------------------+<br>| 5903053 | <br>+---------------------------+<br>1 row in set (18.81 sec)<br> |
Difference is impressive. 4 min 13.61 sec vs 18.81 sec
If you want EXPLAIN plain, here it is:
For Q1:
|
1 |
<br>+----+-------------+-------------------------+------+---------------+---------+---------+-------+---------+--------------------------+<br>| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |<br>+----+-------------+-------------------------+------+---------------+---------+---------+-------+---------+--------------------------+<br>| 1 | SIMPLE | tracker | ref | PRIMARY | PRIMARY | 4 | const | 6880241 | Using where; Using index | <br>+----+-------------+-------------------------+------+---------------+---------+---------+-------+---------+--------------------------+<br>1 row in set (0.02 sec)<br><br> |
For Q2:
|
1 |
<br>+----+-------------+-------------------------+-------+---------------+-------------------------------------+---------+------+----------+--------------------------+<br>| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |<br>+----+-------------+-------------------------+-------+---------------+-------------------------------------+---------+------+----------+--------------------------+<br>| 1 | SIMPLE | tracker | index | NULL | block_id | 5 | NULL | 13760483 | Using where; Using index | <br>+----+-------------+-------------------------+-------+---------------+-------------------------------------+---------+------+----------+--------------------------+<br> |
Query Q1 is executed using Primary Key, and Query Q2 is using block_id key.
To get more details I ran both queries with our extended stats in slow.log (available in 5.0-percona releases)
So for query Q1:
|
1 |
<br># Query_time: 253.643162 Lock_time: 0.000137 Rows_sent: 1 Rows_examined: 11569733 Rows_affected: 0 Rows_read: 11569733<br># InnoDB_IO_r_ops: 73916 InnoDB_IO_r_bytes: 1211039744 InnoDB_IO_r_wait: 236.149003<br># InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000<br># InnoDB_pages_distinct: 54838<br> |
And for query Q2:
|
1 |
<br># Query_time: 18.846855 Lock_time: 0.000123 Rows_sent: 1 Rows_examined: 11864696 Rows_affected: 0 Rows_read: 11864696<br># InnoDB_IO_r_ops: 27510 InnoDB_IO_r_bytes: 450723840 InnoDB_IO_r_wait: 0.165124<br># InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000<br># InnoDB_pages_distinct: 24687<br> |
As you see for Q1 IO read took 236.149003 sec vs 0.165124 for Q2. But Q1 is scan by primary key, which supposed to be
sequential!
Let’s see on another statistic, which available in innodb_check_fragmentation patch:
for Q1:
|
1 |
<br>SHOW STATUS LIKE 'Innodb_scan_pages%';<br>+------------------------------+-------+<br>| Variable_name | Value |<br>+------------------------------+-------+<br>| Innodb_scan_pages_contiguous | 88 | <br>| Innodb_scan_pages_jumpy | 73789 | <br>+------------------------------+-------+<br>2 rows in set (0.00 sec)<br> |
and for Q2:
|
1 |
<br>mysql> SHOW STATUS LIKE 'Innodb_scan_pages%'; <br>+------------------------------+-------+<br>| Variable_name | Value |<br>+------------------------------+-------+<br>| Innodb_scan_pages_contiguous | 26959 | <br>| Innodb_scan_pages_jumpy | 442 | <br>+------------------------------+-------+<br>2 rows in set (0.00 sec)<br> |
So you see for Q1 it was not sequential scan, even it is primary key, but it is sequential for Q2.
So what’s the answer ? It’s fragmentation of primary key (and whole data table, as InnoDB data == primary key). But how it could happen with
primary key after mysqldump ? The answer here if we look on
EXPLAIN SELECT * FROM tracker;
|
1 |
<br>+----+-------------+-------------------------+-------+---------------+-------------------------------------+---------+------+----------+-------------+<br>| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |<br>+----+-------------+-------------------------+-------+---------------+-------------------------------------+---------+------+----------+-------------+<br>| 1 | SIMPLE | tracker | index | NULL | block_id | 5 | NULL | 13760483 | Using index | <br>+----+-------------+-------------------------+-------+---------------+-------------------------------------+---------+------+----------+-------------+<br>1 row in set (0.00 sec)<br> |
We see that dump is taken in key “block_id” order, not in primary key order. And later when we load this table, INSERTS into primary key happens in random order, and that gives us the fragmentation we see here.
How to fix it in our case. It’s easy:
|
1 |
ALTER TABLE tracker ENGINE=InnoDB |
, it will force InnoDB to rebuild table in primary key order.
After that Q1:
|
1 |
<br>+---------------------------+<br>| count(distinct username) |<br>+---------------------------+<br>| 5856156 | <br>+---------------------------+<br>1 row in set (17.72 sec)<br><br>mysql> SHOW STATUS LIKE 'Innodb_scan_pages%';<br>+------------------------------+-------+<br>| Variable_name | Value |<br>+------------------------------+-------+<br>| Innodb_scan_pages_contiguous | 37864 | <br>| Innodb_scan_pages_jumpy | 574 | <br>+------------------------------+-------+<br>2 rows in set (0.00 sec)<br><br>and extended stats:<br># Query_time: 17.765369 Lock_time: 0.000137 Rows_sent: 1 Rows_examined: 11569733 Rows_affected: 0 Rows_read: 11569733<br># InnoDB_IO_r_ops: 38530 InnoDB_IO_r_bytes: 631275520 InnoDB_IO_r_wait: 0.204893<br># InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000<br># InnoDB_pages_distinct: 35584<br> |
You see that time returned to appropriate 17.72 sec.
You may ask what happens now with Q2 ? yes, it’s getting slow now, as we made key “block_id” inserted not in order.
|
1 |
<br>+---------------------------+<br>| count(distinct username) |<br>+---------------------------+<br>| 5903053 |<br>+---------------------------+<br>1 row in set (2 min 8.92 sec)<br>mysql> SHOW STATUS LIKE 'Innodb_scan_pages%';<br>+------------------------------+-------+<br>| Variable_name | Value |<br>+------------------------------+-------+<br>| Innodb_scan_pages_contiguous | 45 | <br>| Innodb_scan_pages_jumpy | 35904 | <br>+------------------------------+-------+<br>2 rows in set (0.00 sec)<br> |
As for mysqldump you may use
|
1 |
--order-by-primary |
options to force dump in primary key order.
So notes to highlight:
|
1 |
Innodb_scan_pages_contiguous ; Innodb_scan_pages_jumpy |
Resources
RELATED POSTS
