Indexing slowlog investigation

Elastic Stack Elasticsearch
1

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:

[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:
[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

2

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.

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

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.

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

3

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..

4

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

5

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

Output:

{
  "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
    } ]
  }
}
6

What storage?

7

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.

1 Like
8

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

9

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