Not Solved!? Sync issues? with bulk create and threads exceeded

esmattdawson · August 26, 2018, 9:52pm

elasticsearch version 6.3.2
Cluster: 3 master + data nodes
Index: 1 shard + 2 replicas, 10 second flush rate

When I perform a bulk create over many indexes sometimes I get a bulk threads exceeded exception, which is fine.
{"_index":"read_59a484e523c0e43a8a40aeaf_201708","_type":"reading","_id":"p0ffogo87q5jp5fj68rr39gg5js0hk1a4g8ndd4c","status":429,"error":{"type":"es_rejected_execution_exception","reason":"rejected execution of org.elasticsearch.transport.TransportService$7@4654ea91 on EsThreadPoolExecutor[name = xxx-elastic-es1.local/write, queue capacity = 200, org.elasticsearch.common.util.concurrent.EsThreadPoolExecutor@62651c07[Running, pool size = 2, active threads = 2, queued tasks = 200, completed tasks = 276758]]"}}

I then take the failed records and re-index them after 5 seconds.
It seems to succeed, yet the records get lost and the server logs report the following:

[2018-08-26T18:35:08,581][WARN ][o.e.i.f.SyncedFlushService] [xxx-elastic-es2.local] [read_5ae66d980a22ab3bda3dbea3_201804][0] can't to issue sync id [T9PDW8AyREOiYT4VoOC8-w] for out of sync replica [[read_5ae66d980a22ab3bda3dbea3_201804][0], node[ot6b_6T5Sv-Mf_7UN8csNg], [R], s[STARTED], a[id=a-6vfKnnRsS-UHUA_VS0Lg]] with num docs [122070]; num docs on primary [122064]

Am I doing something wrong?

warkolm · August 27, 2018, 12:48am

How big is the bulk request?
Do you have Monitoring enabled?

esmattdawson · August 27, 2018, 1:36am

How big is the bulk request?

No larger than 200 documents per bulk. But there may be a queue of bulks pending.
The documents would be spread across 100ish indexes.

Do you have Monitoring enabled?

I am monitoring to kibana.

Some things I've checked...

Last Error:
[2018-08-26T18:35:08,581][WARN ][o.e.i.f.SyncedFlushService] [***-elastic-es2.local] [read_5ae66d980a22ab3bda3dbea3_201804][0] can't to issue sync id [T9PDW8AyREOiYT4VoOC8-w] for out of sync replica [[read_5ae66d980a22ab3bda3dbea3_201804][0], node[ot6b_6T5Sv-Mf_7UN8csNg], [R], s[STARTED], a[id=a-6vfKnnRsS-UHUA_VS0Lg]] with num docs [122070]; num docs on primary [122064]

GET /_cat/indices/read_5ae66d980a22ab3bda3dbea3_201804?v
health status index                                uuid                   pri rep docs.count docs.deleted store.size pri.store.size
green  open   read_5ae66d980a22ab3bda3dbea3_201804 YEpvK9MhSl61QxvD69LKlQ   1   2     122554            0     30.6mb          7.5mb

curl /_cat/shards/read_5ae66d980a22ab3bda3dbea3_201804?v
index                                shard prirep state     docs  store ip             node
read_5ae66d980a22ab3bda3dbea3_201804 0     r      STARTED 122566 15.3mb node1 node1
read_5ae66d980a22ab3bda3dbea3_201804 0     r      STARTED 122566 15.3mb node2 node2
read_5ae66d980a22ab3bda3dbea3_201804 0     p      STARTED 122566 15.1mb node3 node3

{
  "read_5ae66d980a22ab3bda3dbea3_201804" : {
    "aliases" : {
      "read_5ae66d980a22ab3bda3dbea3_201805" : { },
      "read_5ae66d980a22ab3bda3dbea3_201806" : { },
      "read_5ae66d980a22ab3bda3dbea3_201807" : { },
      "read_5ae66d980a22ab3bda3dbea3_201808" : { },
      "read_5ae66d980a22ab3bda3dbea3_201809" : { }
    },
    "mappings" : {
      "reading" : {
        "dynamic" : "strict",
        "_all" : {
          "enabled" : false
        },
        "properties" : {
          "c" : {
            "type" : "keyword"
          },
          "d" : {
            "type" : "boolean"
          },
          "p" : {
            "type" : "keyword"
          },
          "tsr" : {
            "type" : "date",
            "format" : "strict_date_time_no_millis||strict_date_time"
          },
          "vd" : {
            "type" : "double"
          },
          "vg" : {
            "type" : "geo_point"
          },
          "vs" : {
            "type" : "keyword"
          }
        }
      }
    },
    "settings" : {
      "index" : {
        "codec" : "best_compression",
        "refresh_interval" : "10s",
        "number_of_shards" : "1",
        "provided_name" : "read_5ae66d980a22ab3bda3dbea3_201804",
        "creation_date" : "1534835158363",
        "number_of_replicas" : "2",
        "uuid" : "YEpvK9MhSl61QxvD69LKlQ",
        "version" : {
          "created" : "6030299"
        }
      }
    }
  }
}

esmattdawson · August 27, 2018, 1:41am

This is what's in kibana around the error time:
It happens heaps though.

Christian_Dahlqvist · August 27, 2018, 4:26am

The reason behind failed bulk requests is described in this blog post. How many indices do you have in the cluster? How many concurrent indexing threads/processes?

esmattdawson · August 27, 2018, 4:56am

There are currently 500 indexes in the system, about half of which are written to every 5 minutes.
All elasticsearch config is currently using default values except for fielddata size set to 25%.
I have a single nodejs process bulking documents to a maximum of 200 records per bulk, roughly 1200 records every 5 minutes, but spiking on the 5 minute boundary, not spread across the 5 minutes.

Erk! Problem is now solved!
I've been staring at this for 2 weeks, and I knew the minute I posted a question the answer would come to me. I've been using a splice to re-add the record to the queue, but stupidly assigning the result of the splice as a new queue. This had the effect of erasing the queue.
I guess karma requires my public shame before it'll provide me with the answer to my bugs.

Thanks for your help!

esmattdawson · August 29, 2018, 10:38pm

Turns out this isn't solved, with more debugging I find this going on.

I index 1000 records in a bulk over 51 indexes.
The bulk fails 165 records due to bulk threads exceeded.
I wait 5 seconds and send the remaining 165 records.
I get a response saying all 165 records have been stored.
The records aren't in elasticsearch.

Some more info that may help:

I use my own unique Id for the records.
I am using op_type="create" and expecting a 409 on duplicate.
I am seeing sync issues on some of the nodes at the same time.

Some thoughts:

Is it possible that since the refresh_interval is 10 seconds and I'm retrying in 5 seconds, the new records are somehow lost as the id's already exist in an error state?
Is it possible some of the nodes did store the records and haven't removed them due to the flush not occurring yet and the sync between nodes not happened yet? Thus they don't get added as they are considered to already exist?

esmattdawson · August 30, 2018, 12:04am

Update:
Tried removed op_type create, it still has the same issue.
I'm going to trying dropping the refresh_interval to 1 second

Christian_Dahlqvist · August 30, 2018, 5:26am

That is indeed the problem. The new documents will not be available until a refresh has occurred, so your search may not pick them up.

system · September 27, 2018, 5:26am

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.