Skip to content

OutOfMemoryException: Java Heap Space while indexing #22360

Closed
@leilengma

Description

@leilengma

Elasticsearch version:5.0.0

Plugins installed: []

JVM version: 1.8.0_111

OS version: Windows 7

Description of the problem including expected versus actual behavior:

I am using elasticsearch to store objects which are structured as follows:

    properties: {
        date: { type: "date", format:"epoch_second"},
        id: { type: "long" },
        documents: {
            type: "nested",
            properties: {
                id: { type: "long" },
                state: {type: "keyword"},
                class: { type: "text" },
                pages: {
                    type:"nested",
                    properties: {
                        imageId: { type: "long" },
                        is_attachment: { type: "boolean" },
                        thumbnailUri: {type: "text"},
                        imageUri: {type:"text"}, 
                        fields: {
                            type:"nested",
                            properties: {
                                id: { type: "long" },
                                content: { type: "text"}
                            }
                        }
                    }
                }
            }
        }
    }

I am running a single node which has only one index with 5 shards and 0 replicas.

Settings of my node:
bootstrap.memory_lock: true
indices.memory.index_buffer_size: 512mb
indices.fielddata.cache.size: 512mb

jvm options:
-Xms2700m
-Xmx2700m

Settings of that single index:

     "index": {
        "refresh_interval": "-1",
        "number_of_shards": "5",
        "provided_name": "last_test",
        "creation_date": "1481036664335",
        "number_of_replicas": "0",
        "uuid": "UwXRs9Z1Sj2kh7Y0f6AfOg",
        "version": {
           "created": "5000099"
        }
     }

I am using elasticsearchpy client and the bulk api to index 200 documents in one request.

The problem is that while elasticsearch is indexing the documents, the jvm heap usage keeps increasing slowly until an OutOfMemory exception: Java Heap Space occurs.

I also took a look into the heap dump created by elasticsearch when that exception occurs:

log1
log2

and memory usage plot:
mem

Since I am not familiar with both elasticsearch and jvm heap management, I cannot find out why this happens. Have I done somthing wrong? Or it is just due to insufficient heap size?

Thanks for any support and opinions.

Steps to reproduce:

  1. Indexing documents for a while

Provide logs (if relevant):

[2016-12-28T09:04:57,470][INFO ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][34] overhead, spent [417ms] collecting in the last [1.2s]
[2016-12-28T09:04:59,509][INFO ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][36] overhead, spent [435ms] collecting in the last [1s]
[2016-12-28T09:05:01,667][INFO ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][38] overhead, spent [574ms] collecting in the last [1.1s]
[2016-12-28T09:05:03,684][INFO ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][40] overhead, spent [277ms] collecting in the last [1s]
[2016-12-28T09:05:05,686][INFO ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][42] overhead, spent [320ms] collecting in the last [1s]
[2016-12-28T09:05:07,687][INFO ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][44] overhead, spent [361ms] collecting in the last [1s]
[2016-12-28T09:05:09,689][INFO ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][46] overhead, spent [378ms] collecting in the last [1s]
[2016-12-28T09:05:11,692][INFO ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][48] overhead, spent [285ms] collecting in the last [1s]
[2016-12-28T09:05:14,989][INFO ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][51] overhead, spent [373ms] collecting in the last [1.2s]
[2016-12-28T09:05:15,991][INFO ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][52] overhead, spent [381ms] collecting in the last [1s]
[2016-12-28T09:05:17,993][WARN ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][54] overhead, spent [538ms] collecting in the last [1s]
[2016-12-28T09:05:20,096][WARN ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][56] overhead, spent [601ms] collecting in the last [1s]
[2016-12-28T09:05:22,393][INFO ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][58] overhead, spent [478ms] collecting in the last [1.2s]
[2016-12-28T09:05:24,747][INFO ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][60] overhead, spent [476ms] collecting in the last [1.3s]
[2016-12-28T09:05:25,759][INFO ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][61] overhead, spent [319ms] collecting in the last [1s]
[2016-12-28T09:05:27,769][WARN ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][63] overhead, spent [660ms] collecting in the last [1s]
[2016-12-28T09:05:29,771][WARN ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][65] overhead, spent [801ms] collecting in the last [1s]
[2016-12-28T09:05:30,772][INFO ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][66] overhead, spent [469ms] collecting in the last [1s]
[2016-12-28T09:05:32,773][INFO ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][68] overhead, spent [352ms] collecting in the last [1s]
[2016-12-28T09:05:34,836][WARN ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][70] overhead, spent [637ms] collecting in the last [1s]
[2016-12-28T09:05:36,876][WARN ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][72] overhead, spent [612ms] collecting in the last [1s]
[2016-12-28T09:05:37,877][WARN ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][73] overhead, spent [502ms] collecting in the last [1s]
[2016-12-28T09:05:39,878][WARN ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][75] overhead, spent [855ms] collecting in the last [1s]
[2016-12-28T09:05:40,901][INFO ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][76] overhead, spent [365ms] collecting in the last [1s]
[2016-12-28T09:05:44,258][INFO ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][79] overhead, spent [560ms] collecting in the last [1.1s]
[2016-12-28T09:05:45,263][WARN ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][80] overhead, spent [766ms] collecting in the last [1s]
[2016-12-28T09:05:47,321][WARN ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][82] overhead, spent [552ms] collecting in the last [1s]
[2016-12-28T09:05:48,412][WARN ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][83] overhead, spent [1s] collecting in the last [1.1s]
[2016-12-28T09:05:49,712][INFO ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][84] overhead, spent [640ms] collecting in the last [1.3s]
[2016-12-28T09:05:51,918][WARN ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][86] overhead, spent [855ms] collecting in the last [1.1s]
[2016-12-28T09:05:53,052][WARN ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][87] overhead, spent [1s] collecting in the last [1.1s]
[2016-12-28T09:05:54,077][WARN ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][88] overhead, spent [866ms] collecting in the last [1s]
[2016-12-28T09:05:55,080][INFO ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][89] overhead, spent [331ms] collecting in the last [1s]
[2016-12-28T09:05:57,158][WARN ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][91] overhead, spent [846ms] collecting in the last [1s]
[2016-12-28T09:05:58,659][WARN ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][92] overhead, spent [958ms] collecting in the last [1.4s]
[2016-12-28T09:05:59,697][INFO ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][93] overhead, spent [356ms] collecting in the last [1s]
[2016-12-28T09:06:00,920][INFO ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][94] overhead, spent [529ms] collecting in the last [1.2s]
[2016-12-28T09:06:01,922][WARN ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][95] overhead, spent [800ms] collecting in the last [1s]
[2016-12-28T09:06:03,325][WARN ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][96] overhead, spent [653ms] collecting in the last [1.2s]
[2016-12-28T09:06:05,473][WARN ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][98] overhead, spent [979ms] collecting in the last [1.1s]
[2016-12-28T09:06:06,553][WARN ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][99] overhead, spent [1s] collecting in the last [1s]
[2016-12-28T09:06:07,675][WARN ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][100] overhead, spent [791ms] collecting in the last [1s]
[2016-12-28T09:06:08,910][INFO ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][101] overhead, spent [643ms] collecting in the last [1.3s]
[2016-12-28T09:06:10,953][WARN ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][103] overhead, spent [867ms] collecting in the last [1s]
[2016-12-28T09:06:12,011][WARN ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][104] overhead, spent [1s] collecting in the last [1s]
[2016-12-28T09:06:13,335][WARN ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][105] overhead, spent [1.1s] collecting in the last [1s]
[2016-12-28T09:06:14,628][WARN ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][106] overhead, spent [870ms] collecting in the last [1.6s]
[2016-12-28T09:06:16,021][WARN ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][107] overhead, spent [1.1s] collecting in the last [1.4s]
[2016-12-28T09:06:17,438][INFO ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][108] overhead, spent [463ms] collecting in the last [1.1s]
[2016-12-28T09:06:18,603][WARN ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][109] overhead, spent [1.1s] collecting in the last [1.4s]
[2016-12-28T09:06:19,645][WARN ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][110] overhead, spent [1s] collecting in the last [1s]
[2016-12-28T09:06:21,153][WARN ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][111] overhead, spent [1.2s] collecting in the last [1.4s]
[2016-12-28T09:06:22,586][WARN ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][112] overhead, spent [1.2s] collecting in the last [1.1s]
[2016-12-28T09:06:49,673][WARN ][o.e.m.j.JvmGcMonitorService] [node-1] [gc][114] overhead, spent [1.6s] collecting in the last [1.4s]
[2016-12-28T09:06:50,221][ERROR][o.e.b.ElasticsearchUncaughtExceptionHandler] [node-1] fatal error in thread [elasticsearch[node-1][bulk][T#6]], exiting
java.lang.OutOfMemoryError: Java heap space
at org.apache.lucene.index.FreqProxTermsWriterPerField$FreqProxPostingsArray.(FreqProxTermsWriterPerField.java:207) ~[lucene-core-6.2.0.jar:6.2.0 764d0f19151dbff6f5fcd9fc4b2682cf934590c5 - mike - 2016-08-20 05:39:36]
at org.apache.lucene.index.FreqProxTermsWriterPerField$FreqProxPostingsArray.newInstance(FreqProxTermsWriterPerField.java:230) ~[lucene-core-6.2.0.jar:6.2.0 764d0f19151dbff6f5fcd9fc4b2682cf934590c5 - mike - 2016-08-20 05:39:36]
at org.apache.lucene.index.ParallelPostingsArray.grow(ParallelPostingsArray.java:46) ~[lucene-core-6.2.0.jar:6.2.0 764d0f19151dbff6f5fcd9fc4b2682cf934590c5 - mike - 2016-08-20 05:39:36]
at org.apache.lucene.index.TermsHashPerField$PostingsBytesStartArray.grow(TermsHashPerField.java:250) ~[lucene-core-6.2.0.jar:6.2.0 764d0f19151dbff6f5fcd9fc4b2682cf934590c5 - mike - 2016-08-20 05:39:36]
at org.apache.lucene.util.BytesRefHash.add(BytesRefHash.java:271) ~[lucene-core-6.2.0.jar:6.2.0 764d0f19151dbff6f5fcd9fc4b2682cf934590c5 - mike - 2016-08-20 05:39:36]
at org.apache.lucene.index.TermsHashPerField.add(TermsHashPerField.java:149) ~[lucene-core-6.2.0.jar:6.2.0 764d0f19151dbff6f5fcd9fc4b2682cf934590c5 - mike - 2016-08-20 05:39:36]
at org.apache.lucene.index.DefaultIndexingChain$PerField.invert(DefaultIndexingChain.java:762) ~[lucene-core-6.2.0.jar:6.2.0 764d0f19151dbff6f5fcd9fc4b2682cf934590c5 - mike - 2016-08-20 05:39:36]
at org.apache.lucene.index.DefaultIndexingChain.processField(DefaultIndexingChain.java:417) ~[lucene-core-6.2.0.jar:6.2.0 764d0f19151dbff6f5fcd9fc4b2682cf934590c5 - mike - 2016-08-20 05:39:36]
at org.apache.lucene.index.DefaultIndexingChain.processDocument(DefaultIndexingChain.java:373) ~[lucene-core-6.2.0.jar:6.2.0 764d0f19151dbff6f5fcd9fc4b2682cf934590c5 - mike - 2016-08-20 05:39:36]
at org.apache.lucene.index.DocumentsWriterPerThread.updateDocuments(DocumentsWriterPerThread.java:272) ~[lucene-core-6.2.0.jar:6.2.0 764d0f19151dbff6f5fcd9fc4b2682cf934590c5 - mike - 2016-08-20 05:39:36]
at org.apache.lucene.index.DocumentsWriter.updateDocuments(DocumentsWriter.java:433) ~[lucene-core-6.2.0.jar:6.2.0 764d0f19151dbff6f5fcd9fc4b2682cf934590c5 - mike - 2016-08-20 05:39:36]
at org.apache.lucene.index.IndexWriter.updateDocuments(IndexWriter.java:1375) ~[lucene-core-6.2.0.jar:6.2.0 764d0f19151dbff6f5fcd9fc4b2682cf934590c5 - mike - 2016-08-20 05:39:36]
at org.apache.lucene.index.IndexWriter.addDocuments(IndexWriter.java:1351) ~[lucene-core-6.2.0.jar:6.2.0 764d0f19151dbff6f5fcd9fc4b2682cf934590c5 - mike - 2016-08-20 05:39:36]
at org.elasticsearch.index.engine.InternalEngine.index(InternalEngine.java:533) ~[elasticsearch-5.0.0.jar:5.0.0]
at org.elasticsearch.index.engine.InternalEngine.innerIndex(InternalEngine.java:517) ~[elasticsearch-5.0.0.jar:5.0.0]
at org.elasticsearch.index.engine.InternalEngine.index(InternalEngine.java:408) ~[elasticsearch-5.0.0.jar:5.0.0]
at org.elasticsearch.index.shard.IndexShard.index(IndexShard.java:552) ~[elasticsearch-5.0.0.jar:5.0.0]
at org.elasticsearch.index.shard.IndexShard.index(IndexShard.java:542) ~[elasticsearch-5.0.0.jar:5.0.0]
at org.elasticsearch.action.index.TransportIndexAction.executeIndexRequestOnPrimary(TransportIndexAction.java:191) ~[elasticsearch-5.0.0.jar:5.0.0]
at org.elasticsearch.action.bulk.TransportShardBulkAction.shardIndexOperation(TransportShardBulkAction.java:351) ~[elasticsearch-5.0.0.jar:5.0.0]
at org.elasticsearch.action.bulk.TransportShardBulkAction.index(TransportShardBulkAction.java:158) ~[elasticsearch-5.0.0.jar:5.0.0]
at org.elasticsearch.action.bulk.TransportShardBulkAction.handleItem(TransportShardBulkAction.java:137) ~[elasticsearch-5.0.0.jar:5.0.0]
at org.elasticsearch.action.bulk.TransportShardBulkAction.onPrimaryShard(TransportShardBulkAction.java:123) ~[elasticsearch-5.0.0.jar:5.0.0]
at org.elasticsearch.action.bulk.TransportShardBulkAction.onPrimaryShard(TransportShardBulkAction.java:74) ~[elasticsearch-5.0.0.jar:5.0.0]
at org.elasticsearch.action.support.replication.TransportWriteAction.shardOperationOnPrimary(TransportWriteAction.java:78) ~[elasticsearch-5.0.0.jar:5.0.0]
at org.elasticsearch.action.support.replication.TransportWriteAction.shardOperationOnPrimary(TransportWriteAction.java:50) ~[elasticsearch-5.0.0.jar:5.0.0]
at org.elasticsearch.action.support.replication.TransportReplicationAction$PrimaryShardReference.perform(TransportReplicationAction.java:902) ~[elasticsearch-5.0.0.jar:5.0.0]
at org.elasticsearch.action.support.replication.TransportReplicationAction$PrimaryShardReference.perform(TransportReplicationAction.java:872) ~[elasticsearch-5.0.0.jar:5.0.0]
at org.elasticsearch.action.support.replication.ReplicationOperation.execute(ReplicationOperation.java:113) ~[elasticsearch-5.0.0.jar:5.0.0]
at org.elasticsearch.action.support.replication.TransportReplicationAction$AsyncPrimaryAction.onResponse(TransportReplicationAction.java:319) ~[elasticsearch-5.0.0.jar:5.0.0]
at org.elasticsearch.action.support.replication.TransportReplicationAction$AsyncPrimaryAction.onResponse(TransportReplicationAction.java:254) ~[elasticsearch-5.0.0.jar:5.0.0]
at org.elasticsearch.action.support.replication.TransportReplicationAction$1.onResponse(TransportReplicationAction.java:838) ~[elasticsearch-5.0.0.jar:5.0.0]

Metadata

Metadata

Assignees

No one assigned

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions