# Slow document upsert time

**URL:** <https://discuss.elastic.co/t/slow-document-upsert-time/9922>\
**Category:** Elasticsearch\
**Created:** [December 3, 2012, 6:46pm UTC](https://discuss.elastic.co/t/slow-document-upsert-time/9922 "2012-12-03T18:46:19Z")\
**Posts on this page:** 3\
**Page:** 1

<div class="post-metadata">

**Author:** ![mr\_t](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/mr_t/32/2599_2.png) [@mr\_t](https://discuss.elastic.co/u/mr_t)\
**Post date:** [December 3, 2012, 6:46pm UTC](https://discuss.elastic.co/t/slow-document-upsert-time/9922/1 "2012-12-03T18:46:19Z")

</div>

I'm experiencing some unexpectedly high update times for upserting  
documents into a single index using a custom river plugin which I wrote.  
I've noticed that when I start the river plugin, elapsed time to upsert  
documents into my index take on the order of tens of milliseconds with very  
little variance in upsert time. The throughput of document upserts hangs  
around 2k per minute. However, after the cluster (6 nodes) and the river  
have run for a few hours, the variance in update times increases  
dramatically, with a fraction of the upserts still taking in the tens of  
milliseconds, but other upserts taking tens of seconds (sometimes up to 40  
or 50 seconds total). Throughput slowly decreases until it reaches about  
100 per minute.

I've seen this thread  
([https://groups.google.com/forum/?fromgroups=#!topic/elasticsearch/qmCI4sA6lPE](https://groups.google.com/forum/?fromgroups=#!topic/elasticsearch/qmCI4sA6lPE))  
, but wanted to get another opinion.

The code that we use inside our river plugin to upsert documents looks like  
this:

IndexRequestBuilder builder = client.prepareIndex(elasticSearchIndex,  
elasticSearchDocumentType, id);

builder.setRefresh(false);

long beforeIndexUpdateTime = System.currentTimeMillis();  
builder.setSource(payload).execute().actionGet();  
long afterIndexUpdateTime = System.currentTimeMillis();

long elapsedTime = afterIndexUpdateTime - beforeIndexUpdateTime;

When I notice that average upsert times are growing beyond 1 second, I  
begin restarting cluster nodes one at a time. As I restart nodes, the  
average upsert time slowly drops, until I get to the last node of the  
cluster. When I restart the last node, average upsert times immediately  
drop back to about 10 ms, and throughput for upserts goes back to normal  
(2k per minute). I typically have to do this once per day to keep the river  
processing records in an expedient manner.

Something else curious: we have refresh = false for our indexing, and  
refresh interval = -1, yet our nodes stats reports that there is time taken  
up with refresh operations.

Some facts about our cluster:

- 6 identical hardware nodes
- 64 GB ram, 32GB allocated to ES
- Over time (\< 1 day), ES heap space is maxed out and remainder of system  
memory is consumed by OS file cache, which is expected
- Our ES cluster is under sustained query load all of the time, but it's  
not very high load - a few queries a second typically.
- Index refresh interval is -1
- We have not tried bulk insert

Any ideas about what might be going on, or what I could do to prevent these  
upsert slowdowns? Is bulk insert the only possible way to alleviate this,  
or are there other parameters which could be tuned?

Thanks!  
-Taylor

Node stats:  
{"cluster\_name":"merchant\_data\_prod\_snc1","nodes":{"TzYLULMaScSAQvhwh7EuUQ":{"timestamp":1354560090787,"name":"Stevie  
Hunter","transport\_address":"inet[/10.20.71.146:9300]","hostname":"merchant-data-esmaster1","indices":{"store":{"size":"23.3gb","size\_in\_bytes":25025106146,"throttle\_time":"0s","throttle\_time\_in\_millis":0},"docs":{"count":5672834,"deleted":1581696},"indexing":{"index\_total":35687,"index\_time":"54.2s","index\_time\_in\_millis":54298,"index\_current":1,"delete\_total":0,"delete\_time":"0s","delete\_time\_in\_millis":0,"delete\_current":0},"get":{"total":7397,"time":"1.2s","time\_in\_millis":1209,"exists\_total":7374,"exists\_time":"1.2s","exists\_time\_in\_millis":1209,"missing\_total":23,"missing\_time":"0s","missing\_time\_in\_millis":0,"current":0},"search":{"query\_total":331360,"query\_time":"10.3m","query\_time\_in\_millis":618379,"query\_current":0,"fetch\_total":16036,"fetch\_time":"2s","fetch\_time\_in\_millis":2045,"fetch\_current":0},"cache":{"field\_evictions":0,"field\_size":"227.8mb","field\_size\_in\_bytes":238918776,"filter\_count":349,"filter\_evictions":0,"filter\_size":"2.2mb","filter\_size\_in\_bytes":2398392},"merges":{"current":0,"current\_docs":0,"current\_size":"0b","current\_size\_in\_bytes":0,"total":4704,"total\_time":"5.1m","total\_time\_in\_millis":307563,"total\_docs":1404914,"total\_size":"4.7gb","total\_size\_in\_bytes":5140763017},"refresh":{"total":20348,"total\_time":"5.8m","total\_time\_in\_millis":352872},"flush":{"total":62,"total\_time":"2.2m","total\_time\_in\_millis":137203}}},"rukevpq\_QYSMprkFwBw4hg":{"timestamp":1354560090788,"name":"Sekhmet","transport\_address":"inet[/10.20.71.154:9300]","hostname":"merchant-data-search3","indices":{"store":{"size":"18.4gb","size\_in\_bytes":19854219732,"throttle\_time":"0s","throttle\_time\_in\_millis":0},"docs":{"count":4253940,"deleted":1050026},"indexing":{"index\_total":6666,"index\_time":"10.9s","index\_time\_in\_millis":10937,"index\_current":0,"delete\_total":0,"delete\_time":"0s","delete\_time\_in\_millis":0,"delete\_current":0},"get":{"total":1515,"time":"256ms","time\_in\_millis":256,"exists\_total":1508,"exists\_time":"256ms","exists\_time\_in\_millis":256,"missing\_total":7,"missing\_time":"0s","missing\_time\_in\_millis":0,"current":0},"search":{"query\_total":66775,"query\_time":"2m","query\_time\_in\_millis":125095,"query\_current":0,"fetch\_total":3133,"fetch\_time":"307ms","fetch\_time\_in\_millis":307,"fetch\_current":0},"cache":{"field\_evictions":0,"field\_size":"88mb","field\_size\_in\_bytes":92364704,"filter\_count":137,"filter\_evictions":0,"filter\_size":"356.9kb","filter\_size\_in\_bytes":365520},"merges":{"current":1,"current\_docs":33,"current\_size":"296kb","current\_size\_in\_bytes":303191,"total":870,"total\_time":"41.6s","total\_time\_in\_millis":41605,"total\_docs":252721,"total\_size":"849.9mb","total\_size\_in\_bytes":891273472},"refresh":{"total":4258,"total\_time":"28.9s","total\_time\_in\_millis":28973},"flush":{"total":5,"total\_time":"660ms","total\_time\_in\_millis":660}}},"JxtjB0NxSXm5nFMlVERvlw":{"timestamp":1354560090788,"name":"Hammerhead","transport\_address":"inet[/10.20.73.21:9300]","hostname":"merchant-data-esmaster2","indices":{"store":{"size":"40gb","size\_in\_bytes":42955598450,"throttle\_time":"0s","throttle\_time\_in\_millis":0},"docs":{"count":9465644,"deleted":2395535},"indexing":{"index\_total":35631,"index\_time":"1m","index\_time\_in\_millis":64685,"index\_current":0,"delete\_total":0,"delete\_time":"0s","delete\_time\_in\_millis":0,"delete\_current":0},"get":{"total":8860,"time":"19.8s","time\_in\_millis":19894,"exists\_total":8842,"exists\_time":"19.8s","exists\_time\_in\_millis":19894,"missing\_total":18,"missing\_time":"0s","missing\_time\_in\_millis":0,"current":0},"search":{"query\_total":390440,"query\_time":"14m","query\_time\_in\_millis":843619,"query\_current":0,"fetch\_total":18766,"fetch\_time":"48.1s","fetch\_time\_in\_millis":48148,"fetch\_current":0},"cache":{"field\_evictions":0,"field\_size":"296.1mb","field\_size\_in\_bytes":310580060,"filter\_count":264,"filter\_evictions":0,"filter\_size":"2.3mb","filter\_size\_in\_bytes":2464480},"merges":{"current":0,"current\_docs":0,"current\_size":"0b","current\_size\_in\_bytes":0,"total":4642,"total\_time":"6.7m","total\_time\_in\_millis":402696,"total\_docs":1293547,"total\_size":"4.7gb","total\_size\_in\_bytes":5113798115},"refresh":{"total":24125,"total\_time":"6.4m","total\_time\_in\_millis":385515},"flush":{"total":47,"total\_time":"1.4m","total\_time\_in\_millis":86634}}},"mCUKsUBqRnyJ\_iHrR0zaYQ":{"timestamp":1354560090787,"name":"Whitemane,  
Kofi","transport\_address":"inet[/10.20.70.120:9300]","hostname":"merchant-data-search1","indices":{"store":{"size":"30.7gb","size\_in\_bytes":33065685443,"throttle\_time":"0s","throttle\_time\_in\_millis":0},"docs":{"count":7265217,"deleted":1865636},"indexing":{"index\_total":24208,"index\_time":"36.2s","index\_time\_in\_millis":36276,"index\_current":0,"delete\_total":0,"delete\_time":"0s","delete\_time\_in\_millis":0,"delete\_current":0},"get":{"total":6779,"time":"17.2s","time\_in\_millis":17295,"exists\_total":6752,"exists\_time":"17.2s","exists\_time\_in\_millis":17295,"missing\_total":27,"missing\_time":"0s","missing\_time\_in\_millis":0,"current":0},"search":{"query\_total":276755,"query\_time":"9.1m","query\_time\_in\_millis":547407,"query\_current":0,"fetch\_total":13301,"fetch\_time":"32.3s","fetch\_time\_in\_millis":32368,"fetch\_current":0},"cache":{"field\_evictions":0,"field\_size":"234.1mb","field\_size\_in\_bytes":245493260,"filter\_count":167,"filter\_evictions":0,"filter\_size":"1.1mb","filter\_size\_in\_bytes":1194392},"merges":{"current":0,"current\_docs":0,"current\_size":"0b","current\_size\_in\_bytes":0,"total":3195,"total\_time":"3.2m","total\_time\_in\_millis":193794,"total\_docs":864134,"total\_size":"3.2gb","total\_size\_in\_bytes":3524762890},"refresh":{"total":17687,"total\_time":"2.4m","total\_time\_in\_millis":148159},"flush":{"total":16,"total\_time":"4.9s","total\_time\_in\_millis":4992}}},"WBvkgmDcQUG7rYbRhKTGgQ":{"timestamp":1354560090789,"name":"Typhoid  
Mary","transport\_address":"inet[/10.20.73.22:9300]","hostname":"merchant-data-search4","indices":{"store":{"size":"5.7gb","size\_in\_bytes":6215870795,"throttle\_time":"0s","throttle\_time\_in\_millis":0},"docs":{"count":1464830,"deleted":403712},"indexing":{"index\_total":4138,"index\_time":"3.3s","index\_time\_in\_millis":3345,"index\_current":0,"delete\_total":0,"delete\_time":"0s","delete\_time\_in\_millis":0,"delete\_current":0},"get":{"total":658,"time":"112ms","time\_in\_millis":112,"exists\_total":654,"exists\_time":"112ms","exists\_time\_in\_millis":112,"missing\_total":4,"missing\_time":"0s","missing\_time\_in\_millis":0,"current":0},"search":{"query\_total":29127,"query\_time":"55.4s","query\_time\_in\_millis":55428,"query\_current":0,"fetch\_total":1453,"fetch\_time":"145ms","fetch\_time\_in\_millis":145,"fetch\_current":0},"cache":{"field\_evictions":0,"field\_size":"59.4mb","field\_size\_in\_bytes":62355984,"filter\_count":85,"filter\_evictions":0,"filter\_size":"240.1kb","filter\_size\_in\_bytes":245896},"merges":{"current":0,"current\_docs":0,"current\_size":"0b","current\_size\_in\_bytes":0,"total":654,"total\_time":"38.8s","total\_time\_in\_millis":38889,"total\_docs":155980,"total\_size":"503.9mb","total\_size\_in\_bytes":528471197},"refresh":{"total":1986,"total\_time":"11.7s","total\_time\_in\_millis":11700},"flush":{"total":6,"total\_time":"189ms","total\_time\_in\_millis":189}}},"GzpOGQUnSQunG7lBXOh9aQ":{"timestamp":1354560090787,"name":"Jones,  
Gabe","transport\_address":"inet[/10.20.70.119:9300]","hostname":"merchant-data-search2","indices":{"store":{"size":"31.2gb","size\_in\_bytes":33527799828,"throttle\_time":"0s","throttle\_time\_in\_millis":0},"docs":{"count":7280148,"deleted":1696965},"indexing":{"index\_total":12755,"index\_time":"15.7s","index\_time\_in\_millis":15717,"index\_current":0,"delete\_total":0,"delete\_time":"0s","delete\_time\_in\_millis":0,"delete\_current":0},"get":{"total":3320,"time":"3.7s","time\_in\_millis":3722,"exists\_total":3310,"exists\_time":"3.7s","exists\_time\_in\_millis":3722,"missing\_total":10,"missing\_time":"0s","missing\_time\_in\_millis":0,"current":0},"search":{"query\_total":138146,"query\_time":"4.5m","query\_time\_in\_millis":272979,"query\_current":0,"fetch\_total":6607,"fetch\_time":"6.9s","fetch\_time\_in\_millis":6930,"fetch\_current":0},"cache":{"field\_evictions":0,"field\_size":"139.3mb","field\_size\_in\_bytes":146091020,"filter\_count":129,"filter\_evictions":0,"filter\_size":"644.2kb","filter\_size\_in\_bytes":659728},"merges":{"current":0,"current\_docs":0,"current\_size":"0b","current\_size\_in\_bytes":0,"total":1789,"total\_time":"1.9m","total\_time\_in\_millis":115117,"total\_docs":405066,"total\_size":"1.4gb","total\_size\_in\_bytes":1607732305},"refresh":{"total":8965,"total\_time":"1m","total\_time\_in\_millis":63856},"flush":{"total":11,"total\_time":"3.9s","total\_time\_in\_millis":3983}}}}}

Index stats:  
{"ok":true,"\_shards":{"total":60,"successful":60,"failed":0},"\_all":{"primaries":{"docs":{"count":8675769,"deleted":1679654},"store":{"size":"38.1gb","size\_in\_bytes":40998312655,"throttle\_time":"0s","throttle\_time\_in\_millis":0},"indexing":{"index\_total":0,"index\_time":"0s","index\_time\_in\_millis":0,"index\_current":0,"delete\_total":0,"delete\_time":"0s","delete\_time\_in\_millis":0,"delete\_current":0},"get":{"total":0,"time":"0s","time\_in\_millis":0,"exists\_total":0,"exists\_time":"0s","exists\_time\_in\_millis":0,"missing\_total":0,"missing\_time":"0s","missing\_time\_in\_millis":0,"current":0},"search":{"query\_total":0,"query\_time":"0s","query\_time\_in\_millis":0,"query\_current":0,"fetch\_total":0,"fetch\_time":"0s","fetch\_time\_in\_millis":0,"fetch\_current":0}},"total":{"docs":{"count":26027307,"deleted":5038962},"store":{"size":"114.5gb","size\_in\_bytes":122994937965,"throttle\_time":"0s","throttle\_time\_in\_millis":0},"indexing":{"index\_total":0,"index\_time":"0s","index\_time\_in\_millis":0,"index\_current":0,"delete\_total":0,"delete\_time":"0s","delete\_time\_in\_millis":0,"delete\_current":0},"get":{"total":0,"time":"0s","time\_in\_millis":0,"exists\_total":0,"exists\_time":"0s","exists\_time\_in\_millis":0,"missing\_total":0,"missing\_time":"0s","missing\_time\_in\_millis":0,"current":0},"search":{"query\_total":0,"query\_time":"0s","query\_time\_in\_millis":0,"query\_current":0,"fetch\_total":0,"fetch\_time":"0s","fetch\_time\_in\_millis":0,"fetch\_current":0}},"indices":{"places\_2012\_10\_24":{"primaries":{"docs":{"count":8675769,"deleted":1679654},"store":{"size":"38.1gb","size\_in\_bytes":40998312655,"throttle\_time":"0s","throttle\_time\_in\_millis":0},"indexing":{"index\_total":0,"index\_time":"0s","index\_time\_in\_millis":0,"index\_current":0,"delete\_total":0,"delete\_time":"0s","delete\_time\_in\_millis":0,"delete\_current":0},"get":{"total":0,"time":"0s","time\_in\_millis":0,"exists\_total":0,"exists\_time":"0s","exists\_time\_in\_millis":0,"missing\_total":0,"missing\_time":"0s","missing\_time\_in\_millis":0,"current":0},"search":{"query\_total":0,"query\_time":"0s","query\_time\_in\_millis":0,"query\_current":0,"fetch\_total":0,"fetch\_time":"0s","fetch\_time\_in\_millis":0,"fetch\_current":0}},"total":{"docs":{"count":26027307,"deleted":5038962},"store":{"size":"114.5gb","size\_in\_bytes":122994937965,"throttle\_time":"0s","throttle\_time\_in\_millis":0},"indexing":{"index\_total":0,"index\_time":"0s","index\_time\_in\_millis":0,"index\_current":0,"delete\_total":0,"delete\_time":"0s","delete\_time\_in\_millis":0,"delete\_current":0},"get":{"total":0,"time":"0s","time\_in\_millis":0,"exists\_total":0,"exists\_time":"0s","exists\_time\_in\_millis":0,"missing\_total":0,"missing\_time":"0s","missing\_time\_in\_millis":0,"current":0},"search":{"query\_total":0,"query\_time":"0s","query\_time\_in\_millis":0,"query\_current":0,"fetch\_total":0,"fetch\_time":"0s","fetch\_time\_in\_millis":0,"fetch\_current":0}}}}}}

--

---

<div class="post-metadata">

**Author:** ![jprante](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/jprante/32/44941_2.png) [@jprante](https://discuss.elastic.co/u/jprante)\
**Post date:** [December 4, 2012, 8:04am UTC](https://discuss.elastic.co/t/slow-document-upsert-time/9922/2 "2012-12-04T08:04:02Z")

</div>

You are using very large heaps. From what it seems, you suffer from long  
garbage collection (GC) runs. GC runs can not be influenced by changing  
inserts to bulk inserts, or changed refresh settings.

I would like to recommend the following steps for better diagnostics:

- take a fraction of your data you are indexing, configure a test cluster  
with a single node with a small heap, index your data into this node with  
your river setup
- enable debug logging, enable Java heap logging
- monitor your test node, there are tools like BigDesk out there
- just like in each Java app, analyze what is on your heap, how the heap  
grows, eventually take heap snapshots, use tools like jvisualvm
- watch out for memory leaks, especially in your custom river

For more about understanding the Java Virtual machine settings, the large  
heap challenge, and some strategies against performance degradation, see  
also

[http://jprante.github.com/2012/11/28/Elasticsearch-Java-Virtual-Machine-settings-explained.html](http://jprante.github.com/2012/11/28/Elasticsearch-Java-Virtual-Machine-settings-explained.html)

Best regards,

Jörg

--

---

<div class="post-metadata">

**Author:** ![system](https://us1.discourse-cdn.com/elastic/original/3X/1/a/1ac57faf039f6b580b3f104ef42a2a89e41014de.png) [@system](https://discuss.elastic.co/u/system)\
**Post date:** [July 6, 2017, 3:01am UTC](https://discuss.elastic.co/t/slow-document-upsert-time/9922/3 "2017-07-06T03:01:43Z")

</div>