Investigate high GC time when indexing

Elastic Stack Elasticsearch
1

Hello,

I am looking for some advice as to why we are seeing a high GC time on our Elasticsearch cluster. On average, we see 5 - 8% of GC time across all the nodes. This is the setup we have:

  • 150 data nodes
  • 1000 primary shards and each has 2 replicas
  • each data node is receiving max up to 2k indexing calls, but avg is usually 200
  • avg doc size = 3 kb
  • refresh_interval = 10 sec
  • We provide the document id and an external version, so it is doing a lot of merges

Initially, we thought it is due to the high indexing rate, but looking at this benchmark docs like this Benchmarking and sizing your Elasticsearch cluster for logs and metrics | Elastic Blog, it seems es should be able to handle the current load easily. So could it be:

  • as we provide our own document id, too many merges?
  • or our doc size is too big/too many fields and that takes time?
  • or it's probably some memory/heap misconfiguration?

Our end goal is to bring down refresh_interval to as low as possible, but a bit unsure with such a high GC.

Any help would be greatly appreciated.

2

Which version of Elasticsearch are you using?

What is the specification of the data nodes with respect to CPU allocation, RAM and heap size?

What type of storage are you using?

What is your average shard size? How much data does each node hold?

What is the full output of the cluster stats APi?

Is this 2k bulk indexing requests per second? Would 2k indexing calls mean 300k indexing requests per second across the cluster?

Is this a single index or multiple indices? If multiple indices, how many indices can a single bulk indexing request cover?

1 Like
3

Thanks @Christian_Dahlqvist for the response. Here are the answers:

  • Which version of Elasticsearch are you using? - Elasticsearch version 7.10
  • What is the specification of the data nodes with respect to CPU allocation, RAM and heap size? -
    • heap: 27 gb/node
    • ram: 61.8gb/node
    • cpu allocation - Our usage is around 30 - 40%. I will back to you with the exact allocation soon.
  • What is your average shard size? - 12 GB, 4.7 million docs
  • How much data does each node hold? - 250 gb
  • What type of storage are you using? - gp2
  • What is the full output of the cluster stats APi? - stats.json · GitHub
  • Is this 2k bulk indexing requests per second? - No, that is individual indexing count, but we use bulk indexing. Per node, we see max 2k/sec and avg 300/sec. For the entire cluster, we see max 30k/sec and avg 10k/sec.
  • Is this a single index or multiple indices? - It is a single index
4

This version is often used with third-party plugins, which naturally can affect heap usage and GC. Do you have any third-party plugins installed?

What is the size of gp2 storage per node? Small volumes can have very low IOPS which can cause performance issues. Given the number of shards in your index I would expect a lot of small writes to shards even if you use quite large bulk requests, which could overhead. The fact that you are updating and using your own IDs will also add a lot of reads. What does I/O performance look like if you run e.g. iostat -x on the data nodes?

"versions": [
{
"bundled_jdk": false,
"count": 165,
"using_bundled_jdk": null,
"version": "17.0.3",
}
]

The stats you provided shows that you seem to be using a JVM that is not officially supported according to the official support matrix. Not sure if this could have any impact or special configuration considerations.

5

Ya, we have a few plugins installed. Is there a way to see what impact it could be having?

30 GB

A few general questions:

  • Is there a max indexing rate per node/shard per sec?
  • With our current indexing rate, if we do change some configuration, would it be possible to have a very low refresh interval like 1 sec OR that is just too low for our volume? Could adding more data nodes help or splitting the cluster?
  • Does the number of fields in a doc impact GC?
6

TBH the simplest piece of tuning advice we can offer is to use a newer version. 7.10.2 passed EOL a long time ago, and there's been a lot of performance-related improvements in the ~2½ years since it was released, some of which I would expect to reduce the load on the GC.

You could try using something like async profiler to understand where the time is being spent and/or what bits of the system are allocating the most heap objects (which directly contributes to GC pressure). Maybe that will point to problems in a particular plugin.

30k docs per sec does seem very low for such a large cluster. It very much depends on the details of the workload, but at least some of the nightly benchmarks achieve several times that ingest rate using just 3 nodes running recent versions.

1 Like
7

@DavidTurner @Christian_Dahlqvist wanted to follow up. We did some testing and analysis. For example: we set up an index with a lot of mapping properties like 10 - 12k and saw a huge increase in GC, up to 20%. Our heap is 27 GB. Based on a few use cases:

  • Do # of mappings in an index have an impact on GC or basically like how the heap is populated?
  • Is the heap somehow split between writes and reads? We are doing writes on this cluster (just for testing) and see around 50 - 60% heap used, but GC is so high, so wondering if something changed in es7?
  • Could the indexing buffer setting impacting it somehow ? Like a 10% indices.memory.index_buffer_size means we are not flushing mesages to disk fast enough and the heap is getting filled up?

Any help is appreciated as always.

8

  • Mappings take up some amount of memory, yes.

  • Heap is not split between writes and reads.

  • The whole point of the indexing buffer is to prevent heap from filling up.

Did you try upgrading? Did you try async profiler? They were the two things I suggested would be most helpful.

9

We just finished upgrading to 7 a few months back, so we are a bit behind here. For the async profiler, I will try that next. I was setting up some use cases in our staging environment and had those questions.

Thanks.

10

@DavidTurner We did the async profiler for allocations on two clusters. The prod cluster has ~6% GC and QA cluster has 1% (not bad but just wanted to compare). There is no clear outlier, but the topmost caller is org/apache/lucene/index/DefaultIndexingChain.flush path. Here are some other stats:

  • prod cluster - html file.

    • 27 GB heap,
    • all gc is in young gc heap
    • The refresh interval is 5 sec.
    • The number of fields per doc is ranging from 100 - 250
    • doc size ~3 kb
    • 36 data ndoes, ~100 individual requests per sec per node

  • qa cluster, html file. 27 GB, but has less volume and doc size.

I will be digging in more, but if you have any advice, please let me know. Thanks.

11

Thanks @ktech007, can you share the profiler options you used too? I think we want to see allocation profiles and wall-clock profiles, which are these?

12

This is the allocation profile: /opt/async-profiler/profiler.sh -e alloc -d 30 -f /tmp/foo.html {pid}.

Are there any specific options you would like for allocation and wall profile?

13

@DavidTurner , I have more data now.

We ran the allocation profile (/opt/async-profiler/profiler.sh -e alloc -d 30 ) and wall clock profile (/opt/async-profiler/profiler.sh -e wall -t -i 5ms) for two clusters that are seeing high GC.

14

These profiles indicate that the nodes are almost completely idle. There's no tuning needed here.

15

So I have an idea. I have been running some tests.

Let's say an index has 3000 mappings and indexing doc with ~100 fields. If we are indexing documents with similar fields, GC is fine. But if I start indexing documents that all have very varied fields, GC starts to go high.

Do you know if there is a cache or something we can adjust?

16

According to these profiles you're barely using your cluster at all. There's no need to worry about GC time here.

17

Ok, thank you. One last question, so high GC would basically impact indexing speed, right? We want to reduce our refresh_interval but one of the concerns was high GC. Do you think it would be ok to reduce it?

18

GC time doesn't look like it's having any impact on performance here.

1 Like
19

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