Самовольное выключение searchd

General Discussions - Russian
45

Раньше вы показывали show threads в момент зависания и там было

| 2684599 | work_5     | http  | net_read | 127.0.0.1:50498     |  76899 |   909.270391 | 6m        |   2469465 | 15m           | No (working) | Mini Mini Mini Query Conn  | 1 ch 0: 1 ch 1: api-search query="{"bool":{"must":[{"query_string":"15 Pro"},{"equals":{"area_id":13}},{"in":{"is_available":[11,6]}}]}}" comment="" index="products" |

Это типичный симптом, когда зависает после попытки стопа (что есть запрос с No (working) и большим значением в Last job took?

Может дело обстоит так, что зависает оно сперва на каком-то запросе, а это в свою очередь обеспечивает зависание на стопе? Можете логировать show threads раз в N минут, чтоб подтвердить эту гипотезу?

46

Хорошо, только подскажите, как это лучше сделать?

47

Есть опыт со screen?

48

Нет, не приходилось сталкиваться, но разберусь. Какой алгоритм действий?

49

можете так же после остановки демона померить обем занимаемый всех .ram файлов во всех индексах?

у нас есть задача ускорить сохранение RT индексов при остановке демона https://github.com/manticoresoftware/dev/issues/186

Тк сейчас RAM часть RT индекса сохраняется на диск, вне зависомости от того есть ли изменения в ней по сравнению с тем что уже лежит на диске или нет.

Если у вас большой обем RAM или много индексов - то просто запись их всех на диске при остановке демона может занять продолжительное время. И systemd пытается убить его по таймауту?

50

Запустить вот это в скрине:

while true; do (date; mysql -P9306 -h0 -e "select 'show threads -----------'; show threads option format=all; select '@@system.sessions ------------------'; select * from @@system.sessions; select 'show status ---------------------'; show status"; echo =========================================) >> /tmp/log 2>&1; sleep 60; done;

Можно и не в скрине, а просто в терминале, но если коннект пропадёт, то всё прервётся. Или в кроне раз в минуту, но тогда убрать while true выше.

Дождаться, когда зависнет, затем показать нам /tmp/log.

51

Разметочная сетка не записывается корректно почему-то в файлик, а так работает.

Fri 24 Nov 2023 08:59:42 AM MSK
Value
show threads -----------
Tid	Name	Proto	State	Host	ConnID	Time	Work time	Jobs done	Last job took	In idle	Chain	Info
3362314	work_0		-		-1	85090.730912	12m	4382771	31us	391us ago		
3362315	work_1		-		-1	85090.730843	12m	4376543	324us	591us ago		
3362316	work_2		-		-1	85090.730735	12m	4389695	313us	39ms ago		
3362317	work_3	mysql	query	127.0.0.1:55964	129610	0.000282	12m	4390582	430us	No (working)	Conn 	show threads option format=all
3362318	work_4		-		-1	85090.730571	12m	4400803	208us	9ms ago		
3362319	work_5		-		-1	85090.730528	12m	4390846	298us	37ms ago		
3362320	work_6		-		-1	85090.730490	12m	4381861	269us	9ms ago		
3362321	work_7		-		-1	85090.730438	12m	4387076	240us	6ms ago		
3362500	TickPool_0		-		-1	84917.703986	16m	0	21us	499us ago	Listen 	tick:  11300007  works:  0  state:  in polling
3362322	Timer		-		-1	85090.729114	0us	0	-	-		
Value
@@system.sessions ------------------
id	proto	state	host	connid	killed	last cmd
2	mysql	query	127.0.0.1:55964	129610	0	select * from @@system.sessions
1	http	net_idle	127.0.0.1:42682	128714	0	
Value
show status ---------------------
Counter	Value
uptime	84918
connections	129610
maxed_out	0
version	6.2.12 dc5144d35@230822 (columnar 2.2.4 5aec342@230822) (secondary 2.2.4 5aec342@230822)
mysql_version	6.2.12 dc5144d35@230822 (columnar 2.2.4 5aec342@230822) (secondary 2.2.4 5aec342@230822)
command_search	4092
command_excerpt	0
command_update	4346849
command_keywords	389
command_persist	0
command_status	3126
command_flushattrs	0
command_sphinxql	0
command_ping	0
command_delete	78
command_set	1
command_insert	1036459
command_replace	52510
command_commit	0
command_suggest	253
command_json	0
command_callpq	0
command_cluster	0
command_getfield	0
agent_connect	0
agent_tfo	0
agent_retry	0
queries	34840
dist_queries	0
workers_total	8
workers_active	3
workers_clients	2
workers_clients_vip	0
work_queue_length	409
load	0.05 0.08 0.08
load_primary	0.00 0.00 0.00
load_secondary	0.00 0.01 0.01
query_wall	348.504
query_cpu	OFF
dist_wall	0.000
dist_local	0.000
dist_wait	0.000
query_reads	OFF
query_readkb	OFF
query_readtime	OFF
avg_query_wall	0.010
avg_query_cpu	OFF
avg_dist_wall	0.000
avg_dist_local	0.000
avg_dist_wait	0.000
avg_query_reads	OFF
avg_query_readkb	OFF
avg_query_readtime	OFF
qcache_max_bytes	16777216
qcache_thresh_msec	3000
qcache_ttl_sec	60
qcache_cached_queries	0
qcache_used_bytes	0
qcache_hits	0
=========================================
52

И время от времени почему-то вот такая ошибка записывается:

Fri 24 Nov 2023 09:06:01 AM MSK
ERROR 1064 (42000) at line 1: P01: syntax error, unexpected $end, expecting '=' near ''show status ---------------------''

UPD
Буквально, через раз с этой ошибкой записывается.

53

Зависло сегодня примерно в 7.15

mysql threads:
https:// disk.yandex.kz/d/umUNNrsuXN5Iwg

logs:
https:// disk.yandex.kz/d/PO_ZxMiluC5jmQ

54

В двух индексах products и products_keywords .ram файлов не было, во всех остальных индексах - 1kb

55

Вот этот запрос завис, судя по show threads:

Tue 28 Nov 2023 06:59:01 AM MSK
...
3362317	work_3	http	net_read	127.0.0.1:46854	612875	904.418126	54m	18368422	15m	No (working)	Mini Mini Mini Query Conn 	2 ch 0: 2 ch 2: api-search query="ddr4" comment="" index="products"

Следующий (conn id на единицу больше) вероятно такой же в query log’е:

/* Tue Nov 28 06:59:00.916 2023 conn 612876 real 0.009 wall 0.010 found 116 */ SELECT 1 FROM products WHERE MATCH('ddr4') AND is_public=3 AND is_available=11 AND price_client_front>=10 LIMIT 1 OPTION max_matches=1;

и ещё один через 3 секунды:

/* Tue Nov 28 06:59:03.756 2023 conn 612878 real 0.006 wall 0.007 found 116 */ SELECT 1 FROM products WHERE MATCH('ddr4') AND is_public=3 AND is_available=11 AND price_client_front>=10 LIMIT 1 OPTION max_matches=1;

По conn 612875 в query log’е ничего не находится.

Можете попробовать в цикле несколько тысяч раз сделать запрос SELECT 1 FROM products WHERE MATCH('ddr4') AND is_public=3 AND is_available=11 AND price_client_front>=10 LIMIT 1 OPTION max_matches=1 ? Может зависнет? Если нет, то попробуйте то же самое с concurrency 5 (легче всего - просто запустив команду одновременно из нескольких окон в терминале).

1 Like
56

Прогнал на 5к запросах в 5 окнах. Вроде не зависло и отработало, но No (working) сообщения встречались:

Tue 28 Nov 2023 09:28:01 AM MSK
Value
show threads -----------
Tid	Name	Proto	State	Host	ConnID	Time	Work time	Jobs done	Last job took	In idle	Chain	Info
3785067	work_0	http	net_read	127.0.0.1:47896	2082	0.000634	55s	370209	34ms	No (working)	Mini Mini Query Conn 	987 ch 0: api-search query="ddr4" comment="" index="products"
3785068	work_1	http	net_read	127.0.0.1:47736	2081	0.012213	58s	376479	17ms	No (working)	Mini Mini Query Conn 	1074 ch 1: api-search query="ddr4" comment="" index="products"
3785069	work_2	http	net_read	127.0.0.1:48076	2085	0.001711	58s	382298	6ms	No (working)	Mini Mini Query Conn 	911 ch 2: api-search query="ddr4" comment="" index="products"
3785070	work_3	http	net_read	127.0.0.1:48024	2083	0.004780	59s	384910	7ms	No (working)	Mini Mini Query Conn 	972 ch 2: api-search query="ddr4" comment="" index="products"
3785071	work_4	http	net_read	127.0.0.1:48030	2084	0.000972	59s	379504	9ms	No (working)	Mini Mini Query Conn 	905 ch 1: api-search query="ddr4" comment="" index="products"
3785072	work_5	http	net_read	127.0.0.1:47896	2082	0.025017	57s	375477	27ms	No (working)	Mini Mini Query Conn 	1 ch 2: api-search query="ddr4" comment="" index="products"
3785073	work_6	mysql	query	127.0.0.1:52568	2087	0.000181	58s	393944	206us	No (working)	Conn 	show threads option format=all
3785074	work_7		-		-1	1557.110529	58s	363356	183us	321us ago		
3785201	TickPool_0		-		-1	1446.260335	2s	0	7us	219us ago	Listen 	tick:  22985  works:  0  state:  in polling
3785075	Timer		-		-1	1557.110603	0us	0	-	-		
Value
@@system.sessions ------------------
id	proto	state	host	connid	killed	last cmd
2	http	net_read	127.0.0.1:47896	2082	0	
3	http	net_read	127.0.0.1:48024	2083	0	
4	http	net_read	127.0.0.1:48030	2084	0	
5	http	net_read	127.0.0.1:48076	2085	0	
6	mysql	net_idle	127.0.0.1:51610	2086	0	show threads option format=all
7	mysql	query	127.0.0.1:52568	2087	0	select * from @@system.sessions
1	http	net_read	127.0.0.1:47736	2081	0	
Value
show status ---------------------
Counter	Value
uptime	1446
connections	2087
maxed_out	0
version	6.2.12 dc5144d35@230822 (columnar 2.2.4 5aec342@230822) (secondary 2.2.4 5aec342@230822)
mysql_version	6.2.12 dc5144d35@230822 (columnar 2.2.4 5aec342@230822) (secondary 2.2.4 5aec342@230822)
command_search	27
command_excerpt	0
command_update	0
command_keywords	0
command_persist	0
command_status	33
command_flushattrs	0
command_sphinxql	0
command_ping	0
command_delete	0
command_set	0
command_insert	0
command_replace	0
command_commit	0
command_suggest	0
command_json	0
command_callpq	0
command_cluster	0
command_getfield	0
agent_connect	0
agent_tfo	0
agent_retry	0
queries	17133
dist_queries	0
workers_total	8
workers_active	8
workers_clients	7
workers_clients_vip	0
work_queue_length	419
load	1.75 0.57 0.25
load_primary	0.00 0.00 0.00
load_secondary	0.00 0.03 0.02
query_wall	175.027
query_cpu	OFF
dist_wall	0.000
dist_local	0.000
dist_wait	0.000
query_reads	OFF
query_readkb	OFF
query_readtime	OFF
avg_query_wall	0.010
avg_query_cpu	OFF
avg_dist_wall	0.000
avg_dist_local	0.000
avg_dist_wait	0.000
avg_query_reads	OFF
avg_query_readkb	OFF
avg_query_readtime	OFF
qcache_max_bytes	16777216
qcache_thresh_msec	3000
qcache_ttl_sec	60
qcache_cached_queries	0
qcache_used_bytes	0
qcache_hits	0
=========================================
Tue 28 Nov 2023 09:29:01 AM MSK
Value
show threads -----------
Tid	Name	Proto	State	Host	ConnID	Time	Work time	Jobs done	Last job took	In idle	Chain	Info
3785067	work_0	mysql	query	127.0.0.1:55998	2088	0.000126	1m	371794	160us	No (working)	Conn 	show threads option format=all
3785068	work_1		-		-1	1617.589984	1m	377958	45us	5ms ago		
3785069	work_2		-		-1	1617.589899	1m	383935	22us	11ms ago		
3785070	work_3		-		-1	1617.589770	1m	386407	119us	3ms ago		
3785071	work_4		-		-1	1617.589805	1m	381137	22us	67ms ago		
3785072	work_5		-		-1	1617.589734	1m	377112	21us	39ms ago		
3785073	work_6		-		-1	1617.587673	1m	395599	115us	467us ago		
3785074	work_7		-		-1	1617.589164	1m	364908	42us	6ms ago		
3785201	TickPool_0		-		-1	1506.738968	5s	0	11us	188us ago	Listen 	tick:  35630  works:  0  state:  in polling
3785075	Timer		-		-1	1617.589234	0us	0	-	-		
Value
@@system.sessions ------------------
id	proto	state	host	connid	killed	last cmd
2	mysql	query	127.0.0.1:55998	2088	0	select * from @@system.sessions
1	mysql	net_idle	127.0.0.1:51610	2086	0	show threads option format=all
Value
show status ---------------------
Counter	Value
uptime	1506
connections	2088
maxed_out	0
version	6.2.12 dc5144d35@230822 (columnar 2.2.4 5aec342@230822) (secondary 2.2.4 5aec342@230822)
mysql_version	6.2.12 dc5144d35@230822 (columnar 2.2.4 5aec342@230822) (secondary 2.2.4 5aec342@230822)
command_search	28
command_excerpt	0
command_update	0
command_keywords	0
command_persist	0
command_status	34
command_flushattrs	0
command_sphinxql	0
command_ping	0
command_delete	0
command_set	0
command_insert	0
command_replace	0
command_commit	0
command_suggest	0
command_json	0
command_callpq	0
command_cluster	0
command_getfield	0
agent_connect	0
agent_tfo	0
agent_retry	0
queries	32591
dist_queries	0
workers_total	8
workers_active	3
workers_clients	2
workers_clients_vip	0
work_queue_length	409
load	2.77 1.15 0.48
load_primary	0.05 0.02 0.01
load_secondary	0.14 0.07 0.04
query_wall	369.167
query_cpu	OFF
dist_wall	0.000
dist_local	0.000
dist_wait	0.000
query_reads	OFF
query_readkb	OFF
query_readtime	OFF
avg_query_wall	0.011
avg_query_cpu	OFF
avg_dist_wall	0.000
avg_dist_local	0.000
avg_dist_wait	0.000
avg_query_reads	OFF
avg_query_readkb	OFF
avg_query_readtime	OFF
qcache_max_bytes	16777216
qcache_thresh_msec	3000
qcache_ttl_sec	60
qcache_cached_queries	0
qcache_used_bytes	0
qcache_hits	0
=========================================
57

Понаблюдал, всегда зависает именно на каком-то запросе, причем зависший запрос каждый раз разный.

=========================================
Thu 30 Nov 2023 06:44:01 AM MSK
Value
show threads -----------
Tid	Name	Proto	State	Host	ConnID	Time	Work time	Jobs done	Last job took	In idle	Chain	Info
3921748	work_0		-		-1	47167.908832	5m	2224059	38us	26ms ago		
3921749	work_1		-		-1	47167.908739	5m	2236102	171us	521us ago		
3921750	work_2		-		-1	47167.908682	5m	2230535	390us	3ms ago		
3921751	work_3	http	net_read	127.0.0.1:37998	65591	512.166431	5m	2221334	9m	No (working)	Mini Mini Mini Query Conn 	1 ch 0: 1 ch 1: api-search query="{"bool":{"must":[{"match_phrase":{"_all":"tp"}},{"equals":{"area_id":3}},{"equals":{"is_public":3}},{"in":{"is_available":[11]}},{"range":{"price_client_front":{"gte":10}}}]}}" comment="" index="products"
3921752	work_4		-		-1	47167.908581	5m	2228164	48us	55ms ago		
3921753	work_5		-		-1	47167.908520	5m	2236098	243us	6ms ago		
3921754	work_6		-		-1	47167.908490	5m	2228185	168us	6ms ago		
3921755	work_7	mysql	query	127.0.0.1:43174	65648	0.000206	5m	2221042	338us	No (working)	Conn 	show threads option format=all
3922217	TickPool_0		-		-1	46989.631354	2m	0	17us	369us ago	Listen 	tick:  4290953  works:  0  state:  in polling
3921756	Timer		-		-1	47167.907182	0us	0	-	-

С чем может быть связано это?

58

Переустановка мантикоры может помочь?

А как можно находить и убивать зависший запрос по id? Полагаю, что это должно решать проблему зависания демона?

59

С чем может быть связано это?

Баг. Как раз позавчера один зависон пофиксили - fixed hit sorting in quorum · manticoresoftware/manticoresearch@8496317 · GitHub

, но это не ваш случай похоже.

Переустановка мантикоры может помочь?

Нет. Баг надо фиксить, если он повторяется на dev версии, т.е. ещё не пофикшен. Для этого его нужно или как-то повторить или, когда зависнет, проделать эти манипуляции.

Это вы уже делали, но не на dev, насколько я помню. Обсудим с командой на звонке сегодня тот backtrace, который там получился в gdb, но вообще желательно повторить в dev, т.к. мы фиксили с релиза и крэши и зависания.

60

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

61

Думаете все таки поставить на прод dev версию? В принципе, учитывая, что все равно раз в 1-2 дня зависает, наверное можно пойти на такой эксперимент.

62

Думаете все таки поставить на прод dev версию? В принципе, учитывая, что все равно раз в 1-2 дня зависает, наверное можно пойти на такой эксперимент.

Ну да, с учётом этого пожалуй можно. Но мы обсудили - попробуйте ещё indextool --check’ом проверить таблицы, может они побитые по какой-то причине.

63

Вроде бы все таблицы по которым были зависания прошли проверку.

Manticore 6.2.12 dc5144d35@230822 (columnar 2.2.4 5aec342@230822) (secondary 2.2.4 5aec342@230822)
Copyright (c) 2001-2016, Andrew Aksyonoff
Copyright (c) 2008-2016, Sphinx Technologies Inc (http://sphinxsearch.com)
Copyright (c) 2017-2023, Manticore Software LTD (https://manticoresearch.com)

using config file '/etc/manticoresearch/manticore.conf'...
checking table 'products'...
WARNING: failed to load RAM chunks, checking only 4 disk chunks
checking schema...
checking disk chunk, extension 0, 0(4)...
checking schema...
checking dictionary...
checking data...
checking rows...
checking attribute blocks index...
checking kill-list...
checking docstore...
checking dead row map...
checking doc-id lookup...
check passed, 1.4 sec elapsed
checking disk chunk, extension 1, 1(4)...
checking schema...
checking dictionary...
checking data...
checking rows...
checking attribute blocks index...
checking kill-list...
checking docstore...
checking dead row map...
checking doc-id lookup...
check passed, 6.4 sec elapsed
checking disk chunk, extension 2, 2(4)...
checking schema...
checking dictionary...
checking data...
checking rows...
checking attribute blocks index...
checking kill-list...
checking docstore...
checking dead row map...
checking doc-id lookup...
check passed, 11.6 sec elapsed
checking disk chunk, extension 3, 3(4)...
checking schema...
checking dictionary...
checking data...
checking rows...
checking attribute blocks index...
checking kill-list...
checking docstore...
checking dead row map...
checking doc-id lookup...
check passed, 13.6 sec elapsed
check passed, 13.6 sec elapsed
64

ОК. Ну тогда да, желательно в dev повторить и ещё раз собрать SHOW THREADS и gdb output при зависании.

1 Like