From f00747bd2fb8396fbbdb21da0586e4f74c3370d1 Mon Sep 17 00:00:00 2001 From: Kai Fricke Date: Wed, 6 Oct 2021 15:03:54 +0100 Subject: [PATCH 1/2] [tune] track and print elapsed time in reporters --- python/ray/tune/progress_reporter.py | 42 +++++++++++++++++++++++++++- python/ray/tune/tune.py | 1 + 2 files changed, 42 insertions(+), 1 deletion(-) diff --git a/python/ray/tune/progress_reporter.py b/python/ray/tune/progress_reporter.py index 0b69faa51550..383f8bb3c6c7 100644 --- a/python/ray/tune/progress_reporter.py +++ b/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} 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: diff --git a/python/ray/tune/tune.py b/python/ray/tune/tune.py index 8077f7c6e6cd..975327b2f262 100644 --- a/python/ray/tune/tune.py +++ b/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): From df0a8bbf4ea5181cb805f6f6ab72ba2065fb61bc Mon Sep 17 00:00:00 2001 From: Kai Fricke Date: Wed, 6 Oct 2021 15:32:33 +0100 Subject: [PATCH 2/2] Add unit test --- python/ray/tune/progress_reporter.py | 2 +- .../ray/tune/tests/test_progress_reporter.py | 28 +++++++++++++++++-- 2 files changed, 26 insertions(+), 4 deletions(-) diff --git a/python/ray/tune/progress_reporter.py b/python/ray/tune/progress_reporter.py index 383f8bb3c6c7..67a380c87eab 100644 --- a/python/ray/tune/progress_reporter.py +++ b/python/ray/tune/progress_reporter.py @@ -540,7 +540,7 @@ def time_passed_str(start_time: float, current_time: float): seconds = rest - minutes * 60 if days > 0: - running_for_str = f"{days} days, " + running_for_str = f"{days:.0f} days, " else: running_for_str = "" diff --git a/python/ray/tune/tests/test_progress_reporter.py b/python/ray/tune/tests/test_progress_reporter.py index 2e85fe0a6b36..e47db0b8b6cc 100644 --- a/python/ray/tune/tests/test_progress_reporter.py +++ b/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):