What causes temporary slow (fulltext) queries?

Question

I logged this slow query on a 400k rows MySQL 5.6 InnoDB table:

SELECT SQL_NO_CACHE
    topic_id
FROM
    topics_search
WHERE
    host_id = 1
AND
    forum_id IN (23, 50)
AND
    MATCH(topic_text)AGAINST ('+zum' IN BOOLEAN MODE)
ORDER BY
    MATCH(topic_text) AGAINST('+zum' IN BOOLEAN MODE) DESC
LIMIT 1000

Log:

11.02.2017, 16:10:58 - CPU 16% - Time 4,33s
11.02.2017, 16:11:26 - CPU 15% - Time 5,77s
11.02.2017, 16:35:29 - CPU 15% - Time 3,93s

But that query is "fast" in my own tests:

mysql>{sql query with SQL_NO_CACHE option}
29 rows in set (390 ms)

But what could be the reason for the particular slow queries? I tried massive UPDATE ... CONCAT on this table while I parallel repeated the SELECT ... MATCH ... BOOLEAN query:

100 iterations: 
5035 ms (CPU: 29%)
4797 ms (CPU: 33.75%)
3978 ms (CPU: 41%)
1733 ms (CPU: 39.75%)
927 ms (CPU: 39.75%)
1183 ms (CPU: 39.75%)
572 ms (CPU: 39.75%)
747 ms (CPU: 39.75%)
779 ms (CPU: 39.75%)
1340 ms (CPU: 38.5%)
423 ms (CPU: 38.5%)
...
417 ms (CPU: 36.5%)
678 ms (CPU: 36.5%)
432 ms (CPU: 36.5%)
734 ms (CPU: 36.5%)
478 ms (CPU: 36.5%)
425 ms (CPU: 36.5%)
...
741 ms (CPU: 38.625%)
489 ms (CPU: 38.625%)
487 ms (CPU: 38.625%)
413 ms (CPU: 38.625%)
1099 ms (CPU: 38.625%)
29434 ms (CPU: 33.25%)
508 ms (CPU: 33.25%)
439 ms (CPU: 33.25%)
420 ms (CPU: 33.25%)
477 ms (CPU: 33.25%)

As you can see it became expectable slower, because of the higher CPU load, but what happened in this situation?

29434 ms (CPU: 33.25%)

I looked into my slow logs and found these entries:

11.02.2017, 18:12:27 - CPU 33% - Time 28.99s:
/* From the 100 iterations */
SELECT SQL_NO_CACHE
topic_id
FROM
topics_search
WHERE
host_id = 1
AND
forum_id IN (23, 50)
AND
MATCH(topic_text) AGAINST ('+zum' IN BOOLEAN MODE)
ORDER BY
MATCH(topic_text) AGAINST('+zum' IN BOOLEAN MODE) DESC
LIMIT 1000

11.02.2017, 18:12:27 - CPU 33% - Time 29.01s
/* From the heavy writing process */
UPDATE topics_search
SET topic_text = CONCAT(topic_text, "{string with 2000 chars that does not contain 'zum'}"), topic_last_post_id = 1157888
WHERE topic_id = 36565

How is that possible? I tought InnoDB has row based locking or does it lock the complete fulltext index if new entries are added?

Update 1 - More information about the setup

mysql>SHOW TABLE STATUS LIKE 'topics_search'
+---------------+--------+---------+------------+--------+----------------+-------------+-----------------+--------------+-----------+----------------+---------------------+-------------+------------+-------------------+----------+--------------------+---------+
| Name          | Engine | Version | Row_format | Rows   | Avg_row_length | Data_length | Max_data_length | Index_length | Data_free | Auto_increment | Create_time         | Update_time | Check_time | Collation         | Checksum | Create_options     | Comment | 
+---------------+--------+---------+------------+--------+----------------+-------------+-----------------+--------------+-----------+----------------+---------------------+-------------+------------+-------------------+----------+--------------------+---------+
| topics_search | InnoDB | 10      | Compact    | 217686 | 7796           | 1697120256  | 0               | 15302656     | 4194304   |                | 2017-02-11 16:38:09 |             |            | latin1_swedish_ci |          | row_format=DYNAMIC |         |
+---------------+--------+---------+------------+--------+----------------+-------------+-----------------+--------------+-----------+----------------+---------------------+-------------+------------+-------------------+----------+--------------------+---------+
1 rows in set (0 ms)


mysql>SHOW CREATE TABLE topics_search
+---------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Table         | Create Table                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                        | 
+---------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| topics_search | CREATE TABLE `topics_search` (
  `topic_id` mediumint(8) unsigned NOT NULL,
  `forum_id` mediumint(8) unsigned NOT NULL,
  `host_id` mediumint(8) unsigned NOT NULL,
  `topic_poster` mediumint(8) unsigned NOT NULL,
  `topic_last_post_id` mediumint(8) unsigned NOT NULL,
  `search_version` tinyint(3) unsigned NOT NULL DEFAULT '0',
  `topic_title` text NOT NULL,
  `topic_text` longtext NOT NULL,
  PRIMARY KEY (`topic_id`),
  KEY `topic_last_post_id` (`topic_last_post_id`) USING BTREE,
  KEY `forum_id` (`forum_id`) USING BTREE,
  FULLTEXT KEY `topic_title` (`topic_title`),
  FULLTEXT KEY `topic_text` (`topic_text`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1 ROW_FORMAT=DYNAMIC |
+---------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 rows in set (0 ms)

innodb_buffer_pool_size is set to 2.2 Gbyte:

mysql>SHOW VARIABLES LIKE 'innodb_%';
+------------------------------------------+------------------------+
| Variable_name                            | Value                  | 
+------------------------------------------+------------------------+
...
| innodb_additional_mem_pool_size          | 110100480              |
| innodb_api_bk_commit_interval            | 5                      |
| innodb_api_disable_rowlock               | OFF                    |
| innodb_api_enable_binlog                 | OFF                    |
| innodb_api_enable_mdl                    | OFF                    |
| innodb_api_trx_level                     | 0                      |
| innodb_autoextend_increment              | 64                     |
| innodb_autoinc_lock_mode                 | 1                      |
| innodb_buffer_pool_dump_at_shutdown      | OFF                    |
| innodb_buffer_pool_dump_now              | OFF                    |
| innodb_buffer_pool_filename              | ib_buffer_pool         |
| innodb_buffer_pool_instances             | 8                      |
| innodb_buffer_pool_load_abort            | OFF                    |
| innodb_buffer_pool_load_at_startup       | OFF                    |
| innodb_buffer_pool_load_now              | OFF                    |
| innodb_buffer_pool_size                  | 2196766720             |
| innodb_change_buffer_max_size            | 25                     |
| innodb_change_buffering                  | all                    |
| innodb_checksum_algorithm                | innodb                 |
| innodb_checksums                         | ON                     |
| innodb_cmp_per_index_enabled             | OFF                    |
| innodb_commit_concurrency                | 0                      |
| innodb_compression_failure_threshold_pct | 5                      |
| innodb_compression_level                 | 6                      |
| innodb_compression_pad_pct_max           | 50                     |
| innodb_concurrency_tickets               | 5000                   |
| innodb_data_file_path                    | ibdata1:12M:autoextend |
| innodb_data_home_dir                     |                        |
| innodb_disable_sort_file_cache           | OFF                    |
| innodb_doublewrite                       | ON                     |
| innodb_fast_shutdown                     | 1                      |
| innodb_file_format                       | Antelope               |
| innodb_file_format_check                 | ON                     |
| innodb_file_format_max                   | Antelope               |
| innodb_file_per_table                    | ON                     |
| innodb_flush_log_at_timeout              | 1                      |
...
121 rows in set (0 ms)

The machine has 32 GB RAM:

top - 02:39:08 up 114 days,  9:58,  1 user,  load average: 2.27, 2.27, 2.03
Tasks: 260 total,   2 running, 258 sleeping,   0 stopped,   0 zombie
%Cpu(s):  0.1 us,  0.6 sy, 10.0 ni, 87.2 id,  2.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem:  32914036 total, 32634648 used,   279388 free,   871616 buffers
KiB Swap:  4194300 total,   139332 used,  4054968 free. 23525912 cached Mem

Update 2 - Every retry makes it faster

An additional SELECT SQL_NO_CACHE ... MATCH( ... BOOLEAN test resulted:

4063 ms (CPU 12.625%)

Then I retried multiple times:

3268 ms (CPU 12.625%)
2867 ms (CPU 13.625%)
2703 ms (CPU 12.625%)
2033 ms (CPU 13.625%)
1163 ms (CPU 14.625%)
744 ms (CPU 14.625%)
730 ms (CPU 14.625%)
609 ms (CPU 14.625%)
539 ms (CPU 14.625%)
390 ms (CPU 15.625%)
...
every additional request needs 400 ms +/- 10 ms
...
waited several minutes
...
2691 ms (CPU 10.25%)

Conspicuous:

It becomes faster an faster although no cache should be active
Every additional query adds CPU load (this does not happen with the same query on a MyISAM table!)
Something resets the cache

Update 3 - CPU load

I obtain the CPU load through sys_getloadavg()[0] * 100 / 8 (eight cores). This is what top shows on heavy load:

Update 4 - JSON Explain

mysql>EXPLAIN FORMAT=JSON SELECT SQL_NO_CACHE
    topic_id
FROM
    topics_search
WHERE
    host_id = 1
AND
    forum_id IN (23, 50)
AND
    MATCH(topic_text) AGAINST('+zum' IN BOOLEAN MODE)
ORDER BY
    MATCH(topic_text) AGAINST('+zum' IN BOOLEAN MODE) DESC
LIMIT 1000
+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| EXPLAIN                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                               | 
+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| {
  "query_block": {
    "select_id": 1,
    "ordering_operation": {
      "using_filesort": true,
      "table": {
        "table_name": "topics_search",
        "access_type": "fulltext",
        "possible_keys": [
          "forum_id",
          "topic_text"
        ],
        "key": "topic_text",
        "used_key_parts": [
          "topic_text"
        ],
        "key_length": "0",
        "rows": 1,
        "filtered": 100,
        "attached_condition": "((`mysqld_db1`.`topics_search`.`host_id` = 1) and (`mysqld_db1`.`topics_search`.`forum_id` in (23,50)) and (match `mysqld_db1`.`topics_search`.`topic_text` against ('+zum' in boolean mode)))"
      }
    }
  }
} |
+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 rows in set (0 ms)

Update 5 - COUNT() "zum"

mysql>SELECT COUNT(topic_id)
FROM
    topics_search
WHERE
    MATCH(topic_text) AGAINST('+zum' IN BOOLEAN MODE)
+-----------------+
| COUNT(topic_id) | 
+-----------------+
| 69133           |
+-----------------+
1 rows in set (0 ms)

mysql>SELECT COUNT(topic_id)
FROM
    topics_search
+-----------------+
| COUNT(topic_id) | 
+-----------------+
| 366391          |
+-----------------+
1 rows in set (0 ms)

The word "zum" is found in 69133 of 366391 rows (19%).

Update 6 - MyISAM delivers constant query speeds

I know "zum" is a common german word and it will not be fast to search for, but do not forget my question. I asked why it is temporary slower than usual!

The main reason why I opened this question is because this did not happen in the past with a MyISAM table:

mysql>SELECT SQL_NO_CACHE topic_id
FROM topics_search_copy_myisam
WHERE host_id = 1
AND forum_id IN (23, 50)
AND MATCH(topic_text) AGAINST('+ein' IN BOOLEAN MODE)
ORDER BY MATCH(topic_text) AGAINST('ein') DESC
LIMIT 1000
+----------+
| topic_id | 
+----------+
| 56037    |
| 32464    |
| 32459    |
...
+----------+
61 rows in set (835 ms)

28 iterations: 
das: 1106 ms (CPU 7.625%)
auch: 1059 ms (CPU 9.625%)
mit: 1051 ms (CPU 9.625%)
nicht: 1020 ms (CPU 8.125%)
noch: 989 ms (CPU 8.125%)
mal: 916 ms (CPU 8.125%)
bei: 916 ms (CPU 9.375%)
ein: 910 ms (CPU 10.875%)
oder: 909 ms (CPU 7.625%)
von: 894 ms (CPU 8.125%)
nur: 879 ms (CPU 7.625%)
mir: 861 ms (CPU 10.875%)
auf: 851 ms (CPU 9.625%)
hat: 828 ms (CPU 8.125%)
wie: 822 ms (CPU 7.625%)
kann: 817 ms (CPU 9.375%)
wenn: 784 ms (CPU 9.375%)
hier: 755 ms (CPU 10.875%)
habe: 748 ms (CPU 9.625%)
http: 746 ms (CPU 9.625%)
dann: 730 ms (CPU 9.375%)
sind: 729 ms (CPU 9.625%)
schon: 728 ms (CPU 9.375%)
einen: 714 ms (CPU 9.375%)
aus: 676 ms (CPU 7.625%)
eine: 661 ms (CPU 8.125%)
euro: 656 ms (CPU 9.375%)
haben: 638 ms (CPU 10.875%)

Compare again with InnoDB:

mysql>SELECT SQL_NO_CACHE topic_id
FROM topics_search
WHERE host_id = 1
AND forum_id IN (23, 50)
AND MATCH(topic_text) AGAINST('+ein' IN BOOLEAN MODE)
ORDER BY MATCH(topic_text) AGAINST('+ein' IN BOOLEAN MODE) DESC
LIMIT 1000
+----------+
| topic_id | 
+----------+
| 321      |
| 308781   |
| 251074   |
...
+----------+
61 rows in set (1904 ms)

28 iterations: 
nicht: 6136 ms (CPU 15.75%)
hat: 5929 ms (CPU 15.25%)
mal: 5511 ms (CPU 15.375%)
oder: 5287 ms (CPU 15%)
aus: 5269 ms (CPU 14.625%)
das: 4680 ms (CPU 13%)
wie: 4361 ms (CPU 14.75%)
eine: 2455 ms (CPU 15.75%)
von: 944 ms (CPU 15.75%)
noch: 892 ms (CPU 15.5%)
mit: 891 ms (CPU 15.25%)
auch: 861 ms (CPU 15.25%)
ein: 778 ms (CPU 16%)
bei: 746 ms (CPU 15.5%)
auf: 743 ms (CPU 15.25%)
wenn: 735 ms (CPU 15.5%)
mir: 728 ms (CPU 16%)
habe: 675 ms (CPU 15.25%)
kann: 675 ms (CPU 15.5%)
dann: 653 ms (CPU 15.5%)
http: 652 ms (CPU 15.25%)
hier: 648 ms (CPU 16%)
sind: 634 ms (CPU 15.25%)
schon: 630 ms (CPU 15.5%)
euro: 612 ms (CPU 15.5%)
einen: 597 ms (CPU 15.5%)
haben: 536 ms (CPU 16%)
nur: 52 ms (CPU 14.75%)

And two minutes later multiple tries on "nicht":

10 iterations: 
nicht: 843 ms (CPU 5.25%)
nicht: 838 ms (CPU 5.25%)
nicht: 835 ms (CPU 5.875%)
nicht: 835 ms (CPU 5.875%)
nicht: 835 ms (CPU 5.25%)
nicht: 834 ms (CPU 5.875%)
nicht: 833 ms (CPU 5.875%)
nicht: 833 ms (CPU 5.25%)
nicht: 832 ms (CPU 5.875%)
nicht: 831 ms (CPU 5.875%)

Now the query is fast again. Why? That's the question.

How many cores? I ask because "12.625%" sounds awfully close to 1/8, as in one of eight cores being fully utilized?? — Rick James, Commented Feb 12, 2017 at 23:27
Strange coincidence -- xx.625% in all of 10 numbers? Virtually impossible. — Rick James, Commented Feb 12, 2017 at 23:33

Rick James · Accepted Answer · 2017-02-13 22:32:27Z

1

(Too long for Comment. These may help debug the situation.)

SHOW TABLE STATUS LIKE 'topics_search'

Some of the metrics may be useful.

SHOW VARIABLES LIKE 'innodb_buffer_pool_size';

Is that about 70% of available RAM?

SHOW CREATE TABLE topics_search

It may be practical to do "vertical" partitioning. And need to see other indexes.

Are there transactions going on that relate to topics_search? In particular, see if some other query is busy at the same time that this one takes 'too long'.

More (after Update 5)

Are you searching German text? And 'zum' is a very common word? Please do your experiments with a less common word, say one that occurs on less than 1% of the rows.

Here's what is happening. (And there is no way around it.)

Find the rows that match the FT part of the WHERE. FT is always picked first because (a) there is no other mechanism built in, and (b) any 'realistic' FT search won't come back with 69K rows.
Filter the 69K rows for the rest of the WHERE clause conditions.
Sort the results.
Deliver the first 1000 (LIMIT) rows.

Note that everything hinges on the number of rows that matches the FT query. The execute time will be roughly linear. And only one CPU will be involved per connection. So a word that occurs in about 690 rows will probably lead to a query that runs 100 times as fast. (Probably not a full 100, but you get the idea.)

You can probably chew up all 8 CPUs if you run 8 copies of the benchark in parallel. But, that also implies that if you have lots of users searching for 'reasonable' words, there won't be a system-wide performance issue.

edited Feb 13, 2017 at 22:32

answered Feb 11, 2017 at 19:46

Rick James

79.4k5 gold badges51 silver badges117 bronze badges

I updated my question. I do not use any transactions on this table. This table is only for the search function and updated time-shifted as long the CPU load is under 15%. By that it has less INSERT/UPDATE, but many SELECT ... MATCH. "And need to see other indexes." Do you think its possible to use the forum_id index? A COUNT() on forum_id IN (23, 50) returns only < 300 rows. So I wonder already about the > 100 ms query time.
– mgutt
Commented Feb 12, 2017 at 2:04
I added Update 2. Do you think it is because of a too small innodb_buffer_pool_size value?
– mgutt
Commented Feb 12, 2017 at 22:36
The data+index is smaller than the BP. And you are (I assuming) fetching the same rows repeatedly. So, it is plenty big.
– Rick James
Commented Feb 12, 2017 at 23:35
I think it will (1) find all rows matching the FT index, then (2) check forum_id and host_id - without using any index. How many rows match the FT?
– Rick James
Commented Feb 12, 2017 at 23:37
Please provide EXPLAIN FORMAT=JSON SELECT ...
– Rick James
Commented Feb 12, 2017 at 23:39

| Show 3 more comments

Stack Exchange Network

What causes temporary slow (fulltext) queries?

1 Answer 1

Your Answer

Not the answer you're looking for? Browse other questions tagged
mysql
full-text-search
performance
slow-log
query-performance
or ask your own question.

Hot Network Questions

What causes temporary slow (fulltext) queries?

1 Answer 1

Your Answer

Sign up or log in

Post as a guest

Not the answer you're looking for? Browse other questions tagged mysqlfull-text-searchperformanceslow-logquery-performance or ask your own question.

Related

Hot Network Questions

Not the answer you're looking for? Browse other questions tagged
mysql
full-text-search
performance
slow-log
query-performance
or ask your own question.