Highlighting slows down Kibana searches considerably

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

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

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)?

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