Comments (9)
GuyAv46
commented on June 19, 2024
Cancelling background indexing should only happen if the index was altered with FT.ALTER (and in this case we would've seen Scanning index %s in background: cancelled and restarted), or because the index was dropped before the scan was complete.
Can you confirm this is not the case for you? Loading index from AOF file may yield this log if an index is both created and deleted in the AOF
from redisearch.
Czechh
commented on June 19, 2024
We don't drop indexes. But it's really imposible to tell if that happened or not.
We went through the whole aof file and didn't find any evidence of drops. But the file is just a segment. Is there another way to ensure that that command didn't happen?
Thank for the response. @GuyAv46
from redisearch.
GuyAv46
commented on June 19, 2024
No problem :)
What is the source of the AOF file? Do you have a single redis instance? Replication? Cluster?
Can you try restarting the instance with log level verbose or debug? We might get more useful information
from redisearch.
Czechh
commented on June 19, 2024
It's a single Redis contianer, running with docker-compose inside of a VM. Something like this:
version: "3"
services:
redis:
image: redis/redis-stack-server:latest
ports:
- "6379:6379"
environment:
REDIS_ARGS: "--appendonly yes --loglevel debug"
LL_VERBOSE:
volumes:
- ./local:/data
Here's the debug logs
8:C 18 Feb 2024 17:00:49.655 # WARNING Memory overcommit must be enabled! Without it, a background save or replication may fail under low memory condition. To fix this issue add 'vm.overcommit_memory = 1' to /etc/sysctl.conf and then reboot or run the command 'sysctl vm.overcommit_memory=1' for this to take effect.
8:C 18 Feb 2024 17:00:49.660 * oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
8:C 18 Feb 2024 17:00:49.660 * Redis version=7.2.3, bits=64, commit=00000000, modified=0, pid=8, just started
8:C 18 Feb 2024 17:00:49.660 * Configuration loaded
8:M 18 Feb 2024 17:00:49.667 * monotonic clock: POSIX clock_gettime
8:M 18 Feb 2024 17:00:49.672 * Running mode=standalone, port=6379.
8:M 18 Feb 2024 17:00:49.673 * Module 'RedisCompat' loaded from /opt/redis-stack/lib/rediscompat.so
8:M 18 Feb 2024 17:00:49.682 * <search> Redis version found by RedisSearch : 7.2.3 - oss
8:M 18 Feb 2024 17:00:49.682 * <search> RediSearch version 2.8.9 (Git=HEAD-58db69da)
8:M 18 Feb 2024 17:00:49.683 * <search> Low level api version 1 initialized successfully
8:M 18 Feb 2024 17:00:49.683 * <search> concurrent writes: OFF, gc: ON, prefix min length: 2, prefix max expansions: 200, query timeout (ms): 500, timeout policy: return, cursor read size: 1000, cursor max idle (ms): 300000, max doctable size: 1000000, max number of search results: 10000, search pool size: 20, index pool size: 8,
8:M 18 Feb 2024 17:00:49.683 - <search> Creating background thread--1148656192
8:M 18 Feb 2024 17:00:49.683 - <search> Thread pool of size ��z created successfully
8:M 18 Feb 2024 17:00:49.683 - <search> Creating background thread--1157110336
8:M 18 Feb 2024 17:00:49.683 - <search> Thread pool of size ��z created successfully
8:M 18 Feb 2024 17:00:49.683 * <search> Initialized thread pools!
8:M 18 Feb 2024 17:00:49.683 * <search> Enabled role change notification
8:M 18 Feb 2024 17:00:49.683 - <search> Successfully executed DictRegister
8:M 18 Feb 2024 17:00:49.683 - <search> Successfully executed TrieType_Register
8:M 18 Feb 2024 17:00:49.683 - <search> Successfully executed IndexSpec_RegisterType
8:M 18 Feb 2024 17:00:49.683 - <search> Successfully executed TagIndex_RegisterType
8:M 18 Feb 2024 17:00:49.683 - <search> Successfully executed InvertedIndex_RegisterType
8:M 18 Feb 2024 17:00:49.683 - <search> Successfully executed NumericIndexType_Register
8:M 18 Feb 2024 17:00:49.683 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 - <search> Successfully executed RedisModule_CreateCommand
8:M 18 Feb 2024 17:00:49.684 * Module 'search' loaded from /opt/redis-stack/lib/redisearch.so
8:M 18 Feb 2024 17:00:49.686 * <timeseries> RedisTimeSeries version 11009, git_sha=6782c54bcb7dddeb6669f24cd5113dad64a4b03d
8:M 18 Feb 2024 17:00:49.686 * <timeseries> Redis version found by RedisTimeSeries : 7.2.3 - oss
8:M 18 Feb 2024 17:00:49.686 * <timeseries> loaded default CHUNK_SIZE_BYTES policy: 4096
8:M 18 Feb 2024 17:00:49.686 * <timeseries> loaded server DUPLICATE_POLICY: block
8:M 18 Feb 2024 17:00:49.686 * <timeseries> Setting default series ENCODING to: compressed
8:M 18 Feb 2024 17:00:49.687 * <timeseries> Detected redis oss
8:M 18 Feb 2024 17:00:49.687 * Module 'timeseries' loaded from /opt/redis-stack/lib/redistimeseries.so
8:M 18 Feb 2024 17:00:49.688 * <ReJSON> Created new data type 'ReJSON-RL'
8:M 18 Feb 2024 17:00:49.689 * <ReJSON> version: 20607 git sha: unknown branch: unknown
8:M 18 Feb 2024 17:00:49.689 * <ReJSON> Exported RedisJSON_V1 API
8:M 18 Feb 2024 17:00:49.689 * <ReJSON> Exported RedisJSON_V2 API
8:M 18 Feb 2024 17:00:49.689 * <ReJSON> Exported RedisJSON_V3 API
8:M 18 Feb 2024 17:00:49.689 * <ReJSON> Exported RedisJSON_V4 API
8:M 18 Feb 2024 17:00:49.689 * <ReJSON> Exported RedisJSON_V5 API
8:M 18 Feb 2024 17:00:49.689 * <ReJSON> Enabled diskless replication
8:M 18 Feb 2024 17:00:49.689 * Module 'ReJSON' loaded from /opt/redis-stack/lib/rejson.so
8:M 18 Feb 2024 17:00:49.689 * <search> Acquired RedisJSON_V4 API
8:M 18 Feb 2024 17:00:49.689 * <bf> RedisBloom version 2.6.8 (Git=unknown)
8:M 18 Feb 2024 17:00:49.689 * Module 'bf' loaded from /opt/redis-stack/lib/redisbloom.so
8:M 18 Feb 2024 17:00:49.692 * <redisgears_2> Created new data type 'GearsType'
8:M 18 Feb 2024 17:00:49.693 * <redisgears_2> Detected redis oss
8:M 18 Feb 2024 17:00:49.693 # <redisgears_2> could not initialize RedisAI_InitError
redis-1 |
8:M 18 Feb 2024 17:00:49.693 * <redisgears_2> Failed loading RedisAI API.
8:M 18 Feb 2024 17:00:49.693 * <redisgears_2> RedisGears v2.0.14, sha='7b124f80636f6b58007a6b7093d65b96a8c2d920', build_type='release', built_for='Linux-ubuntu22.04.arm64v8'.
8:M 18 Feb 2024 17:00:49.699 * <redisgears_2> Registered backend: js.
8:M 18 Feb 2024 17:00:49.699 * Module 'redisgears_2' loaded from /opt/redis-stack/lib/redisgears.so
8:M 18 Feb 2024 17:00:49.699 * Server initialized
8:M 18 Feb 2024 17:00:49.700 * <search> Loading event starts
8:M 18 Feb 2024 17:00:49.700 * <redisgears_2> Got a loading start event, clear the entire functions data.
8:M 18 Feb 2024 17:00:49.711 * Reading RDB base file on AOF loading...
8:M 18 Feb 2024 17:00:49.711 * Loading RDB produced by version 7.2.4
8:M 18 Feb 2024 17:00:49.711 * RDB age 263778 seconds
8:M 18 Feb 2024 17:00:49.711 * RDB memory usage when created 395.68 Mb
8:M 18 Feb 2024 17:00:49.711 * RDB is base AOF
8:M 18 Feb 2024 17:00:49.712 # <search> creating vector index. Server memory limit: 14649540608B, required memory: 6316424B, available memory: 14648171208B
8:M 18 Feb 2024 17:00:49.712 - <search> Starting GC for index org-657cb19bb523e5ca31f9c1ce-index-65ce28fa108c43f5203907bd
8:M 18 Feb 2024 17:00:49.712 # <search> creating vector index. Server memory limit: 14649540608B, required memory: 6316424B, available memory: 14648059832B
8:M 18 Feb 2024 17:00:49.712 - <search> Starting GC for index org-657cb19bb523e5ca31f9c1ce-index-65cd81ce3cddae2e6f227cad
8:M 18 Feb 2024 17:00:49.712 # <search> creating vector index. Server memory limit: 14649540608B, required memory: 6316424B, available memory: 14647949872B
8:M 18 Feb 2024 17:00:49.712 - <search> Starting GC for index org-657cb19bb523e5ca31f9c1ce-index-65ce2ba2108c43f5203907bf
8:M 18 Feb 2024 17:00:49.712 # <search> creating vector index. Server memory limit: 14649540608B, required memory: 6316424B, available memory: 14647839992B
8:M 18 Feb 2024 17:00:49.712 - <search> Starting GC for index org-65830deff0f82d38de3397e0-session-65ce2067f52e4257f0c720e2
8:M 18 Feb 2024 17:00:49.712 # <search> creating vector index. Server memory limit: 14649540608B, required memory: 6316424B, available memory: 14647730152B
8:M 18 Feb 2024 17:00:49.712 - <search> Starting GC for index org-657cb19bb523e5ca31f9c1ce-index-65ce2f3d108c43f5203907c1
8:M 18 Feb 2024 17:00:49.712 # <search> creating vector index. Server memory limit: 14649540608B, required memory: 6316424B, available memory: 14647620136B
8:M 18 Feb 2024 17:00:49.712 - <search> Starting GC for index org-657cb19bb523e5ca31f9c1ce-index-65cd7d283cddae2e6f227cab
8:M 18 Feb 2024 17:00:49.712 # <search> creating vector index. Server memory limit: 14649540608B, required memory: 6316424B, available memory: 14647510112B
8:M 18 Feb 2024 17:00:49.712 - <search> Starting GC for index org-65830deff0f82d38de3397e0-index-65ce1d43108c43f5203907b7
8:M 18 Feb 2024 17:00:49.712 # <search> creating vector index. Server memory limit: 14649540608B, required memory: 6316424B, available memory: 14647399992B
8:M 18 Feb 2024 17:00:49.712 - <search> Starting GC for index org-65830deff0f82d38de3397e0-session-65ce25e5f52e4257f0c7214f
8:M 18 Feb 2024 17:00:51.918 * Done loading RDB, keys loaded: 23753, keys expired: 0.
8:M 18 Feb 2024 17:00:51.918 * DB loaded from base file appendonly.aof.14.base.rdb: 2.218 seconds
8:M 18 Feb 2024 17:00:52.098 # <search> creating vector index. Server memory limit: 14649540608B, required memory: 6316424B, available memory: 14242562192B
8:M 18 Feb 2024 17:00:52.098 - <search> Starting GC for index org-65830deff0f82d38de3397e0-index-65ce3659108c43f5203907c3
8:M 18 Feb 2024 17:00:52.098 - <search> Creating background thread--1512163904
8:M 18 Feb 2024 17:00:52.098 - <search> Thread pool of size (�z created successfully
8:M 18 Feb 2024 17:00:52.098 . <search> Thread--1512163904 is running iteration
8:M 18 Feb 2024 17:00:52.099 . <search> Thread--1157110336 is running iteration
8:M 18 Feb 2024 17:00:52.099 . <search> All threads are idle
8:M 18 Feb 2024 17:00:52.100 # <search> creating vector index. Server memory limit: 14649540608B, required memory: 6316424B, available memory: 14242524240B
8:M 18 Feb 2024 17:00:52.100 - <search> Starting GC for index org-657cb19bb523e5ca31f9c1ce-index-65cd23cb9c04fe16cf905a5d
8:M 18 Feb 2024 17:00:52.103 . <search> Thread--1157110336 is running iteration
8:M 18 Feb 2024 17:00:52.104 . <search> All threads are idle
8:M 18 Feb 2024 17:00:52.104 # <search> creating vector index. Server memory limit: 14649540608B, required memory: 6316424B, available memory: 14242502856B
8:M 18 Feb 2024 17:00:52.104 - <search> Starting GC for index org-657cb19bb523e5ca31f9c1ce-index-65cd23cb9c04fe16cf905a5d
8:M 18 Feb 2024 17:00:52.106 . <search> Thread--1157110336 is running iteration
8:M 18 Feb 2024 17:00:52.106 . <search> All threads are idle
8:M 18 Feb 2024 17:00:52.106 # <search> creating vector index. Server memory limit: 14649540608B, required memory: 6316424B, available memory: 14242492112B
8:M 18 Feb 2024 17:00:52.106 - <search> Starting GC for index org-657cb19bb523e5ca31f9c1ce-index-65ce4674108c43f5203907ca
8:M 18 Feb 2024 17:00:52.107 # <search> creating vector index. Server memory limit: 14649540608B, required memory: 6316424B, available memory: 14235987704B
8:M 18 Feb 2024 17:00:52.107 - <search> Starting GC for index org-657cb19bb523e5ca31f9c1ce-index-65b2e28dff2b62055f53a514
8:M 18 Feb 2024 17:00:52.139 . <search> Thread--1157110336 is running iteration
8:M 18 Feb 2024 17:00:52.139 . <search> All threads are idle
8:M 18 Feb 2024 17:00:52.140 # <search> creating vector index. Server memory limit: 14649540608B, required memory: 6316424B, available memory: 14235817816B
8:M 18 Feb 2024 17:00:52.140 - <search> Starting GC for index org-65830deff0f82d38de3397e0-index-65ce59ed75e0765d5cdecc12
8:M 18 Feb 2024 17:00:52.237 * DB loaded from incr file appendonly.aof.14.incr.aof: 0.319 seconds
8:M 18 Feb 2024 17:00:52.237 # <search> Skip background reindex scan, redis version contains loaded event.
8:M 18 Feb 2024 17:00:52.237 * <search> Loading event ends
8:M 18 Feb 2024 17:00:52.237 * <redisgears_2> Loading finished, re-enable key space notificaitons.
8:M 18 Feb 2024 17:00:52.237 * DB loaded from append only file: 2.537 seconds
8:M 18 Feb 2024 17:00:52.241 * Opening AOF incr file appendonly.aof.14.incr.aof on server start
8:M 18 Feb 2024 17:00:52.241 * Ready to accept connections tcp
8:M 18 Feb 2024 17:00:52.241 * <module> Scanning index org-65830deff0f82d38de3397e0-index-65ce3659108c43f5203907c3 in background
8:M 18 Feb 2024 17:00:52.241 * <module> Scanning indexes in background: cancelled (scanned=27837)
8:M 18 Feb 2024 17:00:52.241 . <search> All threads are idle
8:M 18 Feb 2024 17:00:52.241 . <search> Thread--1512163904 is running iteration
8:M 18 Feb 2024 17:00:52.241 * <module> Scanning index org-657cb19bb523e5ca31f9c1ce-index-65cd23cb9c04fe16cf905a5d in background
8:M 18 Feb 2024 17:00:52.241 * <module> Scanning indexes in background: cancelled (scanned=27846)
8:M 18 Feb 2024 17:00:52.241 . <search> All threads are idle
8:M 18 Feb 2024 17:00:52.241 . <search> Thread--1512163904 is running iteration
8:M 18 Feb 2024 17:00:52.241 * <module> Scanning index org-657cb19bb523e5ca31f9c1ce-index-65cd23cb9c04fe16cf905a5d in background
8:M 18 Feb 2024 17:00:52.241 * <module> Scanning indexes in background: cancelled (scanned=27845)
8:M 18 Feb 2024 17:00:52.241 . <search> All threads are idle
8:M 18 Feb 2024 17:00:52.241 . <search> Thread--1512163904 is running iteration
8:M 18 Feb 2024 17:00:52.241 * <module> Scanning index org-657cb19bb523e5ca31f9c1ce-index-65ce4674108c43f5203907ca in background
8:M 18 Feb 2024 17:00:52.295 * <module> Scanning index org-657cb19bb523e5ca31f9c1ce-index-65ce4674108c43f5203907ca in background: done (scanned=27845)
8:M 18 Feb 2024 17:00:52.295 . <search> All threads are idle
8:M 18 Feb 2024 17:00:52.295 . <search> Thread--1512163904 is running iteration
8:M 18 Feb 2024 17:00:52.295 * <module> Scanning index org-657cb19bb523e5ca31f9c1ce-index-65b2e28dff2b62055f53a514 in background
8:M 18 Feb 2024 17:00:52.295 * <module> Scanning indexes in background: cancelled (scanned=27854)
8:M 18 Feb 2024 17:00:52.295 . <search> All threads are idle
8:M 18 Feb 2024 17:00:52.295 . <search> Thread--1512163904 is running iteration
8:M 18 Feb 2024 17:00:52.295 * <module> Scanning index org-65830deff0f82d38de3397e0-index-65ce59ed75e0765d5cdecc12 in background
8:M 18 Feb 2024 17:00:52.390 * <module> Scanning index org-65830deff0f82d38de3397e0-index-65ce59ed75e0765d5cdecc12 in background: done (scanned=27853)
8:M 18 Feb 2024 17:00:52.390 . <search> All threads are idle
8:M 18 Feb 2024 17:00:52.390 . <search> Thread--1512163904 is running iteration
8:M 18 Feb 2024 17:00:52.390 . <search> All threads are idle
8:M 18 Feb 2024 17:00:52.390 . <search> Thread--1512163904 is running iteration
8:M 18 Feb 2024 17:00:52.390 . <search> All threads are idle
8:M 18 Feb 2024 17:00:52.390 . <search> Thread--1512163904 is running iteration
8:M 18 Feb 2024 17:00:52.390 . <search> All threads are idle
8:M 18 Feb 2024 17:00:52.390 . <search> Thread--1512163904 is running iteration
8:M 18 Feb 2024 17:00:52.390 . <search> All threads are idle
8:M 18 Feb 2024 17:00:54.675 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:00:54.676 . 0 clients connected (0 replicas), 441804968 bytes in use
8:M 18 Feb 2024 17:00:59.771 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:00:59.771 . 0 clients connected (0 replicas), 441804968 bytes in use
8:M 18 Feb 2024 17:01:04.892 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:01:04.892 . 0 clients connected (0 replicas), 441804968 bytes in use
8:M 18 Feb 2024 17:01:10.014 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:01:10.014 . 0 clients connected (0 replicas), 441804968 bytes in use
8:M 18 Feb 2024 17:01:15.099 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:01:15.099 . 0 clients connected (0 replicas), 441804968 bytes in use
8:M 18 Feb 2024 17:01:20.207 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:01:20.207 . 0 clients connected (0 replicas), 441804968 bytes in use
8:M 18 Feb 2024 17:01:24.715 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:01:24.717 . <search> All threads are idle
8:M 18 Feb 2024 17:01:25.309 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:01:25.309 . 0 clients connected (0 replicas), 441804984 bytes in use
8:M 18 Feb 2024 17:01:28.714 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:01:28.715 . <search> All threads are idle
8:M 18 Feb 2024 17:01:28.715 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:01:28.715 . <search> All threads are idle
8:M 18 Feb 2024 17:01:28.715 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:01:28.715 . <search> All threads are idle
8:M 18 Feb 2024 17:01:29.141 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:01:29.179 - Module fork started pid: 17
8:M 18 Feb 2024 17:01:29.195 - Killing running module fork child: 17
8:M 18 Feb 2024 17:01:29.199 . <search> All threads are idle
8:M 18 Feb 2024 17:01:30.406 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:01:30.406 . 0 clients connected (0 replicas), 441762128 bytes in use
8:M 18 Feb 2024 17:01:30.712 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:01:30.712 . <search> All threads are idle
8:M 18 Feb 2024 17:01:32.713 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:01:32.714 . <search> All threads are idle
8:M 18 Feb 2024 17:01:33.713 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:01:33.714 . <search> All threads are idle
8:M 18 Feb 2024 17:01:34.713 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:01:34.713 . <search> All threads are idle
8:M 18 Feb 2024 17:01:35.506 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:01:35.506 . 0 clients connected (0 replicas), 441762120 bytes in use
8:M 18 Feb 2024 17:01:40.604 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:01:40.604 . 0 clients connected (0 replicas), 441762120 bytes in use
8:M 18 Feb 2024 17:01:42.714 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:01:42.714 . <search> All threads are idle
8:M 18 Feb 2024 17:01:45.712 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:01:45.712 . 0 clients connected (0 replicas), 441762080 bytes in use
8:M 18 Feb 2024 17:01:47.108 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:01:47.108 . <search> All threads are idle
8:M 18 Feb 2024 17:01:50.008 * 10000 changes in 60 seconds. Saving...
8:M 18 Feb 2024 17:01:50.076 * Background saving started by pid 18
18:C 18 Feb 2024 17:01:50.084 - Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
8:M 18 Feb 2024 17:01:50.878 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:01:50.878 . 0 clients connected (0 replicas), 441762104 bytes in use
18:C 18 Feb 2024 17:01:51.109 - Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
18:C 18 Feb 2024 17:01:52.272 - Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
18:C 18 Feb 2024 17:01:53.405 - Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
18:C 18 Feb 2024 17:01:54.515 - Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
18:C 18 Feb 2024 17:01:55.666 - Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
8:M 18 Feb 2024 17:01:55.904 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:01:55.904 . 0 clients connected (0 replicas), 441762104 bytes in use
18:C 18 Feb 2024 17:01:56.429 * DB saved on disk
18:C 18 Feb 2024 17:01:56.433 * Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
8:M 18 Feb 2024 17:01:56.509 * Background saving terminated with success
8:M 18 Feb 2024 17:02:00.716 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:02:00.716 . <search> All threads are idle
8:M 18 Feb 2024 17:02:00.981 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:02:00.981 . 0 clients connected (0 replicas), 441762104 bytes in use
8:M 18 Feb 2024 17:02:03.203 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:02:03.203 . <search> All threads are idle
8:M 18 Feb 2024 17:02:06.094 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:02:06.094 . 0 clients connected (0 replicas), 441762120 bytes in use
8:M 18 Feb 2024 17:02:07.715 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:02:07.716 . <search> All threads are idle
8:M 18 Feb 2024 17:02:08.718 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:02:08.719 . <search> All threads are idle
8:M 18 Feb 2024 17:02:09.718 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:02:09.718 . <search> All threads are idle
8:M 18 Feb 2024 17:02:10.720 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:02:10.720 . <search> All threads are idle
8:M 18 Feb 2024 17:02:11.203 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:02:11.203 . 0 clients connected (0 replicas), 441762208 bytes in use
8:M 18 Feb 2024 17:02:11.712 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:02:11.712 . <search> All threads are idle
8:M 18 Feb 2024 17:02:16.277 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:02:16.277 . 0 clients connected (0 replicas), 441762184 bytes in use
8:M 18 Feb 2024 17:02:21.369 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:02:21.369 . 0 clients connected (0 replicas), 441762184 bytes in use
8:M 18 Feb 2024 17:02:22.717 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:02:22.717 . <search> All threads are idle
8:M 18 Feb 2024 17:02:26.463 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:02:26.463 . 0 clients connected (0 replicas), 441762192 bytes in use
8:M 18 Feb 2024 17:02:31.561 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:02:31.561 . 0 clients connected (0 replicas), 441762192 bytes in use
8:M 18 Feb 2024 17:02:34.111 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:02:34.111 . <search> All threads are idle
8:M 18 Feb 2024 17:02:36.657 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:02:36.657 . 0 clients connected (0 replicas), 441762168 bytes in use
8:M 18 Feb 2024 17:02:40.715 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:02:40.715 . <search> All threads are idle
8:M 18 Feb 2024 17:02:41.739 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:02:41.739 . 0 clients connected (0 replicas), 441762152 bytes in use
8:M 18 Feb 2024 17:02:42.718 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:02:42.718 . <search> All threads are idle
8:M 18 Feb 2024 17:02:43.724 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:02:43.724 . <search> All threads are idle
8:M 18 Feb 2024 17:02:46.845 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:02:46.845 . 0 clients connected (0 replicas), 441762192 bytes in use
8:M 18 Feb 2024 17:02:51.713 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:02:51.713 . <search> All threads are idle
8:M 18 Feb 2024 17:02:51.938 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:02:51.938 . 0 clients connected (0 replicas), 441762192 bytes in use
8:M 18 Feb 2024 17:02:57.023 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:02:57.023 . 0 clients connected (0 replicas), 441762192 bytes in use
8:M 18 Feb 2024 17:02:57.720 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:02:57.720 . <search> All threads are idle
8:M 18 Feb 2024 17:02:57.720 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:02:57.720 . <search> All threads are idle
8:M 18 Feb 2024 17:02:57.720 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:02:57.720 . <search> All threads are idle
8:M 18 Feb 2024 17:03:00.720 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:03:00.720 . <search> All threads are idle
8:M 18 Feb 2024 17:03:01.204 . <search> Thread--1148656192 is running iteration
8:M 18 Feb 2024 17:03:01.204 . <search> All threads are idle
8:M 18 Feb 2024 17:03:02.115 - DB 0: 29711 keys (4 volatile) in 32768 slots HT.
8:M 18 Feb 2024 17:03:02.115 . 0 clients connected (0 replicas), 441762200 bytes in use```
Thank you!
from redisearch.
GuyAv46
commented on June 19, 2024
Thank you for your cooperation!
I’ll dig deeper into it tomorrow. My suspect is that it is related to the AOF process that I’ll admit I don’t know much about yet.
What I was able to get this far:
- None of the indexes "declared" between
Loading RDB produced by version 7.2.4andDone loading RDB, keys loaded: 23753, keys expired: 0.gets their scan canceled. - All the indexes that get their scan canceled get the cancelation immediately, as can be seen by the timestamp. The
(scanned=27854)is a lie (a bug that is already fixed, the number is the number of keys in the database and not the number of scanned keys). org-657cb19bb523e5ca31f9c1ce-index-65cd23cb9c04fe16cf905a5dgets its GC started twice and its BG scan is canceled twice. There is an assertion if a GC is attempted to start twice, so the index was very likely dropped and recreated at least once.- The number of indexes created after the
Done loading RDB, keys loaded:mark matches the number of scans. This makes sense as when loading from RDB, there is no BG indexing at all, so only creations from the AOF section could cause a BG scan (the indexes that are created in the first section get loaded directly)
After I'll dig a bit deeper on the AOF section, I can confirm there is no real problem, and that the scans were canceled because the index was actually dropped in the AOF file.
Can you add the output of FT._LIST so we can see if any of the indexes that get their scan canceled still exist after the load is complete?
from redisearch.
Czechh
commented on June 19, 2024
Thank you here's the ft._list
127.0.0.1:6379> ft._list
1) org-657cb19bb523e5ca31f9c1ce-index-65ce4674108c43f5203907ca
2) org-657cb19bb523e5ca31f9c1ce-index-65ce28fa108c43f5203907bd
3) org-657cb19bb523e5ca31f9c1ce-index-65cd81ce3cddae2e6f227cad
4) org-65830deff0f82d38de3397e0-session-65ce2067f52e4257f0c720e2
5) org-657cb19bb523e5ca31f9c1ce-index-65ce2ba2108c43f5203907bf
6) org-65830deff0f82d38de3397e0-index-65ce59ed75e0765d5cdecc12
7) org-657cb19bb523e5ca31f9c1ce-index-65ce2f3d108c43f5203907c1
8) org-657cb19bb523e5ca31f9c1ce-index-65cd7d283cddae2e6f227cab
9) org-65830deff0f82d38de3397e0-index-65ce1d43108c43f5203907b7
10) org-65830deff0f82d38de3397e0-session-65ce25e5f52e4257f0c7214f
Is there a way to reconstruct the who AOF file? given that's its partial? Got these files:
.
├── appendonlydir
│ ├── appendonly.aof.14.base.rdb
│ ├── appendonly.aof.14.incr.aof
│ └── appendonly.aof.manifest
└── dump.rdb
from redisearch.
GuyAv46
commented on June 19, 2024
So basically the AOF mechanism includes a manifest file, a base RDB, and an incremental file/s. Depending on your setup, every once in a while a forked process "applies" the changes in the incr file into the base RDB.
The loading process of an AOF starts by reading the manifest to find the base RDB and the AOF file/s, then we first load the base RDB file and then apply the commands from the AOF file/s in order.
When loading an index from an RDB, there is no BG indexing and when the loading is done the index is ready. The AOF file contains more commands to apply, and it may create or delete indexes and thus may trigger a background scan. Since the entire loading event happens while holding the redis GIL, the BG index tasks cannot start until the entire loading process is done.
When it's done (at the Ready to accept connections log message), the BG index tasks can take the GIL and perform the indexing, but if the index was both created and dropped in the AOF file, the BG indexer recognizes the index is no longer exists, it cancels the tasks and returns.
The RDB file is binary, but the AOF incremental files are mostly text and you can verify that the indexes that got their BG scan canceled are both created and dropped in it.
TL;DR: Not a bug. expected and correct behavior.
You can read more about AOF and persistence here.
Let me know if there is anything else I can help with
from redisearch.
Czechh
commented on June 19, 2024
Thanks for the explanation! That makes 100% sense.
What I'm trying to understand then is why these indexes try to get loaded and get cancelled, given that the AOF (latest segment) file doesn't have any FT.DROPINDEX command in them. I would've assumed that the RDB file is consolidated, meaning it wouldn't trigger an index creation process as a previous DROPINDEX command was incrementally added to that state file.
I just want to make 100% sure that command actually happen to ensure that my setup isn't somehow dropping data in some other way. Please let me know if my assumptions are incorrect, and again thanks for your help.
from redisearch.
GuyAv46
commented on June 19, 2024
Yes, if an index was dropped and the change was applied to the RDB file, it won't be created when loaded. We can also see in the log what indexes were created from the RDB (before Done loading RDB, keys loaded: 23753, keys expired: 0.) and what from the AOF
It's strange that there is no DROP command in the AOF. Do you see the creation of the canceled indexes there? Maybe another command of the DROP family? (FT.DROP, FT._DROPIFX...)
from redisearch.
Related Issues (20)
- [BUG] Is There a offset limit when using `limit offset num` HOT 3
- [BUG] Redis Search silently fails to Sort when the index schema is too large HOT 6
- [BUG] ft.aggregate slowdown with high frequency updates HOT 3
- [BUG] Wildcard redisearch on TEXT field does not return result HOT 2
- [BUG] Unable to do full-text exact search with a colon in the text HOT 2
- [BUG] simple ft.create/ft.search with <100 bytes of data is leaking 1300 bytes of memory. HOT 3
- [BUG] FT.AGGREGATE performance problem HOT 6
- [BUG] Order of precedence not honored in APPLY functions with exponents HOT 3
- MOD-7133: [Feature Request] Add FT.ALIASGET command HOT 2
- L2 distance computation misunderstanding in documentation HOT 4
- [BUG] I can't run "make build" command successfully HOT 3
- Document Distributed Search (RSCoordinator) build/installation HOT 7
- Boost File Error when building 2.8.13 with Bullseye HOT 1
- [BUG] RediSearch HNSW indexing deadlock? HOT 2
- Facing build issue on PPC64LE architecture. HOT 3
- [BUG] APPLY substr function not using -1 count as documented - [MOD-6959]
- the results obtained after indexing are incomplete HOT 29
- Please Help Fix RSCoordinator So that Redis Search (RediSearch) Can Be Used Across Redis Cluster - module-oss.so initialization failed HOT 17
- Configuration of Custom Tokenizer HOT 1
- [BUG] Redis freezes and stops responding with 100% CPU Utilization while using redissearch with HNSW vector indexes HOT 2
Recommend Projects
-
React
A declarative, efficient, and flexible JavaScript library for building user interfaces.
-
Vue.js
🖖 Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.
-
Typescript
TypeScript is a superset of JavaScript that compiles to clean JavaScript output.
-
TensorFlow
An Open Source Machine Learning Framework for Everyone
-
Django
The Web framework for perfectionists with deadlines.
-
Laravel
A PHP framework for web artisans
-
D3
Bring data to life with SVG, Canvas and HTML. 📊📈🎉
-
Recommend Topics
-
javascript
JavaScript (JS) is a lightweight interpreted programming language with first-class functions.
-
web
Some thing interesting about web. New door for the world.
-
server
A server is a program made to process requests and deliver data to clients.
-
Machine learning
Machine learning is a way of modeling and interpreting data that allows a piece of software to respond intelligently.
-
Visualization
Some thing interesting about visualization, use data art
-
Game
Some thing interesting about game, make everyone happy.
Recommend Org
-
Facebook
We are working to build community through open source technology. NB: members must have two-factor auth.
-
Microsoft
Open source projects and samples from Microsoft.
-
Google
Google ❤️ Open Source for everyone.
-
Alibaba
Alibaba Open Source for everyone
-
D3
Data-Driven Documents codes.
-
Tencent
China tencent open source team.
from redisearch.