# Profiling kNN search **URL:** \ **Category:** Elasticsearch\ **Tags:** vector-search\ **Created:** [March 6, 2023, 10:26am UTC](https://discuss.elastic.co/t/profiling-knn-search/327065 "2023-03-06T10:26:18Z")\ **Posts on this page:** 6\ **Page:** 1
**Author:** ![ruslaniv](https://avatars.discourse-cdn.com/v4/letter/r/9de053/32.png) [@ruslaniv](https://discuss.elastic.co/u/ruslaniv)\ **Post date:** [March 6, 2023, 10:26am UTC](https://discuss.elastic.co/t/profiling-knn-search/327065/1 "2023-03-06T10:26:18Z")
I'm trying to profile slow kNN search as discussed [here](https://discuss.elastic.co/t/slow-aknn-search/326915) . So I read the documentation [here](https://www.elastic.co/guide/en/elasticsearch/reference/8.6/search-profile.html) and set up this query in Postman: ```auto { "profile": true, "knn": { "field": "title_vector", "query_vector": {{SEARCH_TEXT}}, "k": 40, "num_candidates": 500, "boost": 0.8, "filter": { "term": { "_meta.seo_friendly": false } } } } ``` After going through the profiling results I have 2 questions: 1. All of the timing results are either in nano- or micro- seconds and still the whole query takes about 30 seconds, and it definitely does not add up to 30 seconds. So why I'm not seeing anything even remotely close to 30 seconds in the profiler results? 2. The document on profiler mentions DFS statistics that can actually show how much time actual kNN search takes, but I'm not seeing this statistics in the results. How can I enable this? ---
**Author:** ![BenTrent](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/bentrent/32/33915_2.png) [@BenTrent](https://discuss.elastic.co/u/BenTrent)\ **Post date:** [March 6, 2023, 1:39pm UTC](https://discuss.elastic.co/t/profiling-knn-search/327065/2 "2023-03-06T13:39:01Z")
@ruslaniv what version of Elasticsearch? The DFS statistics wasn't added until recently (8.6) and to profile KNN, you will probably need that information. ---
**Author:** ![ruslaniv](https://avatars.discourse-cdn.com/v4/letter/r/9de053/32.png) [@ruslaniv](https://discuss.elastic.co/u/ruslaniv)\ **Post date:** [March 7, 2023, 5:39am UTC](https://discuss.elastic.co/t/profiling-knn-search/327065/3 "2023-03-07T05:39:52Z")
Ah, yes, we had 8.4. So we have upgraded the test server to 8.6 and here is the results: ```auto "took": 32146, "timed_out": false, "_shards": { "total": 1, "successful": 1, "skipped": 0, "failed": 0 }, "hits": {...} "profile": { "shards": [ { "id": "[VyKbexZxTP24nHpcsNtS6w][proposals.proposals.vector_20221216][0]", "dfs": { "statistics": { "type": "statistics", "description": "collect term statistics", "time": "95.3micros", "time_in_nanos": 95396, "breakdown": { "term_statistics": 0, "collection_statistics": 0, "collection_statistics_count": 0, "create_weight": 58698, "term_statistics_count": 0, "rewrite_count": 0, "create_weight_count": 1, "rewrite": 0 } }, "knn": { "query": [ { "type": "BoostQuery", "description": "(DocAndScore[500])^0.8", "time": "2ms", "time_in_nanos": 2094416, "breakdown": { "set_min_competitive_score_count": 0, "match_count": 0, "shallow_advance_count": 0, "set_min_competitive_score": 0, "next_doc": 597276, "match": 0, "next_doc_count": 500, "score_count": 500, "compute_max_score_count": 0, "compute_max_score": 0, "advance": 40897, "advance_count": 49, "score": 289088, "build_scorer_count": 98, "create_weight": 345387, "shallow_advance": 0, "create_weight_count": 1, "build_scorer": 821768 } } ], "rewrite_time": 32019008501, "collector": [ { "name": "SimpleTopScoreDocCollector", "reason": "search_top_hits", "time": "1.3ms", "time_in_nanos": 1308447 } ] } }, "searches": [ { "query": [ { "type": "KnnScoreDocQuery", "description": "ScoreAndDocQuery", "time": "843.2micros", "time_in_nanos": 843270, "breakdown": { "set_min_competitive_score_count": 0, "match_count": 0, "shallow_advance_count": 0, "set_min_competitive_score": 0, "next_doc": 153495, "match": 0, "next_doc_count": 40, "score_count": 40, "compute_max_score_count": 0, "compute_max_score": 0, "advance": 38398, "advance_count": 49, "score": 80297, "build_scorer_count": 98, "create_weight": 284389, "shallow_advance": 0, "create_weight_count": 1, "build_scorer": 286691 } } ], "rewrite_time": 6000, "collector": [ { "name": "SimpleTopScoreDocCollector", "reason": "search_top_hits", "time": "591.1micros", "time_in_nanos": 591179 } ] } ], "aggregations": [], "fetch": { "type": "fetch", "description": "", "time": "24ms", "time_in_nanos": 24071502, "breakdown": { "load_stored_fields": 18872699, "load_source": 290889, "load_stored_fields_count": 10, "next_reader_count": 9, "load_source_count": 10, "next_reader": 1781233 }, "debug": { "stored_fields": [ "_id", "_routing", "_source" ] }, "children": [ { "type": "FetchSourcePhase", "description": "", "time": "24.1micros", "time_in_nanos": 24100, "breakdown": { "process_count": 10, "process": 21500, "next_reader": 2600, "next_reader_count": 9 }, "debug": { "fast_path": 10 } }, { "type": "StoredFieldsPhase", "description": "", "time": "13.5micros", "time_in_nanos": 13599, "breakdown": { "process_count": 10, "process": 8099, "next_reader": 5500, "next_reader_count": 9 } } ] } } ] } } ``` ---
**Author:** ![ruslaniv](https://avatars.discourse-cdn.com/v4/letter/r/9de053/32.png) [@ruslaniv](https://discuss.elastic.co/u/ruslaniv)\ **Post date:** [March 7, 2023, 8:44am UTC](https://discuss.elastic.co/t/profiling-knn-search/327065/4 "2023-03-07T08:44:08Z")
> [@ruslaniv](#): > > `knn: {"rewrite_time": 32019008501,`} So I guess this is the hotspot, where ES spends most of its time? ---
**Author:** ![BenTrent](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/bentrent/32/33915_2.png) [@BenTrent](https://discuss.elastic.co/u/BenTrent)\ **Post date:** [March 7, 2023, 1:33pm UTC](https://discuss.elastic.co/t/profiling-knn-search/327065/5 "2023-03-07T13:33:27Z")
KNN spends most of its time in the rewrite. So, that is indeed the hot spot. Its where the KNN search occurs. We do segment searches serially. So, comparing your two open KNN search tickets this is what I think is happening. You are on a single node with a single shard. That single shard has 49 segments, each seems to be an OK size (at least a GB or so). But, this then means, on a single node, you are exploring 49 different HNSW graphs. In the future, we want to make KNN work in parallel on the same shard but with different segments, but right now, that doesn't happen. I think you should try force-merging your test node to fewer segments. It doesn't have to be 1. 1 would be best, but it could take a while to complete. So, I think: > **[Force merge API | Elasticsearch Guide \[8.6\] | Elastic](https://www.elastic.co/guide/en/elasticsearch/reference/8.6/indices-forcemerge.html#docs-forcemerge-task-api)** Run it asynchronously (it will take a while), and set `max_num_segments` to something 10 or below. Again, `1` is best, but you would see significant improvements with `10` I think. ---
**Author:** ![system](https://us1.discourse-cdn.com/elastic/original/3X/1/a/1ac57faf039f6b580b3f104ef42a2a89e41014de.png) [@system](https://discuss.elastic.co/u/system)\ **Post date:** [April 4, 2023, 1:33pm UTC](https://discuss.elastic.co/t/profiling-knn-search/327065/6 "2023-04-04T13:33:39Z")
This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.