Highlighting slows down Kibana searches considerably

Elastic Stack Kibana
1

Hi,

we have Kibana Discover queries in our env where the highlighting functionality seems to have a big impact on the search experience. It is not really clear to me why highlighting is a bottleneck at all for this query. Some details

  • Elastic version 8.10.4
  • roughly 280 million documents in the time range
  • 2379 hits when executing the query
  • the bar chart in the Discover app returns pretty soon (seconds range)
  • table returns
    • gt 10m if highlighting in Kibana is enabled
    • ~10s if highlighting is disabled (and the query is not cached)

The query looks like this

  "query": {
    "bool": {
      "must": [],
      "filter": [
        {
          "bool": {
            "should": [
              {
                "term": {
                  "kubernetes.pod.name": {
                    "value": "xyz"
                  }
                }
              }
            ],
            "minimum_should_match": 1
          }
        },
        {
          "range": {
            "@timestamp": {
              "format": "strict_date_optional_time",
              "gte": "2024-02-07T04:56:45.528Z",
              "lte": "2024-02-07T13:03:08.005Z"
            }
          }
        },
        {
          "match_phrase": {
            "kubernetes.container.name": "xyz"
          }
        }
      ],
      "should": [],
      "must_not": [
        {
          "bool": {
            "minimum_should_match": 1,
            "should": [
              {
                "match_phrase": {
                  "message": "Yielding request"
                }
              },
              {
                "match_phrase": {
                  "message": "handler"
                }
              },
              {
                "match_phrase": {
                  "message": "np.ComponentRegistry"
                }
              },
              {
                "match_phrase": {
                  "message": "Active requests"
                }
              },
              {
                "match_phrase": {
                  "message": "np.CleanupWorker"
                }
              },
              {
                "match_phrase": {
                  "message": "np.DeletedNodeWorker"
                }
              },
              {
                "match_phrase": {
                  "message": "Possibly leaked uploads"
                }
              }
            ]
          }
        }
      ]
    }
  }

I see threads like this within ES which seem to run quite long

   100.3% [cpu=100.3%, other=0.0%] (501.6ms out of 500ms) cpu usage by thread 'elasticsearch[xyz-4][search][T#19]'
     6/10 snapshots sharing following 34 elements
       app/org.apache.lucene.memory@9.7.0/org.apache.lucene.index.memory.MemoryIndex.addField(MemoryIndex.java:273)
       org.elasticsearch.mapper.extras@8.10.4/org.elasticsearch.index.mapper.extras.SourceConfirmedTextQuery$RuntimePhraseScorer.computeFreq(SourceConfirmedTextQuery.java:399)
       org.elasticsearch.mapper.extras@8.10.4/org.elasticsearch.index.mapper.extras.SourceConfirmedTextQuery$RuntimePhraseScorer.freq(SourceConfirmedTextQuery.java:385)
       org.elasticsearch.mapper.extras@8.10.4/org.elasticsearch.index.mapper.extras.SourceConfirmedTextQuery$RuntimePhraseScorer$1.matches(SourceConfirmedTextQuery.java:344)
       app/org.apache.lucene.core@9.7.0/org.apache.lucene.search.TwoPhaseIterator$TwoPhaseIteratorAsDocIdSetIterator.doNext(TwoPhaseIterator.java:85)
       app/org.apache.lucene.core@9.7.0/org.apache.lucene.search.TwoPhaseIterator$TwoPhaseIteratorAsDocIdSetIterator.advance(TwoPhaseIterator.java:78)
       org.elasticsearch.mapper.extras@8.10.4/org.elasticsearch.index.mapper.extras.SourceConfirmedTextQuery$2.matches(SourceConfirmedTextQuery.java:308)
       app/org.apache.lucene.core@9.7.0/org.apache.lucene.search.BooleanWeight.matches(BooleanWeight.java:134)
       app/org.apache.lucene.core@9.7.0/org.apache.lucene.search.BooleanWeight.matches(BooleanWeight.java:134)
       app/org.apache.lucene.highlighter@9.7.0/org.apache.lucene.search.uhighlight.FieldOffsetStrategy.createOffsetsEnumsWeightMatcher(FieldOffsetStrategy.java:147)
       app/org.apache.lucene.highlighter@9.7.0/org.apache.lucene.search.uhighlight.FieldOffsetStrategy.createOffsetsEnumFromReader(FieldOffsetStrategy.java:74)
       app/org.apache.lucene.highlighter@9.7.0/org.apache.lucene.search.uhighlight.MemoryIndexOffsetStrategy.getOffsetsEnum(MemoryIndexOffsetStrategy.java:119)
       app/org.apache.lucene.highlighter@9.7.0/org.apache.lucene.search.uhighlight.FieldHighlighter.highlightFieldForDoc(FieldHighlighter.java:80)
       app/org.elasticsearch.server@8.10.4/org.elasticsearch.lucene.search.uhighlight.CustomFieldHighlighter.highlightFieldForDoc(CustomFieldHighlighter.java:63)
       app/org.elasticsearch.server@8.10.4/org.elasticsearch.lucene.search.uhighlight.CustomUnifiedHighlighter.highlightField(CustomUnifiedHighlighter.java:147)
       app/org.elasticsearch.server@8.10.4/org.elasticsearch.search.fetch.subphase.highlight.DefaultHighlighter.highlight(DefaultHighlighter.java:81)
       app/org.elasticsearch.server@8.10.4/org.elasticsearch.search.fetch.subphase.highlight.HighlightPhase$1.process(HighlightPhase.java:69)
       app/org.elasticsearch.server@8.10.4/org.elasticsearch.search.fetch.FetchPhase$1.nextDoc(FetchPhase.java:158)
       app/org.elasticsearch.server@8.10.4/org.elasticsearch.search.fetch.FetchPhaseDocsIterator.iterate(FetchPhaseDocsIterator.java:70)
       app/org.elasticsearch.server@8.10.4/org.elasticsearch.search.fetch.FetchPhase.buildSearchHits(FetchPhase.java:164)
       app/org.elasticsearch.server@8.10.4/org.elasticsearch.search.fetch.FetchPhase.execute(FetchPhase.java:77)
       app/org.elasticsearch.server@8.10.4/org.elasticsearch.search.SearchService.lambda$executeFetchPhase$9(SearchService.java:860)
       app/org.elasticsearch.server@8.10.4/org.elasticsearch.search.SearchService$$Lambda/0x00007f7b9d5f99c0.get(Unknown Source)
       app/org.elasticsearch.server@8.10.4/org.elasticsearch.action.ActionRunnable$2.accept(ActionRunnable.java:51)
       app/org.elasticsearch.server@8.10.4/org.elasticsearch.action.ActionRunnable$2.accept(ActionRunnable.java:48)
       app/org.elasticsearch.server@8.10.4/org.elasticsearch.action.ActionRunnable$3.doRun(ActionRunnable.java:73)
       app/org.elasticsearch.server@8.10.4/org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:26)
       app/org.elasticsearch.server@8.10.4/org.elasticsearch.common.util.concurrent.TimedRunnable.doRun(TimedRunnable.java:33)
       app/org.elasticsearch.server@8.10.4/org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:983)
       app/org.elasticsearch.server@8.10.4/org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:26)
       java.base@21/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
       java.base@21/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
       java.base@21/java.lang.Thread.runWith(Thread.java:1596)
       java.base@21/java.lang.Thread.run(Thread.java:1583)
     4/10 snapshots sharing following 29 elements
       app/org.apache.lucene.core@9.7.0/org.apache.lucene.search.TwoPhaseIterator$TwoPhaseIteratorAsDocIdSetIterator.advance(TwoPhaseIterator.java:78)
       org.elasticsearch.mapper.extras@8.10.4/org.elasticsearch.index.mapper.extras.SourceConfirmedTextQuery$2.matches(SourceConfirmedTextQuery.java:308)
       app/org.apache.lucene.core@9.7.0/org.apache.lucene.search.BooleanWeight.matches(BooleanWeight.java:134)
       app/org.apache.lucene.core@9.7.0/org.apache.lucene.search.BooleanWeight.matches(BooleanWeight.java:134)
       app/org.apache.lucene.highlighter@9.7.0/org.apache.lucene.search.uhighlight.FieldOffsetStrategy.createOffsetsEnumsWeightMatcher(FieldOffsetStrategy.java:147)
       app/org.apache.lucene.highlighter@9.7.0/org.apache.lucene.search.uhighlight.FieldOffsetStrategy.createOffsetsEnumFromReader(FieldOffsetStrategy.java:74)
       app/org.apache.lucene.highlighter@9.7.0/org.apache.lucene.search.uhighlight.MemoryIndexOffsetStrategy.getOffsetsEnum(MemoryIndexOffsetStrategy.java:119)
       app/org.apache.lucene.highlighter@9.7.0/org.apache.lucene.search.uhighlight.FieldHighlighter.highlightFieldForDoc(FieldHighlighter.java:80)
       app/org.elasticsearch.server@8.10.4/org.elasticsearch.lucene.search.uhighlight.CustomFieldHighlighter.highlightFieldForDoc(CustomFieldHighlighter.java:63)
       app/org.elasticsearch.server@8.10.4/org.elasticsearch.lucene.search.uhighlight.CustomUnifiedHighlighter.highlightField(CustomUnifiedHighlighter.java:147)
       app/org.elasticsearch.server@8.10.4/org.elasticsearch.search.fetch.subphase.highlight.DefaultHighlighter.highlight(DefaultHighlighter.java:81)
       app/org.elasticsearch.server@8.10.4/org.elasticsearch.search.fetch.subphase.highlight.HighlightPhase$1.process(HighlightPhase.java:69)
       app/org.elasticsearch.server@8.10.4/org.elasticsearch.search.fetch.FetchPhase$1.nextDoc(FetchPhase.java:158)
       app/org.elasticsearch.server@8.10.4/org.elasticsearch.search.fetch.FetchPhaseDocsIterator.iterate(FetchPhaseDocsIterator.java:70)
       app/org.elasticsearch.server@8.10.4/org.elasticsearch.search.fetch.FetchPhase.buildSearchHits(FetchPhase.java:164)
       app/org.elasticsearch.server@8.10.4/org.elasticsearch.search.fetch.FetchPhase.execute(FetchPhase.java:77)
       app/org.elasticsearch.server@8.10.4/org.elasticsearch.search.SearchService.lambda$executeFetchPhase$9(SearchService.java:860)
       app/org.elasticsearch.server@8.10.4/org.elasticsearch.search.SearchService$$Lambda/0x00007f7b9d5f99c0.get(Unknown Source)
       app/org.elasticsearch.server@8.10.4/org.elasticsearch.action.ActionRunnable$2.accept(ActionRunnable.java:51)
       app/org.elasticsearch.server@8.10.4/org.elasticsearch.action.ActionRunnable$2.accept(ActionRunnable.java:48)
       app/org.elasticsearch.server@8.10.4/org.elasticsearch.action.ActionRunnable$3.doRun(ActionRunnable.java:73)
       app/org.elasticsearch.server@8.10.4/org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:26)
       app/org.elasticsearch.server@8.10.4/org.elasticsearch.common.util.concurrent.TimedRunnable.doRun(TimedRunnable.java:33)
       app/org.elasticsearch.server@8.10.4/org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:983)
       app/org.elasticsearch.server@8.10.4/org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:26)
       java.base@21/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
       java.base@21/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
       java.base@21/java.lang.Thread.runWith(Thread.java:1596)
       java.base@21/java.lang.Thread.run(Thread.java:1583)

Any idea why this takes so long?

Regards
Bernd

2

It looks like you're querying the message field... could you check if it is mapped as match_only_text?

I expect you're running into the same issue as reported here: [Bug] Discover document query timeout - 8.12.0 · Issue #175216 · elastic/kibana · GitHub

3

Yes you are right, thanks for pointing in the right direction. So changing the mapping to text would workaround this issue for now (sacrificing disk space)?

4

Yes, that's right, or just disabling highlighting would also help.

5

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.