In this article we discuss the tools available for profiling queries in Manticore Search.
SHOW META
By default the SHOW META command provides statistics about the keywords used in the match. For each keyword we get the number of documents in which the keywords was found and total number of hits. High values - for example docs are almost as high as the total documents in the index - can indicate the keyword is a candidate for being a stopword.
SHOW META output can be enriched by starting the searchd daemon with –cpustats –iostats. This enables collecting query metrics about IO and CPU effort needed to execute the query.
mysql> SELECT * FROM myindex WHERE MATCH('search engine*');SHOW META;
....
+-----------------------+---------+
| Variable_name | Value |
+-----------------------+---------+
| total | 1000 |
| total_found | 3994 |
| time | 0.090 |
| cpu_time | 42.950 |
| agents_cpu_time | 0.000 |
| io_read_time | 82.276 |
| io_read_ops | 1633 |
| io_read_kbytes | 1264.5 |
| io_write_time | 0.000 |
| io_write_ops | 0 |
| io_write_kbytes | 0.0 |
| agent_io_read_time | 0.000 |
| agent_io_read_ops | 0 |
| agent_io_read_kbytes | 0.0 |
| agent_io_write_time | 0.000 |
| agent_io_write_ops | 0 |
| agent_io_write_kbytes | 0.0 |
| keyword[0] | engine* |
| docs[0] | 55037 |
| hits[0] | 135095 |
| keyword[1] | search |
| docs[1] | 32768 |
| hits[1] | 53800 |
+-----------------------+---------+
23 rows in set (0.00 sec)
iostats tell us how much data was read from the disk, how many I/O ops were made and the time spent. Large io data read means the query has keywords with lot of hits that are required to be read for building the ranking score. If data is not large, but we are experiencing high times, our storage could be slow or overloaded. This can happen because of high traffic, but it can also signal that there is an issue with the storage that needs to be investigated.
cpustats provides the CPU time used to do the processing. If iostats are low and cpu is high, our query hits a CPU bound. Generally CPU bound is solved by splitting the index into multiple shards and perform local cluster searches using dist_threads > 0. Long CPU times can also point that server is being overloaded. High CPU time spent can have various causes, a common one is caused by expansions in case of wildcard searches (with the default dict=keywords).
The agent_ metrics have values in case the index is a distributed one and provide how much data was read/write between the master index and it’s nodes.
SHOW PROFILE
Profiling can be enabled per session with SET PROFILING=1 ( or pass profile:true in case of HTTP API).
SHOW PROFILE must run right away after the query. It provides how much time is spent on different stages of query execution. The switches column provide the number of logical engine state switches (not OS level context switches). The stages times can help understand why a query is slow. In the example below, a lot of time is spent on the read_* stages because the query was executed right after the index was loaded, so it has to perform reads from the disk. Profiling a distributed index with remote nodes will add stages for connecting to agents and wait times for remote results.
mysql> SHOW PROFILE;
+--------------+----------+----------+---------+
| Status | Duration | Switches | Percent |
+--------------+----------+----------+---------+
| unknown | 0.000827 | 4 | 0.91 |
| local_search | 0.000011 | 1 | 0.01 |
| sql_parse | 0.000019 | 1 | 0.02 |
| dict_setup | 0.000001 | 1 | 0.00 |
| parse | 0.000029 | 1 | 0.03 |
| transforms | 0.000104 | 1 | 0.11 |
| init | 0.000668 | 1169 | 0.73 |
| read_docs | 0.069948 | 1348 | 76.58 |
| read_hits | 0.012602 | 285 | 13.80 |
| get_docs | 0.004021 | 804 | 4.40 |
| get_hits | 0.002276 | 704 | 2.49 |
| filter | 0.000069 | 258 | 0.08 |
| rank | 0.000252 | 791 | 0.28 |
| sort | 0.000266 | 8 | 0.29 |
| finalize | 0.000234 | 1 | 0.26 |
| aggregate | 0.000014 | 2 | 0.02 |
| eval_post | 0.000000 | 1 | 0.00 |
| total | 0.091341 | 5380 | 0 |
+--------------+----------+----------+---------+
18 rows in set (0.00 sec)
SHOW PLAN
SHOW PLAN shows how the evaluated query tree of the fulltext match. This is useful to understand how the input search is transformed and executed. The keywords are showed with their position in the query and if they are expanded keyword coming from a wildcarded term. In case of searches with wildcards, the command is useful as we can see the entire list of expansions.
mysql> SHOW PLAN\G
*************************** 1. row ***************************
Variable: transformed_tree
Value: AND(
AND(KEYWORD(search, querypos=1)),
OR(
OR(
AND(KEYWORD(engineer, querypos=2, expanded)),
OR(
AND(KEYWORD(engineering, querypos=2, expanded)),
OR(
AND(KEYWORD(engineers, querypos=2, expanded)),
AND(KEYWORD(engines, querypos=2, expanded)))),
AND(KEYWORD(engineered, querypos=2, expanded))),
OR(
AND(KEYWORD(engine's, querypos=2, expanded)),
OR(
AND(KEYWORD(engine_power, querypos=2, expanded)),
AND(KEYWORD(engined, querypos=2, expanded)))),
AND(KEYWORD(engine, querypos=2, expanded)),
OR(KEYWORD(engine*, querypos=2, expanded))))
1 row in set (0.00 sec)
SHOW PLAN also requires enabling profiling and must run before SHOW META.
Ultimately, the system resources needs to be monitored as well. If you are running other active services beside Manticore (like a database or application code), the impact of those needs to be monitored. While Manticore can live alongside other services, since it can be both CPU and IO intensive, for high traffic setups it’s better to have Manticore standalone so it doesn’t be influenced (or influence) by others.