Slower Query Response Times - Intermittent

israni.amit · March 9, 2021, 5:44am

Hi there,

We recently noticed that some of the queries were having high response times like 12-15 seconds compared to others which were in miliseconds.

We have a query layer (Spring Boot App) which uses RestHighLevelClient to fire queries to ES Nodes.

We pulled out the queries from the logs and ran the same using postman directly to ES nodes and they seem to be performing well.

We have 5 ES nodes (7.10) and each box is 16 GB with 50% allocated to ES. The Active Primary Shards are 25 in our cluster and Total Active Shards are 50.

In total we have around 25 indexes.

We have noticed that the performance degrades sometimes where some queries start showing slower response times but then soon this goes away.

Please help

dadoonet · March 9, 2021, 7:59am

It sounds like a refresh effect.
If the index is not often queried, it will stop refreshing the index to act creating too many segments.

Is that happening in production or only when running your tests?

israni.amit · March 9, 2021, 8:04am

Hi David, thanks for your response.

The indexes are queried often. It happens in production as well.

We ran a load test of 20 users and we could see the behavior frequently.

Thanks,
Amit

dadoonet · March 9, 2021, 8:15am

I'd look at Index modules | Elasticsearch Guide [8.11] | Elastic

And see if this helps.

How often to perform a refresh operation, which makes recent changes to the index visible to search. Defaults to 1s . Can be set to -1 to disable refresh. If this setting is not explicitly set, shards that haven’t seen search traffic for at least index.search.idle.after seconds will not receive background refreshes until they receive a search request. Searches that hit an idle shard where a refresh is pending will wait for the next background refresh (within 1s ). This behavior aims to automatically optimize bulk indexing in the default case when no searches are performed. In order to opt out of this behavior an explicit value of 1s should set as the refresh interval.

israni.amit · March 9, 2021, 8:36am

Hi David, yes the refresh operation is default in our case which means 1s.

The index.search.idle.after is also default which is 30 seconds.

Does it have to be related to how frequently we index documents in our index. We are indexing almost every 2 hours. Can you guide us what value we should use here?

Also all our nodes are having default roles. Will it help if I have specific indexing nodes? All we want to ensure if that data nodes on which the search is being performed are optimized for queries with minimal impact to customer.

Thanks for all your help.

israni.amit · March 9, 2021, 8:38am

Also here is the cluster stats from our environment. If there is any specific thing you can point in this which indicates something is not right.

{
  "_nodes": {
    "total": 5,
    "successful": 5,
    "failed": 0
  },
  "cluster_name": "kcom-production",
  "cluster_uuid": "MbdtdJqbQeSsEI-n67PaQA",
  "timestamp": 1615277226374,
  "status": "green",
  "indices": {
    "count": 25,
    "shards": {
      "total": 50,
      "primaries": 25,
      "replication": 1,
      "index": {
        "shards": {
          "min": 2,
          "max": 2,
          "avg": 2
        },
        "primaries": {
          "min": 1,
          "max": 1,
          "avg": 1
        },
        "replication": {
          "min": 1,
          "max": 1,
          "avg": 1
        }
      }
    },
    "docs": {
      "count": 11071220,
      "deleted": 1126448
    },
    "store": {
      "size_in_bytes": 14783826840,
      "reserved_in_bytes": 0
    },
    "fielddata": {
      "memory_size_in_bytes": 667160,
      "evictions": 0
    },
    "query_cache": {
      "memory_size_in_bytes": 48156246,
      "total_count": 335946247,
      "hit_count": 63218628,
      "miss_count": 272727619,
      "cache_size": 12181,
      "cache_count": 1554431,
      "evictions": 1542250
    },
    "completion": {
      "size_in_bytes": 0
    },
    "segments": {
      "count": 385,
      "memory_in_bytes": 13349014,
      "terms_memory_in_bytes": 10357320,
      "stored_fields_memory_in_bytes": 372024,
      "term_vectors_memory_in_bytes": 0,
      "norms_memory_in_bytes": 1727232,
      "points_memory_in_bytes": 0,
      "doc_values_memory_in_bytes": 892438,
      "index_writer_memory_in_bytes": 14255520,
      "version_map_memory_in_bytes": 0,
      "fixed_bit_set_memory_in_bytes": 755888,
      "max_unsafe_auto_id_timestamp": 1612078346328,
      "file_sizes": {}
    },
    "mappings": {
      "field_types": [
        {
          "name": "date",
          "count": 17,
          "index_count": 17
        },
        {
          "name": "double",
          "count": 58,
          "index_count": 2
        },
        {
          "name": "float",
          "count": 4,
          "index_count": 2
        },
        {
          "name": "keyword",
          "count": 2840,
          "index_count": 25
        },
        {
          "name": "long",
          "count": 1269,
          "index_count": 5
        },
        {
          "name": "nested",
          "count": 7,
          "index_count": 4
        },
        {
          "name": "object",
          "count": 679,
          "index_count": 8
        },
        {
          "name": "text",
          "count": 3038,
          "index_count": 25
        }
      ]
    },
    "analysis": {
      "char_filter_types": [],
      "tokenizer_types": [],
      "filter_types": [
        {
          "name": "edge_ngram",
          "count": 24,
          "index_count": 13
        },
        {
          "name": "ngram",
          "count": 11,
          "index_count": 11
        }
      ],
      "analyzer_types": [
        {
          "name": "custom",
          "count": 58,
          "index_count": 14
        }
      ],
      "built_in_char_filters": [
        {
          "name": "icu_normalizer",
          "count": 11,
          "index_count": 11
        }
      ],
      "built_in_tokenizers": [
        {
          "name": "keyword",
          "count": 1,
          "index_count": 1
        },
        {
          "name": "kuromoji_tokenizer",
          "count": 11,
          "index_count": 11
        },
        {
          "name": "nori_tokenizer",
          "count": 11,
          "index_count": 11
        },
        {
          "name": "smartcn_tokenizer",
          "count": 11,
          "index_count": 11
        },
        {
          "name": "standard",
          "count": 24,
          "index_count": 13
        }
      ],
      "built_in_filters": [
        {
          "name": "cjk_width",
          "count": 11,
          "index_count": 11
        },
        {
          "name": "ja_stop",
          "count": 11,
          "index_count": 11
        },
        {
          "name": "kuromoji_baseform",
          "count": 11,
          "index_count": 11
        },
        {
          "name": "kuromoji_part_of_speech",
          "count": 11,
          "index_count": 11
        },
        {
          "name": "kuromoji_stemmer",
          "count": 11,
          "index_count": 11
        },
        {
          "name": "lowercase",
          "count": 58,
          "index_count": 14
        },
        {
          "name": "nori_part_of_speech",
          "count": 11,
          "index_count": 11
        },
        {
          "name": "nori_readingform",
          "count": 11,
          "index_count": 11
        },
        {
          "name": "smartcn_stop",
          "count": 11,
          "index_count": 11
        }
      ],
      "built_in_analyzers": [
        {
          "name": "german",
          "count": 15,
          "index_count": 5
        },
        {
          "name": "kuromoji",
          "count": 42,
          "index_count": 9
        },
        {
          "name": "nori",
          "count": 42,
          "index_count": 9
        },
        {
          "name": "portuguese",
          "count": 15,
          "index_count": 5
        },
        {
          "name": "russian",
          "count": 15,
          "index_count": 5
        },
        {
          "name": "smartcn",
          "count": 42,
          "index_count": 9
        },
        {
          "name": "standard",
          "count": 42,
          "index_count": 9
        }
      ]
    }
  },
  "nodes": {
    "count": {
      "total": 5,
      "coordinating_only": 0,
      "data": 5,
      "ingest": 5,
      "master": 5,
      "ml": 5,
      "remote_cluster_client": 5,
      "transform": 5,
      "voting_only": 0
    },
    "versions": [
      "7.9.0"
    ],
    "os": {
      "available_processors": 40,
      "allocated_processors": 40,
      "names": [
        {
          "name": "Linux",
          "count": 5
        }
      ],
      "pretty_names": [
        {
          "pretty_name": "Amazon Linux 2",
          "count": 5
        }
      ],
      "mem": {
        "total_in_bytes": 81308901376,
        "free_in_bytes": 7094743040,
        "used_in_bytes": 74214158336,
        "free_percent": 9,
        "used_percent": 91
      }
    },
    "process": {
      "cpu": {
        "percent": 15
      },
      "open_file_descriptors": {
        "min": 447,
        "max": 474,
        "avg": 461
      }
    },
    "jvm": {
      "max_uptime_in_millis": 3198760874,
      "versions": [
        {
          "version": "14.0.1",
          "vm_name": "OpenJDK 64-Bit Server VM",
          "vm_version": "14.0.1+7",
          "vm_vendor": "AdoptOpenJDK",
          "bundled_jdk": true,
          "using_bundled_jdk": true,
          "count": 5
        }
      ],
      "mem": {
        "heap_used_in_bytes": 12763383280,
        "heap_max_in_bytes": 42949672960
      },
      "threads": 337
    },
    "fs": {
      "total_in_bytes": 1584664739840,
      "free_in_bytes": 1558152237056,
      "available_in_bytes": 1477537714176
    },
    "plugins": [
      {
        "name": "analysis-kuromoji",
        "version": "7.9.0",
        "elasticsearch_version": "7.9.0",
        "java_version": "1.8",
        "description": "The Japanese (kuromoji) Analysis plugin integrates Lucene kuromoji analysis module into elasticsearch.",
        "classname": "org.elasticsearch.plugin.analysis.kuromoji.AnalysisKuromojiPlugin",
        "extended_plugins": [],
        "has_native_controller": false
      },
      {
        "name": "analysis-icu",
        "version": "7.9.0",
        "elasticsearch_version": "7.9.0",
        "java_version": "1.8",
        "description": "The ICU Analysis plugin integrates the Lucene ICU module into Elasticsearch, adding ICU-related analysis components.",
        "classname": "org.elasticsearch.plugin.analysis.icu.AnalysisICUPlugin",
        "extended_plugins": [],
        "has_native_controller": false
      },
      {
        "name": "analysis-smartcn",
        "version": "7.9.0",
        "elasticsearch_version": "7.9.0",
        "java_version": "1.8",
        "description": "Smart Chinese Analysis plugin integrates Lucene Smart Chinese analysis module into elasticsearch.",
        "classname": "org.elasticsearch.plugin.analysis.smartcn.AnalysisSmartChinesePlugin",
        "extended_plugins": [],
        "has_native_controller": false
      },
      {
        "name": "analysis-nori",
        "version": "7.9.0",
        "elasticsearch_version": "7.9.0",
        "java_version": "1.8",
        "description": "The Korean (nori) Analysis plugin integrates Lucene nori analysis module into elasticsearch.",
        "classname": "org.elasticsearch.plugin.analysis.nori.AnalysisNoriPlugin",
        "extended_plugins": [],
        "has_native_controller": false
      }
    ],
    "network_types": {
      "transport_types": {
        "security4": 5
      },
      "http_types": {
        "security4": 5
      }
    },
    "discovery_types": {
      "zen": 5
    },
    "packaging_types": [
      {
        "flavor": "default",
        "type": "rpm",
        "count": 5
      }
    ],
    "ingest": {
      "number_of_pipelines": 2,
      "processor_stats": {
        "gsub": {
          "count": 0,
          "failed": 0,
          "current": 0,
          "time_in_millis": 0
        },
        "script": {
          "count": 0,
          "failed": 0,
          "current": 0,
          "time_in_millis": 0
        }
      }
    }
  }
}

dadoonet · April 2, 2021, 9:41am

I'd probably run:

A manual refresh after the injection of the new data
Run some searches on the new index to warm it up

system · April 30, 2021, 9:42am

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

Topic		Replies	Views
Slow response times query first couple of times Elasticsearch	3	566	October 22, 2021
Slow first request on an index after a short amount of time Elasticsearch	6	9901	March 13, 2020
Elasticsearch bulk slows down after a certain amount of documents Elasticsearch	4	1288	April 24, 2020
ES Index performance Elasticsearch	26	994	July 6, 2017
ES 7.0 takes longer to respond the first search query Elasticsearch elastic-stack-monitoring	2	435	June 28, 2019

Slower Query Response Times - Intermittent

Related topics