ES 2.3.5 Node gets unstable (memory issue) if role is master

[theely]

Elasticsearch version: 2.3.5

Plugins installed: [license,marvel-agent]

JVM version:
openjdk version "1.8.0_102"
OpenJDK Runtime Environment (build 1.8.0_102-8u102-b14.1-1~bpo8+1-b14)
OpenJDK 64-Bit Server VM (build 25.102-b14, mixed mode)

OS version: Official Docker ES Image 2.3.5

Description of the problem including expected versus actual behavior:

I am running two nodes (elastic1, elastic2) on top of Mesos and Docker. Both nodes are running the official elasticsearch docker image version 2.3.5. Both nodes have the same Docker (1.11.2) and Mesos (0.28.1) version.
The main difference among the node is the hardware:
elastic1: 2 magnetic disks (RIDE 0), 64GB RAM, AMD Opteron 6338P
elastic2: 2 SSD disks (RIDE 0), 128GB RAM, Intel Xeon E5-1650V2

Since elastic 1 uses magnetic disks it has an additional es setting:
index.merge.scheduler.max_thread_count: 1

The issue is a bit complex to describe but basically when the node elastic2 acts as master it enters in a loop where it will use up all assigned memory (5GB) and than garbage collect all of it (takes about 10sec) to start over again. However if the node elastic2 is acting as slave everything runs smoothly. Attached you will find an image showing some metrics of the before and after master role assignment. The red line on the image indicates the exact time when roles are switch between the nodes.

Also I will attach the log file showing the before and after entries. You can see the many GC runs and the time it takes. After the restart and the role switch no more entries were logged and the cluster was stable.

Provide logs (if relevant):
[2016-08-22 12:43:21,536][WARN ][monitor.jvm ] [elastic2] [gc][old][57319][19431] duration [10.5s], collections [1]/[10.6s], total [10.5s]/[2.6d], memory [4.7gb]->[4.7gb]/[4.9gb], all_pools {[young] [605.3mb]->[592.1mb]/[665.6mb]}{[survivor] [0b]->[0b]/[83.1mb]}{[old] [4.1gb]->[4.1gb]/[4.1gb]}
[2016-08-22 12:43:35,087][WARN ][monitor.jvm ] [elastic2] [gc][old][57320][19432] duration [13.3s], collections [1]/[13.5s], total [13.3s]/[2.6d], memory [4.7gb]->[4.7gb]/[4.9gb], all_pools {[young] [592.1mb]->[603.2mb]/[665.6mb]}{[survivor] [0b]->[0b]/[83.1mb]}{[old] [4.1gb]->[4.1gb]/[4.1gb]}
[2016-08-22 12:43:46,271][WARN ][monitor.jvm ] [elastic2] [gc][old][57321][19433] duration [11s], collections [1]/[11.1s], total [11s]/[2.6d], memory [4.7gb]->[4.8gb]/[4.9gb], all_pools {[young] [603.2mb]->[629.5mb]/[665.6mb]}{[survivor] [0b]->[0b]/[83.1mb]}{[old] [4.1gb]->[4.1gb]/[4.1gb]}
[2016-08-22 12:43:59,236][WARN ][monitor.jvm ] [elastic2] [gc][old][57322][19434] duration [12.8s], collections [1]/[12.9s], total [12.8s]/[2.6d], memory [4.8gb]->[4.7gb]/[4.9gb], all_pools {[young] [629.5mb]->[593.4mb]/[665.6mb]}{[survivor] [0b]->[0b]/[83.1mb]}{[old] [4.1gb]->[4.1gb]/[4.1gb]}
[2016-08-22 12:44:10,448][WARN ][monitor.jvm ] [elastic2] [gc][old][57323][19435] duration [11s], collections [1]/[10.6s], total [11s]/[2.6d], memory [4.7gb]->[4.7gb]/[4.9gb], all_pools {[young] [593.4mb]->[653.2mb]/[665.6mb]}{[survivor] [0b]->[0b]/[83.1mb]}{[old] [4.1gb]->[4.1gb]/[4.1gb]}
[2016-08-22 12:44:23,487][WARN ][monitor.jvm ] [elastic2] [gc][old][57324][19436] duration [12.9s], collections [1]/[13.5s], total [12.9s]/[2.6d], memory [4.7gb]->[4.8gb]/[4.9gb], all_pools {[young] [653.2mb]->[636.9mb]/[665.6mb]}{[survivor] [0b]->[0b]/[83.1mb]}{[old] [4.1gb]->[4.1gb]/[4.1gb]}
[2016-08-22 12:44:34,708][WARN ][monitor.jvm ] [elastic2] [gc][old][57325][19437] duration [11s], collections [1]/[10.6s], total [11s]/[2.6d], memory [4.8gb]->[4.7gb]/[4.9gb], all_pools {[young] [636.9mb]->[596.3mb]/[665.6mb]}{[survivor] [0b]->[0b]/[83.1mb]}{[old] [4.1gb]->[4.1gb]/[4.1gb]}
[2016-08-22 12:44:49,023][WARN ][monitor.jvm ] [elastic2] [gc][old][57326][19438] duration [14.1s], collections [1]/[14.8s], total [14.1s]/[2.6d], memory [4.7gb]->[4.7gb]/[4.9gb], all_pools {[young] [596.3mb]->[588mb]/[665.6mb]}{[survivor] [0b]->[0b]/[83.1mb]}{[old] [4.1gb]->[4.1gb]/[4.1gb]}
Received killTask
Shutting down

================ MASTER SWITCH ================

[2016-08-22 12:44:58,478][INFO ][node ] [elastic2] version[2.3.5], pid[1], build[90f439f/2016-07-27T10:36:52Z]
[2016-08-22 12:44:58,478][INFO ][node ] [elastic2] initializing ...
[2016-08-22 12:44:58,825][INFO ][plugins ] [elastic2] modules [reindex, lang-expression, lang-groovy], plugins [license, marvel-agent], sites []
[2016-08-22 12:44:58,842][INFO ][env ] [elastic2] using [1] data paths, mounts [[/usr/share/elasticsearch/data (/dev/sda3)]], net usable_space [149.3gb], net total_space [434.5gb], spins? [possibly], types [ext4]
[2016-08-22 12:44:58,842][INFO ][env ] [elastic2] heap size [4.9gb], compressed ordinary object pointers [true]
[2016-08-22 12:44:59,955][INFO ][node ] [elastic2] initialized
[2016-08-22 12:44:59,955][INFO ][node ] [elastic2] starting ...
[2016-08-22 12:45:00,043][INFO ][transport ] [elastic2] publish_address {xx.xx.xx.xx:9300}, bound_addresses {[::]:9300}
[2016-08-22 12:45:00,046][INFO ][discovery ] [elastic2] newsriver/-JAQ76_VT3iWrWvYlre-rA
[2016-08-22 12:45:03,103][INFO ][cluster.service ] [elastic2] detected_master {elastic1}{8iaBxIvQQn2JM7tNFMjaYg}{xx.xx.xx.xx}{xx.xx.xx.xx:9300}{master=true}, added {{elastic1}{8iaBxIvQQn2JM7tNFMjaYg}{xx.xx.xx.xx}{xx.xx.xx.xx:9300}{master=true},}, reason: zen-disco-receive(from master [{elastic1}{8iaBxIvQQn2JM7tNFMjaYg}{xx.xx.xx.xx}{xx.xx.xx.xx:9300}{master=true}])
[2016-08-22 12:45:03,182][INFO ][http ] [elastic2] publish_address {xx.xx.xx.xx:9200}, bound_addresses {[::]:9200}
[2016-08-22 12:45:03,182][INFO ][node ] [elastic2] started

[clintongormley]

Hi @theely

The long GC messages make me think that you are swapping heap to disk. Please see the documentation, and ask questions like these in the forum instead: https://discuss.elastic.co/

The github issues list is reserved for bug reports and feature requests only.

thanks

[theely]

Hi @clintongormley
Thanks for the quick reply, I don't believe it is a swapping problem ES is running with the bootstrap.mlockall: true option as indicated by the documentation: https://www.elastic.co/guide/en/elasticsearch/guide/current/heap-sizing.html
Also if the issue would be some miss configuration why would it happen only if the node is running as master? And way does it affect only one node, they both share the same config?

I am writing here and not in the forum because to me this looks like some kind of memory leak, or some bug that under certain circumstances is eating up a lot of memory very quickly.
Anyway I am going to open a forum discussion as well and reporting back here if needed.

Thanks

[clintongormley]

hi @theely - sorry you're right, i read too quickly. Have you tried dumping the heap on the master and seeing what is using all of the memory?

[clintongormley]

Even just a nodes stats request when memory is full may be revealing

[jasontedor]

Official Docker ES Image 2.3.5

Perhaps you already know this, but I say this for general benefit because there is a lot of confusion on this issue: at this time there is not an official Elasticsearch image. That is, there is no Docker image that claims to be "official" that is affiliated with Elastic.

Regarding your issue, do you have a lot of churn in your cluster state? Can you get a heap dump immediately before a full GC (you can't use a standard tool for this, they usually trigger a full GC and then take the heap dump; instead run jinfo -flag +HeapDumpBeforeFullGC <PID> and don't forget to disable it with jinfo -flag +HeapDumpBeforeFullGC <PID>after the heap dump that is produced immediately proceeding the next full GC).

[theely]

Hi there,
I am having some troubles in providing you with the memory dump. Firstly I have problems in replicating the issue on the node, expect for the disk space nothing has changed since I reported the issue. However the node elastic2 is now running as master for several days and the described memory issue has still not manifested himself.
The second problem is that jinfo or jmap binaries are not installed on the Docker image I am using since it is based on openJDK 8 JRE. I tried to manually copy the missing binaries from the JDK of the same openJDK version but that wont work (it can not locate the java runtime). Alternatively I could modify the Docker image to install the JDK instead of the JRE but I am afraid this will jeopardize the issue reproducibility. Alternatively I could try to enable JMX and remotely dumping the heap.

Any thoughts on how I could proceed?

[theely]

@clintongormley Looks like we were able to replicate the issue and we may also have isolated the problem. The node enters in a faulty behaviour under heavy usage of the following update script:

public long updateLastVisit(String hostname, BaseSource source) {

        String lastVisit = dateFormatter.format(new Date());
        //This script iterates trough all sources of a website and 
        //updates the lastVisit field of the specific source.
        Script updateSource = new Script("ctx._source['lastUpdate']='" + lastVisit + "' \n " +
                "ctx._source.sources = ctx._source.sources.each({ " +
                "item -> if (item['url'] == '" + source.getUrl() + "') { " +
                "item['lastVisit'] = '" + lastVisit +
                "'}" +
                "})");

        Client client;
        client = ElasticsearchPoolUtil.getInstance().getClient();
        try {

            UpdateRequest updateRequest = new UpdateRequest();
            updateRequest.index("newsriver-website")
                    .type("website")
                    .id(hostname)
                    .script(updateSource)
                    .retryOnConflict(3);


            return client.update(updateRequest).get().getVersion();

        } catch (ExecutionException e) {
            logger.error("Unable to update website source", e);
        } catch (InterruptedException e) {
            logger.error("Unable to update website source", e);
        }
        return -1;
    }

Is it possible that this script is causing the issue? It is executed concurrently several times per second.

In the mean time we are extending the Docker image to use the Java 8 JDK (see previous comment) hoping to retrieve a heap dump soon.

[jasontedor]

@theely It looks like you might not be returning the client to the pool or am I misunderstanding your script?

[tlrx]

You could also use script parameters so that the script will be compiled once and then cached and reused.

In the current state it is compiled every time source & lastVisit changed (every time this code runs). The compilation produces many objects that need to be garbage collected and the fact that the script changed at almost every execution put a lot of pressure on the script cache.

[theely]

@jasontedor No the class name ElasticsearchPoolUtil is misleading, in fact getClient() is sharing a singleton instance of a ES's Client object. If I am not mistaken this is the suggested approach, since the ES Client is thread safe.

We are testing a slight variation of the script that is updating the nested objects using a for loop instead of the .each() method.

 Script updateSource = new Script("ctx._source['lastUpdate']='" + lastVisit + "' \n " +
                "for (item in ctx._source.sources) {" +
                    "if (item['url'] == '" + source.getUrl() + "') { " +
                       "item['lastVisit'] = '" + lastVisit +
                   "'}" +
                "}");

The new script started at 14h20 and beside a load increase on the machines (witch was expected, previously we disabled the old script) the nodes are quite stable.

Is it possible that the issue was related to the usage of the .each() method? Is there any issue using lambdas?

@tlrx I see I was not aware of it, I thought Groovy was fully interpreted. I will try it right away and post performance results.

I am actually not even sure we are supposed to make such an heavy use of nested object update method (via script)? The documentation concerning nested objects (https://www.elastic.co/guide/en/elasticsearch/guide/current/nested-objects.html) is not covering the update topic.

[jasontedor]

No the class name ElasticsearchPoolUtil is misleading, in fact getClient() is sharing a singleton instance of a ES's Client object. If I am not mistaken this is the suggested approach, since the ES Client is thread safe.

You should definitely rename that class as it's terribly misleading. 😢 The clients that we provide are thread-safe so your usage is fine then.

I think then that your issue is the issue that @tlrx pointed out.

I see I was not aware of it, I thought Groovy was fully interpreted.

No, it gets compiled to bytecode at runtime.