В этой статье мы разберём инструменты профилирования запросов, которые есть в Manticore Search.
SHOW META
По умолчанию команда SHOW META предоставляет статистику по ключевым словам, использованным в совпадении. Для каждого ключевого слова мы получаем количество документов, в которых слово было найдено, и общее количество попаданий. Высокие значения — например, количество документов почти равно общему числу документов в индексе — могут указывать на то, что слово является кандидатом на стоп-слово.
Вывод SHOW META можно обогатить, запустив демон searchd с параметрами --cpustats --iostats . Это позволяет собирать метрики запросов о затратах ввода-вывода и процессора, необходимых для выполнения запроса.
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 показывает, сколько данных прочитано с диска, сколько выполнено операций ввода-вывода и сколько времени на это ушло. Большой объём прочитанных данных означает, что в запросе есть ключевые слова с большим числом вхождений, которые нужно прочитать, чтобы вычислить оценку ранжирования. Если данных прочитано немного, а время всё равно большое, хранилище может быть медленным или перегруженным. Причиной может быть высокий трафик, но это может указывать и на проблему с хранилищем, которую нужно расследовать.
cpustats показывает процессорное время, затраченное на обработку. Если iostats низкие, а CPU высокий, запрос ограничен процессором. Обычно это решается разбиением индекса на несколько шардов и локальным распределённым поиском с dist_threads > 0. Большое процессорное время может также указывать на перегрузку сервера. У высокого расхода CPU бывают разные причины; одна из частых — раскрытие шаблонов при подстановочном поиске (с dict=keywords по умолчанию).
Метрики agent_ имеют значения, если индекс распределённый, и показывают, сколько данных было прочитано/записано между главным индексом и его узлами.
SHOW PROFILE
Профилирование можно включить для сессии с помощью SET
PROFILING=1 (или передать profile:true в случае HTTP API).
SHOW PROFILE
должен выполняться сразу после запроса. Он показывает, сколько времени тратится на различные стадии выполнения запроса. Столбец switches отображает количество переключений логических состояний движка (не переключения контекста ОС). Времена стадий могут помочь понять, почему запрос медленный. В приведённом ниже примере много времени тратится на стадии read_* потому, что запрос был выполнен сразу после загрузки индекса, поэтому необходимо выполнять чтение с диска. Профилирование распределённого индекса с удалёнными узлами добавит стадии подключения к агентам и время ожидания удалённых результатов.
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 показывает план выполнения запроса — дерево, по которому вычисляется полнотекстовое совпадение. Это помогает понять, как исходный поисковый запрос преобразуется и выполняется. Ключевые слова выводятся с позицией в запросе и пометкой, если слово получено расширением терма с подстановочным знаком. При поиске с подстановочными знаками команда полезна тем, что показывает полный список расширений.
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 также требует включения профилирования и должен выполняться до SHOW META.
Наконец, нужно следить и за системными ресурсами. Если рядом с Manticore работают другие активные сервисы (например, база данных или код приложения), их влияние тоже нужно отслеживать. Manticore может уживаться с другими сервисами, но он способен интенсивно нагружать и CPU, и ввод-вывод, поэтому при высоком трафике его лучше запускать отдельно, чтобы другие сервисы не влияли на него (а он — на них).