ES6.1 Heap memory used by the index writer

[loren (Loren Siebert)]

QQ: what would cause IndexWriter memory to constantly spike?

I'm indexing data to a new 3 node ES6.1 cluster running on i3.xlarge instances. Each node is showing roughly equal numbers for index request rate, disk usage, doc counts, shard counts, and merge activity. I'm indexing almost exclusively to two indices, each with 3 shards evenly distributed to the 3 nodes. But one node is GCing a lot and the system load is 4-5x the others. I've restarted the node and quadrupled the heap from 4GB to 16GB, but the frequent GCs are still happening. There are two differences between the problem node and the two well-bahaved nodes:

1. In Monitoring->Nodes->Node 2->Advanced->Index Memory (Elasticsearch), there are frequent Index Writer memory spikes to 20MB. The baseline of ~1MB is what the other two nodes hover at all the time, without any spikes. My hunch is that this is what's creating work for the GC.
2. iotop shows the problem node writing about 3-4x more to disk than the other two nodes.

My best guess at this point is that the node is trying to merge segments and failing, but I'm not seeing any reports of that in the logs. Can anyone suggest what else I should look at, or what transient logging I should enable to shine a light on what is causing that IndexWriter memory to be constantly allocated?

Below are snapshots from Monitoring showing some of the differences, including the Index Writer spikes.

[s1monw (Simon Willnauer)]

I can't see anything odd here. IW memory growing in that way is expected. We monitor it internally and flush it if it gets too large. Can you identify anything else ie. can you capture hot threads when this happens?

[loren (Loren Siebert)]

Thank you for taking a look @s1monw.

Nothing jumped out at me when I ran hot threads. I got different values every time I ran it. Best I can tell, I was just overloading the 2 vCPU's on the i3.large instances. I added some c4 instances with more CPU resources and they didn't show this behavior at all.

I'd been so worried about my workload being IO-bound that I guess I under-provisioned CPU.

[s1monw (Simon Willnauer)]

thanks for reporting back. feel free to ping me here again if you got news

[loren (Loren Siebert)]

Hey @s1monw, I am seeing this high-CPU behavior again and I was able to isolate it to a single shard in an index with 9 shards. The cluster has 9 nodes, with two indices getting indexed heavily. Each index has 9 shards and 1 replica. All the shards have pretty equal document counts and segment sizes.

One node showed a lot of memory pressure with frequent ineffective GC's. I increased the heap from 4GB to 8GB and then again from 8GB to 16GB and the node still showed a lot of GCs, and 10GB+ in the old gen.

I started moving shards off the node one at a time and found a single shard that when moved to a new node immediately spiked the CPU/memory on that node, and completely relieved the pressure on the first node. The shard is 1.1G with 8m docs.

I ran hot threads many times but didn't see a particular stack trace appear every time.

I am going to try splitting the index from 9 to 90 shards.

Meanwhile, is there anything else I should be looking at or trying? I'm on 6.1.3.

[loren (Loren Siebert)]

Might also be relevant to add that this problem index gets a lot of updates, and the updates happen via a Painless script:

{
  "script": {
    "source": "ctx._source.child_ids.add(params.child_id)",
    "params": {
      "child_id": 1234
    }
  }
}

It's maintaining an array that has an average length of 3 but a maximum length of 100,000.

Perhaps if all 100,000 of those Painless updates happened to a given document in series it would place an unusual stress on the shard?

Reading @nik9000's post about how Lucene handles _source has me wondering.

[loren (Loren Siebert)]

The bursts of frequent updates turned out to be the problem. I was able to change the code to batch them up and the JVM heap immediately dropped, CPU usage dropped, and the indexing rate shot up.

[s1monw (Simon Willnauer)]

@loren thanks so much for bringing this to conclusion. I wonder if we can detect things like this down the road but it seems like it isn't a low hanging fruit. good troubleshooting on your end by separating out the problematic shard and getting down to that level.

[loren (Loren Siebert)]

Oddly enough, I think this would have been easier to spot in Marvel on a 1.7 cluster than in Monitoring on a 6.1 cluster, as I suppose I'd have seen per-node spikes in both "Indices Current Merges" and "Disk Write Per (Bytes)".

I knew from iotop that there was more disk activity, but the segment count chart in Monitoring looked like the rest of the nodes and there was no index throttling reported from merges, so I started looking elsewhere. The only thing I could see in the Monitoring screens for each node that was different was the IndexWriter queue, which of course was just a red herring. A timeseries of merge counts would have been really valuable.

I suppose it's uncommon for ES users to sequentially update the same document hundreds of thousands of times while also indexing 5K docs/sec into the same index. Lesson learned!