[tune] track and print elapsed time in reporters

python/ray/tune/progress_reporter.py

@@ -1,5 +1,6 @@
 from __future__ import print_function
 
+import datetime
 from typing import Dict, List, Optional, Union
 
 import collections
@@ -159,6 +160,8 @@ def __init__(
         self._max_report_freqency = max_report_frequency
         self._last_report_time = 0
 
+        self._start_time = time.time()
+
         self._metric = metric
         self._mode = mode
 
@@ -188,6 +191,12 @@ def set_search_properties(self, metric: Optional[str],
     def set_total_samples(self, total_samples: int):
         self._total_samples = total_samples
 
+    def set_start_time(self, timestamp: Optional[float] = None):
+        if timestamp is not None:
+            self._start_time = time.time()
+        else:
+            self._start_time = timestamp
+
     def should_report(self, trials: List[Trial], done: bool = False):
         if time.time() - self._last_report_time > self._max_report_freqency:
             self._last_report_time = time.time()
@@ -267,7 +276,11 @@ def _progress_str(self,
         if not self._metrics_override:
             user_metrics = self._infer_user_metrics(trials, self._infer_limit)
             self._metric_columns.update(user_metrics)
-        messages = ["== Status ==", memory_debug_str(), *sys_info]
+        messages = [
+            "== Status ==",
+            time_passed_str(self._start_time, time.time()),
+            memory_debug_str(), *sys_info
+        ]
         if done:
             max_progress = None
             max_error = None
@@ -510,6 +523,33 @@ def memory_debug_str():
                 "to resolve)")
 
 
+def time_passed_str(start_time: float, current_time: float):
+    current_time_dt = datetime.datetime.fromtimestamp(current_time)
+    start_time_dt = datetime.datetime.fromtimestamp(start_time)
+    delta: datetime.timedelta = current_time_dt - start_time_dt
+
+    rest = delta.total_seconds()
+    days = rest // (60 * 60 * 24)
+
+    rest -= days * (60 * 60 * 24)
+    hours = rest // (60 * 60)
+
+    rest -= hours * (60 * 60)
+    minutes = rest // 60
+
+    seconds = rest - minutes * 60
+
+    if days > 0:
+        running_for_str = f"{days:.0f} days, "
+    else:
+        running_for_str = ""
+
+    running_for_str += f"{hours:02.0f}:{minutes:02.0f}:{seconds:05.2f}"
+
+    return (f"Current time: {current_time_dt:%Y-%m-%d %H:%M:%S} "
+            f"(running for {running_for_str})")
+
+
 def _get_trials_by_state(trials: List[Trial]):
     trials_by_state = collections.defaultdict(list)
     for t in trials:

python/ray/tune/tests/test_progress_reporter.py

@@ -3,13 +3,14 @@
 import os
 import unittest
 from unittest.mock import MagicMock, Mock, patch
+
 from ray import tune
 from ray._private.test_utils import run_string_as_driver
 from ray.tune.trial import Trial
 from ray.tune.result import AUTO_RESULT_KEYS
-from ray.tune.progress_reporter import (CLIReporter, JupyterNotebookReporter,
-                                        _fair_filter_trials, best_trial_str,
-                                        detect_reporter, trial_progress_str)
+from ray.tune.progress_reporter import (
+    CLIReporter, JupyterNotebookReporter, _fair_filter_trials, best_trial_str,
+    detect_reporter, trial_progress_str, time_passed_str)
 
 EXPECTED_RESULT_1 = """Result logdir: /foo
 Number of trials: 5 (1 PENDING, 3 RUNNING, 1 TERMINATED)
@@ -424,6 +425,27 @@ def testProgressStr(self):
         best1 = best_trial_str(trials[1], "metric_1")
         assert best1 == EXPECTED_BEST_1
 
+    def testTimeElapsed(self):
+        # Sun Feb 7 14:18:40 2016 -0800
+        # (time of the first Ray commit)
+        time_start = 1454825920
+        time_now = (
+            time_start + 1 * 60 * 60  # 1 hour
+            + 31 * 60  # 31 minutes
+            + 22  # 22 seconds
+        )  # time to second commit
+
+        # Local timezone output can be tricky, so we don't check the
+        # day and the hour in this test.
+        output = time_passed_str(time_start, time_now)
+        self.assertIn("Current time: 2016-02-", output)
+        self.assertIn(":50:02 (running for 01:31:22.00)", output)
+
+        time_now += 2 * 60 * 60 * 24  # plus two days
+        output = time_passed_str(time_start, time_now)
+        self.assertIn("Current time: 2016-02-", output)
+        self.assertIn(":50:02 (running for 2 days, 01:31:22.00)", output)
+
     def testCurrentBestTrial(self):
         trials = []
         for i in range(5):

python/ray/tune/tune.py

@@ -531,6 +531,7 @@ def sigint_handler(sig, frame):
         signal.signal(signal.SIGINT, sigint_handler)
 
     tune_start = time.time()
+    progress_reporter.set_start_time(tune_start)
     while not runner.is_finished() and not state[signal.SIGINT]:
         runner.step()
         if has_verbosity(Verbosity.V1_EXPERIMENT):