Долгое выполнение запроса в мантикору

abramovich_artem · July 5, 2023, 9:40am

Добрый день.
В рамках проекта был произведен переход со Sphinx на Manticore. Был развернут кластер из 3 нод. Также сталкивались с проблемой, которую решили в этой теме Поломка индекса после изменения структуры таблицы

Сейчас столкнулись со следующей проблемой:
Есть несколько контуров продуктивная и тестовая. По количеству записей: примерно 4 миллиона. Стенды между собой по производительности одинаковые. При этом наблюдается:
на продуктивной среде на одном из индексов при определенном запросе к индексу время ответа превышает 20 секунд. Если обращаться к тому же индексу но с другими параметрами, то скорость ответа не превышает 1 секунды.

В результате анализа определили, что именно ответ от мантикоры занимает основное время(более 80%).
Пытались вывести расширенное логирование через установку глобальной переменной - SET GLOBAL log_level=debugvv;

Прикладываю лог:

[Wed Jul  5 11:37:26.587 2023] [26550] DEBUG: EngageWaiterAndYield awake (m_iSock=226, events=1)
[Wed Jul  5 11:37:26.587 2023] [26550] DEBUG: SockRecv 226, for 4096 bytes
[Wed Jul  5 11:37:26.587 2023] [26550] DEBUG: AsyncRecvNBChunk 233 when read 4096 bytes, sock=226
[Wed Jul  5 11:37:26.587 2023] [26550] DEBUG: SyncSockRead: AsyncRecvNBChunk returned 233, sock=226
[Wed Jul  5 11:37:26.587 2023] [26550] DEBUG: DiscardProcessed(4) iPos=4->0, iLen=233->229, sock=226
[Wed Jul  5 11:37:26.587 2023] [26550] DEBUG: AsyncReadMySQLPacketHeader returned 229 len...
[Wed Jul  5 11:37:26.587 2023] [26550] DEBUG: LoopClientMySQL command 3, 'SELECT requestid, MegaRelationStatusId, ServiceClassId, deadline, serviceName FROM ***:requestind_actual WHERE SsoId='guid' AND EducationTypeId=1 ORDER BY Id DESC LIMIT 1, 11 OPTION MAX_MATCHES=11'
[Wed Jul  5 11:37:26.973 2023] [26567] DEBUG: got events=1, tick=1854703, interrupted=0
[Wed Jul  5 11:37:26.973 2023] [26559] DEBUG: EngageWaiterAndYield awake (m_iSock=230, events=1)
[Wed Jul  5 11:37:26.973 2023] [26559] DEBUG: SockRecv 230, for 4096 bytes
[Wed Jul  5 11:37:26.973 2023] [26559] DEBUG: AsyncRecvNBChunk 5 when read 4096 bytes, sock=230
[Wed Jul  5 11:37:26.974 2023] [26559] DEBUG: SyncSockRead: AsyncRecvNBChunk returned 5, sock=230
[Wed Jul  5 11:37:26.974 2023] [26559] DEBUG: DiscardProcessed(4) iPos=4->0, iLen=5->1, sock=230
[Wed Jul  5 11:37:26.974 2023] [26559] DEBUG: AsyncReadMySQLPacketHeader returned 1 len...
[Wed Jul  5 11:37:26.974 2023] [26559] DEBUG: LoopClientMySQL command 14
[Wed Jul  5 11:37:26.974 2023] [26559] DEBUG: AsyncSend 11 bytes, sock=230
[Wed Jul  5 11:37:26.974 2023] [26559] DEBUG: DiscardProcessed(1) iPos=1->0, iLen=1->0, sock=230
[Wed Jul  5 11:37:26.974 2023] [26559] DEBUG: Receiving command... 0 bytes in buf
[Wed Jul  5 11:37:26.974 2023] [26559] DEBUG: SockRecv 230, for 4096 bytes
[Wed Jul  5 11:37:26.974 2023] [26559] DEBUG: AsyncRecvNBChunk -1 when read 4096 bytes, sock=230
[Wed Jul  5 11:37:26.974 2023] [26559] DEBUG: AsyncRecvNBChunk -1 bytes (4 requested), sock=230
[Wed Jul  5 11:37:26.974 2023] [26559] DEBUG: Still need to receive 4 bytes, sock=230
[Wed Jul  5 11:37:26.974 2023] [26559] DEBUG: Coro::YieldWith (m_iEvent=1), timeout 899999988
[Wed Jul  5 11:37:26.974 2023] [26559] DEBUG: AddAction action as 230, events 13, timeout 480913103
[Wed Jul  5 11:37:26.982 2023] [26559] DEBUG: Kick
[Wed Jul  5 11:37:26.982 2023] [26567] DEBUG: got events=1, tick=1854704, interrupted=0
[Wed Jul  5 11:37:26.982 2023] [26567] DEBUG: 0x7f920c0039c0 epoll 342 setup, ev=0x3221225473, op=EPOLL_CTL_MOD, sock=230
[Wed Jul  5 11:37:26.982 2023] [26567] DEBUG: got events=1, tick=1854705, interrupted=0
[Wed Jul  5 11:37:26.982 2023] [26561] DEBUG: EngageWaiterAndYield awake (m_iSock=230, events=1)
[Wed Jul  5 11:37:26.982 2023] [26561] DEBUG: SockRecv 230, for 4096 bytes
[Wed Jul  5 11:37:26.982 2023] [26561] DEBUG: AsyncRecvNBChunk 105 when read 4096 bytes, sock=230
[Wed Jul  5 11:37:26.982 2023] [26561] DEBUG: SyncSockRead: AsyncRecvNBChunk returned 105, sock=230
[Wed Jul  5 11:37:26.982 2023] [26561] DEBUG: DiscardProcessed(4) iPos=4->0, iLen=105->101, sock=230
[Wed Jul  5 11:37:26.982 2023] [26561] DEBUG: AsyncReadMySQLPacketHeader returned 101 len...
[Wed Jul  5 11:37:26.982 2023] [26561] DEBUG: LoopClientMySQL command 3, 'UPDATE ***:services_v2 SET IsPlacesAvailable = 1, IsActive = 1, volumeFree = 1000 WHERE Id = id'

Видим, что в searchd.log появился запрос в [Wed Jul 5 11:37:26.587 2023] , а в query.log появился в Wed Jul 05 11:37:43.819 2023.
Это единственное, что удалось понять из логов.

Подскажите, пожалуйста, в какую сторону идти дальше, как можно определить проблему.
При необходимости можем предоставить дополнительную информацию.

tomat · July 5, 2023, 11:50am

ну лучше было бы запустить демон с параметрами --cpustats --iostats searchd cli options, выполнить оба запроса и показать строчки из query.log где были бы видны запросы и статистика по запросам.

У вас запросы идут к одиночному индексу или к нескольким индексам или к distributed index?
Если к одиночному индексу то приведите для обоих запросов вызовы

set profiling=1;
query;
show profile;

только query должен быть сам по себе поисковый запрос - без show meta и прочего мультизапроса

abramovich_artem · July 5, 2023, 12:21pm

Индекс одиночный.
Произвели запрос с профайлом без show meta.

tomat · July 5, 2023, 12:24pm

я просил бы показать оба запроса - чтобы было понятно о каких запросах идет речь
и для обоих вывод профайлера и query.log
чтобы было понятно какая разница - сколько документов просканировано, сколько нашлось, какой резалт сет

abramovich_artem · July 5, 2023, 1:50pm

демон запустили с параметрами --cpustats --iostats произвели рестарт мантикоры. Рестарт на некоторое время помогает и запросы выполняются быстро. В течение дня проблема появляется снова.
Как воспроизведем, отпишу снова.

FunkForever · July 5, 2023, 1:55pm

Запрос:

SELECT requestid, MegaRelationStatusId, ServiceClassId, deadline, serviceName FROM cluster:requestind_actual WHERE SsoId=‘807ba4a0-8b27-4abd-8019-00b90d1314f0’ AND EducationTypeId = 2 ORDER BY Id DESC LIMIT 1, 10 OPTION MAX_MATCHES=11;

Если выставлять EducationTypeId = 1, то выполняется медленно. Если выставлять EducationTypeId = 2, то выполняется быстро.

P.S.: Записей с EducationTypeId = 1 в разы больше

tomat · July 5, 2023, 2:04pm

ну если записей в разы больше - то и выполняется запрос дольше
если вы дадите какие-то цифры, тогда будет и понятно что так или не так, а пока если записей больше, то и запрос выполняется дольше - пока все кажется логичным

Например на быстром запросе включается Secondary Index, а на медленном работает full-scan или min-max index может срабатывать и ускорять выполнение

FunkForever · July 10, 2023, 8:40am

Проблема исчезла после полного перезапуска кластера мантикоры и проявилась через 4 дня. Запрос:

/* Mon Jul 10 10:03:47.137 2023 conn 34576 real 22.395 wall 22.396 found 7 */ SELECT requestid, MegaRelationStatusId, ServiceClassId, deadline, serviceName FROM requestind_actual WHERE ssoid='807ba4a0-8b27-4abd-8019-00b90d1314f0' AND educationtypeid=1 ORDER BY Id DESC LIMIT 1,10 OPTION max_matches=11; /*ios=0 kb=0.0 ioms=0.0 cpums=370.4 *

Выяснили, что если удалить фильтр ssoid, то поиск работает быстро. EducationTypeId на скорость поиска не аффектит.
Ссылка на файлы с логами: manticore – Google Drive

tomat · July 10, 2023, 9:04am

вы можете привести вывод show meta после этих запросов?

SELECT requestid, MegaRelationStatusId, ServiceClassId, deadline, serviceName FROM requestind_actual WHERE ssoid='807ba4a0-8b27-4abd-8019-00b90d1314f0' AND educationtypeid=1 ORDER BY Id DESC LIMIT 1,10 OPTION max_matches=11; show meta;
SELECT id FROM requestind_actual WHERE ssoid='807ba4a0-8b27-4abd-8019-00b90d1314f0' AND educationtypeid=1 ORDER BY Id DESC LIMIT 1,10 OPTION max_matches=11; show meta;
SELECT id FROM requestind_actual WHERE ssoid='807ba4a0-8b27-4abd-8019-00b90d1314f0' ORDER BY Id DESC LIMIT 1,10 OPTION max_matches=11; show meta;
SELECT id FROM requestind_actual WHERE educationtypeid=1 ORDER BY Id DESC LIMIT 1,10 OPTION max_matches=11; show meta;

FunkForever · July 10, 2023, 10:18am

1. SELECT requestid, MegaRelationStatusId, ServiceClassId, deadline, serviceName FROM requestind_actual WHERE ssoid='807ba4a0-8b27-4abd-8019-00b90d1314f0' AND educationtypeid=1 ORDER BY Id DESC LIMIT 1,10 OPTION max_matches=11; show meta;

total	7
total_found	7
total_relation	eq
time	22.908
cpu_time	289.935
agents_cpu_time	0.000
io_read_time	0.000
io_read_ops	0
io_read_kbytes	0.0
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

2. SELECT id FROM requestind_actual WHERE ssoid='807ba4a0-8b27-4abd-8019-00b90d1314f0' AND educationtypeid=1 ORDER BY Id DESC LIMIT 1,10 OPTION max_matches=11; show meta;

total	7
total_found	7
total_relation	eq
time	20.081
cpu_time	402.415
agents_cpu_time	0.000
io_read_time	0.000
io_read_ops	0
io_read_kbytes	0.0
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


3. SELECT id FROM requestind_actual WHERE ssoid='807ba4a0-8b27-4abd-8019-00b90d1314f0' ORDER BY Id DESC LIMIT 1,10 OPTION max_matches=11; show meta;

total	8
total_found	8
total_relation	eq
time	17.784
cpu_time	291.687
agents_cpu_time	0.000
io_read_time	0.000
io_read_ops	0
io_read_kbytes	0.0
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

SELECT id FROM requestind_actual WHERE educationtypeid=1 ORDER BY Id DESC LIMIT 1,10 OPTION max_matches=11; show meta;

total	11
total_found	3539208
total_relation	eq
time	0.181
cpu_time	141.574
agents_cpu_time	0.000
io_read_time	0.000
io_read_ops	0
io_read_kbytes	0.0
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

abramovich_artem · July 13, 2023, 11:58am

Коллеги, добрый день, есть ли какие-то предположения? Понятна ли проблема?

tomat · July 13, 2023, 12:09pm

вы используете библиотеку MCL \ Secondary index?

можете выполнить запрос в форсированным SI как описано в optimizer-hints - такой запрос?

SELECT id FROM requestind_actual WHERE ssoid='807ba4a0-8b27-4abd-8019-00b90d1314f0' AND educationtypeid=1 ORDER BY Id DESC LIMIT 1,10 OPTION max_matches=11 /*+ SecondaryIndex(ssoid) */;
show meta;`

abramovich_artem · July 13, 2023, 1:41pm

По первому вопросу:

Выполнили запрос ниже,

SELECT id FROM requestind_actual WHERE ssoid='807ba4a0-8b27-4abd-8019-00b90d1314f0' AND educationtypeid=1 ORDER BY Id DESC LIMIT 1,10 OPTION max_matches=11 /*+ SecondaryIndex(ssoid) */;
show meta;`

Получили такой варнинг: warning: index requestind_actual: hint error: requested hint type not supported for ‘ssoid’ attribute
Время выполнение также большое

tomat · July 13, 2023, 2:47pm

можете показать еще вывод show index requestind_actual status ?

вы используете update для атрибута ssoid ?

abramovich_artem · July 14, 2023, 6:38am

С 1 ноды

index_type  rt
indexed_documents  3594644
indexed_bytes  13358518962
ram_bytes  421181614
disk_bytes  3070725564
disk_mapped  1813030215
disk_mapped_cached  304492544
disk_mapped_doclists  0
disk_mapped_cached_doclists  0
disk_mapped_hitlists  0
disk_mapped_cached_hitlists  0
killed_documents  114448
killed_rate  3.18%
ram_chunk  116632494
ram_chunk_segments_count  29
disk_chunks  13
mem_limit  1073741824
mem_limit_rate  95.00%
ram_bytes_retired  0
tid  44067267
tid_saved  44067081
query_time_1min  {"queries":0, "avg":"-", "min":"-", "max":"-", "pct95":"-", "pct99":"-"}
query_time_5min  {"queries":7, "avg_sec":0.001, "min_sec":0.001, "max_sec":0.002, "pct95_sec":0.002, "pct99_sec":0.002}
query_time_15min  {"queries":39, "avg_sec":0.001, "min_sec":0.001, "max_sec":0.002, "pct95_sec":0.002, "pct99_sec":0.002}
query_time_total  {"queries":4546, "avg_sec":0.001, "min_sec":0.000, "max_sec":0.014, "pct95_sec":0.002, "pct99_sec":0.002}
found_rows_1min  {"queries":0, "avg":"-", "min":"-", "max":"-", "pct95":"-", "pct99":"-"}
found_rows_5min  {"queries":7, "avg":6508, "min":0, "max":14188, "pct95":14188, "pct99":14188}
found_rows_15min  {"queries":39, "avg":9412, "min":0, "max":60146, "pct95":60146, "pct99":60146}
found_rows_total  {"queries":4546, "avg":9505, "min":0, "max":3539905, "pct95":727, "pct99":11651}

Со 2 ноды(3-я аналогично)

index_type  rt
indexed_documents  3594647
indexed_bytes  13358521003
ram_bytes  2283390725
disk_bytes  8933869634
disk_mapped  4602677417
disk_mapped_cached  1303883776
disk_mapped_doclists  0
disk_mapped_cached_doclists  0
disk_mapped_hitlists  0
disk_mapped_cached_hitlists  0
killed_documents  7364419
killed_rate  204.87%
ram_chunk  979454541
ram_chunk_segments_count  29
disk_chunks  12
mem_limit  1073741824
mem_limit_rate  95.00%
ram_bytes_retired  0
tid  44067273
tid_saved  44067081
query_time_1min  {"queries":1, "avg_sec":0.001, "min_sec":0.001, "max_sec":0.001, "pct95_sec":0.001, "pct99_sec":0.001}
query_time_5min  {"queries":13, "avg_sec":0.001, "min_sec":0.001, "max_sec":0.002, "pct95_sec":0.002, "pct99_sec":0.002}
query_time_15min  {"queries":37, "avg_sec":0.001, "min_sec":0.001, "max_sec":0.002, "pct95_sec":0.002, "pct99_sec":0.002}
query_time_total  {"queries":5692, "avg_sec":0.001, "min_sec":0.000, "max_sec":0.014, "pct95_sec":0.002, "pct99_sec":0.002}
found_rows_1min  {"queries":1, "avg":1, "min":1, "max":1, "pct95":1, "pct99":1}
found_rows_5min  {"queries":13, "avg":2784, "min":0, "max":9603, "pct95":9603, "pct99":9603}
found_rows_15min  {"queries":37, "avg":6310, "min":0, "max":60146, "pct95":13935, "pct99":60146}
found_rows_total  {"queries":5692, "avg":6487, "min":0, "max":3539890, "pct95":727, "pct99":7156}

В части update: нет, используется полное пересохранение записи REPLACE INTO

tomat · July 14, 2023, 10:05pm

возможно что это был баг сохранения диск чанков, когда гистограммы для строк не генерились и SI поэтому не включается

вы можете выполнить OPTIMIZE TABLE requestind_actual OPTION cutoff=4; для того чтобы все данные смержились в один диск чанк и перегенерились вспомогательные структуры или другой вариант - сделать truncate и вставить данные заново - после чего повторить поисковый запрос

FunkForever · July 19, 2023, 11:43am

Добрый день!

Заметил, что после выполнения процедуры оптимизации на одной из нод кластера измененные файлы не реплицируются на остальные ноды кластера. Это баг или так задумано, что на каждой ноде необходимо выполнять оптимизацию индексов понодно?
Да, индекс действительно сильно фрагментирован и расплодились чанки. Но тут возникает вопрос: автооптимизация не должно в автоматическом режиме контролировать размер и количество чанков индексов? Или это требуется определить в настройках явно?

tomat · July 19, 2023, 11:57am

если у вас НЕ выключена auto_optimize то демон периодически оптимизирует количество диск-чанков = cores * 2

это значение не реплицируется тк на разных нодах может быть разное количество ядер процессора и разные ноды будут иметь разное количество диск чанков, которое оптимально на этой ноде

FunkForever · July 25, 2023, 8:57am

Добрый день! Спасибо за наводку, процедура оптимизации в ручном режиме решила проблему. Но появились вопросы.

Вы указали, что автооптимизация контролирует число фрагментов индекса на диске, равное удвоенному значению ядер на ноде. Полистав документацию, я увидел, что максимальное число чанков для индексов можно переопределить через глобальную переменную optimize_cutoff, либо через переменную optimize_cutoff, индивидуальную для каждого индекса. До появления проблемы переменная optimize_cutoff под каждый индекс была не определена, однако глобальная переменная optimize_cutoff была и равна 4 (см. вывод по глобальным переменным на каждой ноде)

|Variable_name|Value|
|---|---|
|autocommit|1|
|auto_optimize|1|
|optimize_cutoff|4|
|collation_connection|utf8_general_ci|
|query_log_format|sphinxql|
|session_read_only|0|
|log_level|info|
|max_allowed_packet|134217728|
|character_set_client|utf8|
|character_set_connection|utf8|
|grouping_in_utc|0|
|last_insert_id||
|pseudo_sharding|1|
|secondary_indexes|1|
|accurate_aggregation|0|
|threads_ex_effective||
|threads_ex||

И собственно вопрос: должна ли автооптимизация учитывать на значения optimize_cutoff, прописанной в глобальных переменных или в настройках индекса?
2. Есть ли рекомендации по числу фрагментов индекса? Интересует этот вопрос потому, что разные индексы могут значительно отличаться по размеру и хотелось бы извлечь максимально быстрый отклик при обращении к индексу.

tomat · July 25, 2023, 11:14am

если auto-optimize не выключено то оно будет периодически уменьшать количество disk chunk до default значения (полученого на старте демона) или если задана опция в демоне то до этого значения или же если задана опция в индексе то до этого значения

Есть ли рекомендации по числу фрагментов индекса

мне кажется лучше оставить дефолтные значения и позволить auto-optimize и pseudo-sharding делать свою работу