Update batch metric logging to use millisecond timestamps (mlflow#1333)

mlflow/tracking/fluent.py

@@ -194,7 +194,7 @@ def log_metrics(metrics, step=None):
     :returns: None
     """
     run_id = _get_or_start_run().info.run_id
-    timestamp = int(time.time())
+    timestamp = int(time.time() * 1000)
     metrics_arr = [Metric(key, value, timestamp, step or 0) for key, value in metrics.items()]
     MlflowClient().log_batch(run_id=run_id, metrics=metrics_arr, params=[], tags=[])
 

tests/tracking/test_tracking.py

@@ -225,7 +225,7 @@ def test_log_batch(tracking_uri_mock, tmpdir):
     assert finished_run.data.params == expected_params
 
 
-def test_log_metric(tracking_uri_mock, tmpdir):
+def test_log_metric(tracking_uri_mock):
     with start_run() as active_run, mock.patch("time.time") as time_mock:
         time_mock.side_effect = range(300, 400)
         run_id = active_run.info.run_id
@@ -253,8 +253,36 @@ def test_log_metric(tracking_uri_mock, tmpdir):
     ])
 
 
+def test_log_metrics_uses_millisecond_timestamp_resolution(tracking_uri_mock):
+    with start_run() as active_run, mock.patch("time.time") as time_mock:
+        time_mock.side_effect = range(300, 400)
+        mlflow.log_metrics({
+            "name_1": 25,
+            "name_2": -3,
+        })
+        mlflow.log_metrics({
+            "name_1": 30,
+        })
+        mlflow.log_metrics({
+            "name_1": 40,
+        })
+        run_id = active_run.info.run_id
+    finished_run = tracking.MlflowClient().get_run(run_id)
+    client = tracking.MlflowClient()
+    metric_history_name1 = client.get_metric_history(run_id, "name_1")
+    assert set([(m.value, m.timestamp) for m in metric_history_name1]) == set([
+        (25, 300 * 1000),
+        (30, 301 * 1000),
+        (40, 302 * 1000),
+    ])
+    metric_history_name2 = client.get_metric_history(run_id, "name_2")
+    assert set([(m.value, m.timestamp) for m in metric_history_name2]) == set([
+        (-3, 300 * 1000),
+    ])
+
+
 @pytest.mark.parametrize("step_kwarg", [None, -10, 5])
-def test_log_metrics(tracking_uri_mock, step_kwarg):
+def test_log_metrics_uses_common_timestamp_and_step_per_invocation(tracking_uri_mock, step_kwarg):
     expected_metrics = {"name_1": 30, "name_2": -3, "nested/nested/name": 40}
     with start_run() as active_run:
         run_id = active_run.info.run_id