# Rally Track Report Analysis

**URL:** <https://discuss.elastic.co/t/rally-track-report-analysis/117589>\
**Category:** Elasticsearch\
**Tags:** rally\
**Created:** [January 30, 2018, 9:32am UTC](https://discuss.elastic.co/t/rally-track-report-analysis/117589 "2018-01-30T09:32:25Z")\
**Posts on this page:** 8\
**Page:** 1

<div class="post-metadata">

**Author:** ![ize0j10](https://avatars.discourse-cdn.com/v4/letter/i/7ea924/32.png) [@ize0j10](https://discuss.elastic.co/u/ize0j10)\
**Post date:** [January 30, 2018, 9:32am UTC](https://discuss.elastic.co/t/rally-track-report-analysis/117589/1 "2018-01-30T09:32:26Z")

</div>

Hello,

we want to get a measurement on resources that still might be available in our elasticsearch cluster.

To get an idea we run Rally 0.9.:  
`esrally --track="http_logs" --target-hosts="node1, node2" --pipeline=benchmark-only --client-options="use_ssl:true,verify_certs:false,basic_auth_user:'superuser',basic_auth_password:'...'"`

We now have difficulties to interpret the report:

| Lap | Metric | Task | Value | Unit |
| --- | --- | --- | --- | --- |
| All | Indexing time | | 0 | min |
| All | Indexing throttle time | | 0 | min |
| All | Merge time | | 0 | min |
| All | Refresh time | | 0 | min |
| All | Flush time | | 0 | min |
| All | Merge throttle time | | 0 | min |
| All | Total Young Gen GC | | 0 | s |
| All | Total Old Gen GC | | 0 | s |
| All | Min Throughput | index-append | 74604.3 | docs/s |
| All | Median Throughput | index-append | **76929.9** | docs/s |
| All | Max Throughput | index-append | 77214.6 | docs/s |
| All | 50th percentile latency | index-append | **445.248** | ms |
| All | 90th percentile latency | index-append | 693.113 | ms |
| All | 99th percentile latency | index-append | 1090.24 | ms |
| All | 99.9th percentile latency | index-append | 1497.43 | ms |
| All | 99.99th percentile latency | index-append | 1918.44 | ms |
| All | 100th percentile latency | index-append | 2313.48 | ms |
| All | 50th percentile service time | index-append | 445.248 | ms |
| All | 90th percentile service time | index-append | 693.113 | ms |
| All | 99th percentile service time | index-append | 1090.24 | ms |
| All | 99.9th percentile service time | index-append | 1497.43 | ms |
| All | 99.99th percentile service time | index-append | 1918.44 | ms |
| All | 100th percentile service time | index-append | 2313.48 | ms |
| All | error rate | index-append | 0 | % |
| All | I CUT term, hourly\_agg, index-stats and node stats to match body limitation. | | | |
| All | Min Throughput | default | 3.33 | ops/s |
| All | Median Throughput | default | 3.36 | ops/s |
| All | Max Throughput | default | 3.38 | ops/s |
| All | 50th percentile latency | default | 69916.2 | ms |
| All | 50th percentile latency | default | 69916.2 | ms |
| All | 90th percentile latency | default | 108802 | ms |
| All | 99th percentile latency | default | 117133 | ms |
| All | 100th percentile latency | default | 118069 | ms |
| All | 50th percentile service time | default | 285.997 | ms |
| All | 90th percentile service time | default | 344.239 | ms |
| All | 99th percentile service time | default | 452.941 | ms |
| All | 100th percentile service time | default | 547.525 | ms |
| All | error rate | default | 0 | % |
| All | Min Throughput | range | 1.76 | ops/s |
| All | Median Throughput | range | 1.78 | ops/s |
| All | Max Throughput | range | 1.79 | ops/s |
| All | 50th percentile latency | range | 12738.3 | ms |
| All | 90th percentile latency | range | 19092.1 | ms |
| All | 99th percentile latency | range | 20829.9 | ms |
| All | 100th percentile latency | range | 21039.9 | ms |
| All | 50th percentile service time | range | 559.023 | ms |
| All | 90th percentile service time | range | 665.189 | ms |
| All | 99th percentile service time | range | 852.438 | ms |
| All | 100th percentile service time | range | 1131.42 | ms |
| All | error rate | range | 0 | % |
| All | Min Throughput | scroll | 19.45 | ops/s |
| All | Median Throughput | scroll | 20.25 | ops/s |
| All | Max Throughput | scroll | 20.84 | ops/s |
| All | 50th percentile latency | scroll | 228750 | ms |
| All | 90th percentile latency | scroll | 313780 | ms |
| All | 99th percentile latency | scroll | 332907 | ms |
| All | 100th percentile latency | scroll | 335018 | ms |
| All | 50th percentile service time | scroll | 1151.23 | ms |
| All | 90th percentile service time | scroll | 1516.23 | ms |
| All | 99th percentile service time | scroll | 2033.21 | ms |
| All | 100th percentile service time | scroll | 2359.8 | ms |
| All | error rate | scroll | 0 | % |

The questions are:

- Why are there no values at the top of the table for 'Indexing time', 'Indexing throttle time'... How can it be fixed?
- I can guess it but am I right to say that:  
`| All | Median Throughput | index-append | **76929.9** | docs/s |` means that the cluster is able to index 76929.9 documents per second? We need such information to limit new clients that send documents to index.
- Is there any good measurement to get an idea on search performance (how many users can run simple searches like '\*') while the elasticsearch nodes are continuously indexing documents?
- What would be the main conclusion reading this report regarding search and index performance?

Could you please help to interpret the report or point to further documentation?

Thank you very much!

Regards,  
ize0j10

---

<div class="post-metadata">

**Author:** ![danielmitterdorfer](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/danielmitterdorfer/32/110510_2.png) [@danielmitterdorfer](https://discuss.elastic.co/u/danielmitterdorfer)\
**Post date:** [January 30, 2018, 10:35am UTC](https://discuss.elastic.co/t/rally-track-report-analysis/117589/2 "2018-01-30T10:35:55Z")

</div>

> [@ize0j10](#):
>
> Why are there no values at the top of the table for 'Indexing time', 'Indexing throttle time'... How can it be fixed?

There might have been a problem retrieving these values which you should see in the logs. You can check if you can retrieve the value by yourself via the indices stats API (that's what Rally uses internally). Can you please also share which version of Elasticsearch you are using?

> [@ize0j10](#):
>
> I can guess it but am I right to say that:
> 
> | All | Median Throughput | index-append | **76929.9** | docs/s | means that the cluster is able to index 76929.9 documents per second?

Yes, this is correct. The cluster can index that many documents per second with the given document corpus (i.e. http\_logs), the given bulk size, number of clients, cluster configuration and index settings.

> [@ize0j10](#):
>
> Is there any good measurement to get an idea on search performance (how many users can run simple searches like '\*') while the elasticsearch nodes are continuously indexing documents?

You can do that but you need to [create your own track](http://esrally.readthedocs.io/en/stable/adding_tracks.html) to achieve that as we don't this in our standard tracks. You should especially look at the docs that explain [how to use the "parallel" element in Rally](http://esrally.readthedocs.io/en/stable/track.html#running-tasks-in-parallel). You might also be interested in the [eventdata track](https://github.com/elastic/rally-eventdata-track) which does that and also want to watch the Webinar [Getting your cluster size right](https://www.elastic.co/de/webinars/using-rally-to-get-your-elasticsearch-cluster-size-right) (free to watch but requires registration). Especially if you want to simulate multiple users executing operations it is crucial to think about [choosing the correct schedule](http://esrally.readthedocs.io/en/stable/track.html#choosing-a-schedule) to model client arrivals in order to get meaningful results.

> [@ize0j10](#):
>
> What would be the main conclusion reading this report regarding search and index performance?

You need to watch out for two things:

1. An error rate of zero otherwise you might look at non-representative results (e.g. it might include bulk rejections and the like). In your case that's fine.
2. Check whether the system can achieve the target throughput which means that it can keep up with the injected load. This is not the case for a few queries (like `term`) where you can see that the throughput is less than what's specified in the track. Also, service time and latency are quite far apart indicating that clients need to wait for a very long time. See also the article [Relating Service Utilisation to Latency](https://robharrop.github.io/maths/performance/2016/02/20/service-latency-and-utilisation.html) and the [Rally FAQ](http://esrally.readthedocs.io/en/stable/faq.html#what-does-latency-and-service-time-mean-and-how-do-they-related-to-the-took-field-that-elasticsearch-returns).

In general I'd suggest that you use the tracks that come out of the box only to get started and write your own track so you can measure a scenario that is close to your production workload to get a better idea of how the system behaves for your use-case and configuration.

---

<div class="post-metadata">

**Author:** ![ize0j10](https://avatars.discourse-cdn.com/v4/letter/i/7ea924/32.png) [@ize0j10](https://discuss.elastic.co/u/ize0j10)\
**Post date:** [January 31, 2018, 11:42am UTC](https://discuss.elastic.co/t/rally-track-report-analysis/117589/3 "2018-01-31T11:42:45Z")

</div>

> [@danielmitterdorfer](#):
>
> Why are there no values at the top of the table for 'Indexing time', 'Indexing throttle time'... How can it be fixed?

Using the API directly provided such values on the existing indices. Could it be that the API call took place before there had been such operations (for this reason zero values)?

> [@danielmitterdorfer](#):
>
> Can you please also share which version of Elasticsearch you are using?

For this benchmark we used Elasticsearch 6.1.2.

---

<div class="post-metadata">

**Author:** ![danielmitterdorfer](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/danielmitterdorfer/32/110510_2.png) [@danielmitterdorfer](https://discuss.elastic.co/u/danielmitterdorfer)\
**Post date:** [February 6, 2018, 8:05am UTC](https://discuss.elastic.co/t/rally-track-report-analysis/117589/4 "2018-02-06T08:05:54Z")

</div>

Hi,

> [@ize0j10](#):
>
> Could it be that the API call took place before there had been such operations (for this reason zero values)?

Rally queries all values at the start of a benchmark (which is, after the cluster has started), queries them again after the benchmark has ended and calculates the difference. In case a value cannot be retrieved, Rally will set the value to zero and issue a warning like:

```auto
Could not determine value at path [merges,total_time_in_millis]. Returning default value [0]

```

I just started a 6.1.2 node locally and ran `esrally --pipeline=benchmark-only --challenge=append-no-conflicts-index-only` which has produced:

```auto
| Lap | Metric | Task | Value | Unit |
|------:|-------------------------------:|-------------:|----------:|-------:|
| All | Indexing time | | 41.9884 | min |
| All | Indexing throttle time | | 0.2213 | min |
| All | Merge time | | 20.5545 | min |
| All | Refresh time | | 6.41378 | min |
| All | Flush time | | 0.6925 | min |
| All | Merge throttle time | | 2.38558 | min |

```

So it does not seem to be a systematic problem.

For reference, Rally issues basically the following (requires [jq](https://stedolan.github.io/jq/)):

```auto
curl -s -XGET 'localhost:9200/_stats/_all?pretty&level=shards' | jq "._all.primaries"

```

If you could run this before you start Rally and after the benchmark has finished this might help me resolve the issue.

---

<div class="post-metadata">

**Author:** ![ize0j10](https://avatars.discourse-cdn.com/v4/letter/i/7ea924/32.png) [@ize0j10](https://discuss.elastic.co/u/ize0j10)\
**Post date:** [February 12, 2018, 11:12am UTC](https://discuss.elastic.co/t/rally-track-report-analysis/117589/5 "2018-02-12T11:12:03Z")

</div>

Hi Daniel,

> If you could run this before you start Rally and after the benchmark has finished this might help me resolve the issue.

Before:

{  
"docs": {  
"count": 1437022,  
"deleted": 1702  
},  
"store": {  
"size\_in\_bytes": 656372799  
},  
"indexing": {  
"index\_total": 2632778,  
"index\_time\_in\_millis": 1150048,  
"index\_current": 0,  
"index\_failed": 7,  
"delete\_total": 26351,  
"delete\_time\_in\_millis": 1051,  
"delete\_current": 0,  
"noop\_update\_total": 8,  
"is\_throttled": false,  
"throttle\_time\_in\_millis": 0  
},  
"get": {  
"total": 105914,  
"time\_in\_millis": 14243,  
"exists\_total": 105863,  
"exists\_time\_in\_millis": 14235,  
"missing\_total": 51,  
"missing\_time\_in\_millis": 8,  
"current": 0  
},  
"search": {  
"open\_contexts": 0,  
"query\_total": 209483,  
"query\_time\_in\_millis": 29444,  
"query\_current": 0,  
"fetch\_total": 187514,  
"fetch\_time\_in\_millis": 15158,  
"fetch\_current": 0,  
"scroll\_total": 26102,  
"scroll\_time\_in\_millis": 7460,  
"scroll\_current": 0,  
"suggest\_total": 0,  
"suggest\_time\_in\_millis": 0,  
"suggest\_current": 0  
},  
"merges": {  
"current": 0,  
"current\_docs": 0,  
"current\_size\_in\_bytes": 0,  
"total": 34293,  
"total\_time\_in\_millis": 6486023,  
"total\_docs": 666452775,  
"total\_size\_in\_bytes": 183250991598,  
"total\_stopped\_time\_in\_millis": 0,  
"total\_throttled\_time\_in\_millis": 707,  
"total\_auto\_throttle\_in\_bytes": 663462632  
},  
"refresh": {  
"total": 334707,  
"total\_time\_in\_millis": 4129307,  
"listeners": 0  
},  
"flush": {  
"total": 24,  
"total\_time\_in\_millis": 480  
},  
"warmer": {  
"current": 0,  
"total": 308319,  
"total\_time\_in\_millis": 29123  
},  
"query\_cache": {  
"memory\_size\_in\_bytes": 254278,  
"total\_count": 112798,  
"hit\_count": 9320,  
"miss\_count": 103478,  
"cache\_size": 34,  
"cache\_count": 1879,  
"evictions": 1845  
},  
"fielddata": {  
"memory\_size\_in\_bytes": 2632,  
"evictions": 0  
},  
"completion": {  
"size\_in\_bytes": 0  
},  
"segments": {  
"count": 147,  
"memory\_in\_bytes": 2587970,  
"terms\_memory\_in\_bytes": 1119254,  
"stored\_fields\_memory\_in\_bytes": 194600,  
"term\_vectors\_memory\_in\_bytes": 0,  
"norms\_memory\_in\_bytes": 56512,  
"points\_memory\_in\_bytes": 240808,  
"doc\_values\_memory\_in\_bytes": 976796,  
"index\_writer\_memory\_in\_bytes": 21126311,  
"version\_map\_memory\_in\_bytes": 6151324,  
"fixed\_bit\_set\_memory\_in\_bytes": 159720,  
"max\_unsafe\_auto\_id\_timestamp": 1518163942643,  
"file\_sizes": {}  
},  
"translog": {  
"operations": 610477,  
"size\_in\_bytes": 840225274,  
"uncommitted\_operations": 421715,  
"uncommitted\_size\_in\_bytes": 544563526  
},  
"request\_cache": {  
"memory\_size\_in\_bytes": 5136,  
"evictions": 0,  
"hit\_count": 111219,  
"miss\_count": 113  
},  
"recovery": {  
"current\_as\_source": 0,  
"current\_as\_target": 0,  
"throttle\_time\_in\_millis": 0  
}  
}

After:  
{  
"docs": {  
"count": 248720257,  
"deleted": 1906  
},  
"store": {  
"size\_in\_bytes": 22079040416  
},  
"indexing": {  
"index\_total": 249970865,  
"index\_time\_in\_millis": 8934976,  
"index\_current": 0,  
"index\_failed": 7,  
"delete\_total": 26965,  
"delete\_time\_in\_millis": 1070,  
"delete\_current": 0,  
"noop\_update\_total": 8,  
"is\_throttled": false,  
"throttle\_time\_in\_millis": 0  
},  
"get": {  
"total": 108378,  
"time\_in\_millis": 14554,  
"exists\_total": 108327,  
"exists\_time\_in\_millis": 14546,  
"missing\_total": 51,  
"missing\_time\_in\_millis": 8,  
"current": 0  
},  
"search": {  
"open\_contexts": 0,  
"query\_total": 536867,  
"query\_time\_in\_millis": 4015818,  
"query\_current": 0,  
"fetch\_total": 455888,  
"fetch\_time\_in\_millis": 119689,  
"fetch\_current": 0,  
"scroll\_total": 37231,  
"scroll\_time\_in\_millis": 14369092,  
"scroll\_current": 0,  
"suggest\_total": 0,  
"suggest\_time\_in\_millis": 0,  
"suggest\_current": 0  
},  
"merges": {  
"current": 0,  
"current\_docs": 0,  
"current\_size\_in\_bytes": 0,  
"total": 39936,  
"total\_time\_in\_millis": 12879214,  
"total\_docs": 1340704824,  
"total\_size\_in\_bytes": 250882666611,  
"total\_stopped\_time\_in\_millis": 0,  
"total\_throttled\_time\_in\_millis": 4050187,  
"total\_auto\_throttle\_in\_bytes": 1270120170  
},  
"refresh": {  
"total": 357658,  
"total\_time\_in\_millis": 5126715,  
"listeners": 0  
},  
"flush": {  
"total": 131,  
"total\_time\_in\_millis": 15469  
},  
"warmer": {  
"current": 0,  
"total": 330245,  
"total\_time\_in\_millis": 29907  
},  
"query\_cache": {  
"memory\_size\_in\_bytes": 25793830,  
"total\_count": 258252,  
"hit\_count": 49516,  
"miss\_count": 208736,  
"cache\_size": 230,  
"cache\_count": 2080,  
"evictions": 1850  
},  
"fielddata": {  
"memory\_size\_in\_bytes": 8504,  
"evictions": 0  
},  
"completion": {  
"size\_in\_bytes": 0  
},  
"segments": {  
"count": 739,  
"memory\_in\_bytes": 95424188,  
"terms\_memory\_in\_bytes": 79959842,  
"stored\_fields\_memory\_in\_bytes": 8047600,  
"term\_vectors\_memory\_in\_bytes": 0,  
"norms\_memory\_in\_bytes": 99584,  
"points\_memory\_in\_bytes": 6278918,  
"doc\_values\_memory\_in\_bytes": 1038244,  
"index\_writer\_memory\_in\_bytes": 267279,  
"version\_map\_memory\_in\_bytes": 53971,  
"fixed\_bit\_set\_memory\_in\_bytes": 163368,  
"max\_unsafe\_auto\_id\_timestamp": 1518163942643,  
"file\_sizes": {}  
},  
"translog": {  
"operations": 77655904,  
"size\_in\_bytes": 16659955310,  
"uncommitted\_operations": 33608,  
"uncommitted\_size\_in\_bytes": 37007332  
},  
"request\_cache": {  
"memory\_size\_in\_bytes": 27728,  
"evictions": 0,  
"hit\_count": 113956,  
"miss\_count": 173  
},  
"recovery": {  
"current\_as\_source": 0,  
"current\_as\_target": 0,  
"throttle\_time\_in\_millis": 0  
}  
}

Thanks,  
ize0j10

---

<div class="post-metadata">

**Author:** ![danielmitterdorfer](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/danielmitterdorfer/32/110510_2.png) [@danielmitterdorfer](https://discuss.elastic.co/u/danielmitterdorfer)\
**Post date:** [February 13, 2018, 7:06am UTC](https://discuss.elastic.co/t/rally-track-report-analysis/117589/6 "2018-02-13T07:06:44Z")

</div>

Thanks for the data. Your output looks fine to me and should indeed produce numbers. I will improve the error handling and logging in this area so we have more information what goes wrong here. I have raised [https://github.com/elastic/rally/issues/416](https://github.com/elastic/rally/issues/416).

---

<div class="post-metadata">

**Author:** ![danielmitterdorfer](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/danielmitterdorfer/32/110510_2.png) [@danielmitterdorfer](https://discuss.elastic.co/u/danielmitterdorfer)\
**Post date:** [February 20, 2018, 9:30am UTC](https://discuss.elastic.co/t/rally-track-report-analysis/117589/7 "2018-02-20T09:30:29Z")

</div>

fyi, we've just [released Rally 0.9.2](https://discuss.elastic.co/t/rally-0-9-2-released/120583) which adds a bit more logging in that area of the code.

---

<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 20, 2018, 9:30am UTC](https://discuss.elastic.co/t/rally-track-report-analysis/117589/8 "2018-03-20T09:30:30Z")

</div>

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