# ES 7.5 translog recovery is extremely slow **URL:** \ **Category:** Elasticsearch\ **Created:** [January 17, 2020, 6:48pm UTC](https://discuss.elastic.co/t/es-7-5-translog-recovery-is-extremely-slow/215505 "2020-01-17T18:48:47Z")\ **Posts on this page:** 16\ **Page:** 1
**Author:** ![Jonathan\_Mendenhall](https://avatars.discourse-cdn.com/v4/letter/j/ebca7d/32.png) [@Jonathan\_Mendenhall](https://discuss.elastic.co/u/Jonathan_Mendenhall)\ **Post date:** [January 17, 2020, 6:48pm UTC](https://discuss.elastic.co/t/es-7-5-translog-recovery-is-extremely-slow/215505/1 "2020-01-17T18:48:48Z")
A sample of the response from the recovery API: "translog" : { "recovered" : 17201, "total" : 4686825, "percent" : "0.4%", "total\_on\_start" : -1, "total\_time\_in\_millis" : 1790702 } This is on an index that is no longer being written to. The size is well below the cap, but to get 0.4% for the way through it has taken 30 minutes. At that rate, letting it complete would take far too long (although, admittedly, they seem to eventually go away on their own log before they would it that pace was maintained). The shards for this index are all around 6GB. And when I get shard stats for the index "translog" : { "operations" : 0, "size\_in\_bytes" : 55, "uncommitted\_operations" : 0, "uncommitted\_size\_in\_bytes" : 55, "earliest\_last\_modified\_age" : 4316474 } Nothing about this index is special (every since moving to 7.5, I have seen this sort of translog slowness on many different indices). And I have not changed any translog settings away from their defaults. To get rid of these parasitic translog operations, I have been reducing replica counts on the index to 0 (I thought reducing from 1 to 2 would work, but it always seems to keep the replica around that is being recovered from the translog), allow the recovery operations to be abandoned, and then I increase the replica count back to its original value. At that point, the translog size is reported as 0, and recovery happens very quickly. From my perspective, we would be better off if the translog did not exist, and we instead just recovered by copying the raw data. Since, translog recovery has always been slow for us, but never this bad. Is there something about the new "soft deletes" (our old cluster was on ES 6.4) that I am not understanding that could be causing this? Assuming that might be to blame, I am tempted to either disable them, or dramatically reduce the lease period. ---
**Author:** ![DavidTurner](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/davidturner/32/22453_2.png) [@DavidTurner](https://discuss.elastic.co/u/DavidTurner)\ **Post date:** [January 17, 2020, 9:28pm UTC](https://discuss.elastic.co/t/es-7-5-translog-recovery-is-extremely-slow/215505/2 "2020-01-17T21:28:08Z")
Could you share the index settings (`GET /index/_settings`), its detailed stats (`GET /index/_stats?level=shards`) and the complete recovery output too? Use [https://gist.github.com/](https://gist.github.com/) since that won't fit here. ---
**Author:** ![Jonathan\_Mendenhall](https://avatars.discourse-cdn.com/v4/letter/j/ebca7d/32.png) [@Jonathan\_Mendenhall](https://discuss.elastic.co/u/Jonathan_Mendenhall)\ **Post date:** [January 17, 2020, 9:59pm UTC](https://discuss.elastic.co/t/es-7-5-translog-recovery-is-extremely-slow/215505/3 "2020-01-17T21:59:02Z")
The recovery info filtered to active only seemed small enough, so I included it here. I removed node and index names, but the only thing interesting there is that the target node for both of these recoveries was the same. ``` { "index2" : { "shards" : [ { "id" : 23, "type" : "PEER", "stage" : "TRANSLOG", "primary" : false, "start_time_in_millis" : 1579283162449, "total_time_in_millis" : 1790028, "source" : { "id" : "", "host" : "", "transport_address" : "", "ip" : "", "name" : "" }, "target" : { "id" : "", "host" : "", "transport_address" : "", "ip" : "", "name" : "" }, "index" : { "size" : { "total_in_bytes" : 0, "reused_in_bytes" : 0, "recovered_in_bytes" : 0, "percent" : "0.0%" }, "files" : { "total" : 0, "reused" : 0, "recovered" : 0, "percent" : "0.0%" }, "total_time_in_millis" : 35, "source_throttle_time_in_millis" : 0, "target_throttle_time_in_millis" : 0 }, "translog" : { "recovered" : 2536, "total" : 47362814, "percent" : "0.0%", "total_on_start" : -1, "total_time_in_millis" : 1789982 }, "verify_index" : { "check_index_time_in_millis" : 0, "total_time_in_millis" : 0 } } ] }, "index1" : { "shards" : [ { "id" : 3, "type" : "PEER", "stage" : "TRANSLOG", "primary" : false, "start_time_in_millis" : 1579283161715, "total_time_in_millis" : 1790771, "source" : { "id" : "-UBHqkQ", "host" : "", "transport_address" : "", "ip" : "", "name" : "" }, "target" : { "id" : "", "host" : "", "transport_address" : "", "ip" : "", "name" : "" }, "index" : { "size" : { "total_in_bytes" : 0, "reused_in_bytes" : 0, "recovered_in_bytes" : 0, "percent" : "0.0%" }, "files" : { "total" : 0, "reused" : 0, "recovered" : 0, "percent" : "0.0%" }, "total_time_in_millis" : 31, "source_throttle_time_in_millis" : 0, "target_throttle_time_in_millis" : 0 }, "translog" : { "recovered" : 17201, "total" : 4686825, "percent" : "0.4%", "total_on_start" : -1, "total_time_in_millis" : 1790702 }, "verify_index" : { "check_index_time_in_millis" : 0, "total_time_in_millis" : 0 } } ] } } ``` And the index settings: ``` { "index1" : { "settings" : { "index" : { "routing" : { "allocation" : { "total_shards_per_node" : "1" } }, "refresh_interval" : "1m", "number_of_shards" : "30", "translog" : { "durability" : "async" }, "provided_name" : "index1", "creation_date" : "1579280534054", "unassigned" : { "node_left" : { "delayed_timeout" : "10m" } }, "number_of_replicas" : "2", "uuid" : "EsBjp6Y8Q8ebQW0ms4ZQYA", "version" : { "created" : "7050099" } } } } } ``` These indices are no longer recovering (one completed about an hour in, the other I cancled by reducing replicas to 0), so I can't get you the full shard stats. Although, I can tell you that when I looked at it during the issue, there were no big numbers in any of the translog sections. the "operations" value for every one was 0, and the sizes were all very low (they certainly did not add up to 4 mb). Once it happens again, however, I could include that in a gist, if it would be useful. Thanks ---
**Author:** ![DavidTurner](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/davidturner/32/22453_2.png) [@DavidTurner](https://discuss.elastic.co/u/DavidTurner)\ **Post date:** [January 18, 2020, 6:37am UTC](https://discuss.elastic.co/t/es-7-5-translog-recovery-is-extremely-slow/215505/4 "2020-01-18T06:37:10Z")
> [@Jonathan\_Mendenhall](#): > > These indices are no longer recovering Ah, yes I think we want this info on a shard that's currently recovering slowly. By all means redact the host names and IP addresses but please leave the random node IDs intact. ---
**Author:** ![DavidTurner](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/davidturner/32/22453_2.png) [@DavidTurner](https://discuss.elastic.co/u/DavidTurner)\ **Post date:** [January 18, 2020, 7:18am UTC](https://discuss.elastic.co/t/es-7-5-translog-recovery-is-extremely-slow/215505/5 "2020-01-18T07:18:09Z")
Would you also be able to set `logger.org.elasticsearch.indices.recovery` to `TRACE` via the [cluster settings API](https://www.elastic.co/guide/en/elasticsearch/reference/current/cluster-update-settings.html)? This might result in quite a lot of output so be ready to set it back to `null` if it seems to be stressing your cluster. ---
**Author:** ![nhat](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/nhat/32/22170_2.png) [@nhat](https://discuss.elastic.co/u/nhat)\ **Post date:** [January 18, 2020, 6:49pm UTC](https://discuss.elastic.co/t/es-7-5-translog-recovery-is-extremely-slow/215505/6 "2020-01-18T18:49:05Z")
> "total" : 4686825 Also, how long was the replica offline (while the indexing continued)? ---
**Author:** ![Jonathan\_Mendenhall](https://avatars.discourse-cdn.com/v4/letter/j/ebca7d/32.png) [@Jonathan\_Mendenhall](https://discuss.elastic.co/u/Jonathan_Mendenhall)\ **Post date:** [January 21, 2020, 9:10pm UTC](https://discuss.elastic.co/t/es-7-5-translog-recovery-is-extremely-slow/215505/7 "2020-01-21T21:10:56Z")
> Also, how long was the replica offline (while the indexing continued)? I'm not sure I understand the question. This recovery operation was to bring the index back to a green state, so this replica was offline for the duration of the recovery. At the time I collected that data, that was about 30 minutes. I've recently seen them approach an hour. After that, I am unsure if they tend to speed up at some point, or if I have just not noticed them. ---
**Author:** ![Jonathan\_Mendenhall](https://avatars.discourse-cdn.com/v4/letter/j/ebca7d/32.png) [@Jonathan\_Mendenhall](https://discuss.elastic.co/u/Jonathan_Mendenhall)\ **Post date:** [January 21, 2020, 9:14pm UTC](https://discuss.elastic.co/t/es-7-5-translog-recovery-is-extremely-slow/215505/8 "2020-01-21T21:14:08Z")
> [@DavidTurner](#): > > Would you also be able to set `logger.org.elasticsearch.indices.recovery` to `TRACE` via the [cluster settings API](https://www.elastic.co/guide/en/elasticsearch/reference/current/cluster-update-settings.html)? This might result in quite a lot of output so be ready to set it back to `null` if it seems to be stressing your cluster. The last time we set nodes to TRACE, the output to disk actually managed to overwhelm our hardware, which caused problems for the node, and prompted it to output even more to disk. I could look at doing this again, but maybe as a last resort? ---
**Author:** ![DavidTurner](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/davidturner/32/22453_2.png) [@DavidTurner](https://discuss.elastic.co/u/DavidTurner)\ **Post date:** [January 21, 2020, 9:47pm UTC](https://discuss.elastic.co/t/es-7-5-translog-recovery-is-extremely-slow/215505/9 "2020-01-21T21:47:10Z")
> [@Jonathan\_Mendenhall](#): > > The last time we set nodes to TRACE, the output to disk actually managed to overwhelm our hardware Noted. Do you mean the last time you tried tracing recoveries only (as I suggested here) or were you tracing with a broader scope? If you try and trace the transport layers, for instance, then you're going to have a bad time. In any case it's ok not to add logging for now and hope that the stats have some clues. ---
**Author:** ![Jonathan\_Mendenhall](https://avatars.discourse-cdn.com/v4/letter/j/ebca7d/32.png) [@Jonathan\_Mendenhall](https://discuss.elastic.co/u/Jonathan_Mendenhall)\ **Post date:** [January 21, 2020, 10:56pm UTC](https://discuss.elastic.co/t/es-7-5-translog-recovery-is-extremely-slow/215505/10 "2020-01-21T22:56:11Z")
> [@DavidTurner](#): > > Noted. Do you mean the last time you tried tracing recoveries only (as I suggested here) or were you tracing with a broader scope? If you try and trace the transport layers, for instance, then you're going to have a bad time. In any case it's ok not to add logging for now and hope that the stats have some clues. Ah, that's fair. Last time we enabled TRACE globally. Scoping it down to a specific scope would probably be fine. Here's a gist with the info you requested: > ---
**Author:** ![DavidTurner](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/davidturner/32/22453_2.png) [@DavidTurner](https://discuss.elastic.co/u/DavidTurner)\ **Post date:** [January 21, 2020, 11:38pm UTC](https://discuss.elastic.co/t/es-7-5-translog-recovery-is-extremely-slow/215505/11 "2020-01-21T23:38:41Z")
Thanks, that's helpful. Here are some edited highlights: ```nohighlight "commit": { "user_data": { "local_checkpoint": "212661", "min_retained_seq_no": "178451", "max_seq_no": "212732" }, "num_docs": 47198999 }, "seq_no": { "max_seq_no": 215715, "local_checkpoint": 215711, "global_checkpoint": 215579 }, "retention_leases": { "primary_term": 1, "version": 287, "leases": [ { "id": "peer_recovery/up6P4q_ARIO1W7Wewt5s7g", "retaining_seq_no": 178451, "timestamp": 1579646940678, "source": "peer recovery" }, ... ] }, ``` In particular `"max_seq_no": 215715` means that this shard only contains 215715 operations. The target of the recovery in question is `up6P4q_ARIO1W7Wewt5s7g` and the lease for that node has `"retaining_seq_no": 178451` indicating that the target is missing 37264 of them. But there is some disagreement: `"num_docs": 47198999`. I think this means you have a lot of nested documents? Looking at the recovery stats: ```nohighlight "translog" : { "recovered" : 16507, "total" : 2870006, "percent" : "0.6%", "total_on_start" : -1, "total_time_in_millis" : 519729 }, ``` The `total` is supposed to be the total number of operations to recover, which should be in the region of `37264`, but is instead much larger than the total number of operations in this shard. I suspect we might be calculating the `total` wrong in the presence of nested documents, maybe counting documents instead of operations, and in fact this recovery need only complete ~37000 operations so it's around 44% complete. If you let it run for another 10-15 minutes does it finish? @nhat does that sound like a plausible explanation to you? Since this replica is missing ~17% of the operations in this shard Elasticsearch would normally consider it more efficient simply to copy the files over again, but unfortunately for tricky technical reasons if you're using nested documents then that calculation is skewed in favour of replaying the translog. ---
**Author:** ![Jonathan\_Mendenhall](https://avatars.discourse-cdn.com/v4/letter/j/ebca7d/32.png) [@Jonathan\_Mendenhall](https://discuss.elastic.co/u/Jonathan_Mendenhall)\ **Post date:** [January 21, 2020, 11:49pm UTC](https://discuss.elastic.co/t/es-7-5-translog-recovery-is-extremely-slow/215505/12 "2020-01-21T23:49:23Z")
> [@DavidTurner](#): > > I think this means you have a lot of nested documents? You are absolutely correct that we are using a lot of Nested documents in this index. > [@DavidTurner](#): > > If you let it run for another 10-15 minutes does it finish? I generally see them finish somewhere between 30 and 60 minutes. > [@DavidTurner](#): > > Since this replica is missing ~17% of the operations in this shard Elasticsearch would normally consider it more efficient simply to copy the files over again, but unfortunately for tricky technical reasons if you're using nested documents then that calculation is skewed in favour of replaying the translog. Ah. That's interesting. It explains why that calculation always seemed so far off. Is there any way for me to configure the cluster to force it to always favor copying files over (or better yet, just change the math in that calculation)? So far as I can tell, a non-translog recovery is always much faster than a translog one for us. I had a thought of reducing the retention on those logs, but I'm not sure if that would do what I wanted, and I do not know if I would risk data loss by reducing it too far. ---
**Author:** ![DavidTurner](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/davidturner/32/22453_2.png) [@DavidTurner](https://discuss.elastic.co/u/DavidTurner)\ **Post date:** [January 22, 2020, 12:20am UTC](https://discuss.elastic.co/t/es-7-5-translog-recovery-is-extremely-slow/215505/13 "2020-01-22T00:20:48Z")
> [@Jonathan\_Mendenhall](#): > > Is there any way for me to configure the cluster to force it to always favor copying files over (or better yet, just change the math in that calculation)? ... I had a thought of reducing the retention on those logs, but I'm not sure if that would do what I wanted, and I do not know if I would risk data loss by reducing it too far. There's no config available to influence the ops-vs-files decision directly, but you can indeed achieve a similar effect by reducing `index.soft_deletes.retention_lease.period` on these heavily-nested indices, especially if you're not using cross-cluster replication. This setting won't cause data loss however it's set. The lower you set it, the shorter the time a node can disconnect and reconnect and catch up without copying everything over. You probably want ops-based recoveries if a node is only offline for a few seconds or minutes, but the default of `12h` may be too long for your case. **Addendum (edit)**: I recommend setting `index.soft_deletes.retention_lease.period` back to the default when you stop writing to each index, assuming these indices are time-based. Once the index is read-only you should heavily prefer ops-based recoveries since replaying zero missing operations will certainly be faster than copying the data again. ---
**Author:** ![nhat](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/nhat/32/22170_2.png) [@nhat](https://discuss.elastic.co/u/nhat)\ **Post date:** [January 22, 2020, 1:53am UTC](https://discuss.elastic.co/t/es-7-5-translog-recovery-is-extremely-slow/215505/14 "2020-01-22T01:53:46Z")
@DavidTurner Great find. Your analysis makes a lot of sense to me. Yes, we can make LuceneChangesSnapshot report an accurate number of operations and faster with nested documents. ---
**Author:** ![nhat](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/nhat/32/22170_2.png) [@nhat](https://discuss.elastic.co/u/nhat)\ **Post date:** [January 22, 2020, 2:45am UTC](https://discuss.elastic.co/t/es-7-5-translog-recovery-is-extremely-slow/215505/15 "2020-01-22T02:45:24Z")
I opened [https://github.com/elastic/elasticsearch/pull/51279](https://github.com/elastic/elasticsearch/pull/51279). ---
**Author:** ![system](https://us1.discourse-cdn.com/elastic/original/3X/1/a/1ac57faf039f6b580b3f104ef42a2a89e41014de.png) [@system](https://discuss.elastic.co/u/system)\ **Post date:** [February 19, 2020, 2:45am UTC](https://discuss.elastic.co/t/es-7-5-translog-recovery-is-extremely-slow/215505/16 "2020-02-19T02:45:24Z")
This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.