Store relative-time in milliseconds (#1221)

Previously `relative-time` has denoted the relative time in microseconds
since the start of a task. This is inconvenient as all other times are
denoted in milliseconds. Therefore, we will migrate this field to be
denoted in milliseconds as well. In the first step we deprecate the
current field and introduce a new field `relative-time-ms` that is used
for the transition period.

Relates #1198

docs/metrics.rst

@@ -15,6 +15,7 @@ Here is a typical metrics record::
           "race-id": "6ebc6e53-ee20-4b0c-99b4-09697987e9f4",
           "@timestamp": 1461213093093,
           "relative-time": 10507328,
+          "relative-time-ms": 10507.328,
           "track": "geonames",
           "track-params": {
             "shard-count": 3
@@ -81,8 +82,23 @@ The timestamp in milliseconds since epoch determined when the sample was taken.
 relative-time
 ~~~~~~~~~~~~~
 
+.. warning::
+
+    This property is deprecated with Rally 2.1.0. Use ``relative-time-ms`` for the transition period (between Rally 2.1.0 and Rally 2.3.0). In Rally 2.2.0 this field will be dropped and reintroduced in Rally 2.3.0 as the relative time denoted in milliseconds.
+
+
 The relative time in microseconds since the start of the benchmark. This is useful for comparing time-series graphs over multiple races, e.g. you might want to compare the indexing throughput over time across multiple races. Obviously, they should always start at the same (relative) point in time and absolute timestamps are useless for that.
 
+relative-time-ms
+~~~~~~~~~~~~~~~~
+
+.. warning::
+
+    This property is introduced for a transition period between Rally 2.1.0 and Rally 2.4.0. It will be deprecated with Rally 2.3.0 and removed in Rally 2.4.0.
+
+
+The relative time in milliseconds since the start of the benchmark. This is useful for comparing time-series graphs over multiple races, e.g. you might want to compare the indexing throughput over time across multiple races. As they should always start at the same (relative) point in time, absolute timestamps are not helpful.
+
 name, value, unit
 ~~~~~~~~~~~~~~~~~
 

docs/migrate.rst

@@ -4,6 +4,20 @@ Migration Guide
 Migrating to Rally 2.1.0
 ------------------------
 
+``relative-time`` is deprecated
+^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
+
+.. note::
+
+    This deprecation is only relevant if you have configured an Elasticsearch metrics store for Rally.
+
+The metric ``relative-time`` contains the relative time since Rally has started executing a task denoted in microseconds. All other time-based metrics like service time or latency are denoted in milliseconds and we will align this property over the coming minor releases as follows:
+
+* Rally 2.1.0: ``relative-time`` is deprecated and Rally adds a new field ``relative-time-ms`` which contains the relative time in milliseconds.
+* Rally 2.2.0: ``relative-time`` will be dropped. Rally only populates the field ``relative-time-ms`` which contains the relative time in milliseconds.
+* Rally 2.3.0: ``relative-time`` will be reintroduced and contain the relative time in milliseconds. The field ``relative-time-ms`` will be deprecated.
+* Rally 2.4.0: ``relative-time-ms`` will be dropped.
+
 Semantics of request-related timestamps have changed
 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
 

docs/recipes.rst

@@ -271,6 +271,7 @@ The number of hits from queries can also be investigated if you have configured
 	{
 	  "@timestamp" : 1597681313435,
 	  "relative-time" : 130273374,
+	  "relative-time-ms" : 130273.374,
 	  "race-id" : "452ad9d7-9c21-4828-848e-89974af3230e",
 	  "race-timestamp" : "20200817T160412Z",
 	  "environment" : "Personal",

esrally/metrics.py

@@ -521,7 +521,9 @@ def _put_metric(self, level, level_key, name, value, unit, task, operation, oper
 
         doc = {
             "@timestamp": time.to_epoch_millis(absolute_time),
+            # deprecated
             "relative-time": int(relative_time * 1000 * 1000),
+            "relative-time-ms": convert.seconds_to_ms(relative_time),
             "race-id": self._race_id,
             "race-timestamp": self._race_timestamp,
             "environment": self._environment_name,
@@ -579,6 +581,7 @@ def put_doc(self, doc, level=None, node_name=None, meta_data=None, absolute_time
         doc.update({
             "@timestamp": time.to_epoch_millis(absolute_time),
             "relative-time": int(relative_time * 1000 * 1000),
+            "relative-time-ms": convert.seconds_to_ms(relative_time),
             "race-id": self._race_id,
             "race-timestamp": self._race_timestamp,
             "environment": self._environment_name,

esrally/resources/metrics-template.json

@@ -31,6 +31,9 @@
         "relative-time": {
           "type": "long"
         },
+        "relative-time-ms": {
+          "type": "float"
+        },
         "race-id": {
           "type": "keyword"
         },

tests/metrics_test.py

@@ -315,6 +315,7 @@ def test_put_value_without_meta_info(self):
             "race-id": EsMetricsTests.RACE_ID,
             "race-timestamp": "20160131T000000Z",
             "relative-time": 0,
+            "relative-time-ms": 0,
             "environment": "unittest",
             "sample-type": "normal",
             "track": "test",
@@ -344,6 +345,7 @@ def test_put_value_with_explicit_timestamps(self):
             "race-id": EsMetricsTests.RACE_ID,
             "race-timestamp": "20160131T000000Z",
             "relative-time": 10000000,
+            "relative-time-ms": 10000,
             "environment": "unittest",
             "sample-type": "normal",
             "track": "test",
@@ -382,6 +384,7 @@ def test_put_value_with_meta_info(self):
             "race-id": EsMetricsTests.RACE_ID,
             "race-timestamp": "20160131T000000Z",
             "relative-time": 0,
+            "relative-time-ms": 0,
             "environment": "unittest",
             "sample-type": "normal",
             "track": "test",
@@ -420,6 +423,7 @@ def test_put_doc_no_meta_data(self):
             "race-id": EsMetricsTests.RACE_ID,
             "race-timestamp": "20160131T000000Z",
             "relative-time": 0,
+            "relative-time-ms": 0,
             "environment": "unittest",
             "track": "test",
             "track-params": {
@@ -465,6 +469,7 @@ def test_put_doc_with_metadata(self):
             "race-id": EsMetricsTests.RACE_ID,
             "race-timestamp": "20160131T000000Z",
             "relative-time": 0,
+            "relative-time-ms": 0,
             "environment": "unittest",
             "track": "test",
             "track-params": {
@@ -1662,7 +1667,9 @@ def test_add_administrative_task_with_error_rate_in_report(self):
 
         self.metrics_store.open(InMemoryMetricsStoreTests.RACE_ID, InMemoryMetricsStoreTests.RACE_TIMESTAMP,
                                 "test", "append-fast-with-conflicts", "defaults", create=True)
-        self.metrics_store.put_doc(doc={"@timestamp": 1595896761994, "relative-time": 283382,
+        self.metrics_store.put_doc(doc={"@timestamp": 1595896761994,
+                                        "relative-time": 283382,
+                                        "relative-time-ms": 283.382,
                                         "race-id": "fb26018b-428d-4528-b36b-cf8c54a303ec",
                                         "race-timestamp": "20200728T003905Z", "environment": "local",
                                         "track": "geonames", "challenge": "append-fast-with-conflicts",