Добрый день.
В рамках проекта был произведен переход со Sphinx на Manticore. Был развернут кластер из 3 нод. Также сталкивались с проблемой, которую решили в этой теме https://forum.manticoresearch.com/t/topic/1431This text will be hidden
Сейчас столкнулись со следующей проблемой:
Есть несколько контуров продуктивная и тестовая. По количеству записей: примерно 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.
Это единственное, что удалось понять из логов.
Подскажите, пожалуйста, в какую сторону идти дальше, как можно определить проблему.
При необходимости можем предоставить дополнительную информацию.