Hey Jochen,
Yes, I had to manually trigger the index range rebuild. Note that if you
make an API call to /system/indexer/indices/{index}/close it also triggers
a recalc across all indices. Since concurrent range recalcs are not
possible, that means in our system if you make an API call to close an
index, you have to wait 2.5 hours to try to close another. I see warnings
like this frequently:
2015-10-05_14:47:03.98401 WARN [EsIndexRangeService] Couldn't load index
range for index graylog_4128
2015-10-05_14:47:03.99521 WARN [EsIndexRangeService] Couldn't load index
range for index graylog_4132
2015-10-05_14:47:05.33256 WARN [EsIndexRangeService] Couldn't load index
range for index graylog_4135
2015-10-05_14:47:05.33283 WARN [EsIndexRangeService] Couldn't load index
range for index graylog_4136
2015-10-05_14:48:02.03805 WARN [EsIndexRangeService] Couldn't load index
range for index graylog_4128
2015-10-05_14:48:02.03828 WARN [EsIndexRangeService] Couldn't load index
range for index graylog_4132
Since the System->Indices page won't load, I manually made a call
to /system/indices/ranges/rebuild to trigger it. After several hours, it
eventually finds the problematic indices and throws these exceptions:
2015-10-05_03:03:58.03817 INFO [EsIndexRangeService] Calculated range of
[graylog_3282] in [58ms].
2015-10-05_03:04:01.05886 INFO [EsIndexRangeService] Calculated range of
[graylog_3281] in [146ms].
2015-10-05_03:04:05.29949 INFO [EsIndexRangeService] Calculated range of
[graylog_3288] in [57ms].
2015-10-05_03:04:08.30944 ERROR [EsIndexRangeService] Error while
calculating timestamp stats in index <graylog_4136>
2015-10-05_03:04:08.30947
org.elasticsearch.action.search.SearchPhaseExecutionException: Failed to
execute phase [query], all shards failed; shardFailures
{[hPjzunuIQHivOLVhGMugsg][graylog_4136][0]:
RemoteTransportException[[Cethlann][inet[/x.x.x.x:9300]][indices:data/read/search[phase/query]]];
nested:
ClassCastException[org.elasticsearch.index.fielddata.plain.PagedBytesIndexFieldData
cannot be cast to org.elasticsearch.index.fielddata.IndexNumericFieldData];
}{[2lLV-RaMTUWwl74xETQ8HA][graylog_4136][1]:
RemoteTransportException[[Unseen][inet[/x.x.x.x:9300]][indices:data/read/search[phase/query]]];
nested:
ClassCastException[org.elasticsearch.index.fielddata.plain.PagedBytesIndexFieldData
cannot be cast to org.elasticsearch.index.fielddata.IndexNumericFieldData];
}{[2lLV-RaMTUWwl74xETQ8HA][graylog_4136][2]:
RemoteTransportException[[Unseen][inet[/x.x.x.x:9300]][indices:data/read/search[phase/query]]];
nested:
ClassCastException[org.elasticsearch.index.fielddata.plain.PagedBytesIndexFieldData
cannot be cast to org.elasticsearch.index.fielddata.IndexNumericFieldData];
}{[hPjzunuIQHivOLVhGMugsg][graylog_4136][3]:
RemoteTransportException[[Cethlann][inet[/x.x.x.x:9300]][indices:data/read/search[phase/query]]];
nested:
ClassCastException[org.elasticsearch.index.fielddata.plain.PagedBytesIndexFieldData
cannot be cast to org.elasticsearch.index.fielddata.IndexNumericFieldData];
}
2015-10-05_03:04:08.30951 at
org.elasticsearch.action.search.type.TransportSearchTypeAction$BaseAsyncAction.onFirstPhaseResult(TransportSearchTypeAction.java:237)
2015-10-05_03:04:08.30951 at
org.elasticsearch.action.search.type.TransportSearchTypeAction$BaseAsyncAction$1.onFailure(TransportSearchTypeAction.java:183)
2015-10-05_03:04:08.30951 at
org.elasticsearch.search.action.SearchServiceTransportAction$6.handleException(SearchServiceTransportAction.java:249)
2015-10-05_03:04:08.30952 at
org.elasticsearch.transport.netty.MessageChannelHandler.handleException(MessageChannelHandler.java:190)
2015-10-05_03:04:08.30952 at
org.elasticsearch.transport.netty.MessageChannelHandler.handlerResponseError(MessageChannelHandler.java:180)
2015-10-05_03:04:08.30953 at
org.elasticsearch.transport.netty.MessageChannelHandler.messageReceived(MessageChannelHandler.java:130)
2015-10-05_03:04:08.30953 at
org.elasticsearch.common.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70)
2015-10-05_03:04:08.30954 at
org.elasticsearch.common.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)
2015-10-05_03:04:08.30954 at
org.elasticsearch.common.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)
2015-10-05_03:04:08.30955 at
org.elasticsearch.common.netty.channel.Channels.fireMessageReceived(Channels.java:296)
2015-10-05_03:04:08.30955 at
org.elasticsearch.common.netty.handler.codec.frame.FrameDecoder.unfoldAndFireMessageReceived(FrameDecoder.java:462)
2015-10-05_03:04:08.30956 at
org.elasticsearch.common.netty.handler.codec.frame.FrameDecoder.callDecode(FrameDecoder.java:443)
2015-10-05_03:04:08.30956 at
org.elasticsearch.common.netty.handler.codec.frame.FrameDecoder.messageReceived(FrameDecoder.java:303)
2015-10-05_03:04:08.30956 at
org.elasticsearch.common.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70)
2015-10-05_03:04:08.30957 at
org.elasticsearch.common.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)
2015-10-05_03:04:08.30958 at
org.elasticsearch.common.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:559)
2015-10-05_03:04:08.30958 at
org.elasticsearch.common.netty.channel.Channels.fireMessageReceived(Channels.java:268)
2015-10-05_03:04:08.30958 at
org.elasticsearch.common.netty.channel.Channels.fireMessageReceived(Channels.java:255)
2015-10-05_03:04:08.30959 at
org.elasticsearch.common.netty.channel.socket.nio.NioWorker.read(NioWorker.java:88)
2015-10-05_03:04:08.30959 at
org.elasticsearch.common.netty.channel.socket.nio.AbstractNioWorker.process(AbstractNioWorker.java:108)
2015-10-05_03:04:08.30960 at
org.elasticsearch.common.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:337)
2015-10-05_03:04:08.30961 at
org.elasticsearch.common.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:89)
2015-10-05_03:04:08.30961 at
org.elasticsearch.common.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178)
2015-10-05_03:04:08.30961 at
org.elasticsearch.common.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108)
2015-10-05_03:04:08.30962 at
org.elasticsearch.common.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:42)
2015-10-05_03:04:08.30963 at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
2015-10-05_03:04:08.30963 at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
2015-10-05_03:04:08.30964 at java.lang.Thread.run(Thread.java:745)
2015-10-05_03:04:08.31020 INFO [RebuildIndexRangesJob] Could not calculate
range of index [graylog_4136]. Skipping.
2015-10-05_03:04:08.31022 org.elasticsearch.indices.IndexMissingException:
[graylog_4136] missing
2015-10-05_03:04:08.31022 at
org.graylog2.indexer.ranges.EsIndexRangeService.timestampStatsOfIndex(EsIndexRangeService.java:249)
2015-10-05_03:04:08.31022 at
org.graylog2.indexer.ranges.EsIndexRangeService.calculateRange(EsIndexRangeService.java:217)
2015-10-05_03:04:08.31023 at
org.graylog2.indexer.ranges.RebuildIndexRangesJob.execute(RebuildIndexRangesJob.java:96)
2015-10-05_03:04:08.31023 at
org.graylog2.system.jobs.SystemJobManager$1.run(SystemJobManager.java:88)
2015-10-05_03:04:08.31024 at
com.codahale.metrics.InstrumentedScheduledExecutorService$InstrumentedRunnable.run(InstrumentedScheduledExecutorService.java:235)
2015-10-05_03:04:08.31024 at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
2015-10-05_03:04:08.31024 at
java.util.concurrent.FutureTask.run(FutureTask.java:266)
2015-10-05_03:04:08.31025 at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
2015-10-05_03:04:08.31025 at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
2015-10-05_03:04:08.31026 at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
2015-10-05_03:04:08.31027 at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
2015-10-05_03:04:08.31027 at java.lang.Thread.run(Thread.java:745)
2015-10-05_03:04:08.38399 INFO [EsIndexRangeService] Calculated range of
[graylog_3287] in [73ms].
2015-10-05_03:04:11.52658 INFO [EsIndexRangeService] Calculated range of
[graylog_4137] in [42ms].
So unfortunately, those indices never have valid ranges due to the
exception.
The range recalc seems to have trouble with "index missing" exceptions,
probably due to ES throwing other exceptions related to that index. The
index is not missing.
2015-10-05_14:37:02.99050 WARN [EsIndexRangeService] Couldn't load index
range for index graylog_4128
2015-10-05_14:37:02.99091 WARN [EsIndexRangeService] Couldn't load index
range for index graylog_4136
2015-10-05_14:37:02.99214 WARN [EsIndexRangeService] Couldn't load index
range for index graylog_4293
2015-10-05_14:37:17.78183 INFO [SetIndexReadOnlyJob] Flushing old index
<graylog_4292>.
2015-10-05_14:37:18.30641 INFO [SetIndexReadOnlyJob] Setting old index
<graylog_4292> to read-only.
2015-10-05_14:37:21.84393 INFO [SystemJobManager] Submitted SystemJob
<9664c833-6b6e-11e5-b272-0ae24e7f4757>
[org.graylog2.indexer.indices.jobs.OptimizeIndexJob]
2015-10-05_14:37:21.84397 INFO [SystemJobManager] SystemJob
<82175553-6b6e-11e5-b272-0ae24e7f4757>
[org.graylog2.indexer.SetIndexReadOnlyJob] finished in 4062ms.
2015-10-05_14:37:21.84419 INFO [OptimizeIndexJob] Optimizing index
<graylog_4292>.
2015-10-05_14:37:31.82487 WARN [EsIndexRangeService] Couldn't load index
range for index graylog_4128
2015-10-05_14:37:31.82519 WARN [EsIndexRangeService] Couldn't load index
range for index graylog_4136
2015-10-05_14:37:31.82658 WARN [EsIndexRangeService] Couldn't load index
range for index graylog_4293
2015-10-05_14:37:31.83269 WARN [IndexHelper] Couldn't find latest
deflector target index
2015-10-05_14:37:31.83270 org.graylog2.database.NotFoundException: Couldn't
find index range for index graylog_4293
2015-10-05_14:37:31.83271 at
org.graylog2.indexer.ranges.EsIndexRangeService.loadIndexRange(EsIndexRangeService.java:156)
2015-10-05_14:37:31.83271 at
org.graylog2.indexer.ranges.EsIndexRangeService.access$000(EsIndexRangeService.java:79)
2015-10-05_14:37:31.83271 at
org.graylog2.indexer.ranges.EsIndexRangeService$1.load(EsIndexRangeService.java:107)
2015-10-05_14:37:31.83272 at
org.graylog2.indexer.ranges.EsIndexRangeService$1.load(EsIndexRangeService.java:104)
2015-10-05_14:37:31.83272 at
com.google.common.cache.LocalCache$LoadingValueReference.loadFuture(LocalCache.java:3527)
2015-10-05_14:37:31.83272 at
com.google.common.cache.LocalCache$Segment.loadSync(LocalCache.java:2319)
2015-10-05_14:37:31.83273 at
com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(LocalCache.java:2282)
2015-10-05_14:37:31.83273 at
com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2197)
2015-10-05_14:37:31.83273 at
com.google.common.cache.LocalCache.get(LocalCache.java:3937)
2015-10-05_14:37:31.83273 at
com.google.common.cache.LocalCache.getOrLoad(LocalCache.java:3941)
2015-10-05_14:37:31.83274 at
com.google.common.cache.LocalCache$LocalLoadingCache.get(LocalCache.java:4824)
2015-10-05_14:37:31.83274 at
org.graylog2.indexer.ranges.EsIndexRangeService.get(EsIndexRangeService.java:131)
2015-10-05_14:37:31.83274 at
org.graylog2.indexer.IndexHelper.determineAffectedIndicesWithRanges(IndexHelper.java:119)
2015-10-05_14:37:31.83275 at
org.graylog2.indexer.searches.Searches.search(Searches.java:241)
2015-10-05_14:37:31.83275 at
org.graylog2.rest.resources.search.RelativeSearchResource.searchRelative(RelativeSearchResource.java:103)
2015-10-05_14:37:31.83275 at
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
2015-10-05_14:37:31.83276 at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
2015-10-05_14:37:31.83277 at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2015-10-05_14:37:31.83277 at
java.lang.reflect.Method.invoke(Method.java:497)
2015-10-05_14:37:31.83277 at
org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory$1.invoke(ResourceMethodInvocationHandlerFactory.java:81)
2015-10-05_14:37:31.83277 at
org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:144)
2015-10-05_14:37:31.83278 at
org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:161)
2015-10-05_14:37:31.83278 at
org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$TypeOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:205)
2015-10-05_14:37:31.83278 at
org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:99)
2015-10-05_14:37:31.83278 at
org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:389)
2015-10-05_14:37:31.83279 at
org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:347)
2015-10-05_14:37:31.83279 at
org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:102)
2015-10-05_14:37:31.83279 at
org.glassfish.jersey.server.ServerRuntime$2.run(ServerRuntime.java:308)
2015-10-05_14:37:31.83279 at
org.glassfish.jersey.internal.Errors$1.call(Errors.java:271)
2015-10-05_14:37:31.83280 at
org.glassfish.jersey.internal.Errors$1.call(Errors.java:267)
2015-10-05_14:37:31.83280 at
org.glassfish.jersey.internal.Errors.process(Errors.java:315)
2015-10-05_14:37:31.83280 at
org.glassfish.jersey.internal.Errors.process(Errors.java:297)
2015-10-05_14:37:31.83280 at
org.glassfish.jersey.internal.Errors.process(Errors.java:267)
2015-10-05_14:37:31.83281 at
org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:317)
2015-10-05_14:37:31.83281 at
org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:291)
2015-10-05_14:37:31.83281 at
org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1140)
2015-10-05_14:37:31.83281 at
org.graylog2.jersey.container.netty.NettyContainer.messageReceived(NettyContainer.java:356)
2015-10-05_14:37:31.83281 at
org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70)
2015-10-05_14:37:31.83282 at
org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)
2015-10-05_14:37:31.83283 at
org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)
2015-10-05_14:37:31.83283 at
org.jboss.netty.handler.execution.ChannelUpstreamEventRunnable.doRun(ChannelUpstreamEventRunnable.java:43)
2015-10-05_14:37:31.83283 at
org.jboss.netty.handler.execution.ChannelEventRunnable.run(ChannelEventRunnable.java:67)
2015-10-05_14:37:31.83284 at
com.codahale.metrics.InstrumentedExecutorService$InstrumentedRunnable.run(InstrumentedExecutorService.java:176)
2015-10-05_14:37:31.83284 at
org.jboss.netty.handler.execution.MemoryAwareThreadPoolExecutor$MemoryAwareRunnable.run(MemoryAwareThreadPoolExecutor.java:606)
2015-10-05_14:37:31.83284 at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
2015-10-05_14:37:31.83285 at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
2015-10-05_14:37:31.83285 at java.lang.Thread.run(Thread.java:745)
2015-10-05_14:37:34.54268 ERROR [AnyExceptionClassMapper] Unhandled
exception in REST resource
2015-10-05_14:37:34.54272 org.elasticsearch.ElasticsearchTimeoutException:
Timeout waiting for task.
2015-10-05_14:37:34.54273 at
org.elasticsearch.action.support.AdapterActionFuture.actionGet(AdapterActionFuture.java:73)
2015-10-05_14:37:34.54274 at
org.graylog2.indexer.elasticsearch.GlobalTimeoutClient$GlobalTimeoutActionFuture.actionGet(GlobalTimeoutClient.java:150)
2015-10-05_14:37:34.54274 at
org.graylog2.indexer.searches.Searches.histogram(Searches.java:467)
2015-10-05_14:37:34.54275 at
org.graylog2.rest.resources.search.RelativeSearchResource.histogramRelative(RelativeSearchResource.java:251)
2015-10-05_14:37:34.54275 at
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
2015-10-05_14:37:34.54275 at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
2015-10-05_14:37:34.54276 at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2015-10-05_14:37:34.54277 at
java.lang.reflect.Method.invoke(Method.java:497)
2015-10-05_14:37:34.54278 at
org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory$1.invoke(ResourceMethodInvocationHandlerFactory.java:81)
2015-10-05_14:37:34.54279 at
org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:144)
2015-10-05_14:37:34.54280 at
org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:161)
2015-10-05_14:37:34.54280 at
org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$TypeOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:205)
2015-10-05_14:37:34.54280 at
org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:99)
2015-10-05_14:37:34.54281 at
org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:389)
2015-10-05_14:37:34.54281 at
org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:347)
2015-10-05_14:37:34.54281 at
org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:102)
2015-10-05_14:37:34.54282 at
org.glassfish.jersey.server.ServerRuntime$2.run(ServerRuntime.java:308)
2015-10-05_14:37:34.54282 at
org.glassfish.jersey.internal.Errors$1.call(Errors.java:271)
2015-10-05_14:37:34.54282 at
org.glassfish.jersey.internal.Errors$1.call(Errors.java:267)
2015-10-05_14:37:34.54283 at
org.glassfish.jersey.internal.Errors.process(Errors.java:315)
2015-10-05_14:37:34.54283 at
org.glassfish.jersey.internal.Errors.process(Errors.java:297)
2015-10-05_14:37:34.54285 at
org.glassfish.jersey.internal.Errors.process(Errors.java:267)
2015-10-05_14:37:34.54285 at
org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:317)
2015-10-05_14:37:34.54286 at
org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:291)
2015-10-05_14:37:34.54286 at
org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1140)
2015-10-05_14:37:34.54286 at
org.graylog2.jersey.container.netty.NettyContainer.messageReceived(NettyContainer.java:356)
2015-10-05_14:37:34.54287 at
org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70)
2015-10-05_14:37:34.54287 at
org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)
2015-10-05_14:37:34.54287 at
org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)
2015-10-05_14:37:34.54288 at
org.jboss.netty.handler.execution.ChannelUpstreamEventRunnable.doRun(ChannelUpstreamEventRunnable.java:43)
2015-10-05_14:37:34.54288 at
org.jboss.netty.handler.execution.ChannelEventRunnable.run(ChannelEventRunnable.java:67)
2015-10-05_14:37:34.54289 at
com.codahale.metrics.InstrumentedExecutorService$InstrumentedRunnable.run(InstrumentedExecutorService.java:176)
2015-10-05_14:37:34.54289 at
org.jboss.netty.handler.execution.MemoryAwareThreadPoolExecutor$MemoryAwareRunnable.run(MemoryAwareThreadPoolExecutor.java:606)
2015-10-05_14:37:34.54289 at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
2015-10-05_14:37:34.54294 at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
2015-10-05_14:37:34.54295 at java.lang.Thread.run(Thread.java:745)
2015-10-05_14:37:34.66572 ERROR [AnyExceptionClassMapper] Unhandled
exception in REST resource
2015-10-05_14:37:34.66574
com.google.common.util.concurrent.UncheckedExecutionException:
org.elasticsearch.ElasticsearchTimeoutException: Timeout waiting for task.
2015-10-05_14:37:34.66575 at
com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2203)
2015-10-05_14:37:34.66575 at
com.google.common.cache.LocalCache.get(LocalCache.java:3937)
2015-10-05_14:37:34.66576 at
com.google.common.cache.LocalCache$LocalManualCache.get(LocalCache.java:4739)
2015-10-05_14:37:34.66576 at
org.graylog2.rest.resources.sources.SourcesResource.list(SourcesResource.java:89)
2015-10-05_14:37:34.66577 at
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
2015-10-05_14:37:34.66578 at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
2015-10-05_14:37:34.66578 at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2015-10-05_14:37:34.66579 at
java.lang.reflect.Method.invoke(Method.java:497)
2015-10-05_14:37:34.66579 at
org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory$1.invoke(ResourceMethodInvocationHandlerFactory.java:81)
2015-10-05_14:37:34.66579 at
org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:144)
2015-10-05_14:37:34.66580 at
org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:161)
2015-10-05_14:37:34.66581 at
org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$TypeOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:205)
2015-10-05_14:37:34.66581 at
org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:99)
2015-10-05_14:37:34.66582 at
org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:389)
2015-10-05_14:37:34.66582 at
org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:347)
2015-10-05_14:37:34.66582 at
org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:102)
2015-10-05_14:37:34.66583 at
org.glassfish.jersey.server.ServerRuntime$2.run(ServerRuntime.java:308)
2015-10-05_14:37:34.66583 at
org.glassfish.jersey.internal.Errors$1.call(Errors.java:271)
2015-10-05_14:37:34.66583 at
org.glassfish.jersey.internal.Errors$1.call(Errors.java:267)
2015-10-05_14:37:34.66584 at
org.glassfish.jersey.internal.Errors.process(Errors.java:315)
2015-10-05_14:37:34.66585 at
org.glassfish.jersey.internal.Errors.process(Errors.java:297)
2015-10-05_14:37:34.66585 at
org.glassfish.jersey.internal.Errors.process(Errors.java:267)
2015-10-05_14:37:34.66586 at
org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:317)
2015-10-05_14:37:34.66586 at
org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:291)
2015-10-05_14:37:34.66586 at
org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1140)
2015-10-05_14:37:34.66587 at
org.graylog2.jersey.container.netty.NettyContainer.messageReceived(NettyContainer.java:356)
2015-10-05_14:37:34.66587 at
org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70)
2015-10-05_14:37:34.66589 at
org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)
2015-10-05_14:37:34.66589 at
org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)
2015-10-05_14:37:34.66591 at
org.jboss.netty.handler.execution.ChannelUpstreamEventRunnable.doRun(ChannelUpstreamEventRunnable.java:43)
2015-10-05_14:37:34.66591 at
org.jboss.netty.handler.execution.ChannelEventRunnable.run(ChannelEventRunnable.java:67)
2015-10-05_14:37:34.66593 at
com.codahale.metrics.InstrumentedExecutorService$InstrumentedRunnable.run(InstrumentedExecutorService.java:176)
2015-10-05_14:37:34.66595 at
org.jboss.netty.handler.execution.MemoryAwareThreadPoolExecutor$MemoryAwareRunnable.run(MemoryAwareThreadPoolExecutor.java:606)
2015-10-05_14:37:34.66595 at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
2015-10-05_14:37:34.66595 at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
2015-10-05_14:37:34.66596 at java.lang.Thread.run(Thread.java:745)
2015-10-05_14:37:34.66596 Caused by:
org.elasticsearch.ElasticsearchTimeoutException: Timeout waiting for task.
2015-10-05_14:37:34.66597 at
org.elasticsearch.action.support.AdapterActionFuture.actionGet(AdapterActionFuture.java:73)
2015-10-05_14:37:34.66597 at
org.graylog2.indexer.elasticsearch.GlobalTimeoutClient$GlobalTimeoutActionFuture.actionGet(GlobalTimeoutClient.java:150)
2015-10-05_14:37:34.66597 at
org.graylog2.indexer.searches.Searches.terms(Searches.java:283)
2015-10-05_14:37:34.66598 at
org.graylog2.indexer.searches.Searches.terms(Searches.java:298)
2015-10-05_14:37:34.66598 at
org.graylog2.rest.resources.sources.SourcesResource$1.call(SourcesResource.java:93)
2015-10-05_14:37:34.66598 at
org.graylog2.rest.resources.sources.SourcesResource$1.call(SourcesResource.java:89)
2015-10-05_14:37:34.66599 at
com.google.common.cache.LocalCache$LocalManualCache$1.load(LocalCache.java:4742)
2015-10-05_14:37:34.66600 at
com.google.common.cache.LocalCache$LoadingValueReference.loadFuture(LocalCache.java:3527)
2015-10-05_14:37:34.66600 at
com.google.common.cache.LocalCache$Segment.loadSync(LocalCache.java:2319)
2015-10-05_14:37:34.66600 at
com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(LocalCache.java:2282)
2015-10-05_14:37:34.66601 at
com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2197)
2015-10-05_14:37:34.66601 ... 35 more
2015-10-05_14:37:47.23951 INFO [EsIndexRangeService] Calculated range of
[graylog_4293] in [59453ms].
2015-10-05_14:37:47.24239 INFO [CreateNewSingleIndexRangeJob] Created
ranges for index graylog_4293.
2015-10-05_14:37:47.24246 INFO [SystemJobManager] SystemJob
<82175554-6b6e-11e5-b272-0ae24e7f4757>
[org.graylog2.indexer.ranges.CreateNewSingleIndexRangeJob] finished in
59456ms.
2015-10-05_14:37:47.45459 INFO [EsIndexRangeService] Calculated range of
[graylog_4292] in [59672ms].
On Monday, October 5, 2015 at 8:17:45 AM UTC-6, Jochen Schalanda wrote:
>
> Hi Jesse,
>
> did you manually trigger the calculation of all the index ranges?
>
> During normal operations of Graylog 1.2.x, only the index range of the
> latest index should be calculated and stored (in contrast to Graylog 1.1.x
> and earlier, which most of the time calculated all index ranges).
>
> Cheers,
> Jochen
>
> On Saturday, 3 October 2015 19:11:15 UTC+2, Jesse Skrivseth wrote:
>>
>> A few examples of index recalc performance differences:
>>
>> In 1.1.6
>> ...
>> 2015-09-04_03:56:38.19431 INFO [RebuildIndexRangesJob] Calculated range
>> of [graylog_2075] in [9ms].
>> 2015-09-04_03:56:38.20487 INFO [RebuildIndexRangesJob] Calculated range
>> of [graylog_1800] in [10ms].
>> 2015-09-04_03:56:38.21176 INFO [RebuildIndexRangesJob] Calculated range
>> of [graylog_1802] in [6ms].
>> 2015-09-04_03:56:38.22028 INFO [RebuildIndexRangesJob] Calculated range
>> of [graylog_1801] in [8ms].
>> 2015-09-04_03:56:38.23003 INFO [RebuildIndexRangesJob] Calculated range
>> of [graylog_1808] in [9ms].
>> 2015-09-04_03:56:38.23855 INFO [RebuildIndexRangesJob] Calculated range
>> of [graylog_1807] in [8ms].
>> 2015-09-04_03:56:38.24877 INFO [RebuildIndexRangesJob] Calculated range
>> of [graylog_1809] in [10ms].
>> 2015-09-04_03:56:38.26011 INFO [RebuildIndexRangesJob] Calculated range
>> of [graylog_1804] in [11ms].
>> 2015-09-04_03:56:38.26902 INFO [RebuildIndexRangesJob] Calculated range
>> of [graylog_1803] in [8ms].
>> 2015-09-04_03:56:38.28049 INFO [RebuildIndexRangesJob] Calculated range
>> of [graylog_1806] in [11ms].
>> 2015-09-04_03:56:38.29289 INFO [RebuildIndexRangesJob] Calculated range
>> of [graylog_1805] in [12ms].
>> 2015-09-04_03:56:38.41557 INFO [RebuildIndexRangesJob] Done calculating
>> index ranges for 800 indices. Took 10608ms.
>>
>> In 1.2.1:
>> ...
>> 2015-10-03_17:00:59.70210 INFO [EsIndexRangeService] Calculated range of
>> [graylog_3358] in [1609ms].
>> 2015-10-03_17:01:05.63202 INFO [EsIndexRangeService] Calculated range of
>> [graylog_3357] in [50ms].
>> 2015-10-03_17:01:08.85062 INFO [EsIndexRangeService] Calculated range of
>> [graylog_3359] in [47ms].
>> 2015-10-03_17:01:12.39922 INFO [EsIndexRangeService] Calculated range of
>> [graylog_3365] in [119ms].
>> 2015-10-03_17:01:15.80573 INFO [EsIndexRangeService] Calculated range of
>> [graylog_3364] in [40ms].
>> 2015-10-03_17:01:19.29222 INFO [EsIndexRangeService] Calculated range of
>> [graylog_3367] in [43ms].
>> 2015-10-03_17:01:22.98674 INFO [EsIndexRangeService] Calculated range of
>> [graylog_3366] in [142ms].
>> 2015-10-03_17:01:29.74936 INFO [EsIndexRangeService] Calculated range of
>> [graylog_3361] in [120ms].
>> 2015-10-03_17:01:34.11754 INFO [EsIndexRangeService] Calculated range of
>> [graylog_3360] in [128ms].
>> 2015-10-03_17:01:37.91544 INFO [EsIndexRangeService] Calculated range of
>> [graylog_3363] in [134ms].
>> 2015-10-03_17:01:41.41116 INFO [EsIndexRangeService] Calculated range of
>> [graylog_3362] in [237ms].
>> 2015-10-03_17:01:45.31576 INFO [RebuildIndexRangesJob] Done calculating
>> index ranges for 1855 indices. Took 9551409ms.
>>
>> For good measure, I tried scaling the ES cluster up and down. Performance
>> is exactly the same whether I run on a single large server vs 4 smaller
>> servers.
>>
>> On Friday, October 2, 2015 at 9:29:37 AM UTC-6, Jesse Skrivseth wrote:
>>>
>>> Note that for the 1800 indices we have in this instance, the ~5 second
>>> delay between each index during range calculation adds up to ~150 minutes
>>> of additional delay when calculating ranges. My "> 20 minutes" comment
>>> should be more like "> 2.5 hours", plus actual time spent calculating
>>> ranges.
>>>
>>
--
You received this message because you are subscribed to the Google Groups
"Graylog Users" group.
To unsubscribe from this group and stop receiving emails from it, send an email
to [email protected].
To view this discussion on the web visit
https://groups.google.com/d/msgid/graylog2/9482a5f2-f9aa-4265-bc99-622c36e084c4%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.
