FATAL: out of memory (unable to allocate 9007199254740992 bytes)

dds · June 17, 2021, 8:57pm

Приветствую!

Версия Мантикоры 3.6.0. Запись русского текста (размер записей от 2 до 500 КБ, общим объёмом менее 500 МБ) приводит к раздуванию searchd.exe на несколько десятков гигабайт (на 32 ГБ ОЗУ и с уходом в подкачку), после чего обычно Мантикора либо начинает тормозить, либо подвисает, либо не даёт подключаться - по разному, но начинается всегда с взрывного захвата всей памяти и строчки в логе

FATAL: out of memory (unable to allocate 9007199254740992 bytes)

при этом число байт как правило это или ещё бывает 137438953472.
При попытке остановить сервис после этого - Мантикора обычно крашится и создаёт минидамп, а иногда не стопится и приходится её убивать.

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

Посмотрел похожий тред

github.com/manticoresoftware/manticoresearch

FATAL: out of memory

opened 03:03AM - 24 Jun 20 UTC

closed 09:23AM - 02 Jul 20 UTC

donbing007

bug waiting for reply

searchd.log ```text [Mon Jun 22 04:01:55.689 2020] [16886] rt: index o…qsindex: ramchunk saved ok (mode=periodic, last TID=0, current TID=2, ram=0.000 Mb, time delta=349199 sec, took=0.001 sec) [Mon Jun 22 05:01:56.104 2020] [16772] rt: index oqsindex: ramchunk saved ok (mode=periodic, last TID=2, current TID=2424032, ram=627.925 Mb, time delta=3600 sec, took=0.415 sec) [Mon Jun 22 06:01:56.773 2020] [16886] rt: index oqsindex: ramchunk saved ok (mode=periodic, last TID=2423898, current TID=3551945, ram=927.200 Mb, time delta=3600 sec, took=0.670 sec) [Mon Jun 22 07:01:57.586 2020] [16772] rt: index oqsindex: ramchunk saved ok (mode=periodic, last TID=3551814, current TID=4333815, ram=1151.926 Mb, time delta=3600 sec, took=0.812 sec) [Mon Jun 22 08:01:58.555 2020] [16886] rt: index oqsindex: ramchunk saved ok (mode=periodic, last TID=4333657, current TID=4952732, ram=1311.447 Mb, time delta=3600 sec, took=0.969 sec) [Mon Jun 22 09:01:59.609 2020] [16772] rt: index oqsindex: ramchunk saved ok (mode=periodic, last TID=4952577, current TID=5486547, ram=1449.168 Mb, time delta=3601 sec, took=1.054 sec) [Mon Jun 22 10:02:00.746 2020] [16772] rt: index oqsindex: ramchunk saved ok (mode=periodic, last TID=5486403, current TID=5948923, ram=1568.645 Mb, time delta=3601 sec, took=1.136 sec) [Mon Jun 22 11:02:02.013 2020] [16886] rt: index oqsindex: ramchunk saved ok (mode=periodic, last TID=5948789, current TID=6362815, ram=1673.831 Mb, time delta=3601 sec, took=1.266 sec) [Mon Jun 22 12:02:03.372 2020] [16886] rt: index oqsindex: ramchunk saved ok (mode=periodic, last TID=6362688, current TID=6749865, ram=1772.204 Mb, time delta=3601 sec, took=1.359 sec) [Mon Jun 22 13:02:05.226 2020] [16772] rt: index oqsindex: ramchunk saved ok (mode=periodic, last TID=6749735, current TID=7118537, ram=1867.750 Mb, time delta=3601 sec, took=1.852 sec) [Mon Jun 22 14:02:07.234 2020] [16886] rt: index oqsindex: ramchunk saved ok (mode=periodic, last TID=7118402, current TID=7441795, ram=1954.620 Mb, time delta=3602 sec, took=2.008 sec) [Mon Jun 22 15:02:09.303 2020] [16772] rt: index oqsindex: ramchunk saved ok (mode=periodic, last TID=7441621, current TID=7774026, ram=2044.575 Mb, time delta=3602 sec, took=2.069 sec) [Mon Jun 22 15:53:50.059 2020] [16775] FATAL: out of memory (unable to allocate 12884901896 bytes) ------- FATAL: CRASH DUMP ------- [Mon Jun 22 15:53:49.974 2020] [16770] --- crashed SphinxQL request dump --- insert into oqsindex (id,entity,pref,cref,attributes,f0,f1,f2,f3,f4) values(1275155045561663488, 100, 0, 0, '{"f0":"6jcayjy4e2", "f1":"5", "f2":205140491395081850, "f3":"393b4ykfkfnm40ryh641x3lnchm34m", "f4":1592855628754}','6jcayjy4e2','5','205140491395081850','393b4ykfkfnm40ryh641x3lnchm34m', '1592855628754') --- request dump end --- --- local index: Manticore 3.4.2 6903305@200410 release Handling signal 11 -------------- backtrace begins here --------------- Program compiled with 4.8.5 Configured with flags: Configured by CMake with these definitions: -DCMAKE_BUILD_TYPE=RelWithDebInfo -DDISTR_BUILD=rhel7 -DUSE_SSL=ON -DDL_UNIXODBC=1 -DUNIXODBC_LIB=libodbc.so.2 -DDL_EXPAT=1 -DEXPAT_LIB=libexpat.so.1 -DUSE_LIBICONV=1 -DDL_MYSQL=1 -DMYSQL_LIB=libmysqlclient.so.18 -DDL_PGSQL=1 -DPGSQL_LIB=libpq.so.5 -DLOCALDATADIR=/var/data -DFULL_SHARE_DIR=/usr/share/manticore -DUSE_ICU=1 -DUSE_BISON=ON -DUSE_FLEX=ON -DUSE_SYSLOG=1 -DWITH_EXPAT=1 -DWITH_ICONV=ON -DWITH_MYSQL=1 -DWITH_ODBC=ON -DWITH_PGSQL=1 -DWITH_RE2=1 -DWITH_STEMMER=1 -DWITH_ZLIB=ON -DGALERA_SOVERSION=31 -DSYSCONFDIR=/etc/manticoresearch Host OS is Linux runner-ed2dce3a-project-3858465-concurrent-0 4.19.78-coreos #1 SMP Mon Oct 14 22:56:39 -00 2019 x86_64 x86_64 x86_64 GNU/Linux Stack bottom = 0x7f4831daad7f, thread stack size = 0x100000 Trying manual backtrace: Frame pointer is null, manual backtrace failed (did you build with -fomit-frame-pointer?) Trying system backtrace: begin of system symbols: /usr/bin/searchd(_Z12sphBacktraceib 0x90)[0x710e50] /usr/bin/searchd(_ZN16SphCrashLogger_c11HandleCrashEi 0x1fe)[0x58409e] /lib64/libpthread.so.0( 0xf5f0)[0x7f4834ee45f0] /lib64/libpthread.so.0(pthread_rwlock_wrlock 0xb)[0x7f4834ee032b] /usr/bin/searchd(_ZN10CSphRwlock9WriteLockEv 0x49)[0x715719] /usr/bin/searchd(_ZN7Threads9ThdDesc_t16RemoveFromGlobalEv 0xe)[0x9019de] /usr/bin/searchd(_ZN10ThdJobQL_t4CallEv 0x2ae)[0x65afde] /usr/bin/searchd(_ZN11CSphThdPool4TickEPv 0xa0)[0x719270] /usr/bin/searchd(_Z20sphThreadProcWrapperPv 0x23)[0x7149d3] /lib64/libpthread.so.0( 0x7e65)[0x7f4834edce65] /lib64/libc.so.6(clone 0x6d)[0x7f48336f388d] -------------- backtrace ends here --------------- Please, create a bug report in our bug tracker (https://github.com/manticoresoftware/manticore/issues) and attach there: a) searchd log, b) searchd binary, c) searchd symbols. Look into the chapter 'Reporting bugs' in the documentation (http://docs.manticoresearch.com/latest/html/reporting_bugs.html) [Mon Jun 22 15:53:54.145 2020] [19248] listening on all interfaces, port=9312 [Mon Jun 22 15:53:54.145 2020] [19248] listening on all interfaces, port=9306 [Mon Jun 22 15:53:54.145 2020] [19248] listening on all interfaces, port=9308 [Mon Jun 22 16:07:14.183 2020] [19248] WARNING: 'binlog_max_log_size = 2147483648' clamped to 2147483647(INT_MAX) [Mon Jun 22 16:07:14.190 2020] [19248] WARNING: Relocking oqsindex [Mon Jun 22 16:07:14.191 2020] [19248] binlog: replaying log /var/lib/manticore/binlog.002 [Mon Jun 22 16:55:10.792 2020] [19248] FATAL: out of memory (unable to allocate 12884901896 bytes) [Mon Jun 22 16:55:14.871 2020] [19290] listening on all interfaces, port=9312 [Mon Jun 22 16:55:14.871 2020] [19290] listening on all interfaces, port=9306 [Mon Jun 22 16:55:14.871 2020] [19290] listening on all interfaces, port=9308 [Mon Jun 22 17:08:35.349 2020] [19290] WARNING: 'binlog_max_log_size = 2147483648' clamped to 2147483647(INT_MAX) [Mon Jun 22 17:08:35.358 2020] [19290] WARNING: Relocking oqsindex [Mon Jun 22 17:08:35.358 2020] [19290] binlog: replaying log /var/lib/manticore/binlog.002 [Mon Jun 22 17:56:37.506 2020] [19290] FATAL: out of memory (unable to allocate 12884901896 bytes) [Mon Jun 22 17:56:41.623 2020] [19328] listening on all interfaces, port=9312 [Mon Jun 22 17:56:41.623 2020] [19328] listening on all interfaces, port=9306 [Mon Jun 22 17:56:41.623 2020] [19328] listening on all interfaces, port=9308 [Mon Jun 22 18:09:58.562 2020] [19328] WARNING: 'binlog_max_log_size = 2147483648' clamped to 2147483647(INT_MAX) [Mon Jun 22 18:09:58.571 2020] [19328] WARNING: Relocking oqsindex [Mon Jun 22 18:09:58.571 2020] [19328] binlog: replaying log /var/lib/manticore/binlog.002 [Mon Jun 22 18:58:00.149 2020] [19328] FATAL: out of memory (unable to allocate 12884901896 bytes) [Mon Jun 22 18:58:04.120 2020] [19368] listening on all interfaces, port=9312 [Mon Jun 22 18:58:04.121 2020] [19368] listening on all interfaces, port=9306 [Mon Jun 22 18:58:04.121 2020] [19368] listening on all interfaces, port=9308 [Mon Jun 22 19:11:21.195 2020] [19368] WARNING: 'binlog_max_log_size = 2147483648' clamped to 2147483647(INT_MAX) [Mon Jun 22 19:11:21.203 2020] [19368] WARNING: Relocking oqsindex [Mon Jun 22 19:11:21.203 2020] [19368] binlog: replaying log /var/lib/manticore/binlog.002 [Mon Jun 22 19:59:09.432 2020] [19368] FATAL: out of memory (unable to allocate 12884901896 bytes) [Mon Jun 22 19:59:13.376 2020] [19407] listening on all interfaces, port=9312 [Mon Jun 22 19:59:13.376 2020] [19407] listening on all interfaces, port=9306 [Mon Jun 22 19:59:13.376 2020] [19407] listening on all interfaces, port=9308 [Mon Jun 22 20:12:29.593 2020] [19407] WARNING: 'binlog_max_log_size = 2147483648' clamped to 2147483647(INT_MAX) [Mon Jun 22 20:12:29.596 2020] [19407] WARNING: Relocking oqsindex [Mon Jun 22 20:12:29.596 2020] [19407] binlog: replaying log /var/lib/manticore/binlog.002 [Mon Jun 22 21:00:01.928 2020] [19407] FATAL: out of memory (unable to allocate 12884901896 bytes) [Mon Jun 22 21:00:05.878 2020] [19446] listening on all interfaces, port=9312 [Mon Jun 22 21:00:05.878 2020] [19446] listening on all interfaces, port=9306 [Mon Jun 22 21:00:05.878 2020] [19446] listening on all interfaces, port=9308 [Mon Jun 22 21:13:21.836 2020] [19446] WARNING: 'binlog_max_log_size = 2147483648' clamped to 2147483647(INT_MAX) [Mon Jun 22 21:13:21.843 2020] [19446] WARNING: Relocking oqsindex [Mon Jun 22 21:13:21.844 2020] [19446] binlog: replaying log /var/lib/manticore/binlog.002 [Mon Jun 22 21:46:29.280 2020] [19503] listening on all interfaces, port=9312 [Mon Jun 22 21:46:29.280 2020] [19503] listening on all interfaces, port=9306 [Mon Jun 22 21:46:29.280 2020] [19503] listening on all interfaces, port=9308 [Mon Jun 22 21:46:29.282 2020] [19503] WARNING: index 'oqsindex': prealloc: failed to lock /var/lib/manticore/oqsindex.lock: Resource temporarily unavailable; NOT SERVING [Mon Jun 22 21:46:29.282 2020] [19503] WARNING: index 'oqsindex': prealloc: failed to lock /var/lib/manticore/oqsindex.lock: Resource temporarily unavailable - NOT SERVING [Mon Jun 22 21:46:29.289 2020] [19503] WARNING: 'binlog_max_log_size = 2147483648' clamped to 2147483647(INT_MAX) [Mon Jun 22 21:46:29.294 2020] [19503] binlog: replaying log /var/lib/manticore/binlog.002 [Mon Jun 22 21:46:29.295 2020] [19503] FATAL: binlog: log open error: failed to open /var/lib/manticore/binlog.002: No such file or directory [Mon Jun 22 21:47:19.209 2020] [19536] listening on all interfaces, port=9312 [Mon Jun 22 21:47:19.209 2020] [19536] listening on all interfaces, port=9306 [Mon Jun 22 21:47:19.209 2020] [19536] listening on all interfaces, port=9308 [Mon Jun 22 21:53:02.010 2020] [19575] listening on all interfaces, port=9312 [Mon Jun 22 21:53:02.010 2020] [19575] listening on all interfaces, port=9306 [Mon Jun 22 21:53:02.010 2020] [19575] listening on all interfaces, port=9308 [Mon Jun 22 22:06:07.048 2020] [19575] WARNING: 'binlog_max_log_size = 2147483648' clamped to 2147483647(INT_MAX) [Mon Jun 22 22:06:07.048 2020] [19575] WARNING: Relocking oqsindex [Mon Jun 22 22:06:07.072 2020] [19596] prereading 1 indexes [Mon Jun 22 22:06:07.072 2020] [19575] accepting connections [Mon Jun 22 22:06:07.072 2020] [19596] prereaded 1 indexes in 0.000 sec [Mon Jun 22 22:54:58.094 2020] [19575] caught SIGTERM, shutting down [Mon Jun 22 22:54:59.318 2020] [19575] WARNING: binlog: failed to unlink /var/lib/manticore/binlog.001: No such file or directory (remove it manually) [Mon Jun 22 22:54:59.318 2020] [19575] rt: index oqsindex: ramchunk saved in 1.173 sec [Mon Jun 22 22:54:59.357 2020] [19575] shutdown complete [Mon Jun 22 22:55:30.379 2020] [19659] listening on all interfaces, port=9312 [Mon Jun 22 22:55:30.379 2020] [19659] listening on all interfaces, port=9306 [Mon Jun 22 22:55:30.379 2020] [19659] listening on all interfaces, port=9308 [Mon Jun 22 22:55:30.385 2020] [19659] WARNING: Relocking oqsindex [Mon Jun 22 22:55:30.385 2020] [19661] prereading 1 indexes [Mon Jun 22 22:55:30.385 2020] [19661] prereaded 1 indexes in 0.000 sec [Mon Jun 22 22:55:30.385 2020] [19659] accepting connections [Mon Jun 22 23:55:30.914 2020] [19661] rt: index oqsindex: ramchunk saved ok (mode=periodic, last TID=0, current TID=2823833, ram=720.506 Mb, time delta=3600 sec, took=0.532 sec) [Tue Jun 23 00:55:31.722 2020] [19661] rt: index oqsindex: ramchunk saved ok (mode=periodic, last TID=2823640, current TID=3742801, ram=982.462 Mb, time delta=3600 sec, took=0.808 sec) [Tue Jun 23 01:55:32.626 2020] [19661] rt: index oqsindex: ramchunk saved ok (mode=periodic, last TID=3742654, current TID=4435108, ram=1179.065 Mb, time delta=3600 sec, took=0.904 sec) [Tue Jun 23 02:55:33.557 2020] [19661] rt: index oqsindex: ramchunk saved ok (mode=periodic, last TID=4434964, current TID=4980889, ram=1319.182 Mb, time delta=3600 sec, took=0.930 sec) [Tue Jun 23 03:55:34.604 2020] [19661] rt: index oqsindex: ramchunk saved ok (mode=periodic, last TID=4980754, current TID=5467998, ram=1444.892 Mb, time delta=3601 sec, took=1.047 sec) [Tue Jun 23 04:55:35.957 2020] [19661] rt: index oqsindex: ramchunk saved ok (mode=periodic, last TID=5467874, current TID=5899161, ram=1554.157 Mb, time delta=3601 sec, took=1.352 sec) [Tue Jun 23 05:55:37.192 2020] [19684] rt: index oqsindex: ramchunk saved ok (mode=periodic, last TID=5899016, current TID=6286331, ram=1654.277 Mb, time delta=3601 sec, took=1.234 sec) [Tue Jun 23 06:55:38.445 2020] [19661] rt: index oqsindex: ramchunk saved ok (mode=periodic, last TID=6286331, current TID=6659405, ram=1749.642 Mb, time delta=3601 sec, took=1.253 sec) [Tue Jun 23 07:55:39.781 2020] [19684] rt: index oqsindex: ramchunk saved ok (mode=periodic, last TID=6659295, current TID=7022604, ram=1842.092 Mb, time delta=3601 sec, took=1.335 sec) [Tue Jun 23 08:55:41.284 2020] [19661] rt: index oqsindex: ramchunk saved ok (mode=periodic, last TID=7022492, current TID=7357589, ram=1932.114 Mb, time delta=3601 sec, took=1.503 sec) [Tue Jun 23 09:55:43.130 2020] [19684] rt: index oqsindex: ramchunk saved ok (mode=periodic, last TID=7357458, current TID=7684790, ram=2020.972 Mb, time delta=3601 sec, took=1.845 sec) [Tue Jun 23 10:55:45.563 2020] [19661] rt: index oqsindex: ramchunk saved ok (mode=periodic, last TID=7684633, current TID=7901480, ram=2111.363 Mb, time delta=3602 sec, took=2.433 sec) [Tue Jun 23 10:57:27.974 2020] [19662] FATAL: out of memory (unable to allocate 12884901896 bytes) [Tue Jun 23 10:57:31.873 2020] [19918] listening on all interfaces, port=9312 [Tue Jun 23 10:57:31.874 2020] [19918] listening on all interfaces, port=9306 [Tue Jun 23 10:57:31.874 2020] [19918] listening on all interfaces, port=9308 [Tue Jun 23 11:11:53.338 2020] [19918] WARNING: Relocking oqsindex [Tue Jun 23 11:11:53.339 2020] [19918] binlog: replaying log /var/lib/manticore/binlog.002 ``` CPU 100%, Unable to respond to close request. ```text Tasks: 178 total, 3 running, 175 sleeping, 0 stopped, 0 zombie %Cpu(s): 25.0 us, 0.1 sy, 0.0 ni, 74.9 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st KiB Mem : 16266540 total, 7691940 free, 4958328 used, 3616272 buff/cache KiB Swap: 4194300 total, 4193780 free, 520 used. 10933312 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME COMMAND 19918 mantico 20 0 4928864 4.5g 1536 R 100.0 28.8 719:50.81 searchd 1283 root 20 0 305180 4400 3024 S 0.3 0.0 233:51.83 vmtoolsd 1 root 20 0 193628 5428 2860 S 0.0 0.0 1:49.19 systemd ``` manticore.conf ```text searchd { listen = 9312 listen = 9306:mysql41 listen = 9308:http log = /var/log/manticore/searchd.log query_log = /var/log/manticore/query.log pid_file = /var/run/manticore/searchd.pid data_dir = /var/lib/manticore binlog_path = /var/lib/manticore binlog_flush = 0 binlog_max_log_size = 256M query_log_format = sphinxql client_timeout = 15m max_children = 6 max_open_files = max rt_flush_period = 3600 rt_merge_iops = 0 rt_merge_maxiosize = 0 shutdown_timeout = 30m sphinxql_timeout = 15m unlink_old = 1 watchdog = 0 workers = thread_pool preopen_indexes = 1 mysql_version_string = 5.0.37 qcache_ttl_sec = 1s qcache_thresh_msec = 0 qcache_max_bytes = 16m } index oqsindex { path = /var/lib/manticore/oqsindex html_strip = 1 index_zones = F* min_infix_len = 3 ngram_chars = U 3000..U 2FA1F ngram_len = 1 rt_attr_bigint = entity rt_attr_bigint = pref rt_attr_bigint = cref rt_attr_json = attributes rt_field = f0 rt_field = f1 rt_field = f2 rt_field = f3 rt_field = f4 rt_field = f5 rt_field = f6 rt_mem_limit = 2048m type = rt } ``` I thought that the binlog setting was too large, but I still reported "FATAL: out of memory (unable to allocate 12884901896 bytes)" after adjusting to 256M. The --stopwait parameter deletes the pid file after execution, but the searchd process still exists, so I directly kill -9 to terminate the searchd process. ```text [root@localhost manticore]# free -h total used free shared buff/cache available Mem: 15G 256M 11G 56M 3.5G 14G Swap: 4.0G 520K 4.0G ``` data ```text [root@localhost manticore]# ls -lh total 3.3G -rw-------. 1 manticore manticore 212M Jun 23 10:57 binlog.002 -rw-------. 1 manticore manticore 0 Jun 23 11:11 binlog.lock -rw-------. 1 manticore manticore 11 Jun 23 08:55 binlog.meta -rw-------. 1 manticore manticore 307M Jun 23 11:11 oqsindex.0.spa -rw-------. 1 manticore manticore 664M Jun 23 11:11 oqsindex.0.spb -rw-------. 1 manticore manticore 84M Jun 24 01:35 oqsindex.0.spd -rw-------. 1 manticore manticore 256K Jun 23 11:55 oqsindex.0.spe -rw-------. 1 manticore manticore 4.3K Jun 23 11:11 oqsindex.0.sphi -rw-------. 1 manticore manticore 104M Jun 24 01:38 oqsindex.0.spi -rw-------. 1 manticore manticore 0 Jun 23 11:11 oqsindex.0.spp -rw-------. 1 manticore manticore 56M Jun 23 11:11 oqsindex.0.spt -rw-------. 1 manticore manticore 0 Jun 24 01:38 oqsindex.lock -rw-------. 1 manticore manticore 506 Jun 23 10:55 oqsindex.meta -rw-------. 1 manticore manticore 1.9G Jun 23 10:55 oqsindex.ram ``` restart searchd log. ```text [root@localhost manticore]# /usr/bin/searchd --config /etc/manticoresearch/manticore.conf --console --logdebugvv Manticore 3.4.2 6903305@200410 release Copyright (c) 2001-2016, Andrew Aksyonoff Copyright (c) 2008-2016, Sphinx Technologies Inc (http://sphinxsearch.com) Copyright (c) 2017-2020, Manticore Software LTD (http://manticoresearch.com) using config file '/etc/manticoresearch/manticore.conf' (1414 chars)... WARNING: 'data_dir' cannot be mixed with index declarations in '/etc/manticoresearch/manticore.conf' DEBUG: 'read_unhinted' - nothing specified, using default value 32768 DEBUG: 'read_buffer' - nothing specified, using default value 262144 DEBUG: 'read_buffer_docs' - nothing specified, using default value 262144 DEBUG: 'read_buffer_hits' - nothing specified, using default value 262144 DEBUG: 'attr_flush_period' - nothing specified, using default value 0 DEBUG: 'max_packet_size' - nothing specified, using default value 8388608 DEBUG: 'ha_ping_interval' - nothing specified, using default value 1000000 DEBUG: 'ha_period_karma' - nothing specified, using default value 60000000 DEBUG: 'query_log_min_msec' - nothing specified, using default value 0 DEBUG: 'agent_connect_timeout' - nothing specified, using default value 1000000 DEBUG: 'agent_query_timeout' - nothing specified, using default value 3000000 DEBUG: 'agent_retry_delay' - nothing specified, using default value 500000 DEBUG: 'docstore_cache_size' - nothing specified, using default value 16777216 Set max_open_files to 4096 (previous was 1024), hardlimit is 4096. listening on all interfaces, port=9312 listening on all interfaces, port=9306 listening on all interfaces, port=9308 DEBUG: 'embedded_limit' - nothing specified, using default value 16384 DEBUG: 'attr_update_reserve' - nothing specified, using default value 131072 DEBUG: 'docstore_block_size' - nothing specified, using default value 16384 DEBUG: WriteLock 0x1e20820 wait DEBUG: WriteLock 0x1e20820 precaching index 'oqsindex' DEBUG: Unlock 0x1e20820 DEBUG: ReadLock 0x1e20820 DEBUG: last message repeated 1 times DEBUG: Unlock 0x1e20820 precached 1 indexes in 873.708 sec DEBUG: last message repeated 1 times DEBUG: uid-short server_id 0, started 100000, seed 1677721600000 DEBUG: ReadLock 0x1e20820 searchd DEBUG: Unlock 0x1e20820 binlog: replaying log /var/lib/manticore/binlog.002 DEBUG: ReadLock 0x1e20820 DEBUG: Unlock 0x1e20820 ``` precached 1 indexes in 873.708 sec is this normal? binlog: replaying log /var/lib/manticore/binlog.004 For a long time, there has been no response. I stopped. Is my configuration unreasonable?

но таких параметров, которые вызывали проблему там - у меня в конфиге нет, также видел похожий тред
https://forum2.manticoresearch.com/t/fatal-out-of-memory/540
и по реккомендации оттуда сделал запись лога с --logdebug

Лог:

[Thu Jun 17 22:01:42.484 2021] [1588] DEBUG: StartGlobalWorkpool
[Thu Jun 17 22:01:42.487 2021] [1588] starting daemon version '3.6.0 96d61d8bf@210504 release' ...
[Thu Jun 17 22:01:42.488 2021] [1588] listening on 127.0.0.1:9312 for sphinx and http(s)
[Thu Jun 17 22:01:42.489 2021] [1588] listening on all interfaces for mysql, port=9306
[Thu Jun 17 22:01:42.491 2021] [1588] listening on 127.0.0.1:9308 for sphinx and http(s)
[Thu Jun 17 22:01:42.492 2021] [1588] DEBUG: 'rt_flush_period' - nothing specified, using default value 36000000000
[Thu Jun 17 22:01:42.494 2021] [6100] DEBUG: 'embedded_limit' - nothing specified, using default value 16384
[Thu Jun 17 22:01:42.494 2021] [6100] DEBUG: 'attr_update_reserve' - nothing specified, using default value 131072
[Thu Jun 17 22:01:42.496 2021] [6100] DEBUG: 'docstore_block_size' - nothing specified, using default value 16384
[Thu Jun 17 22:01:42.688 2021] [6100] DEBUG: 'embedded_limit' - nothing specified, using default value 16384
[Thu Jun 17 22:01:42.689 2021] [6100] DEBUG: 'attr_update_reserve' - nothing specified, using default value 131072
[Thu Jun 17 22:01:42.689 2021] [6100] DEBUG: 'docstore_block_size' - nothing specified, using default value 16384
[Thu Jun 17 22:01:42.703 2021] [1588] DEBUG: expression stack for creation 0
[Thu Jun 17 22:01:42.706 2021] [1588] DEBUG: expression stack for eval/deletion 80
[Thu Jun 17 22:01:42.740 2021] [1588] DEBUG: filter stack delta 240
[Thu Jun 17 22:01:42.741 2021] [1588] DEBUG: 'binlog_max_log_size' - nothing specified, using default value 268435456
[Thu Jun 17 22:01:42.748 2021] [1588] DEBUG: MAC address 00:25:90:e8:38:7f for uuid-short server_id
[Thu Jun 17 22:01:42.748 2021] [1588] DEBUG: uid-short server_id 26, started 67287702, seed 1874626345296723968
[Thu Jun 17 22:01:42.751 2021] [1588] DEBUG: SaveMeta: Done.
[Thu Jun 17 22:01:42.752 2021] [4472] prereading 2 indexes
[Thu Jun 17 22:01:42.752 2021] [4472] DEBUG: prereading index 'main_index'
[Thu Jun 17 22:01:42.752 2021] [1588] accepting connections
[Thu Jun 17 22:01:42.753 2021] [4472] DEBUG: prereaded index 'main_index' in 0.001 sec
[Thu Jun 17 22:01:42.755 2021] [4472] DEBUG: prereading index 'numeric_index'
[Thu Jun 17 22:01:42.756 2021] [4472] DEBUG: prereaded index 'numeric_index' in 0.001 sec
[Thu Jun 17 22:01:42.756 2021] [4472] prereaded 2 indexes in 0.005 sec
[Thu Jun 17 22:01:51.849 2021] [4216] DEBUG: RemoveEvent()
[Thu Jun 17 22:01:55.855 2021] [1588] DEBUG: last message repeated 30 times
[Thu Jun 17 22:01:59.367 2021] [4216] DEBUG: RemoveEvent()
[Thu Jun 17 22:02:01.400 2021] [1588] DEBUG: last message repeated 10 times
[Thu Jun 17 22:02:12.943 2021] [4216] DEBUG: RemoveEvent()
[Thu Jun 17 22:02:16.917 2021] [1588] DEBUG: last message repeated 29 times
[Thu Jun 17 22:02:38.633 2021] [4216] DEBUG: RemoveEvent()
[Thu Jun 17 22:02:38.634 2021] [2108] DEBUG: AsyncNetInputBuffer_c::AppendData: error 0 (No error) return -1
[Thu Jun 17 22:02:38.634 2021] [4216] DEBUG: RemoveEvent()
[Thu Jun 17 22:02:38.635 2021] [2184] DEBUG: last message repeated 1 times
[Thu Jun 17 22:02:38.635 2021] [5024] DEBUG: last message repeated 1 times
[Thu Jun 17 22:02:38.635 2021] [2184] DEBUG: AsyncNetInputBuffer_c::AppendData: error 0 (No error) return -1
[Thu Jun 17 22:02:38.635 2021] [4216] DEBUG: RemoveEvent()
[Thu Jun 17 22:02:38.635 2021] [5024] DEBUG: AsyncNetInputBuffer_c::AppendData: error 0 (No error) return -1
[Thu Jun 17 22:02:38.637 2021] [4216] DEBUG: RemoveEvent()
[Thu Jun 17 22:02:38.637 2021] [5072] DEBUG: AsyncNetInputBuffer_c::AppendData: error 0 (No error) return -1
[Thu Jun 17 22:02:38.638 2021] [4216] DEBUG: RemoveEvent()
[Thu Jun 17 22:02:38.638 2021] [1188] DEBUG: AsyncNetInputBuffer_c::AppendData: error 0 (No error) return -1
[Thu Jun 17 22:02:38.638 2021] [4216] DEBUG: RemoveEvent()
[Thu Jun 17 22:02:38.638 2021] [4876] DEBUG: AsyncNetInputBuffer_c::AppendData: error 0 (No error) return -1
[Thu Jun 17 22:02:39.707 2021] [1588] DEBUG: last message repeated 1 times
[Thu Jun 17 22:02:40.406 2021] [4876] FATAL: out of memory (unable to allocate 137438953472 bytes)
[Thu Jun 17 22:03:31.101 2021] [1588] caught SIGTERM, shutting down
[Thu Jun 17 22:03:31.186 2021] [1588] DEBUG: StopNetLoop()
[Thu Jun 17 22:03:31.190 2021] [1588] DEBUG: TerminateSessions() (000000081A5AEF20) invoked
[Thu Jun 17 22:03:31.192 2021] [1588] DEBUG: StopNetLoop() succeeded
[Thu Jun 17 22:03:31.200 2021] [1588] DEBUG: ReplicateClustersDelete invoked
[Thu Jun 17 22:03:34.111 2021] [1588] WARNING: still 10 alive tasks during shutdown, after 3.005 sec
[Thu Jun 17 22:03:34.143 2021] [1588] DEBUG: SaveMeta: Done.
[Thu Jun 17 22:03:34.144 2021] [1588] rt: index numeric_index: ramchunk saved in 0.029 sec
------- FATAL: CRASH DUMP -------
[Thu Jun 17 22:03:31.101 2021] [ 2924]
[Thu Jun 17 22:03:34.439 2021] [1588] WARNING: GlobalCrashQueryGetRef: thread-local info is not set! Use ad-hoc

--- crashed invalid query ---

--- request dump end ---
--- local index:
Manticore 3.6.0 96d61d8bf@210504 release
minidump located at:  C:/Manticore/log/searchd.pid.2924.0000000000000000.mdmp
--- active threads ---
--- Totally 0 threads, and 0 client-working threads ---
------- CRASH DUMP END -------

Конфиг:

indexer
{
	mem_limit		= 512M
	lemmatizer_cache 	= 512M
}

common {
    plugin_dir = C:/Manticore/usr/local/manticore/lib
    lemmatizer_base = C:/Manticore/usr/dicts/
}

searchd {
    listen = 127.0.0.1:9312
    listen = 9306:mysql41
    listen = 127.0.0.1:9308:http
    log = C:/Manticore/log/searchd.log
    query_log = C:/Manticore/log/query.log
    binlog_path = C:/Manticore/binlog
    pid_file = C:/Manticore/log/searchd.pid
    query_log_format = sphinxql

	seamless_rotate		= 1
	preopen_indexes		= 1
	unlink_old		= 1
	workers			= threads 
	
	thread_stack 		= 2M 
	
	mysql_version_string 	= 5.0.37

}

index main_index
{
	path                     = C:/Manticore/main_index/main
	rt_mem_limit             = 2048m
	type                     = rt
	morphology               = lemmatize_ru_all, lemmatize_en, lemmatize_de
	charset_table            = non_cjk
	stored_fields 		 = content  
	
	rt_field		= content
	rt_attr_string		= guid
	rt_attr_uint		= rubric_id
	rt_attr_string		= fileName
	rt_attr_uint		= size
	rt_attr_uint		= format
	rt_attr_string		= suffix
	rt_attr_timestamp	= dt_inserted
	rt_attr_string		= identifier
	rt_attr_string		= source
	rt_attr_string		= root
	rt_attr_string		=  sreserve_1
	rt_attr_string      	=  sreserve_2
	rt_attr_string      	=  sreserve_3
	rt_attr_uint		=  ireserve_1
	rt_attr_uint		=  ireserve_2
	rt_attr_uint      	=  ireserve_3
	rt_attr_timestamp	=  dtreserve_1
	rt_attr_timestamp	=  dtreserve_2
	rt_attr_timestamp   	=  dtreserve_3
}

index numeric_index
{
	path                     = C:/Manticore/numeric_index/numeric

	rt_mem_limit             = 2048m
	type                     = rt
	morphology               = none
	charset_table            = non_cjk
	stored_fields 		 = number
	
	rt_field		= number
	
	rt_attr_string		= record_guid
	rt_attr_string		= original_number
	rt_attr_uint		= rubric_id
	rt_attr_string		= fileName
	rt_attr_uint		= size
	rt_attr_uint		= format
	rt_attr_string		= suffix
	rt_attr_timestamp 	= dt_inserted
	rt_attr_string		= identifier
	rt_attr_string		= source
	rt_attr_string		= root
	rt_attr_string		=  sreserve_1
	rt_attr_string      	=  sreserve_2
	rt_attr_string      	=  sreserve_3
	rt_attr_uint		=  ireserve_1
	rt_attr_uint		=  ireserve_2
	rt_attr_uint      	=  ireserve_3
	rt_attr_timestamp	=  dtreserve_1
	rt_attr_timestamp	=  dtreserve_2
	rt_attr_timestamp   	=  dtreserve_3
}

В чём может быть причина?

Sergey · June 18, 2021, 2:11am

общим объёмом менее 500 МБ) приводит к раздуванию searchd.exe на несколько десятков гигабайт

Похоже на мемлик.

FATAL: out of memory (unable to allocate 9007199254740992 bytes)

Похоже на баг, т.к. сильно уж много bytes.

Можете завести issue на гитхабе и предоставить воспроизводимый кейс? Можете заслать на наш ftp - Manticore Search Manual

Кстати, а в линуксе воспроизводится?

dds · November 30, 2021, 12:32pm

Признаюсь я старался создать на основе этих случаев какой-то компактный и легко воспроизводимый тестовый пример, но не преуспел: ошибка носит вероятностный характер и обычно проявляется под нагрузкой, т.е. например на 4х потоках записи, причём обычно при записи поочерёдно в оба индекса, описанных в конфиге исходного поста. При записи в один поток в один индекс - эта ошибка редко даёт о себе знать.

Порой этот же сбой возникает сразу при запуске Мантикоры, когда в индексе и бинлоге уже есть немного данных. Но в ходе тестов с копированием этого индекса и бинлога на разные ПК выяснилось, что воспроизводится сбой примерно на половине из них (более старых и медленных), а на более производительных, и с SSD - не воспроизводится (хотя этот же сбой при загрузке данных возникает на любых ПК).

Это всё на винде, попробовать linux и кластрный вариант Мантикоры пока только в планах. Пока я сделал wachdog и перезапуск Мантикоры при сбоях.

tomat · November 30, 2021, 12:35pm

если у вас есть бинлог и файлы индекса на котором воспроизводится поведение - залейти их к нам вместе с конфигом.

Но бинлог и файлы индекса необходимо архивировать ДО рестарта демона иначе после рестарта - состояния индекса меняется и баг пропадает.

Так же может быть полезным проверить файлы индекса с помощью indextool -c your.conf --check indexname чтобы убедится что оригинальный индекс валидный.

dds · November 30, 2021, 1:44pm

Создал тему на гитхабе FATAL: out of memory (unable to allocate 9007199254740992 bytes) · Issue #667 · manticoresoftware/manticoresearch · GitHub
с вложениями на фтп. Вывод проверки конфига для обоих индексов:

C:\IstokSearch\bin>indextool -c C:\IstokSearch\istok.conf.in --check main_index
Manticore 3.6.0 96d61d8@210504 release
Copyright (c) 2001-2016, Andrew Aksyonoff
Copyright (c) 2008-2016, Sphinx Technologies Inc (http://sphinxsearch.com)
Copyright (c) 2017-2021, Manticore Software LTD (https://manticoresearch.com)

using config file ‘C:\IstokSearch\istok.conf.in’…
WARNING: index main_index: index ‘main_index’: morphology option changed from config has no effect, ignoring
checking index ‘main_index’…
checking schema…
check passed, 0.0 sec elapsed

C:\IstokSearch\bin>indextool -c C:\IstokSearch\istok.conf.in --check numeric_index
Manticore 3.6.0 96d61d8@210504 release
Copyright (c) 2001-2016, Andrew Aksyonoff
Copyright (c) 2008-2016, Sphinx Technologies Inc (http://sphinxsearch.com)
Copyright (c) 2017-2021, Manticore Software LTD (https://manticoresearch.com)

using config file ‘C:\IstokSearch\istok.conf.in’…
checking index ‘numeric_index’…
checking schema…
check passed, 0.0 sec elapsed

dds · May 13, 2022, 6:40am

Проблема решена в новом релизе:

https://repo.manticoresearch.com/repository/manticoresearch_windows/dev/x64/manticore-4.2.1-220422-39e1acfad-releasex64-main.zip

Большое спасибо