Slow, High CPU Write Operations After Collection Drop in Typesense
TLDR Himank discussed an issue in Typesense where deleting and recreating a collection led to slow write operations and high CPU usage. Kishore Nallan suggested using an alias to avoid this issue. Numerous tests and debugging was conducted as pboros contributed with local testing. Kishore Nallan aimed to start implementing a range delete and full db compaction after deletion to potentially solve the issue.




Jul 29, 2022 (14 months ago)
pboros
12:58 PMKishore Nallan
12:59 PMdb
directory.Kishore Nallan
12:59 PMpboros
12:59 PMpboros
01:00 PMroot@3942c8bd03f4:/tmp# du -sh db/
77M db/
pboros
01:00 PMKishore Nallan
01:00 PMpboros
01:00 PMpboros
01:01 PMDevice: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
vda 0.00 10.00 0.00 15.00 0.00 0.10 13.33 0.01 0.33 0.00 0.33 0.67 1.00
avg-cpu: %user %nice %system %iowait %steal %idle
11.65 0.00 1.00 0.13 0.00 87.22
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
vda 0.00 11.88 0.00 11.88 0.00 0.09 16.00 0.01 0.33 0.00 0.33 0.75 0.89
Kishore Nallan
01:01 PMpboros
01:02 PMpboros
01:04 PMpboros
01:04 PM{
"delete_latency_ms": 0,
"delete_requests_per_second": 0,
"import_latency_ms": 0,
"import_requests_per_second": 0,
"latency_ms": {
"GET /health": 0.0,
"POST /collections/epnbiqxgrr/documents/": 470.34285714285716,
"POST /collections/imkwwholpv/documents/": 651.0
},
"pending_write_batches": 1,
"requests_per_second": {
"GET /health": 0.1,
"POST /collections/epnbiqxgrr/documents/": 3.5,
"POST /collections/imkwwholpv/documents/": 0.5
},
"search_latency_ms": 0,
"search_requests_per_second": 0,
"total_requests_per_second": 4.1,
"write_latency_ms": 492.925,
"write_requests_per_second": 4.0
}
pboros
01:04 PMKishore Nallan
01:05 PMKishore Nallan
01:06 PMI20220729 18:33:31.825273 92155904 batched_indexer.cpp:67] batch indexer queue notify
I20220729 18:33:33.282867 87326720 batched_indexer.cpp:137] batch indexer queue awake
Kishore Nallan
01:07 PMKishore Nallan
01:07 PMpboros
01:08 PMpboros
01:08 PMKishore Nallan
01:09 PM
pboros
01:11 PMKishore Nallan
01:13 PMKishore Nallan
03:01 PMrocksdb::DBIter::Next()
in batched indexer, so I figured it is taking too long to do db iterations after dropping so many keys.I did a full db compaction after the deletion of the keys and that seems to have helped. I initially tried range compaction on only the key range that was deleted but that didn't help either. Right now, I'm doing a blind compaction as part of every collection drop, but have to probably change it to happen only when a "large" collection is dropped. Not sure if there is another criteria (like some kind of key fragmentation) to use here.
Ovais
03:03 PMKishore Nallan
03:06 PMpboros
03:06 PMpboros
03:07 PMKishore Nallan
03:08 PMpboros
03:08 PMKishore Nallan
03:08 PMThis seems relevant.
Ovais
03:09 PMKishore Nallan
03:09 PMpboros
03:09 PM
Ovais
03:09 PMHimank
04:35 PMKishore Nallan
04:58 PMHimank
04:59 PMOvais
06:07 PMOvais
06:07 PMAug 01, 2022 (13 months ago)
Kishore Nallan
01:35 PMNewCompactOnDeletionCollectorFactory
as described here seems to be the most generic way to account for this: https://github.com/facebook/rocksdb/blob/7fd68b7c39c76b5741533ee2a4d7024f3b513f2d/include/rocksdb/utilities/table_properties_collectors.h#L85Aug 02, 2022 (13 months ago)
Ovais
01:44 PMOvais
01:44 PMAug 03, 2022 (13 months ago)
Kishore Nallan
02:58 AM
Aug 05, 2022 (13 months ago)
Kishore Nallan
07:28 AMNewCompactOnDeletionCollectorFactory
does not help. New writes post deletion still takes as long: I don't even see an improvement. It's not clear to me when this compaction will kick-in. While I do see compaction related logs while deletion happens, it's not clear if it's related to this and in any case, doesn't help. So far the only thing that helps is an outright full DB compaction right after the deletion. Even compacting the range of the deleted collection keys doesn't help.Ovais
01:13 PMOvais
01:14 PMKishore Nallan
01:14 PMa) Modified deletes to use DeleteRange
b) Tried compacting only the deleted range
c) Now tried this compaction factory
Nothing helped.
Kishore Nallan
01:14 PMKishore Nallan
01:18 PMread_options.iterate_upper_bound
which has been recommended. I will check that.Ovais
01:20 PMOvais
01:20 PMKishore Nallan
01:21 PMOvais
01:25 PMKishore Nallan
01:26 PMoptions.table_properties_collector_factories.emplace_back(
rocksdb::NewCompactOnDeletionCollectorFactory(10000, 7500, 0.5));
Kishore Nallan
01:28 PMKishore Nallan
01:28 PMOvais
01:28 PMOvais
01:32 PMAug 06, 2022 (13 months ago)
Kishore Nallan
10:11 AMoptions.level0_file_num_compaction_trigger = 1
(default: 4). Level 0 compaction did not trigger previously because there were not enough level_0 files to trigger that default value. I think if there were sustained writes after the deletion, it would have eventually happened. Need to still understand the implication of setting this value too low but the impact of large number of level-0 files are explained succinctly in this paragraph:> RocksDB level 0 SST files are different from other levels. Memtables are flushed to disk as level 0 SST files. The data in a level 0 SST file are arranged in the order of generation as the memtable, and data from the same regions can be spread across different files. Also, data with the same key can be in multiple SST files. Therefore, when a read occurs, each level 0 SST file must be read in order. The more level 0 SST files, the more likely query read performance will be impacted negatively.
Ovais
01:02 PMOvais
01:03 PMKishore Nallan
01:10 PM20M 000906.sst
21M 000909.sst
10M 001039.sst
9.9M 001040.sst
4.0K 001105.sst
L0: 0
L1: 1 (2 KB)
L2: 4 (60 MB)
Ovais
01:12 PMOvais
01:12 PMKishore Nallan
01:14 PMLOG
file, which matched the file sizes on disk.Ovais
01:14 PMOvais
01:14 PMKishore Nallan
01:15 PM4.0K 001136.sst
16K 001138.sst
Nothing logged in LOG file on this run. I've to probably use some rocksdb CLI tool or something to get what levels these are on.
Ovais
01:16 PMKishore Nallan
01:17 PMmax_bytes_for_level_base
is default of 256M so I am not able to understand how anything would ever end up in L2 because total size ~60M even without compaction.Kishore Nallan
01:20 PMOvais
01:23 PM
Ovais
01:49 PMOvais
01:50 PMKishore Nallan
01:53 PMI've another idea which I am now exploring. It's the
.next()
call which is taking time and not the initial iterator seek
call. This is because the next call is not bounded and according to another comment on RocksDB GH, setting an upper bound on the iterator will help. This is because the deleted key range exists after the seek's prefix so maybe without an upper bound the iterator keeps looking at all those tombstones that can be skipped (there's an open but abandoned PR to handle this scenario).Ovais
01:58 PMOvais
01:59 PMOvais
02:02 PMOvais
02:02 PMKishore Nallan
02:02 PMlevel_compaction_dynamic_level_bytes
on existing DBs, so need to plan how to do that.Kishore Nallan
02:03 PMOvais
02:08 PMOvais
02:18 PMOvais
02:18 PMKishore Nallan
02:28 PM
Ovais
02:30 PMAug 08, 2022 (13 months ago)
Kishore Nallan
01:29 PMOvais
06:04 PMAug 09, 2022 (13 months ago)
pboros
06:43 AMKishore Nallan
06:47 AMI've managed to fix the upper bound API issue I ran into earlier: it's because Slice is like a string_view and I was using a stack allocated local. Apart from that, in the code above, you will notice that compaction does not kick in despite using that factory.
Kishore Nallan
06:49 AMKishore Nallan
01:29 PMtypesense/typesense:0.24.0.rc28
Docker image that contains the iterator upper bound patch that has eliminated the post-bulk-delete write latencies for me locally.

Aug 10, 2022 (13 months ago)
Kishore Nallan
04:50 AMNewCompactOnDeletionCollectorFactory
-- this only works for single deletes and not for range deletes. If range delete is used, then the use of factory is obsolete. I've already switched the collection deletion to range delete as well, so I think we should be good now.
Ovais
03:26 PMpboros
03:30 PM
Kishore Nallan
03:38 PMOvais
04:06 PMTypesense
Indexed 2764 threads (79% resolved)
Similar Threads
Large JSONL Documents Import Issue & Resolution
Suraj was having trouble loading large JSONL documents into Typesense server. After several discussions and attempts, it was discovered that the issue was due to data quality. Once the team extracted the data again, the upload process worked smoothly.

Troubleshooting Stalled Writes in TypeSense Instance
Robert was experiencing typesense instances getting stuck after trying to import documents. Kishore Nallan provided suggestions and added specific logs to diagnose the issue. The two identified queries causing troubles but the issues had not been fully resolved yet.


Addressing High CPU Usage in Typesense
Robert reported high CPU usage on Typesense, even after halting all incoming searches. Kishore Nallan suggested logging heavy queries and increasing thread count. The issue was resolved after Robert found and truncated unusually large documents in the database.
Handling Kinesis Stream Event Batching with Typesense
Dui had questions about how to handle Kinesis stream events with Typesense. Kishore Nallan suggested using upsert mode for creation/update and differentiating with logical deletion. After various discussions including identifying and resolving a bug, they finalized to introduce an `emplace` action in Typesense v0.23.


Systemic Deletion of Collection in Typesense on Amazon EC2 Instance
Tatu's Typesense collections were mysteriously disappearing. After investigating with Kishore Nallan, they discovered it was due to misuse of the PHP library which deleted the whole collection instead of a single record.