Using the plugin on elasticsearch-6.2.2, after a couple of hours, then all the search requests got no responses

[li910802]

We checked the url http://localhost:9214/_nodes/hot_threads?threads=10000&ignore_idle_threads=false,
and we got the thread stack logs below:

0.0% (0s out of 500ms) cpu usage by thread 'elasticsearch[node3][search][T#20]'
 10/10 snapshots sharing following 46 elements
   sun.misc.Unsafe.park(Native Method)
   java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
   java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
   java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
   java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
   java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)
   java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
   org.elasticsearch.common.util.concurrent.ReleasableLock.acquire(ReleasableLock.java:55)
   org.elasticsearch.common.cache.Cache.lambda$computeIfAbsent$4(Cache.java:371)
   org.elasticsearch.common.cache.Cache$$Lambda$2714/1659733949.accept(Unknown Source)
   org.elasticsearch.common.cache.Cache$CacheSegment.lambda$get$0(Cache.java:224)
   org.elasticsearch.common.cache.Cache$CacheSegment$$Lambda$2758/1471429601.apply(Unknown Source)
   java.util.concurrent.CompletableFuture.uniHandle(CompletableFuture.java:822)
   java.util.concurrent.CompletableFuture.uniHandleStage(CompletableFuture.java:834)
   java.util.concurrent.CompletableFuture.handle(CompletableFuture.java:2155)
   org.elasticsearch.common.cache.Cache$CacheSegment.get(Cache.java:215)
   org.elasticsearch.common.cache.Cache.get(Cache.java:344)
   org.elasticsearch.common.cache.Cache.computeIfAbsent(Cache.java:370)
   com.o19s.es.ltr.feature.store.index.Caches.cacheLoad(Caches.java:139)
   com.o19s.es.ltr.feature.store.index.Caches.loadFeatureSet(Caches.java:129)
   com.o19s.es.ltr.feature.store.index.CachedFeatureStore.loadSet(CachedFeatureStore.java:51)
   com.o19s.es.ltr.query.StoredLtrQueryBuilder.doToQuery(StoredLtrQueryBuilder.java:140)
   com.o19s.es.ltr.query.StoredLtrQueryBuilder.doToQuery(StoredLtrQueryBuilder.java:45)
   org.elasticsearch.index.query.AbstractQueryBuilder.toQuery(AbstractQueryBuilder.java:97)
   org.elasticsearch.index.query.AbstractQueryBuilder.toFilter(AbstractQueryBuilder.java:119)
   org.elasticsearch.index.query.BoolQueryBuilder.addBooleanClauses(BoolQueryBuilder.java:409)
   org.elasticsearch.index.query.BoolQueryBuilder.doToQuery(BoolQueryBuilder.java:382)
   org.elasticsearch.index.query.AbstractQueryBuilder.toQuery(AbstractQueryBuilder.java:97)
   org.elasticsearch.index.query.QueryShardContext.lambda$toQuery$2(QueryShardContext.java:304)
   org.elasticsearch.index.query.QueryShardContext$$Lambda$2740/257320679.apply(Unknown Source)
   org.elasticsearch.index.query.QueryShardContext.toQuery(QueryShardContext.java:316)
   org.elasticsearch.index.query.QueryShardContext.toQuery(QueryShardContext.java:303)
   org.elasticsearch.search.SearchService.parseSource(SearchService.java:707)
   org.elasticsearch.search.SearchService.createContext(SearchService.java:558)
   org.elasticsearch.search.SearchService.createAndPutContext(SearchService.java:534)
   org.elasticsearch.search.SearchService.executeQueryPhase(SearchService.java:330)
   org.elasticsearch.search.SearchService$2.onResponse(SearchService.java:316)
   org.elasticsearch.search.SearchService$2.onResponse(SearchService.java:312)
   org.elasticsearch.search.SearchService$3.doRun(SearchService.java:1002)
   org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:672)
   org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
   org.elasticsearch.common.util.concurrent.TimedRunnable.doRun(TimedRunnable.java:41)
   org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
   java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
   java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
   java.lang.Thread.run(Thread.java:748)
   
0.0% (0s out of 500ms) cpu usage by thread 'elasticsearch[node3][search][T#27]'
 10/10 snapshots sharing following 46 elements
   sun.misc.Unsafe.park(Native Method)
   java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
   java.util.concurrent.CompletableFuture$Signaller.block(CompletableFuture.java:1693)
   java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3323)
   java.util.concurrent.CompletableFuture.waitingGet(CompletableFuture.java:1729)
   java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1895)
   org.elasticsearch.common.cache.Cache$CacheSegment.remove(Cache.java:290)
   org.elasticsearch.common.cache.Cache.evictEntry(Cache.java:714)
   org.elasticsearch.common.cache.Cache.lambda$computeIfAbsent$4(Cache.java:372)
   org.elasticsearch.common.cache.Cache$$Lambda$2714/1659733949.accept(Unknown Source)
   org.elasticsearch.common.cache.Cache$CacheSegment.lambda$get$0(Cache.java:224)
   org.elasticsearch.common.cache.Cache$CacheSegment$$Lambda$2758/1471429601.apply(Unknown Source)
   java.util.concurrent.CompletableFuture.uniHandle(CompletableFuture.java:822)
   java.util.concurrent.CompletableFuture.uniHandleStage(CompletableFuture.java:834)
   java.util.concurrent.CompletableFuture.handle(CompletableFuture.java:2155)
   org.elasticsearch.common.cache.Cache$CacheSegment.get(Cache.java:215)
   org.elasticsearch.common.cache.Cache.get(Cache.java:344)
   org.elasticsearch.common.cache.Cache.computeIfAbsent(Cache.java:370)
   com.o19s.es.ltr.feature.store.index.Caches.cacheLoad(Caches.java:139)
   com.o19s.es.ltr.feature.store.index.Caches.loadFeatureSet(Caches.java:129)
   com.o19s.es.ltr.feature.store.index.CachedFeatureStore.loadSet(CachedFeatureStore.java:51)
   com.o19s.es.ltr.query.StoredLtrQueryBuilder.doToQuery(StoredLtrQueryBuilder.java:140)
   com.o19s.es.ltr.query.StoredLtrQueryBuilder.doToQuery(StoredLtrQueryBuilder.java:45)
   org.elasticsearch.index.query.AbstractQueryBuilder.toQuery(AbstractQueryBuilder.java:97)
   org.elasticsearch.index.query.AbstractQueryBuilder.toFilter(AbstractQueryBuilder.java:119)
   org.elasticsearch.index.query.BoolQueryBuilder.addBooleanClauses(BoolQueryBuilder.java:409)
   org.elasticsearch.index.query.BoolQueryBuilder.doToQuery(BoolQueryBuilder.java:382)
   org.elasticsearch.index.query.AbstractQueryBuilder.toQuery(AbstractQueryBuilder.java:97)
   org.elasticsearch.index.query.QueryShardContext.lambda$toQuery$2(QueryShardContext.java:304)
   org.elasticsearch.index.query.QueryShardContext$$Lambda$2740/257320679.apply(Unknown Source)
   org.elasticsearch.index.query.QueryShardContext.toQuery(QueryShardContext.java:316)
   org.elasticsearch.index.query.QueryShardContext.toQuery(QueryShardContext.java:303)
   org.elasticsearch.search.SearchService.parseSource(SearchService.java:707)
   org.elasticsearch.search.SearchService.createContext(SearchService.java:558)
   org.elasticsearch.search.SearchService.createAndPutContext(SearchService.java:534)
   org.elasticsearch.search.SearchService.executeQueryPhase(SearchService.java:330)
   org.elasticsearch.search.SearchService$2.onResponse(SearchService.java:316)
   org.elasticsearch.search.SearchService$2.onResponse(SearchService.java:312)
   org.elasticsearch.search.SearchService$3.doRun(SearchService.java:1002)
   org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:672)
   org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
   org.elasticsearch.common.util.concurrent.TimedRunnable.doRun(TimedRunnable.java:41)
   org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
   java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
   java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
   java.lang.Thread.run(Thread.java:748)

[nomoa]

Thanks for the report,
Is it easy for you to reproduce the issue?
This kind of problem may be hard to reproduce so would it possible for you to give us more information?
What was the search request you sent? I see that it tries to load a featureset were you logging feature vectors?
How many features are in this feature set?
Was it a single node that started to hang or all the nodes in your cluster?
What was the state of the machine, was it struggling on CPU/mem? Could you check gc logs I think elasticsearch enables them by default.
If it's easy to reproduce does it change something if you increase mem cache to 100m adding ltr.caches.max_mem: 100mb in your elasticsearch.yml config file.

Thanks for your help.

[GerardBouchar]

Hello,
I think i am experiencing the same problem on ElasticSearch V 5.6.7 :

• The problem occurs after a few search and training (maybe 30 or 50).
• I can see using the /_cat/thread_pool end point that on some nodes (i have never seen more than two) the number of active search threads increase when i perform search with the ltr plugin but never decrease.
• there are about 15 features in my feature set.
• most of the time the machine (cpu/mem) seems ok, maybe the heap is a bit high on the node that are stuck.
• i have no choice to restart es on the concerned nodes to be able to use the plugin again.
• While searches with the plugin are stuck, my es cluster is handling all kind of operations in "background" (indexation, search, bulk...) and everything works well.
• when i launch POST /_ltr/_clearcache i see that the stats on each nodes are 0

"stats": { "total": { "ram": 0, "count": 0 }, "features": { "ram": 0, "count": 0 }, "featuresets": { "ram": 0, "count": 0 }, "models": { "ram": 0, "count": 0 } } }

but on the nodes with pending ltr search, i see :

"stats": { "total": { "ram": 29752, "count": 2 }, "features": { "ram": 0, "count": 0 }, "featuresets": { "ram": 0, "count": 0 }, "models": { "ram": 29752, "count": 2 } } }

bellow is the stack trace i get when i call /_nodes/hot_threads?threads=10000&ignore_idle_threads=false :

sun.misc.Unsafe.park(Native Method) java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) java.util.concurrent.CompletableFuture$Signaller.block(CompletableFuture.java:1685) java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3320) java.util.concurrent.CompletableFuture.waitingGet(CompletableFuture.java:1721) java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1887) org.elasticsearch.common.cache.Cache$CacheSegment.remove(Cache.java:290) org.elasticsearch.common.cache.Cache.evictEntry(Cache.java:714) org.elasticsearch.common.cache.Cache.lambda$computeIfAbsent$4(Cache.java:372) org.elasticsearch.common.cache.Cache$$Lambda$1970/816286349.accept(Unknown Source) org.elasticsearch.common.cache.Cache$CacheSegment.lambda$get$0(Cache.java:224) org.elasticsearch.common.cache.Cache$CacheSegment$$Lambda$1887/1650549232.apply(Unknown Source) java.util.concurrent.CompletableFuture.uniHandle(CompletableFuture.java:822) java.util.concurrent.CompletableFuture.uniHandleStage(CompletableFuture.java:834) java.util.concurrent.CompletableFuture.handle(CompletableFuture.java:2147) org.elasticsearch.common.cache.Cache$CacheSegment.get(Cache.java:215) org.elasticsearch.common.cache.Cache.get(Cache.java:344) org.elasticsearch.common.cache.Cache.computeIfAbsent(Cache.java:370) com.o19s.es.ltr.feature.store.index.Caches.cacheLoad(Caches.java:139) com.o19s.es.ltr.feature.store.index.Caches.loadModel(Caches.java:133) com.o19s.es.ltr.feature.store.index.CachedFeatureStore.loadModel(CachedFeatureStore.java:56) com.o19s.es.ltr.query.StoredLtrQueryBuilder.doToQuery(StoredLtrQueryBuilder.java:138) com.o19s.es.ltr.query.StoredLtrQueryBuilder.doToQuery(StoredLtrQueryBuilder.java:46) org.elasticsearch.index.query.AbstractQueryBuilder.toQuery(AbstractQueryBuilder.java:96) org.elasticsearch.search.rescore.QueryRescorerBuilder.build(QueryRescorerBuilder.java:172) org.elasticsearch.search.SearchService.parseSource(SearchService.java:672) org.elasticsearch.search.SearchService.createContext(SearchService.java:485) org.elasticsearch.search.SearchService.createAndPutContext(SearchService.java:461) org.elasticsearch.search.SearchService.executeQueryPhase(SearchService.java:257) org.elasticsearch.action.search.SearchTransportService$6.messageReceived(SearchTransportService.java:343) org.elasticsearch.action.search.SearchTransportService$6.messageReceived(SearchTransportService.java:340) org.elasticsearch.transport.RequestHandlerRegistry.processMessageReceived(RequestHandlerRegistry.java:69) org.elasticsearch.transport.TcpTransport$RequestHandler.doRun(TcpTransport.java:1556) org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:638) org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) java.lang.Thread.run(Thread.java:745)

Thank you for your help.

[nomoa]

I found one possible cause this could happen.
If an unexpected exception is thrown while loading the value.
An unexpected exception is very vague but OutOfMemory error is one of them.
For OOM one way to assert this would be to start elasticsearch using the -XX:+ExitOnOutOfMemoryError or -XX:+CrashOnOutOfMemoryError so that elasticsearch would simply stop.

For other errors the only way would be to inspect all elastic response outputs to see if one or more shards failed to execute the query, there should a trace in the elasticsearch response. Having this information would greatly help to debug this issue.

Thanks!

[GerardBouchar]

Thank you ,

What do you mean by "all elastic response outputs" ?

[nomoa]

@GerardBouchar I mean when you read the response elastic returns when searching using the sltr query it's possible that one of them fails and all subsequent calls will trigger the deadlock and hang forever.
If one unexpected error is thrown while the cache is being loaded it should appear in the response you receive from elastic.
It may be a HTTP error code 400 or 500 or a shard failure.
Shard failures are encoded in the response:

{
  "took" : 63,
  "timed_out" : false,
  "_shards" : {
    "total" : 5,
    "successful" : 5,
    "skipped" : 0,
    "failed" : 0
  },
  "hits" : {
    "total" : 1000,
    "max_score" : null,
    "hits" : [ {
    }]
 }
}

Here if failed is non zero you should have an additional block in the response with all distinct shard failures and usually containing the name of the exception thrown.

Thanks.

[GerardBouchar]

Thank you for this precision.

unfortunately, i've got no response at all. A post request using my model just hang up forever.
Also, i am going to check twice but i see nothing in my ElasticSearch logs.

Thank you.

[nomoa]

I meant to check the responses of the few requests that succeeded to return something before the ones that hang.
If the first request hangs then it's troublesome but it still could happen in some conditions such as 2 shards of the same index on the same nodes or if you use the sltr query multiple times in a single request.

Basically my assumption is that the bug behavior:

• 1 failure
• all other calls hang

If I could confirm that there is a a failure before it hangs. Inspecting the type of the exception that was thrown would allow me to confirm that we are being hit by the bug I reported upstream.

[GerardBouchar]

ok i see.
I will try to get you such a response.

Thank you.

[jasontedor]

@GerardBouchar Also do you have any log entries that contain uncaught exception in thread?

[GerardBouchar]

Hello Jasontedor
Thank you for your interest.
i do not see anything like this at info log level on the node that seems to block.

[jasontedor]

@GerardBouchar Thanks for checking. For clarification, this would be at the warn level.