Bug? Elasticsearch 7 (after upgrade from 6.7) slow search during 3-5 seconds every 60 seconds

#1

This post is regarding my Github Issue: https://github.com/elastic/elasticsearch/issues/41231

Elasticsearch Version: 7.0.0
OpenJDK Runtime Environment (build 1.8.0_201-b09)
Centos 7 Linux 3.10.0-957.5.1.el7.x86_64

After upgrade from Elasticsearch 6.7 to 7.0 it every minute took 500 - 1000 ms to deliver the result instead 9 - 12 ms. This happen mostly for 3-5 seconds then work again as usual .
It's a very small dataset of 40K records, that fit completely into the memory.

Need to mention: Every minute logstash import updated documents into elasticsearch, at the moment this are around 100-200 updated documents. There is nothing inside log of Logstash. And logstash was updated too to 7.0.0.

The two nodes we run don't have any signifficant load (<5%).

Is you cluster fully upgraded to 7.0.0 or there are still nodes running on 6.7? All (2) Nodes was upgraded to 7.0.0

How much Heap size have you configured for your cluster? 4 GB (we have 40'000 documents here around 30 MB data)

Could you check from the logs if there is something unusual when the query becomes slow? inside the logs is nothing regarding this, no warning, no error

Could you check if there is GC activity during this period that leads to the slow response? regarding log there is all the time GC activtiy:
...
[2019-04-16T07:47:52.661+0000][29643][safepoint ] Application time: 1.0002825 seconds
[2019-04-16T07:47:52.661+0000][29643][safepoint ] Entering safepoint region: Cleanup
[2019-04-16T07:47:52.662+0000][29643][safepoint ] Leaving safepoint region
[2019-04-16T07:47:52.662+0000][29643][safepoint ] Total time for which application threads were stopped: 0.0003800 seconds, Stopping threads took: 0.0000731 seconds
[2019-04-16T07:47:53.662+0000][29643][safepoint ] Application time: 1.0002561 seconds
[2019-04-16T07:47:53.662+0000][29643][safepoint ] Entering safepoint region: Cleanup
[2019-04-16T07:47:53.662+0000][29643][safepoint ] Leaving safepoint region
[2019-04-16T07:47:53.662+0000][29643][safepoint ] Total time for which application threads were stopped: 0.0004199 seconds, Stopping threads took: 0.0000839 seconds
[2019-04-16T07:47:54.663+0000][29643][safepoint ] Application time: 1.0002671 seconds
[2019-04-16T07:47:54.663+0000][29643][safepoint ] Entering safepoint region: Cleanup
[2019-04-16T07:47:54.663+0000][29643][safepoint ] Leaving safepoint region
[2019-04-16T07:47:54.663+0000][29643][safepoint ] Total time for which application threads were stopped: 0.0003651 seconds, Stopping threads took: 0.0000822 seconds
[2019-04-16T07:47:55.664+0000][29643][safepoint ] Application time: 1.0002670 seconds
[2019-04-16T07:47:55.664+0000][29643][safepoint ] Entering safepoint region: Cleanup
[2019-04-16T07:47:55.664+0000][29643][safepoint ] Leaving safepoint region
[2019-04-16T07:47:55.664+0000][29643][safepoint ] Total time for which application threads were stopped: 0.0003404 seconds, Stopping threads took: 0.0000649 seconds

PUT dating
{
    "mappings": {
      "profile": {
        "properties": {
          "appid": {
            "type": "text"
          },
        "first_name": {
            "type": "text"
          },
         "country": {
            "type": "text"
          },
           "geo_pt": {
            "type": "geo_point"
          },
          "last_update_dt": {
            "type": "date"
          },
         "member_id": {
            "type": "integer"
          },
           "mstatus": {
            "type": "byte"
          },
          "is_hidden": {
            "type": "byte"
          },
           ...
{
                  "size": 100,
                  "from": 0,
                  "script_fields": {
                    "geo_distance": {
                        "script": {
                            "params": {
                                "lat": xxx,
                                "lon": xxx
                            },
                            "source": "doc[\'geo_pt\'].arcDistance(params.lat, params.lon)"
                        }
                    }
                  },
                  "_source": [
                    "first_name",
                    "last_request_dt",
                    "geo_distance"
                  ],
                  "sort": [
                    { "member_id" : {"order" : "desc"} }
                  ],
                  "query": {
                    "bool": {
                      "filter": [
                        {
                            "term": {
                              "mstatus": 1
                            }
                        },
                        {
                            "terms": {
                              "appid": [ xxx, xxx]
                            }
                        },
                        "term": {
                          "country": "xxx"
                        }
                      ]
                      , "must_not": [
                                {
                                  "term": {
                                    "is_hidden": 1
                                  }
                                }, 
                                {
                                  "term": {
                                    "member_id": xxx
                                  }
                                }
                                ]
                    }                    
                  }
                }

It seems it's not related to the Off-heap terms index, as the data is not larger then the available memory.

Is there anything I can try before I downgrade back to 6.7?

1 Like
(David Turner) #2

Can you run your searches with "profile": true and share a profiling output from both a good, fast, search, and a bad, slow one, so we can compare them?

Can you try and obtain the output of GET _nodes/hot_threads while the cluster is responding slowly so we can see what it's trying to do during that time?

(David Turner) #3

Also, you say that every minute you:

  • index 100-200 new documents
  • see slow searches for a few seconds

Are these things correlated in time? If you stop indexing for a few minutes do you still see slow searches?

#4

I have stoped the logstash service and the slow down don't happen anymore.

Should I provide some debug output from Logstash too aside from Elasticsearch? (I'm away now for 3 hrs will do this asap)

(David Turner) #5

Great, that helps to know. It strongly suggests that there's some way that indexing is slowing searches down.

In any logs or other information you show it would be useful to see the times at which the new documents are being indexed, since they seem to be correlated with the slowdowns. This'll help to build up a picture of the timeline of events. Perhaps these times are shown in Logstash's logs? Apart from that I can't think of any other questions I'd like to answer using these logs (yet).

#6

I have attached blow all requested and hopefully this can help to catch the Issue.

The Logstash Log don't show any aside what he does:

[2019-04-16T13:42:00,368][INFO ][logstash.inputs.jdbc     ] (0.066706s) SELECT * FROM (SELECT ... 
[2019-04-16T13:43:00,055][INFO ][logstash.inputs.jdbc     ] (0.000607s) SELECT count(*) AS `count` ... 
[2019-04-16T13:43:00,100][INFO ][logstash.inputs.jdbc     ] (0.001525s) SELECT count(*) AS `count` ...
[2019-04-16T13:43:00,152][INFO ][logstash.inputs.jdbc     ] (0.000930s) SELECT count(*) AS `count` ... 
[2019-04-16T13:43:00,155][INFO ][logstash.inputs.jdbc     ] (0.001017s) SELECT count(*) AS `count` ... 
[2019-04-16T13:43:00,226][INFO ][logstash.inputs.jdbc     ] (0.070825s) SELECT count(*) AS `count` ... 
[2019-04-16T13:43:00,281][INFO ][logstash.inputs.jdbc     ] (0.053188s) SELECT * FROM ... 
[2019-04-16T13:43:00,371][INFO ][logstash.inputs.jdbc     ] (0.071495s) SELECT count(*) AS `count` ... 
[2019-04-16T13:43:00,446][INFO ][logstash.inputs.jdbc     ] (0.074695s) SELECT * FROM ... 
[2019-04-16T13:44:00,136][INFO ][logstash.inputs.jdbc     ] (0.000422s) SELECT count(*) AS `count` ... 
[2019-04-16T13:44:00,162][INFO ][logstash.inputs.jdbc     ] (0.072988s) SELECT count(*) AS `count` ...
[2019-04-16T13:44:00,163][INFO ][logstash.inputs.jdbc     ] (0.000661s) SELECT count(*) AS `count` ...
[2019-04-16T13:44:00,214][INFO ][logstash.inputs.jdbc     ] (0.000472s) SELECT count(*) AS `count` ...
[2019-04-16T13:44:00,214][INFO ][logstash.inputs.jdbc     ] (0.000306s) SELECT count(*) AS `count` ...
[2019-04-16T13:44:00,235][INFO ][logstash.inputs.jdbc     ] (0.071779s) SELECT * FROM (SELECT ...
[2019-04-16T13:44:00,267][INFO ][logstash.inputs.jdbc     ] (0.053682s) SELECT count(*) AS `count` ...
[2019-04-16T13:44:00,333][INFO ][logstash.inputs.jdbc     ] (0.064281s) SELECT * FROM (SELECT ...
[2019-04-16T13:45:00,217][INFO ][logstash.inputs.jdbc     ] (0.000379s) SELECT count(*) AS `count` ...
[2019-04-16T13:45:00,242][INFO ][logstash.inputs.jdbc     ] (0.000561s) SELECT count(*) AS `count` ...
[2019-04-16T13:45:00,253][INFO ][logstash.inputs.jdbc     ] (0.082667s) SELECT count(*) AS `count` ...
[2019-04-16T13:45:00,295][INFO ][logstash.inputs.jdbc     ] (0.000380s) SELECT count(*) AS `count` ...
[2019-04-16T13:45:00,295][INFO ][logstash.inputs.jdbc     ] (0.000354s) SELECT count(*) AS `count` ...
[2019-04-16T13:45:00,321][INFO ][logstash.inputs.jdbc     ] (0.066970s) SELECT * FROM (SELECT ...
[2019-04-16T13:45:00,350][INFO ][logstash.inputs.jdbc     ] (0.054086s) SELECT count(*) AS `count` ...
[2019-04-16T13:45:00,420][INFO ][logstash.inputs.jdbc     ] (0.068839s) SELECT * FROM (SELECT ...
curl node-1-ip:9200/_nodes/hot_threads
::: {node-2}{DKwENWkuQCi7T0hcIZkUfA}{HUJumaUQRHmb2jLqgXCnPQ}{node-2-ip}{node-2-ip:9300}{ml.machine_memory=67161415680, ml.max_open_jobs=20, xpack.installed=true}
   Hot threads at 2019-04-16T11:50:51.656Z, interval=500ms, busiestThreads=3, ignoreIdleThreads=true:

::: {node-1}{QfhDUouzThSJHBHW5LhwvQ}{4uM6mhXYTkCXRo1wxXWEGw}{node-1-ip}{node-1-ip:9300}{ml.machine_memory=67151810560, xpack.installed=true, ml.max_open_jobs=20}
   Hot threads at 2019-04-16T11:50:51.653Z, interval=500ms, busiestThreads=3, ignoreIdleThreads=true:

[root@12345 ~]# curl node-1-ip:9200/_nodes/hot_threads
::: {node-2}{DKwENWkuQCi7T0hcIZkUfA}{HUJumaUQRHmb2jLqgXCnPQ}{node-2-ip}{node-2-ip:9300}{ml.machine_memory=67161415680, ml.max_open_jobs=20, xpack.installed=true}
   Hot threads at 2019-04-16T11:51:07.352Z, interval=500ms, busiestThreads=3, ignoreIdleThreads=true:

::: {node-1}{QfhDUouzThSJHBHW5LhwvQ}{4uM6mhXYTkCXRo1wxXWEGw}{node-1-ip}{node-1-ip:9300}{ml.machine_memory=67151810560, xpack.installed=true, ml.max_open_jobs=20}
   Hot threads at 2019-04-16T11:51:07.351Z, interval=500ms, busiestThreads=3, ignoreIdleThreads=true:

[root@12345 ~]# curl node-1-ip:9200/_nodes/hot_threads
::: {node-2}{DKwENWkuQCi7T0hcIZkUfA}{HUJumaUQRHmb2jLqgXCnPQ}{node-2-ip}{node-2-ip:9300}{ml.machine_memory=67161415680, ml.max_open_jobs=20, xpack.installed=true}
   Hot threads at 2019-04-16T11:51:24.988Z, interval=500ms, busiestThreads=3, ignoreIdleThreads=true:

::: {node-1}{QfhDUouzThSJHBHW5LhwvQ}{4uM6mhXYTkCXRo1wxXWEGw}{node-1-ip}{node-1-ip:9300}{ml.machine_memory=67151810560, xpack.installed=true, ml.max_open_jobs=20}
   Hot threads at 2019-04-16T11:51:24.987Z, interval=500ms, busiestThreads=3, ignoreIdleThreads=true:

[root@12345 ~]# curl node-1-ip:9200/_nodes/hot_threads
::: {node-2}{DKwENWkuQCi7T0hcIZkUfA}{HUJumaUQRHmb2jLqgXCnPQ}{node-2-ip}{node-2-ip:9300}{ml.machine_memory=67161415680, ml.max_open_jobs=20, xpack.installed=true}
   Hot threads at 2019-04-16T11:51:33.939Z, interval=500ms, busiestThreads=3, ignoreIdleThreads=true:

::: {node-1}{QfhDUouzThSJHBHW5LhwvQ}{4uM6mhXYTkCXRo1wxXWEGw}{node-1-ip}{node-1-ip:9300}{ml.machine_memory=67151810560, xpack.installed=true, ml.max_open_jobs=20}
   Hot threads at 2019-04-16T11:51:33.938Z, interval=500ms, busiestThreads=3, ignoreIdleThreads=true:

Below result when result is not slow (no difference):

[root@12345 ~]# curl node-1-ip:9200/_nodes/hot_threads
::: {node-2}{DKwENWkuQCi7T0hcIZkUfA}{HUJumaUQRHmb2jLqgXCnPQ}{node-2-ip}{node-2-ip:9300}{ml.machine_memory=67161415680, ml.max_open_jobs=20, xpack.installed=true}
   Hot threads at 2019-04-16T11:51:40.722Z, interval=500ms, busiestThreads=3, ignoreIdleThreads=true:

::: {node-1}{QfhDUouzThSJHBHW5LhwvQ}{4uM6mhXYTkCXRo1wxXWEGw}{node-1-ip}{node-1-ip:9300}{ml.machine_memory=67151810560, xpack.installed=true, ml.max_open_jobs=20}
   Hot threads at 2019-04-16T11:51:40.721Z, interval=500ms, busiestThreads=3, ignoreIdleThreads=true:
(David Turner) #7

Hmm, these hot threads dumps indicate that these nodes are doing nothing at all.

#8

The Profiles I have pasted on jsonblob as it was not possible to paste them here.

OK speed
https://jsonblob.com/885a5463-6042-11e9-95ef-4198dce7b9a5

Slow speed
https://jsonblob.com/b3403bae-6042-11e9-95ef-e9308a4edf8c

(David Turner) #9

Thanks. I can't see anything anomalous in those profiles apart from the wide variation in the took time at the top level. Everything seems to be taking no more than a few milliseconds. I think this suggests that all the time is being spent in a queue somewhere, but in that case I'd expect hot threads to tell us what the nodes are actually busy doing while they're not processing the queue. The times don't match up so I'm wondering if we missed the problem?

#10

Thank you, I have now repeated curl ip/_nodes/hot_threads many times and got one time two different things back.

curl node-1-ip:9200/_nodes/hot_threads
::: {node-2}{DKwENWkuQCi7T0hcIZkUfA}{HUJumaUQRHmb2jLqgXCnPQ}{node-2-ip}{node-2-ip:9300}{ml.machine_memory=67161415680, ml.max_open_jobs=20, xpack.installed=true}
   Hot threads at 2019-04-16T12:46:00.096Z, interval=500ms, busiestThreads=3, ignoreIdleThreads=true:

    4.8% (24ms out of 500ms) cpu usage by thread 'elasticsearch[node-2][write][T#6]'
     5/10 snapshots sharing following 30 elements
       app//org.elasticsearch.index.shard.IndexShard.applyIndexOperationOnReplica(IndexShard.java:726)
       app//org.elasticsearch.action.bulk.TransportShardBulkAction.performOpOnReplica(TransportShardBulkAction.java:416)
       app//org.elasticsearch.action.bulk.TransportShardBulkAction.performOnReplica(TransportShardBulkAction.java:386)
       app//org.elasticsearch.action.bulk.TransportShardBulkAction.shardOperationOnReplica(TransportShardBulkAction.java:373)
       app//org.elasticsearch.action.bulk.TransportShardBulkAction.shardOperationOnReplica(TransportShardBulkAction.java:79)
       app//org.elasticsearch.action.support.replication.TransportReplicationAction$AsyncReplicaAction.onResponse(TransportReplicationAction.java:619)
       app//org.elasticsearch.action.support.replication.TransportReplicationAction$AsyncReplicaAction.onResponse(TransportReplicationAction.java:579)
       app//org.elasticsearch.index.shard.IndexShard$4.onResponse(IndexShard.java:2712)
       app//org.elasticsearch.index.shard.IndexShard$4.onResponse(IndexShard.java:2690)
       app//org.elasticsearch.index.shard.IndexShardOperationPermits.acquire(IndexShardOperationPermits.java:269)
       app//org.elasticsearch.index.shard.IndexShardOperationPermits.acquire(IndexShardOperationPermits.java:236)
       app//org.elasticsearch.index.shard.IndexShard.lambda$acquireReplicaOperationPermit$17(IndexShard.java:2650)
       app//org.elasticsearch.index.shard.IndexShard$$Lambda$3741/0x0000000801d8f440.accept(Unknown Source)
       app//org.elasticsearch.index.shard.IndexShard.innerAcquireReplicaOperationPermit(IndexShard.java:2757)
       app//org.elasticsearch.index.shard.IndexShard.acquireReplicaOperationPermit(IndexShard.java:2649)
       app//org.elasticsearch.action.support.replication.TransportReplicationAction.acquireReplicaOperationPermit(TransportReplicationAction.java:983)
       app//org.elasticsearch.action.support.replication.TransportReplicationAction$AsyncReplicaAction.doRun(TransportReplicationAction.java:689)
       app//org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
       app//org.elasticsearch.action.support.replication.TransportReplicationAction$ReplicaOperationTransportHandler.messageReceived(TransportReplicationAction.java:562)
       app//org.elasticsearch.action.support.replication.TransportReplicationAction$ReplicaOperationTransportHandler.messageReceived(TransportReplicationAction.java:547)
       org.elasticsearch.xpack.security.transport.SecurityServerTransportInterceptor$ProfileSecuredRequestHandler$1.doRun(SecurityServerTransportInterceptor.java:251)
       app//org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
       org.elasticsearch.xpack.security.transport.SecurityServerTransportInterceptor$ProfileSecuredRequestHandler.messageReceived(SecurityServerTransportInterceptor.java:309)
       app//org.elasticsearch.transport.RequestHandlerRegistry.processMessageReceived(RequestHandlerRegistry.java:63)
       app//org.elasticsearch.transport.TcpTransport$RequestHandler.doRun(TcpTransport.java:1077)
       app//org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:751)
       app//org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
       java.base@12/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
       java.base@12/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
       java.base@12/java.lang.Thread.run(Thread.java:835)
     4/10 snapshots sharing following 10 elements
       java.base@12/jdk.internal.misc.Unsafe.park(Native Method)
       java.base@12/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194)
       java.base@12/java.util.concurrent.LinkedTransferQueue.awaitMatch(LinkedTransferQueue.java:743)
       java.base@12/java.util.concurrent.LinkedTransferQueue.xfer(LinkedTransferQueue.java:684)
       java.base@12/java.util.concurrent.LinkedTransferQueue.take(LinkedTransferQueue.java:1366)
       app//org.elasticsearch.common.util.concurrent.SizeBlockingQueue.take(SizeBlockingQueue.java:165)
       java.base@12/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1054)
       java.base@12/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114)
       java.base@12/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
       java.base@12/java.lang.Thread.run(Thread.java:835)

    4.4% (21.8ms out of 500ms) cpu usage by thread 'elasticsearch[node-2][write][T#8]'
     8/10 snapshots sharing following 26 elements
       app//org.elasticsearch.action.bulk.TransportShardBulkAction.shardOperationOnReplica(TransportShardBulkAction.java:79)
       app//org.elasticsearch.action.support.replication.TransportReplicationAction$AsyncReplicaAction.onResponse(TransportReplicationAction.java:619)
       app//org.elasticsearch.action.support.replication.TransportReplicationAction$AsyncReplicaAction.onResponse(TransportReplicationAction.java:579)
       app//org.elasticsearch.index.shard.IndexShard$4.onResponse(IndexShard.java:2712)
       app//org.elasticsearch.index.shard.IndexShard$4.onResponse(IndexShard.java:2690)
       app//org.elasticsearch.index.shard.IndexShardOperationPermits.acquire(IndexShardOperationPermits.java:269)
       app//org.elasticsearch.index.shard.IndexShardOperationPermits.acquire(IndexShardOperationPermits.java:236)
       app//org.elasticsearch.index.shard.IndexShard.lambda$acquireReplicaOperationPermit$17(IndexShard.java:2650)
       app//org.elasticsearch.index.shard.IndexShard$$Lambda$3741/0x0000000801d8f440.accept(Unknown Source)
       app//org.elasticsearch.index.shard.IndexShard.innerAcquireReplicaOperationPermit(IndexShard.java:2757)
       app//org.elasticsearch.index.shard.IndexShard.acquireReplicaOperationPermit(IndexShard.java:2649)
       
       ...
#11

and one time this:

curl node-1-ip:9200/_nodes/hot_threads
::: {node-2}{DKwENWkuQCi7T0hcIZkUfA}{HUJumaUQRHmb2jLqgXCnPQ}{node-2-ip}{node-2-ip:9300}{ml.machine_memory=67161415680, ml.max_open_jobs=20, xpack.installed=true}
   Hot threads at 2019-04-16T12:48:44.254Z, interval=500ms, busiestThreads=3, ignoreIdleThreads=true:

::: {node-1}{QfhDUouzThSJHBHW5LhwvQ}{4uM6mhXYTkCXRo1wxXWEGw}{node-1-ip}{node-1-ip:9300}{ml.machine_memory=67151810560, xpack.installed=true, ml.max_open_jobs=20}
   Hot threads at 2019-04-16T12:48:44.253Z, interval=500ms, busiestThreads=3, ignoreIdleThreads=true:

    0.0% (72.2micros out of 500ms) cpu usage by thread 'ticker-schedule-trigger-engine'
     10/10 snapshots sharing following 2 elements
       java.base@12/java.lang.Thread.sleep(Native Method)
       org.elasticsearch.xpack.watcher.trigger.schedule.engine.TickerScheduleTriggerEngine$Ticker.run(TickerScheduleTriggerEngine.java:193)
(David Turner) #12

Thanks, ok, none of those threads look important. One of them is to do with watcher (it's busy sleeping!) and the others are in the write threadpool so shouldn't have anything to do with searches.

Can you try GET _nodes/hot_threads?ignore_idle_threads=false&threads=999999 instead so we get a fuller picture?

#13

One catch more, I have shutdown node-2 and done 100+ requests during 4 minutes only one time it took 500ms all other requests was 4 - 12 ms, seems when node-2 is shutdown the Issue don't happen.

(David Turner) #14

That's also interesting. With just one node the search will be executed completely locally, avoiding all the queues in the transport layer. Do you also see consistently fast results if you execute the request with ?preference=_only_local when both nodes are running?

#15

I have executed many times this way and you're right I see consistently fast results.

?preference=_only_local

Is there anything more I should try?

GET _nodes/hot_threads?ignore_idle_threads=false&threads=999999

With node-2 shutdown I got a large output all with 0.0% (0s out of 500ms) cpu usage by thread
When node-2 is active only few tasks have some low cpu load:

0.2% (1ms out of 500ms) cpu usage by thread 'elasticsearch[node-2][scheduler][T#1]'
     10/10 snapshots sharing following 9 elements
       java.base@12/jdk.internal.misc.Unsafe.park(Native Method)
       java.base@12/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:235)
       java.base@12/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2123)
       java.base@12/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1182)
       java.base@12/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:899)
       java.base@12/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1054)
       java.base@12/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114)
       java.base@12/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
       java.base@12/java.lang.Thread.run(Thread.java:835)
   
    0.1% (499.4micros out of 500ms) cpu usage by thread 'elasticsearch[node-2][transport_worker][T#6]'
     10/10 snapshots sharing following 8 elements
       java.base@12/sun.nio.ch.EPoll.wait(Native Method)
       java.base@12/sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:120)
       java.base@12/sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:124)
       java.base@12/sun.nio.ch.SelectorImpl.select(SelectorImpl.java:136)
       io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:765)
       io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:413)
       io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:909)
       java.base@12/java.lang.Thread.run(Thread.java:835)
   
    0.1% (466.7micros out of 500ms) cpu usage by thread 'elasticsearch[node-2][transport_worker][T#2]'
     10/10 snapshots sharing following 8 elements
       java.base@12/sun.nio.ch.EPoll.wait(Native Method)
       java.base@12/sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:120)
       java.base@12/sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:124)
       java.base@12/sun.nio.ch.SelectorImpl.select(SelectorImpl.java:136)
       io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:765)
       io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:413)
       io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:909)
       java.base@12/java.lang.Thread.run(Thread.java:835)
   
    0.1% (253.1micros out of 500ms) cpu usage by thread 'elasticsearch[node-2][refresh][T#1]'
     10/10 snapshots sharing following 9 elements
       java.base@12/jdk.internal.misc.Unsafe.park(Native Method)
       java.base@12/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:235)
       java.base@12/java.util.concurrent.LinkedTransferQueue.awaitMatch(LinkedTransferQueue.java:740)
       java.base@12/java.util.concurrent.LinkedTransferQueue.xfer(LinkedTransferQueue.java:684)
       java.base@12/java.util.concurrent.LinkedTransferQueue.poll(LinkedTransferQueue.java:1374)
       java.base@12/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1053)
       java.base@12/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114)
       java.base@12/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
       java.base@12/java.lang.Thread.run(Thread.java:835)
(David Turner) #16

To be clear, I'd like you to capture these thread dumps while a slow query is running, and then share the whole output. A blocked thread may be consuming no CPU but it'd still be important to see the stack trace as this will tell us what it's blocked on.

#17

I'm sorry I missed this part, here are two full dump:

https://pastebin.com/bJk2JAg8

https://pastebin.com/c5dUVXuA

(David Turner) #18

Thanks. I can see some activity here, but no searches. All the search threads look to be idle, as do all of the transport threads. Are you sure these dumps were taken while a search was ongoing?

#19

Thank you on your feedback, I have try to catch them now better, one search took 900ms during this two dump:

https://pastebin.com/gTZkrfEd

https://pastebin.com/xaavzmNw

(David Turner) #20

Sorry, I still don't see any activity on search threads in these results. Strange.

Tomorrow I will see if I can find some logging settings that might help us dig in a different direction. It might also help to look at some network traces from tcpdump although I'm hoping we get some higher-level clues first.