Slow Shard Assignment

[kelaban]

I have a job that creates a new version on an index every morning then
deletes the old version of the index when it is done. About 3/7 days per
week this job fails. What I am observing is that sometimes when trying to
create the new index shards are either not being assigned at all or taking
a long time to be assigned (around 10 minutes).

The index is small (~100k entries) and cluster setup is really simple.
There are 4 data nodes in the cluster and the index is 1 shard with 3
replicas. So there should be one primary shard and one replica on each of
the rest of the 3 remaining nodes in the cluster.

Any insight on why this is happening would be greatly appreciated. Thanks!

--

[radu_gheorghe]

Hello Keith,

On Wed, Jan 9, 2013 at 12:23 AM, Keith L kelaban17@gmail.com wrote:

I have a job that creates a new version on an index every morning then
deletes the old version of the index when it is done. About 3/7 days per
week this job fails.

Can you give some more information about how this happens? So you create a
new index, insert ~100K docs to it, and when you're done you delete the old
index?

What I am observing is that sometimes when trying to create the new index
shards are either not being assigned at all or taking a long time to be
assigned (around 10 minutes).

Do you see any clues in the logs when shards aren't assigned?

The index is small (~100k entries) and cluster setup is really simple.
There are 4 data nodes in the cluster and the index is 1 shard with 3
replicas. So there should be one primary shard and one replica on each of
the rest of the 3 remaining nodes in the cluster.

Do you have any non-default settings to your cluster? Expecially around
index creation (dynamic index creation, templates, custom mappings...), and
around shard allocation and indexing (routing, allocation limits, etc)?

Best regards,
Radu

http://sematext.com/ -- Elasticsearch -- Solr -- Lucene

--

[kelaban]

Can you give some more information about how this happens? So you create a
new index, insert ~100K docs to it, and when you're done you delete the old
index?

I have a python script that uses the elasticsearch REST api. First creates
the index with a unique name then uses the _bulk call to index documents
(400 max per call). When the process finishes if it was successful it uses
the elasticsearch atomic actions operation to remove the alias from the old
version of the index and give the alias to the new version of the index.
lastly it deletes the old index.

Do you see any clues in the logs when shards aren't assigned?

I don't see anything in the logs as to why it is not being assigned. On one
node I see "[acindex_1357639208] creating index, cause [api], shards
[1]/[3], mappings [entry]" however I don't see anything else from any of
the other nodes

Do you have any non-default settings to your cluster? Expecially around

index creation (dynamic index creation, templates, custom mappings...), and
around shard allocation and indexing (routing, allocation limits, etc)?

When I create the index I use the following settings. Where edgeAnalyzer is
a custom edgeNGram analyzer. No other suspicious settings are being used
"settings": {
"number_of_shards": number_of_shards,
"number_of_replicas": number_of_replicas,
"analysis": self.__get_analyzer()
},
"mappings":{
'entry': {
'_boost': { 'name': '_boost', 'null_value': .0001 },
'_id' : { 'index': 'not_analyzed', 'store': 'no' },
'index_analyzer': "standard",
'search_analyzer': "standard",
'properties':{
'symbol': {
'type':'string',
'index': 'analyzed',
'index_analyzer': "edgeAnalyzer",
'search_analyzer': "whitespace"
},
'ticker': {
'type':'string',
'index': 'analyzed',
'index_analyzer': "edgeAnalyzer",
'search_analyzer': "whitespace"
},
'name': {
'type':'string',
'index': 'analyzed',
'index_analyzer': "edgeAnalyzer",
'search_analyzer': "whitespace"
},
'privilege':{
'type' :'string',
'include_in_all': False,
'index': 'not_analyzed'
}
}
}
}

    }  

On Tuesday, January 8, 2013 5:23:34 PM UTC-5, Keith L wrote:

I have a job that creates a new version on an index every morning then
deletes the old version of the index when it is done. About 3/7 days per
week this job fails. What I am observing is that sometimes when trying to
create the new index shards are either not being assigned at all or taking
a long time to be assigned (around 10 minutes).

The index is small (~100k entries) and cluster setup is really simple.
There are 4 data nodes in the cluster and the index is 1 shard with 3
replicas. So there should be one primary shard and one replica on each of
the rest of the 3 remaining nodes in the cluster.

Any insight on why this is happening would be greatly appreciated. Thanks!

--

[radu_gheorghe]

Hi Keith, and sorry for my late reply.

I'm not sure I get the big picture. You said your indices contain about
100k docs, and that each day you create a new one and delete the old one.
Does that mean that you have at most 2 indices at a time? If yes, it's
really strange that it's so slow, because the total data shouldn't bother 4
nodes. By the way, how big are the nodes and how much RAM do you give to ES?

Also, once indices are created (let's suppose that's successful), does
indexing work OK? Or is that slow too? Or is it only slow when not all
shards are allocated?

What do you get when you simply try creating an index with curl? Something
like:
time curl -XPUT localhost:9200/test

Sorry for the large number of questions, but I know how nasty it is when
nothing looks suspicious, yet the problem is suspicious So I'd rather
put a lot of questions in one mail, maybe we'll get to something a bit
faster.

Best regards,
Radu

http://sematext.com/ -- Elasticsearch -- Solr -- Lucene

On Thu, Jan 10, 2013 at 7:45 PM, Keith L kelaban17@gmail.com wrote:

Can you give some more information about how this happens? So you create a

new index, insert ~100K docs to it, and when you're done you delete the old
index?

I have a python script that uses the elasticsearch REST api. First
creates the index with a unique name then uses the _bulk call to index
documents (400 max per call). When the process finishes if it was
successful it uses the elasticsearch atomic actions operation to remove the
alias from the old version of the index and give the alias to the new
version of the index. lastly it deletes the old index.

Do you see any clues in the logs when shards aren't assigned?

I don't see anything in the logs as to why it is not being assigned. On
one node I see "[acindex_1357639208] creating index, cause [api], shards
[1]/[3], mappings [entry]" however I don't see anything else from any of
the other nodes

Do you have any non-default settings to your cluster? Expecially around

index creation (dynamic index creation, templates, custom mappings...), and
around shard allocation and indexing (routing, allocation limits, etc)?

When I create the index I use the following settings. Where edgeAnalyzer
is a custom edgeNGram analyzer. No other suspicious settings are being used
"settings": {
"number_of_shards": number_of_shards,
"number_of_replicas": number_of_replicas,
"analysis": self.__get_analyzer()
},
"mappings":{
'entry': {
'_boost': { 'name': '_boost', 'null_value': .0001 },
'_id' : { 'index': 'not_analyzed', 'store': 'no' },
'index_analyzer': "standard",
'search_analyzer': "standard",
'properties':{
'symbol': {
'type':'string',
'index': 'analyzed',
'index_analyzer': "edgeAnalyzer",
'search_analyzer': "whitespace"
},
'ticker': {
'type':'string',
'index': 'analyzed',
'index_analyzer': "edgeAnalyzer",
'search_analyzer': "whitespace"
},
'name': {
'type':'string',
'index': 'analyzed',
'index_analyzer': "edgeAnalyzer",
'search_analyzer': "whitespace"
},
'privilege':{
'type' :'string',
'include_in_all': False,
'index': 'not_analyzed'
}
}
}
}

    }

On Tuesday, January 8, 2013 5:23:34 PM UTC-5, Keith L wrote:

I have a job that creates a new version on an index every morning then
deletes the old version of the index when it is done. About 3/7 days per
week this job fails. What I am observing is that sometimes when trying to
create the new index shards are either not being assigned at all or taking
a long time to be assigned (around 10 minutes).

The index is small (~100k entries) and cluster setup is really simple.
There are 4 data nodes in the cluster and the index is 1 shard with 3
replicas. So there should be one primary shard and one replica on each of
the rest of the 3 remaining nodes in the cluster.

Any insight on why this is happening would be greatly appreciated. Thanks!

--

--

[kelaban]

Hi Radu, thanks for getting back to me. This is definately a curious
situation as it happens so sporatically.

First I should note we are using elasticsearch-0.18.7. I am putting off a
version upgrade until it can be ruled a version bug.

Some cluster information:
-There are 4 other indicies totaling about 500gb of data. These hold logs
indexed by logstash.
-ES_MIN_MEM=ES_MAX_MEM=2g
-Indexing fails only about 3 days per week. I am trying to monitor the days
it fails to rule out network issues or congestion from logstash.

I've had no problems using curl or the head plugin to create an index, but
that is most likely luck of the draw.

Here are some curious logs I saw this morning upon failure.
Script details:
Create index at 5am. If indexing fails in script then call
_cluster/health/acindex_1358157608?wait_for_status=green&timeout=600s. (The
last wait_for_status part is new in attemping to actually get the indexing
done). If it never gets green delete the newly created empty index.
Logs:
Node B1:
[2013-01-14 05:00:08,267][INFO ][cluster.metadata ] [B1]
[acindex_1358157608] creating index, cause [api], shards [1]/[3], mappings
[entry]
[2013-01-14 05:11:18,630][INFO ][cluster.metadata ] [B1]
[acindex_1358157608] deleting index

Node A1:
[2013-01-14 05:05:15,289][WARN ][cluster.action.shard ] [A1] failed to
send shard started to
[[B1][NcbSdmFmQCiGrxW86z5zyw][inet[/xxx.x.x.x:9300]]][WARN
][cluster.action.shard ]

Node A2:
[2013-01-14 05:08:27,828][A2] failed to send shard started to
[[B1][NcbSdmFmQCiGrxW86z5zyw][inet[/xxx.x.x.x:9300]]]

On Monday, January 14, 2013 10:55:04 AM UTC-5, Radu Gheorghe wrote:

Hi Keith, and sorry for my late reply.

I'm not sure I get the big picture. You said your indices contain about
100k docs, and that each day you create a new one and delete the old one.
Does that mean that you have at most 2 indices at a time? If yes, it's
really strange that it's so slow, because the total data shouldn't bother 4
nodes. By the way, how big are the nodes and how much RAM do you give to ES?

Also, once indices are created (let's suppose that's successful), does
indexing work OK? Or is that slow too? Or is it only slow when not all
shards are allocated?

What do you get when you simply try creating an index with curl? Something
like:
time curl -XPUT localhost:9200/test

Sorry for the large number of questions, but I know how nasty it is when
nothing looks suspicious, yet the problem is suspicious So I'd rather
put a lot of questions in one mail, maybe we'll get to something a bit
faster.

Best regards,
Radu

http://sematext.com/ -- Elasticsearch -- Solr -- Lucene

On Thu, Jan 10, 2013 at 7:45 PM, Keith L <kela...@gmail.com <javascript:>>wrote:

Can you give some more information about how this happens? So you create

a new index, insert ~100K docs to it, and when you're done you delete the
old index?

I have a python script that uses the elasticsearch REST api. First
creates the index with a unique name then uses the _bulk call to index
documents (400 max per call). When the process finishes if it was
successful it uses the elasticsearch atomic actions operation to remove the
alias from the old version of the index and give the alias to the new
version of the index. lastly it deletes the old index.

Do you see any clues in the logs when shards aren't assigned?

I don't see anything in the logs as to why it is not being assigned. On
one node I see "[acindex_1357639208] creating index, cause [api], shards
[1]/[3], mappings [entry]" however I don't see anything else from any of
the other nodes

Do you have any non-default settings to your cluster? Expecially around

index creation (dynamic index creation, templates, custom mappings...), and
around shard allocation and indexing (routing, allocation limits, etc)?

When I create the index I use the following settings. Where edgeAnalyzer
is a custom edgeNGram analyzer. No other suspicious settings are being used
"settings": {
"number_of_shards": number_of_shards,
"number_of_replicas": number_of_replicas,
"analysis": self.__get_analyzer()
},
"mappings":{
'entry': {
'_boost': { 'name': '_boost', 'null_value': .0001 },
'_id' : { 'index': 'not_analyzed', 'store': 'no' },
'index_analyzer': "standard",
'search_analyzer': "standard",
'properties':{
'symbol': {
'type':'string',
'index': 'analyzed',
'index_analyzer': "edgeAnalyzer",
'search_analyzer': "whitespace"
},
'ticker': {
'type':'string',
'index': 'analyzed',
'index_analyzer': "edgeAnalyzer",
'search_analyzer': "whitespace"
},
'name': {
'type':'string',
'index': 'analyzed',
'index_analyzer': "edgeAnalyzer",
'search_analyzer': "whitespace"
},
'privilege':{
'type' :'string',
'include_in_all': False,
'index': 'not_analyzed'
}
}
}
}

    }  

On Tuesday, January 8, 2013 5:23:34 PM UTC-5, Keith L wrote:

I have a job that creates a new version on an index every morning then
deletes the old version of the index when it is done. About 3/7 days per
week this job fails. What I am observing is that sometimes when trying to
create the new index shards are either not being assigned at all or taking
a long time to be assigned (around 10 minutes).

The index is small (~100k entries) and cluster setup is really simple.
There are 4 data nodes in the cluster and the index is 1 shard with 3
replicas. So there should be one primary shard and one replica on each of
the rest of the 3 remaining nodes in the cluster.

Any insight on why this is happening would be greatly appreciated.
Thanks!

--

--

[radu_gheorghe]

Hi Keith,

The 2GB of allocated RAM and the 500GB logstash indices are to me clues
that your ES might be overloaded in terms of memory.

The rule of thumb for the ES heap size is to use roughly 50% of your total
RAM. It depends on a lot of factors, but that's a good start. So if you
have more than 4GB of RAM on your nodes, try increasing the heap size and
see if the problem still occurs.

If that's not an option, you can try adding more nodes, or closing older
logstash indices to confirm/invalidate the same hypothesis.

Another I'd do is to monitor the cluster and see if something pops up (heap
usage? :D). Our SPM is a good choice for looking up on lots of metrics:

Elasticsearch Monitoring

Regarding the "failed to send shard started" message, I'd change
logging.yml to some more verbose logging. If the problem reappears, maybe
some more context will help.

Best regards,
Radu

http://sematext.com/ -- Elasticsearch -- Solr -- Lucene

On Mon, Jan 14, 2013 at 7:23 PM, Keith L kelaban17@gmail.com wrote:

Hi Radu, thanks for getting back to me. This is definately a curious
situation as it happens so sporatically.

First I should note we are using elasticsearch-0.18.7. I am putting off a
version upgrade until it can be ruled a version bug.

Some cluster information:
-There are 4 other indicies totaling about 500gb of data. These hold logs
indexed by logstash.
-ES_MIN_MEM=ES_MAX_MEM=2g
-Indexing fails only about 3 days per week. I am trying to monitor the
days it fails to rule out network issues or congestion from logstash.

I've had no problems using curl or the head plugin to create an index, but
that is most likely luck of the draw.

Here are some curious logs I saw this morning upon failure.
Script details:
Create index at 5am. If indexing fails in script then call
_cluster/health/acindex_1358157608?wait_for_status=green&timeout=600s. (The
last wait_for_status part is new in attemping to actually get the indexing
done). If it never gets green delete the newly created empty index.
Logs:
Node B1:
[2013-01-14 05:00:08,267][INFO ][cluster.metadata ] [B1]
[acindex_1358157608] creating index, cause [api], shards [1]/[3], mappings
[entry]
[2013-01-14 05:11:18,630][INFO ][cluster.metadata ] [B1]
[acindex_1358157608] deleting index

Node A1:
[2013-01-14 05:05:15,289][WARN ][cluster.action.shard ] [A1] failed to
send shard started to
[[B1][NcbSdmFmQCiGrxW86z5zyw][inet[/xxx.x.x.x:9300]]][WARN
][cluster.action.shard ]

Node A2:
[2013-01-14 05:08:27,828][A2] failed to send shard started to
[[B1][NcbSdmFmQCiGrxW86z5zyw][inet[/xxx.x.x.x:9300]]]

On Monday, January 14, 2013 10:55:04 AM UTC-5, Radu Gheorghe wrote:

Hi Keith, and sorry for my late reply.

I'm not sure I get the big picture. You said your indices contain about
100k docs, and that each day you create a new one and delete the old one.
Does that mean that you have at most 2 indices at a time? If yes, it's
really strange that it's so slow, because the total data shouldn't bother 4
nodes. By the way, how big are the nodes and how much RAM do you give to ES?

Also, once indices are created (let's suppose that's successful), does
indexing work OK? Or is that slow too? Or is it only slow when not all
shards are allocated?

What do you get when you simply try creating an index with curl?
Something like:
time curl -XPUT localhost:9200/test

Sorry for the large number of questions, but I know how nasty it is when
nothing looks suspicious, yet the problem is suspicious So I'd rather
put a lot of questions in one mail, maybe we'll get to something a bit
faster.

Best regards,
Radu

http://sematext.com/ -- Elasticsearch -- Solr -- Lucene

On Thu, Jan 10, 2013 at 7:45 PM, Keith L kela...@gmail.com wrote:

Can you give some more information about how this happens? So you create

a new index, insert ~100K docs to it, and when you're done you delete the
old index?

I have a python script that uses the elasticsearch REST api. First
creates the index with a unique name then uses the _bulk call to index
documents (400 max per call). When the process finishes if it was
successful it uses the elasticsearch atomic actions operation to remove the
alias from the old version of the index and give the alias to the new
version of the index. lastly it deletes the old index.

Do you see any clues in the logs when shards aren't assigned?

I don't see anything in the logs as to why it is not being assigned. On
one node I see "[acindex_1357639208] creating index, cause [api], shards
[1]/[3], mappings [entry]" however I don't see anything else from any of
the other nodes

Do you have any non-default settings to your cluster? Expecially around

index creation (dynamic index creation, templates, custom mappings...), and
around shard allocation and indexing (routing, allocation limits, etc)?

When I create the index I use the following settings. Where edgeAnalyzer
is a custom edgeNGram analyzer. No other suspicious settings are being used
"settings": {
"number_of_shards": number_of_shards,
"number_of_replicas": number_of_replicas,
"analysis": self.__get_analyzer()
},
"mappings":{
'entry': {
'_boost': { 'name': '_boost', 'null_value': .0001 },
'_id' : { 'index': 'not_analyzed', 'store': 'no' },
'index_analyzer': "standard",
'search_analyzer': "standard",
'properties':{
'symbol': {
'type':'string',
'index': 'analyzed',
'index_analyzer': "edgeAnalyzer",
'search_analyzer': "whitespace"
},
'ticker': {
'type':'string',
'index': 'analyzed',
'index_analyzer': "**edgeAnalyzer",
'search_analyzer': "**whitespace"
},
'name': {
'type':'string',
'index': 'analyzed',
'index_analyzer': "**edgeAnalyzer",
'search_analyzer': "**whitespace"
},
'privilege':{
'type' :'string',
'include_in_all': False,
'index': 'not_analyzed'
}
}
}
}

    }

On Tuesday, January 8, 2013 5:23:34 PM UTC-5, Keith L wrote:

I have a job that creates a new version on an index every morning then
deletes the old version of the index when it is done. About 3/7 days per
week this job fails. What I am observing is that sometimes when trying to
create the new index shards are either not being assigned at all or taking
a long time to be assigned (around 10 minutes).

The index is small (~100k entries) and cluster setup is really simple.
There are 4 data nodes in the cluster and the index is 1 shard with 3
replicas. So there should be one primary shard and one replica on each of
the rest of the 3 remaining nodes in the cluster.

Any insight on why this is happening would be greatly appreciated.
Thanks!

--

--

--