Failed to send release search context - SourceLookup fetching cost (?)

We have recently changed some of our code to include additional call to
SourceLookup.extractValue(path) in fetch stage. Soon after, we have started
experiencing some issues with search stability (with some of our searches
failing to finish, others taking very long).

I can see search lookup queue getting filled up (to 1000) and I can see the
following spamming the logs:

es-cluster-3-3 elasticsearch[2014-05-26 18:59:28,584][WARN ][search.action
] [Maeby] Failed to send release search context
es-cluster-3-3
elasticsearchorg.elasticsearch.transport.SendRequestTransportException:
[Oscar][inet[/10.0.0.1/ip-10-0-0-1.eu-west-1.compute.internal:9300]][search/freeContext]
es-cluster-3-3 elasticsearch at
org.elasticsearch.transport.TransportService.sendRequest(TransportService.java:202)
es-cluster-3-3 elasticsearch at
org.elasticsearch.transport.TransportService.sendRequest(TransportService.java:173)
es-cluster-3-3 elasticsearch at
org.elasticsearch.search.action.SearchServiceTransportAction.sendFreeContext(SearchServiceTransportAction.java:103)
es-cluster-3-3 elasticsearch at
org.elasticsearch.action.search.type.TransportSearchTypeAction$BaseAsyncAction.releaseIrrelevantSearchContexts(TransportSearchTypeAction.java:392)
es-cluster-3-3 elasticsearch at
org.elasticsearch.action.search.type.TransportSearchQueryThenFetchAction$AsyncAction.finishHim(TransportSearchQueryThenFetchAction.java:191)
es-cluster-3-3 elasticsearch at
org.elasticsearch.action.search.type.TransportSearchQueryThenFetchAction$AsyncAction.onFetchFailure(TransportSearchQueryThenFetchAction.java:177)
es-cluster-3-3 elasticsearch at
org.elasticsearch.action.search.type.TransportSearchQueryThenFetchAction$AsyncAction$3.onFailure(TransportSearchQueryThenFetchAction.java:165)
es-cluster-3-3 elasticsearch at
org.elasticsearch.search.action.SearchServiceTransportAction$10.handleException(SearchServiceTransportAction.java:426)
es-cluster-3-3 elasticsearch at
org.elasticsearch.transport.TransportService$Adapter$2$1.run(TransportService.java:316)
es-cluster-3-3 elasticsearch at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
es-cluster-3-3 elasticsearch at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
es-cluster-3-3 elasticsearch at java.lang.Thread.run(Thread.java:745)
es-cluster-3-3 elasticsearchCaused by:
org.elasticsearch.transport.NodeNotConnectedException:
[Oscar][inet[/10.0.0.1/ip-10-0-0-1.eu-west-1.compute.internal:9300]] Node
not connected
es-cluster-3-3 elasticsearch at
org.elasticsearch.transport.netty.NettyTransport.nodeChannel(NettyTransport.java:859)
es-cluster-3-3 elasticsearch at
org.elasticsearch.transport.netty.NettyTransport.sendRequest(NettyTransport.java:540)
es-cluster-3-3 elasticsearch at
org.elasticsearch.transport.TransportService.sendRequest(TransportService.java:189)
es-cluster-3-3 elasticsearch ... 11 more

There is also a long GC running at the same time, not sure if it might be
the cause or the effect.
Is it at all possible that this might have been caused by a call to
SourceLookup.extractValue() assuming the field that is extracted was not
specified in the query?

--
You received this message because you are subscribed to the Google Groups "elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send an email to elasticsearch+unsubscribe@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/elasticsearch/0b05891b-b578-42fa-8eed-5e5704c4e686%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Anyone encountered something similar / related?

On Tuesday, 27 May 2014 13:46:19 UTC, Mateusz Kaczynski wrote:

We have recently changed some of our code to include additional call to
SourceLookup.extractValue(path) in fetch stage. Soon after, we have
started experiencing some issues with search stability (with some of our
searches failing to finish, others taking very long).

I can see search lookup queue getting filled up (to 1000) and I can see
the following spamming the logs:

es-cluster-3-3 elasticsearch[2014-05-26 18:59:28,584][WARN ][search.action
] [Maeby] Failed to send release search context
es-cluster-3-3
elasticsearchorg.elasticsearch.transport.SendRequestTransportException:
[Oscar][inet[/
10.0.0.1/ip-10-0-0-1.eu-west-1.compute.internal:9300]][search/freeContexthttp://10.0.0.1/ip-10-0-0-1.eu-west-1.compute.internal:9300]][search/freeContext
]
es-cluster-3-3 elasticsearch at
org.elasticsearch.transport.TransportService.sendRequest(TransportService.java:202)
es-cluster-3-3 elasticsearch at
org.elasticsearch.transport.TransportService.sendRequest(TransportService.java:173)
es-cluster-3-3 elasticsearch at
org.elasticsearch.search.action.SearchServiceTransportAction.sendFreeContext(SearchServiceTransportAction.java:103)
es-cluster-3-3 elasticsearch at
org.elasticsearch.action.search.type.TransportSearchTypeAction$BaseAsyncAction.releaseIrrelevantSearchContexts(TransportSearchTypeAction.java:392)
es-cluster-3-3 elasticsearch at
org.elasticsearch.action.search.type.TransportSearchQueryThenFetchAction$AsyncAction.finishHim(TransportSearchQueryThenFetchAction.java:191)
es-cluster-3-3 elasticsearch at
org.elasticsearch.action.search.type.TransportSearchQueryThenFetchAction$AsyncAction.onFetchFailure(TransportSearchQueryThenFetchAction.java:177)
es-cluster-3-3 elasticsearch at
org.elasticsearch.action.search.type.TransportSearchQueryThenFetchAction$AsyncAction$3.onFailure(TransportSearchQueryThenFetchAction.java:165)
es-cluster-3-3 elasticsearch at
org.elasticsearch.search.action.SearchServiceTransportAction$10.handleException(SearchServiceTransportAction.java:426)
es-cluster-3-3 elasticsearch at
org.elasticsearch.transport.TransportService$Adapter$2$1.run(TransportService.java:316)
es-cluster-3-3 elasticsearch at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
es-cluster-3-3 elasticsearch at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
es-cluster-3-3 elasticsearch at java.lang.Thread.run(Thread.java:745)
es-cluster-3-3 elasticsearchCaused by:
org.elasticsearch.transport.NodeNotConnectedException: [Oscar][inet[/
10.0.0.1/ip-10-0-0-1.eu-west-1.compute.internal:9300]] Node not connected
es-cluster-3-3 elasticsearch at
org.elasticsearch.transport.netty.NettyTransport.nodeChannel(NettyTransport.java:859)
es-cluster-3-3 elasticsearch at
org.elasticsearch.transport.netty.NettyTransport.sendRequest(NettyTransport.java:540)
es-cluster-3-3 elasticsearch at
org.elasticsearch.transport.TransportService.sendRequest(TransportService.java:189)
es-cluster-3-3 elasticsearch ... 11 more

There is also a long GC running at the same time, not sure if it might be
the cause or the effect.
Is it at all possible that this might have been caused by a call to
SourceLookup.extractValue() assuming the field that is extracted was not
specified in the query?

--
You received this message because you are subscribed to the Google Groups "elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send an email to elasticsearch+unsubscribe@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/elasticsearch/8f226f6e-e453-4bb9-b204-2c61a9f30662%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Anyone encoutered something similar / related?

--
You received this message because you are subscribed to the Google Groups "elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send an email to elasticsearch+unsubscribe@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/elasticsearch/498619f8-f05b-44ca-8846-3e15a15946c6%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.