Store duration time of task in rally-results metrics record #1220

ebadyano · 2021-03-26T00:14:10Z

Closes: #1197

# Conflicts: # esrally/metrics.py

danielmitterdorfer

Thanks for the PR! That's very helpful. I left a couple of suggestions.

I also think that a prerequisite for this is #1198 so we have consistent time scale. Otherwise all measurements would be in milliseconds except for relative-time, which would be denoted in microseconds.

danielmitterdorfer · 2021-03-26T06:05:09Z

esrally/metrics.py

@@ -1673,6 +1675,11 @@ def total_transform_metric(self, metric_name):
    def error_rate(self, task_name, operation_type):
        return self.store.get_error_rate(task=task_name, operation_type=operation_type, sample_type=SampleType.Normal)

+    def duration(self, task_name):
+        values = self.store.get_raw("service_time", task_name, mapper=lambda doc: doc["relative-time"])


This can potentially return millions of documents (e.g. in a benchmark with thousands of clients) and we're only interested in one value. I wonder whether this would justify a specialized query method in the metrics store as it would be much cheaper only to retrieve the maximum value directly?

I also want to point out that relative-time is determined before a request is issued:

rally/esrally/driver/driver.py

Lines 1060 to 1062 in 62595bd

@property

def relative_time(self):

return self.request_start - self.task_start

So strictly speaking duration does not account for the service time of the last request. If this is a long-running request (e.g. in frozen tier benchmarks) the duration measurement could be several minutes off. This could be specifically misleading if there is only one measurement iteration as duration would report something in order of several milliseconds when the actual duration would more be like several minutes.

So if we settle on a special query method, I propose that the API allows us to retrieve one sample ordered by a criterion. E.g. we could amend the current get_one method in the metrics store:

rally/esrally/metrics.py

Line 619 in 62595bd

def get_one(self, name, sample_type=None, node_name=None, task=None):

to allow sorting:

def get_one(self, name, sample_type=None, node_name=None, task=None, sort_key=None, sort_reverse=False):

Note: I've borrowed the names of the new parameters sort_key an sort_reverse from Python's sorted function for an idiomatic API.

What do you think?

Sounds good, I will use that, thank you for the suggestion!

@danielmitterdorfer interestingly the current implementation for get_one uses get and the just returns values[0] so it would still return all the values and then pick the first one locally.

rally/esrally/metrics.py

Line 633 in 62595bd

return values[0] if values else None

Was your idea to modify the search query so that it would only return one value?

Yes, we should implement get_one in both subclasses (InMemoryMetricsStore and EsMetricsStore) and remove the generic implementation in the base class.

danielmitterdorfer · 2021-03-26T06:08:23Z

esrally/metrics.py

@@ -1821,6 +1830,7 @@ def add_op_metrics(self, task, operation, throughput, latency, service_time, pro
            "service_time": service_time,
            "processing_time": processing_time,
            "error_rate": error_rate,
+            "duration_time": duration


I'd argue that duration by itself conveys its meaning already and the _time suffix is redundant? (see also https://docs.oracle.com/en/java/javase/15/docs/api/java.base/java/time/Duration.html)

danielmitterdorfer · 2021-03-26T11:08:33Z

I also think that a prerequisite for this is #1198 so we have consistent time scale.

I've pushed #1221 now and we should base the duration on the newly introduced field relative-time-ms in this PR here.

danielmitterdorfer

Thanks for iterating! I left a couple more comments. Can you please also implement tests for get_one for both metrics store implementations (including tests for handling an empty search result)?

danielmitterdorfer · 2021-04-15T07:06:44Z

esrally/metrics.py

@@ -825,6 +828,29 @@ def _get(self, name, task, operation_type, sample_type, node_name, mapper):
        self.logger.debug("Metrics query produced [%s] results.", result["hits"]["total"])
        return [mapper(v["_source"]) for v in result["hits"]["hits"]]

+    def get_one(self, name, sample_type=None, node_name=None, task=None, mapper=lambda doc: doc["value"],
+                sort_key=None, sort_reverse=False):
+        order = "desc"


Maybe this would be simpler?

order = "desc" if sort_reverse else "asc"

danielmitterdorfer · 2021-04-15T07:10:13Z

esrally/metrics.py

+        order = "desc"
+        if not sort_reverse:
+            order = "asc"
+        if sort_key:


Alternatively you could implement this block as follows:

query = { "query": self._query_by_name(name, task, None, sample_type, node_name), "size": 1 } if sort_key: query["sort"] = [{sort_key: {"order": order}}]

This avoids repetition of common elements.

danielmitterdorfer · 2021-04-15T07:11:05Z

esrally/metrics.py

+        self.logger.debug("Issuing get against index=[%s], query=[%s].", self._index, query)
+        result = self._client.search(index=self._index, body=query)
+        self.logger.debug("Metrics query produced [%s] results.", result["hits"]["total"])
+        return mapper(result["hits"]["hits"][0]["_source"])


This would fail with a key error if there are no hits. Can we check this and return None if there are no hits?

danielmitterdorfer · 2021-04-15T07:11:30Z

esrally/metrics.py

+            docs = sorted(self.docs, key=lambda k: k[sort_key], reverse=sort_reverse)
+        else:
+            docs = self.docs
+        for doc in docs:


I think we need to return None if there are no hits (i.e. after the for loop).

danielmitterdorfer · 2021-04-15T07:17:52Z

tests/metrics_test.py

@@ -1583,6 +1585,7 @@ def test_calculate_global_stats(self):
        self.assertEqual(collections.OrderedDict(
            [("50_0", 200), ("100_0", 210), ("mean", 200), ("unit", "ms")]), opm["service_time"])
        self.assertAlmostEqual(0.3333333333333333, opm["error_rate"])
+        self.assertAlmostEqual(709*1000, opm["duration"])


Shouldn't we able to use assertEqual here as this is an integer value?

Opps thank you for catching

danielmitterdorfer · 2021-04-15T07:17:57Z

tests/metrics_test.py

@@ -1595,6 +1598,7 @@ def test_calculate_global_stats(self):
        self.assertEqual(17.2, stats.ml_processing_time[0]["median"])
        self.assertEqual(36.0, stats.ml_processing_time[0]["max"])
        self.assertEqual("ms", stats.ml_processing_time[0]["unit"])
+        self.assertAlmostEqual(600*1000, opm2["duration"])


Shouldn't we able to use assertEqual here as this is an integer value?

danielmitterdorfer

Thanks for iterating! I left one comment but no need for another review round. LGTM

danielmitterdorfer · 2021-04-19T06:36:45Z

tests/metrics_test.py

+        actual_duration = self.metrics_store.get_one("service_time", task="task1", mapper=lambda doc: doc["relative-time-ms"],
+                                                     sort_key="relative-time-ms", sort_reverse=True)
+
+        self.assertEqual(None, actual_duration)


We can use self.assertIsNone here.

ebadyano · 2021-04-19T13:46:25Z

Thank you for the review @danielmitterdorfer

ebadyano added 3 commits March 25, 2021 14:55

Store duration time of task in rally-results metrics record

bce3f67

Closes elastic#1197

Merge branch 'master' of github.com:elastic/rally into time

4aa3d1d

# Conflicts: # esrally/metrics.py

add test for duration-time

2c6f627

ebadyano added enhancement Improves the status quo :Metrics How metrics are stored, calculated or aggregated labels Mar 26, 2021

ebadyano requested a review from dliappis March 26, 2021 00:14

danielmitterdorfer reviewed Mar 26, 2021

View reviewed changes

danielmitterdorfer assigned ebadyano Mar 26, 2021

danielmitterdorfer added this to the 2.1.0 milestone Mar 26, 2021

Merge branch 'master' of github.com:elastic/rally into time

b051bf0

ebadyano modified the milestones: 2.1.0, 2.2.0 Mar 31, 2021

chan

86d3244

danielmitterdorfer modified the milestones: 2.2.0, 2.1.1 Apr 6, 2021

ebadyano added 3 commits April 7, 2021 13:01

Merge branch 'master' of github.com:elastic/rally into time

6bdad80

address Daniel's comments

dcbab13

Merge branch 'master' of github.com:elastic/rally into time

58f2099

ebadyano requested a review from danielmitterdorfer April 14, 2021 14:41

danielmitterdorfer reviewed Apr 15, 2021

View reviewed changes

ebadyano modified the milestones: 2.1.1, 2.2.0 Apr 15, 2021

ebadyano added 3 commits April 15, 2021 12:30

Address Daniel's comments

b6bc660

Merge branch 'master' of github.com:elastic/rally into time

88581ee

add tests

e025006

ebadyano requested a review from danielmitterdorfer April 15, 2021 18:20

danielmitterdorfer approved these changes Apr 19, 2021

View reviewed changes

Address Daniel's comment

4f2ee52

ebadyano merged commit 7dfdbfb into elastic:master Apr 19, 2021

ebadyano deleted the time branch December 16, 2022 15:15

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Store duration time of task in rally-results metrics record #1220

Store duration time of task in rally-results metrics record #1220

ebadyano commented Mar 26, 2021

danielmitterdorfer left a comment

danielmitterdorfer Mar 26, 2021

ebadyano Mar 26, 2021

ebadyano Mar 29, 2021

danielmitterdorfer Apr 6, 2021

danielmitterdorfer Mar 26, 2021

danielmitterdorfer commented Mar 26, 2021

danielmitterdorfer left a comment

danielmitterdorfer Apr 15, 2021

danielmitterdorfer Apr 15, 2021

danielmitterdorfer Apr 15, 2021

danielmitterdorfer Apr 15, 2021

danielmitterdorfer Apr 15, 2021

ebadyano Apr 15, 2021

danielmitterdorfer Apr 15, 2021

danielmitterdorfer left a comment

danielmitterdorfer Apr 19, 2021

ebadyano commented Apr 19, 2021

	@property
	def relative_time(self):
	return self.request_start - self.task_start

Store duration time of task in rally-results metrics record #1220

Store duration time of task in rally-results metrics record #1220

Conversation

ebadyano commented Mar 26, 2021

danielmitterdorfer left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

danielmitterdorfer commented Mar 26, 2021

danielmitterdorfer left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

danielmitterdorfer left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ebadyano commented Apr 19, 2021