# Indexing slowlog investigation

**URL:** <https://discuss.elastic.co/t/indexing-slowlog-investigation/297752>\
**Category:** Elasticsearch\
**Created:** [February 21, 2022, 12:35pm UTC](https://discuss.elastic.co/t/indexing-slowlog-investigation/297752 "2022-02-21T12:35:12Z")\
**Posts on this page:** 9\
**Page:** 1

<div class="post-metadata">

**Author:** ![Itay\_Bittan](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/itay_bittan/32/23527_2.png) [@Itay\_Bittan](https://discuss.elastic.co/u/Itay_Bittan)\
**Post date:** [February 21, 2022, 12:35pm UTC](https://discuss.elastic.co/t/indexing-slowlog-investigation/297752/1 "2022-02-21T12:35:12Z")

</div>

Hi!

We have a very old Elasticsearch cluster v1.6.0 (we will hopefully upgrade soon) with 20 nodes: 3 master nodes and 17 data nodes.

As a B2B service, each index represents a different business (customer).  
This cluster is being heavily indexed and barley read.  
Every day Spark is writing to this cluster and replace almost all indices with a fresh new ones.  
As soon as a new index is ready we switch the customer alias to point on a fresh new index and delete the old one.

We are using `org.elasticsearch.spark.rdd.api.java.JavaEsSpark` to saveToEs.  
I saw that the load on the data nodes is reaching 100% during indexing.  
I suspect that we are using bulks with high number of documents (which are relatively small) or not using bulks at all - so I enabled the index slowlog (this is a legacy code which I'm trying to understand now).

I saw a lot of slow log such as:

```auto
[2022-02-21 09:42:56,942][INFO][index.indexing.slowlog.index] [elasticsearch-data-node-1.use.<my-domain>.com] [9877738_all_27652427755079532m][0] took[5.4s], took_millis[5402], type[user], id[AX8bqYwqNMC-u1yj5V_o], routing[], source[{ <document_content_here> }]

```

**Questions**

- From the log above, is there a chance that we are not using bulk at all? We have another Elasticsearch cluster (v6.3.0) that shows slowlog like:

```auto
[2022-01-31T22:06:44,253][WARN][index.search.slowlog.fetch] [data-worker-fae1695] [s_9877418_1643664046760][0] took[597.4ms], took_millis[597], total_hits[318742], types[], stats[], search_type[QUERY_THEN_FETCH], total_shards[2], source[{"size":400,"query":{ <query_comes_here> },"_source":{ <something_comes_here> },"sort":[{"_doc":{"order":"asc"}}]}],

```

In the log above I can clearly see the bulk size 400, but I'm not sure if I should see it in a "simple" indexing (the log is QUERY\_THEN\_FETCH). In other words, should I always see the size of the bulk in an indexing query? Is the first log implies that we are not indexing in bulks?

- What is the recommended/optimal indexing duration? what are the tradeoffs / implications of slow indexing time? (assuming can deal with long search time and we don't have much serving queries).

- What is the optimal number of shards in our case? most of our indices use only 1 shard (and one replica after finish indexing), but few indices contain 40(!) shards. I assume that's slowing us down as well as write to single index involve the entire cluster. Is that make sense?

Thanks,  
Itay

---

<div class="post-metadata">

**Author:** ![warkolm](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/warkolm/32/39224_2.png) [@warkolm](https://discuss.elastic.co/u/warkolm)\
**Post date:** [February 21, 2022, 11:22pm UTC](https://discuss.elastic.co/t/indexing-slowlog-investigation/297752/2 "2022-02-21T23:22:31Z")

</div>

> [@Itay\_Bittan](#):
>
> From the log above, is there a chance that we are not using bulk at all?

I am not sure that the slowlogs contain this level of information. And you're on a version that was released 7 years ago, so you may not get an adequate answer there.

> [@Itay\_Bittan](#):
>
> In the log above I can clearly see the bulk size 400

No, that's the size of the request that is being made, it's not necessarily any indicator of using `_bulk`.

> [@Itay\_Bittan](#):
>
> What is the recommended/optimal indexing duration? what are the tradeoffs / implications of slow indexing time? (assuming can deal with long search time and we don't have much serving queries).

What's your SLA? If you don't have one, then optimal is whatever you are comfy with. Slow indexing would result in delayed search results, potentially confusing users.

> [@Itay\_Bittan](#):
>
> What is the optimal number of shards in our case? most of our indices use only 1 shard (and one replica after finish indexing), but few indices contain 40(!) shards. I assume that's slowing us down as well as write to single index involve the entire cluster. Is that make sense?

Depends.  
The output from the `_cluster/stats?pretty&human` API might help us understand more about your cluster.

---

<div class="post-metadata">

**Author:** ![Itay\_Bittan](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/itay_bittan/32/23527_2.png) [@Itay\_Bittan](https://discuss.elastic.co/u/Itay_Bittan)\
**Post date:** [February 22, 2022, 8:20am UTC](https://discuss.elastic.co/t/indexing-slowlog-investigation/297752/3 "2022-02-22T08:20:10Z")

</div>

thanks for your answer @warkolm !

Since we are switching alias as soon as a new index is ready (and then the index becomes "read-only"), there's no impact on the search performance.  
We do have SLA regarding our indexing time. We are trying to find the bottleneck that leads to slowness. I thought that in general, indexing should take milliseconds and not seconds and I am not sure what's the other implications or how can I make it index faster..

---

<div class="post-metadata">

**Author:** ![warkolm](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/warkolm/32/39224_2.png) [@warkolm](https://discuss.elastic.co/u/warkolm)\
**Post date:** [February 22, 2022, 8:31am UTC](https://discuss.elastic.co/t/indexing-slowlog-investigation/297752/4 "2022-02-22T08:31:31Z")

</div>

What is the output from the `_cluster/stats?pretty&human` API?  
What sort of hardware do you have for your nodes?

---

<div class="post-metadata">

**Author:** ![Itay\_Bittan](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/itay_bittan/32/23527_2.png) [@Itay\_Bittan](https://discuss.elastic.co/u/Itay_Bittan)\
**Post date:** [February 22, 2022, 8:57am UTC](https://discuss.elastic.co/t/indexing-slowlog-investigation/297752/5 "2022-02-22T08:57:50Z")

</div>

> [@warkolm](#):
>
> \_cluster/stats?pretty&human

We are using `r5.2xlarge` (8 CPU / 64GB).

Output:

```auto
{
  "timestamp" : 1645520189829,
  "cluster_name" : "dyaud-prod",
  "status" : "yellow",
  "indices" : {
    "count" : 1105,
    "shards" : {
      "total" : 7384,
      "primaries" : 3751,
      "replication" : 0.9685417222074113,
      "index" : {
        "shards" : {
          "min" : 1,
          "max" : 80,
          "avg" : 6.682352941176471
        },
        "primaries" : {
          "min" : 1,
          "max" : 40,
          "avg" : 3.3945701357466063
        },
        "replication" : {
          "min" : 0.0,
          "max" : 4.0,
          "avg" : 0.9938687782805429
        }
      }
    },
    "docs" : {
      "count" : 4878571271,
      "deleted" : 0
    },
    "store" : {
      "size_in_bytes" : 6553954064398,
      "throttle_time_in_millis" : 0
    },
    "fielddata" : {
      "memory_size_in_bytes" : 45759286584,
      "evictions" : 5468
    },
    "filter_cache" : {
      "memory_size_in_bytes" : 9739700584,
      "evictions" : 0
    },
    "id_cache" : {
      "memory_size_in_bytes" : 0
    },
    "completion" : {
      "size_in_bytes" : 0
    },
    "segments" : {
      "count" : 72125,
      "memory_in_bytes" : 103869359166,
      "index_writer_memory_in_bytes" : 0,
      "index_writer_max_memory_in_bytes" : 88588328960,
      "version_map_memory_in_bytes" : 0,
      "fixed_bit_set_memory_in_bytes" : 1060925136
    },
    "percolate" : {
      "total" : 0,
      "time_in_millis" : 0,
      "current" : 0,
      "memory_size_in_bytes" : -1,
      "memory_size" : "-1b",
      "queries" : 0
    }
  },
  "nodes" : {
    "count" : {
      "total" : 19,
      "master_only" : 3,
      "data_only" : 16,
      "master_data" : 0,
      "client" : 0
    },
    "versions" : ["1.6.0"],
    "os" : {
      "available_processors" : 134,
      "mem" : {
        "total_in_bytes" : 1116002926592
      },
      "cpu" : [ {
        "vendor" : "Intel",
        "model" : "Xeon",
        "mhz" : 2499,
        "total_cores" : 8,
        "total_sockets" : 1,
        "cores_per_socket" : 8,
        "cache_size_in_bytes" : 36608,
        "count" : 19
      } ]
    },
    "process" : {
      "cpu" : {
        "percent" : 2733
      },
      "open_file_descriptors" : {
        "min" : 640,
        "max" : 7124,
        "avg" : 5900
      }
    },
    "jvm" : {
      "max_uptime_in_millis" : 19966791826,
      "versions" : [ {
        "version" : "1.7.0_261",
        "vm_name" : "OpenJDK 64-Bit Server VM",
        "vm_version" : "24.261-b02",
        "vm_vendor" : "Oracle Corporation",
        "count" : 19
      } ],
      "mem" : {
        "heap_used_in_bytes" : 353586943864,
        "heap_max_in_bytes" : 580800086016
      },
      "threads" : 2096
    },
    "fs" : {
      "total_in_bytes" : 12997193801728,
      "free_in_bytes" : 6340045512704,
      "available_in_bytes" : 5679375523840,
      "disk_reads" : 8011593976,
      "disk_writes" : 7197477729,
      "disk_io_op" : 15209071705,
      "disk_read_size_in_bytes" : 184870066215936,
      "disk_write_size_in_bytes" : 1724655196782592,
      "disk_io_size_in_bytes" : 1909525262998528
    },
    "plugins" : [ {
      "name" : "bigdesk",
      "version" : "NA",
      "description" : "No description found.",
      "url" : "/_plugin/bigdesk/",
      "jvm" : false,
      "site" : true
    }, {
      "name" : "cloud-aws",
      "version" : "2.6.0",
      "description" : "Cloud AWS Plugin",
      "jvm" : true,
      "site" : false
    }, {
      "name" : "head",
      "version" : "NA",
      "description" : "No description found.",
      "url" : "/_plugin/head/",
      "jvm" : false,
      "site" : true
    } ]
  }
}

```

---

<div class="post-metadata">

**Author:** ![warkolm](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/warkolm/32/39224_2.png) [@warkolm](https://discuss.elastic.co/u/warkolm)\
**Post date:** [February 22, 2022, 9:02am UTC](https://discuss.elastic.co/t/indexing-slowlog-investigation/297752/6 "2022-02-22T09:02:25Z")

</div>

> [@Itay\_Bittan](#):
>
> We are using `r5.2xlarge` (8 CPU / 64GB).

What storage?

---

<div class="post-metadata">

**Author:** ![warkolm](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/warkolm/32/39224_2.png) [@warkolm](https://discuss.elastic.co/u/warkolm)\
**Post date:** [February 22, 2022, 9:05am UTC](https://discuss.elastic.co/t/indexing-slowlog-investigation/297752/7 "2022-02-22T09:05:16Z")

</div>

> [@Itay\_Bittan](#):
>
> ```auto
> "data_only" : 16,
> 
> ```

> [@Itay\_Bittan](#):
>
> ```auto
> "total" : 7384,
> 
> ```

That's 461 or so shards per node. Prior to 6.X, Elasticsearch resources around shard management were not handled in an optimal state. So you're likely seeing overhead running such an old version, **and** with that many shards per node.

---

<div class="post-metadata">

**Author:** ![Itay\_Bittan](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/itay_bittan/32/23527_2.png) [@Itay\_Bittan](https://discuss.elastic.co/u/Itay_Bittan)\
**Post date:** [February 22, 2022, 9:31am UTC](https://discuss.elastic.co/t/indexing-slowlog-investigation/297752/8 "2022-02-22T09:31:18Z")

</div>

Thanks again!  
For some reason, some of the indices have 40 shards (while most of them have 1-2 shards only).  
I'll try to figure out why and fix that - hope to see some improvement.  
I'll update

---

<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:** [March 22, 2022, 9:31am UTC](https://discuss.elastic.co/t/indexing-slowlog-investigation/297752/9 "2022-03-22T09:31:50Z")

</div>

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.