CircuitBreakingException on extremely small dataset

[tylersmalley]

Elasticsearch version: alpha2

JVM version: build 1.8.0_74-b02

OS version: OS X El Capitan 10.11.3

Description of the problem including expected versus actual behavior:

Steps to reproduce:

1. Install and run elasticsearch-alpha2, topbeat-alpha2, and kibana-alpha2 (Topbeat is only monitoring the node process on a 20 second interval.)

2. I am using Kibana to monitor a node process. Here is the query Kibana is using to generate the visualization:

   {
      "size":0,
      "aggs":{
         "2":{
            "date_histogram":{
               "field":"@timestamp",
               "interval":"30s",
               "time_zone":"America/Los_Angeles",
               "min_doc_count":1
            },
            "aggs":{
               "1":{
                  "max":{
                     "field":"proc.mem.rss"
                  }
               }
            }
         }
      },
      "highlight":{
         "pre_tags":[
            "@kibana-highlighted-field@"
         ],
         "post_tags":[
            "@/kibana-highlighted-field@"
         ],
         "fields":{
            "*":{
   
            }
         },
         "require_field_match":false,
         "fragment_size":2147483647
      },
      "query":{
         "bool":{
            "must":[
               {
                  "query_string":{
                     "query":"*",
                     "analyze_wildcard":true
                  }
               },
               {
                  "match":{
                     "proc.cmdline":{
                        "query":"/Users/tyler/.nvm/versions/node/v4.4.3/bin/node ./bin/../src/cli",
                        "type":"phrase"
                     }
                  }
               },
               {
                  "range":{
                     "@timestamp":{
                        "gte":1462389453519,
                        "lte":1462390353519,
                        "format":"epoch_millis"
                     }
                  }
               }
            ],
            "must_not":[
   
            ]
         }
      }
   }

3. Run for about 30 minutes.

I have 1027 documents, and the total size is 1.6MB.

Provide logs (if relevant):

CircuitBreakingException[[parent] Data too large, data for [<http_request>] would be larger than limit of [726571417/692.9mb]]
    at org.elasticsearch.indices.breaker.HierarchyCircuitBreakerService.checkParentLimit(HierarchyCircuitBreakerService.java:211)
    at org.elasticsearch.common.breaker.ChildMemoryCircuitBreaker.addEstimateBytesAndMaybeBreak(ChildMemoryCircuitBreaker.java:128)
    at org.elasticsearch.http.HttpServer.dispatchRequest(HttpServer.java:109)
    at org.elasticsearch.http.netty.NettyHttpServerTransport.dispatchRequest(NettyHttpServerTransport.java:489)
    at org.elasticsearch.http.netty.HttpRequestHandler.messageReceived(HttpRequestHandler.java:65)
    at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70)
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)
    at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)
    at org.elasticsearch.http.netty.pipelining.HttpPipeliningHandler.messageReceived(HttpPipeliningHandler.java:85)
    at org.jboss.netty.channel.SimpleChannelHandler.handleUpstream(SimpleChannelHandler.java:88)
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)
    at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)
    at org.jboss.netty.handler.codec.http.HttpChunkAggregator.messageReceived(HttpChunkAggregator.java:145)
    at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70)
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)
    at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)
    at org.jboss.netty.handler.codec.http.HttpContentDecoder.messageReceived(HttpContentDecoder.java:108)
    at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70)
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)
    at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)
    at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:296)
    at org.jboss.netty.handler.codec.frame.FrameDecoder.unfoldAndFireMessageReceived(FrameDecoder.java:459)
    at org.jboss.netty.handler.codec.replay.ReplayingDecoder.callDecode(ReplayingDecoder.java:536)
    at org.jboss.netty.handler.codec.replay.ReplayingDecoder.messageReceived(ReplayingDecoder.java:435)
    at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70)
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)
    at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)
    at org.elasticsearch.common.netty.OpenChannelsHandler.handleUpstream(OpenChannelsHandler.java:83)
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:559)
    at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:268)
    at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:255)
    at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:88)
    at org.jboss.netty.channel.socket.nio.AbstractNioWorker.process(AbstractNioWorker.java:108)
    at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:337)
    at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:89)
    at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178)
    at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108)
    at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:42)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)

Eventually, all requests to ES will fail with this exception including _stats.

[nik9000]

"fun"

data for [<http_request>] would be larger than limit of [726571417/692.9mb]

@danielmitterdorfer this might be you though it is hard to tell.

@tylersmalley is there any chance you can take a thread dump when this happens? Maybe just the hot_threads API (though it might not work because of the breaker)?

[tylersmalley]

@nik9000, I will get that once it returns to a failed state again.

[nik9000]

@nik9000, I will get that once it returns to a failed state again.

Thanks!

[tylersmalley]

The _msearch requests will begin failing before the entire ES cluster. Nothing ever appeared in /_nodes/hot_threads and eventually it would fail with the same exception:

{
  "error" : {
    "root_cause" : [ {
      "type" : "circuit_breaking_exception",
      "reason" : "[parent] Data too large, data for [<http_request>] would be larger than limit of [726571417/692.9mb]",
      "bytes_wanted" : 726582240,
      "bytes_limit" : 726571417
    } ],
    "type" : "circuit_breaking_exception",
    "reason" : "[parent] Data too large, data for [<http_request>] would be larger than limit of [726571417/692.9mb]",
    "bytes_wanted" : 726582240,
    "bytes_limit" : 726571417
  },
  "status" : 503
}

Here is the thread dump: https://gist.githubusercontent.com/tylersmalley/00105a27a0dd7b86016d78dc65e1bfb1/raw/jstack_7647_2.log

I will keep the cluster in a failed state should you need any additional information from it.

[nik9000]

Here is the thread dump

It says "I'm not doing anything". Any chance you can get a task list? curl localhost:9200/_tasks should do it. That is another (new and shiny!) way for me to figure out what is going on.

The breaker you are hitting is trying to prevent requests from overwhelming memory. If you had in flight requests I should have seen them doing something in the thread dump. Lots of stuff in Elasticsearch is async so I wouldn't see everything but I expected something. The task list goes the other way - it registers something whenever a request starts and removes it when it stops. If we see something in the task list, especially if it is a lot of somethings, then we have our smoking gun. If we see nothing, well, we go look other places.

The next place might be getting a heap dump. But I'm not going to put you through that. I should be able to reproduce this on my side.

I believe @danielmitterdorfer, who I pinged, will not be around tomorrow so I might just keep this issue.

[tylersmalley]

Any chance you can get a task list?

curl 'http://localhost:9200/_tasks?pretty=true'
{
  "error" : {
    "root_cause" : [ {
      "type" : "circuit_breaking_exception",
      "reason" : "[parent] Data too large, data for [<http_request>] would be larger than limit of [726571417/692.9mb]",
      "bytes_wanted" : 726582240,
      "bytes_limit" : 726571417
    } ],
    "type" : "circuit_breaking_exception",
    "reason" : "[parent] Data too large, data for [<http_request>] would be larger than limit of [726571417/692.9mb]",
    "bytes_wanted" : 726582240,
    "bytes_limit" : 726571417
  },
  "status" : 503
}

I will restart the cluster and monitor the _tasks endpoint until it begins throwing exceptions and report back.

Here is a heap dump in its current failed state: https://gist.github.com/tylersmalley/00105a27a0dd7b86016d78dc65e1bfb1/raw/jmap_7647.bin

[danielmitterdorfer]

@nik9000 I tried to reproduce the scenario locally by running topbeat and running the query above periodically but so far the circuit breaker did not trip. I am not surprised that the thread dump does not reveal much because the circuit breaker essentially prevents further work from coming into the system. Based on an analysis of the heap dump I guess that the system is not really busy but the bytes are not freed properly and add up over time. I had a closer look at how the bytes are freed in HttpServer.ResourceHandlingHttpChannel:

inFlightRequestsBreaker(circuitBreakerService).addWithoutBreaking(-request().content().length());

Considering that the content is represented by a ChannelBufferBytesReference which returns the readable bytes in the channel buffer we could end up in a situation where we reserve more bytes than we free (as the readable bytes could change over time). But this is only a theory and I was not able to observe this behavior. If this were the case, the fix is to simply provide the number of reserved bytes to HttpServer.ResourceHandlingHttpChannel but I am somewhat reluctant to do a fix without being able to reproduce it.

[danielmitterdorfer]

I have also installed Kibana 5.0.0-alpha2, imported the dashboard from topbeat, opened it and set it to auto-refresh every 5 seconds. I could just see that the request breaker (which is used by BigArrays) is slowly increasing (a few MB after a few minutes). The inflight requests breaker always resets to zero. I think it just happens to be the victim as it's trying very early during request processing to reserve an amount of bytes (we can also see from the stack trace that actually the parent circuit breaker is tripping, not the inflight requests breaker).

So I followed the respective close() calls that are supposed to free the reserved bytes but there are a lot of places to follow. @dakrone: Is it intended that the number of reserved bytes in the request circuit breaker grow over time as BigArrays seems to be intended as some kind of pool or should the reserved number of bytes in BigArrays be zero after a request has been processed?

[dakrone]

@danielmitterdorfer in my testing the request circuit breaker (backing BigArrays) has always reset to 0 if there are no requests

You should be able to turn on TRACE logging for the org.elasticsearch.indices.breaker package and see all increments and decrements to the breakers (note this is very verbose)

[danielmitterdorfer]

@dakrone Thanks for the hint. I'll check that.

[tylersmalley]

@danielmitterdorfer I believe to have found what was causing this on my end, but unsure if it should have triggered the the CircuitBreaker. While doing other testing I still had a script running which hit the cluster/_health endpoint, paused for 100ms, then repeated. I am fairly certain this was not an issue in 2.3, but I can double check.