Elasticsearch 7.6.2 "[parent] Data Too Large": Troubleshooting a Circuit Breaker Exception

Posted on Edited on Views: Word count in article: 2k Reading time ≈ 2 mins.
Troubleshooting the "[parent] Data too large" circuit breaker on Elasticsearch 7.6.2: how use_real_memory and G1 GC interact. The JVM flags here apply to that era's clusters only.

The problem triggered by indices.breaker.total.use_real_memory

🕰️ Version note: This post was written in 2020, against an Elasticsearch 7.6.2 cluster. The technology moves fast — read it alongside the version you actually run.

Recently our business-logs ES (7.6.2) cluster kept returning this exception on writes:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
2020-11-24T02:59:05.557085524Z {"type": "server", "timestamp": "2020-11-24T02:59:05,556Z", "level": "DEBUG", "component": "o.e.a.a.c.n.i.TransportNodesInfoAction", "cluster.name": "business-log", "node.name": "es-b-193", "message": "failed to execute on node [EKFLTB1jTrSbTHi80t8lDw]", "cluster.uuid": "ArYy-qmCTbCQTDUI8ogsBg", "node.id": "w8mHCBNORpa8P73ML3c1zg" ,
2020-11-24T02:59:05.557111874Z "stacktrace": ["org.elasticsearch.transport.RemoteTransportException: [es-b-194][127.0.0.1:9300][cluster:monitor/nodes/info[n]]",
2020-11-24T02:59:05.557116050Z "Caused by: org.elasticsearch.common.breaker.CircuitBreakingException: [parent] Data too large, data for [<transport_request>] would be [27684654388/25.7gb], which is larger than the limit of [26521423052/24.6gb], real usage: [27684652880/25.7gb], new bytes reserved: [1508/1.4kb], usages [request=0/0b, fielddata=19858/19.3kb, in_flight_requests=2805740/2.6mb, accounting=86606929/82.5mb]",
2020-11-24T02:59:05.557120478Z "at org.elasticsearch.indices.breaker.HierarchyCircuitBreakerService.checkParentLimit(HierarchyCircuitBreakerService.java:343) ~[elasticsearch-7.6.2.jar:7.6.2]",
2020-11-24T02:59:05.557123616Z "at org.elasticsearch.common.breaker.ChildMemoryCircuitBreaker.addEstimateBytesAndMaybeBreak(ChildMemoryCircuitBreaker.java:128) ~[elasticsearch-7.6.2.jar:7.6.2]",
2020-11-24T02:59:05.557126392Z "at org.elasticsearch.transport.InboundHandler.handleRequest(InboundHandler.java:171) [elasticsearch-7.6.2.jar:7.6.2]",
2020-11-24T02:59:05.557129043Z "at org.elasticsearch.transport.InboundHandler.messageReceived(InboundHandler.java:119) [elasticsearch-7.6.2.jar:7.6.2]",
2020-11-24T02:59:05.557131767Z "at org.elasticsearch.transport.InboundHandler.inboundMessage(InboundHandler.java:103) [elasticsearch-7.6.2.jar:7.6.2]",
2020-11-24T02:59:05.557134387Z "at org.elasticsearch.transport.TcpTransport.inboundMessage(TcpTransport.java:667) [elasticsearch-7.6.2.jar:7.6.2]",
2020-11-24T02:59:05.557137050Z "at org.elasticsearch.transport.netty4.Netty4MessageChannelHandler.channelRead(Netty4MessageChannelHandler.java:62) [transport-netty4-client-7.6.2.jar:7.6.2]",
2020-11-24T02:59:05.557139775Z "at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374) [netty-transport-4.1.43.Final.jar:4.1.43.Final]",
2020-11-24T02:59:05.557143378Z "at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360) [netty-transport-4.1.43.Final.jar:4.1.43.Final]",
2020-11-24T02:59:05.557146200Z "at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352) [netty-transport-4.1.43.Final.jar:4.1.43.Final]",
2020-11-24T02:59:05.557157569Z "at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:326) [netty-codec-4.1.43.Final.jar:4.1.43.Final]",
2020-11-24T02:59:05.557160772Z "at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:300) [netty-codec-4.1.43.Final.jar:4.1.43.Final]",
2020-11-24T02:59:05.557163614Z "at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374) [netty-transport-4.1.43.Final.jar:4.1.43.Final]",
2020-11-24T02:59:05.557166366Z "at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360) [netty-transport-4.1.43.Final.jar:4.1.43.Final]",
2020-11-24T02:59:05.557169060Z "at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352) [netty-transport-4.1.43.Final.jar:4.1.43.Final]",
2020-11-24T02:59:05.557171799Z "at io.netty.handler.logging.LoggingHandler.channelRead(LoggingHandler.java:241) [netty-handler-4.1.43.Final.jar:4.1.43.Final]",
2020-11-24T02:59:05.557174627Z "at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374) [netty-transport-4.1.43.Final.jar:4.1.43.Final]",
2020-11-24T02:59:05.557177412Z "at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360) [netty-transport-4.1.43.Final.jar:4.1.43.Final]",
2020-11-24T02:59:05.557180299Z "at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352) [netty-transport-4.1.43.Final.jar:4.1.43.Final]",
2020-11-24T02:59:05.557182991Z "at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1422) [netty-transport-4.1.43.Final.jar:4.1.43.Final]",
2020-11-24T02:59:05.557185677Z "at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374) [netty-transport-4.1.43.Final.jar:4.1.43.Final]",
2020-11-24T02:59:05.557188907Z "at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360) [netty-transport-4.1.43.Final.jar:4.1.43.Final]",
2020-11-24T02:59:05.557191750Z "at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:931) [netty-transport-4.1.43.Final.jar:4.1.43.Final]",
2020-11-24T02:59:05.557194464Z "at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163) [netty-transport-4.1.43.Final.jar:4.1.43.Final]",
2020-11-24T02:59:05.557197166Z "at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:700) [netty-transport-4.1.43.Final.jar:4.1.43.Final]",
2020-11-24T02:59:05.557199910Z "at io.netty.channel.nio.NioEventLoop.processSelectedKeysPlain(NioEventLoop.java:600) [netty-transport-4.1.43.Final.jar:4.1.43.Final]",
2020-11-24T02:59:05.557202599Z "at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:554) [netty-transport-4.1.43.Final.jar:4.1.43.Final]",
2020-11-24T02:59:05.557205278Z "at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:514) [netty-transport-4.1.43.Final.jar:4.1.43.Final]",
2020-11-24T02:59:05.557207911Z "at io.netty.util.concurrent.SingleThreadEventExecutor$6.run(SingleThreadEventExecutor.java:1050) [netty-common-4.1.43.Final.jar:4.1.43.Final]",
2020-11-24T02:59:05.557214146Z "at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [netty-common-4.1.43.Final.jar:4.1.43.Final]",
2020-11-24T02:59:05.557216961Z "at java.lang.Thread.run(Thread.java:830) [?:?]"] }

At the time of the exception, jvm.options was configured like this:

1
2
3
4
5
6
7
8
9
10
11
12
## GC configuration
#-XX:+UseConcMarkSweepGC
#-XX:CMSInitiatingOccupancyFraction=75
#-XX:+UseCMSInitiatingOccupancyOnly

## G1GC Configuration
# NOTE: G1GC is only supported on JDK version 10 or later.
# To use G1GC uncomment the lines below.
#-XX:-UseConcMarkSweepGC
#-XX:-UseCMSInitiatingOccupancyOnly
-XX:+UseG1GC
-XX:InitiatingHeapOccupancyPercent=75

After some digging, the problem turned out to be caused by
indices.breaker.total.use_real_memory, introduced in Elasticsearch 7.x.
Per the docs, indices.breaker.total.use_real_memory controls the memory the JVM actually uses.

So at what level of JVM memory usage does the breaker trip?

The cluster’s default settings show that indices.breaker.total.limit defaults to 95%:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
curl --location --request GET 'http://127.0.0.1:9200/_cluster/settings?include_defaults&flat_settings&local&filter_path=defaults.indices*'


{
	"defaults": {
		"indices.analysis.hunspell.dictionary.ignore_case": "false",
		"indices.analysis.hunspell.dictionary.lazy": "false",
		"indices.breaker.accounting.limit": "100%",
		"indices.breaker.accounting.overhead": "1.0",
		"indices.breaker.fielddata.limit": "40%",
		"indices.breaker.fielddata.overhead": "1.03",
		"indices.breaker.fielddata.type": "memory",
		"indices.breaker.request.limit": "60%",
		"indices.breaker.request.overhead": "1.0",
		"indices.breaker.request.type": "memory",
		"indices.breaker.total.limit": "95%",
		"indices.breaker.total.use_real_memory": "true",
		"indices.breaker.type": "hierarchy",
		"indices.cache.cleanup_interval": "1m",
		"indices.fielddata.cache.size": "-1b",
		"indices.id_field_data.enabled": "true",
		"indices.lifecycle.history_index_enabled": "true",
		"indices.lifecycle.poll_interval": "10m",
		"indices.mapping.dynamic_timeout": "30s",
		"indices.memory.index_buffer_size": "10%",
		"indices.memory.interval": "5s",
		"indices.memory.max_index_buffer_size": "-1",
		"indices.memory.min_index_buffer_size": "48mb",
		"indices.memory.shard_inactive_time": "5m",
		"indices.queries.cache.all_segments": "false",
		"indices.queries.cache.count": "10000",
		"indices.queries.cache.size": "10%",
		"indices.query.bool.max_clause_count": "1024",
		"indices.query.query_string.allowLeadingWildcard": "true",
		"indices.query.query_string.analyze_wildcard": "false",
		"indices.recovery.internal_action_long_timeout": "1800000ms",
		"indices.recovery.internal_action_timeout": "15m",
		"indices.recovery.max_bytes_per_sec": "40mb",
		"indices.recovery.max_concurrent_file_chunks": "2",
		"indices.recovery.recovery_activity_timeout": "1800000ms",
		"indices.recovery.retry_delay_network": "5s",
		"indices.recovery.retry_delay_state_sync": "500ms",
		"indices.requests.cache.expire": "0ms",
		"indices.requests.cache.size": "1%",
		"indices.store.delete.shard.timeout": "30s"
	}
}

Why does the breaker trip frequently once indices.breaker.total.use_real_memory is enabled by default and the GC algorithm is G1?

First, a few G1 parameters:

  • InitiatingHeapOccupancyPercent: the heap occupancy threshold at which G1 starts a concurrent cycle; it decides whether a parallel cycle begins. The logic: after a GC completes, G1 compares the space occupied by the old generation against the whole Java heap. If the ratio exceeds this value, it schedules the next GC to start a parallel cycle, beginning with the initial marking phase. The smaller the value, the more frequent the GC; the larger the value, the longer the application gets to run. When memory is being consumed fast, though, I believe running the cycle early beats running it late — better to treat the disease while it is still early.
  • G1NewSizePercent: the initial young generation size, default 5%
  • G1MaxNewSizePercent: the maximum young generation size, default 60% of the whole Java heap

For the detailed analysis of this problem, see: https://github.com/elastic/elasticsearch/pull/46169

Simply put: the previous default configuration in Elasticsearch’s jvm.options causes the old generation + young generation memory usage to exceed 95% (theoretically the memory threshold can reach 60+75=135), which causes frequent circuit breaking.

The most effective way to fix this is to adjust the GC algorithm according to the JDK version:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
# GC configuration
8-13:-XX:+UseConcMarkSweepGC
8-13:-XX:CMSInitiatingOccupancyFraction=75
8-13:-XX:+UseCMSInitiatingOccupancyOnly

## G1GC Configuration
# NOTE: G1 GC is only supported on JDK version 10 or later
# to use G1GC, uncomment the next two lines and update the version on the
# following three lines to your version of the JDK
# 10-13:-XX:-UseConcMarkSweepGC
# 10-13:-XX:-UseCMSInitiatingOccupancyOnly
14-:-XX:+UseG1GC
14-:-XX:G1ReservePercent=25
14-:-XX:InitiatingHeapOccupancyPercent=30

This is also the default configuration in the latest Elasticsearch jvm.options.

This article is the English edition of a post originally published in Chinese.