2470 report batch times automlsearch

docs/source/release_notes.rst

@@ -2,6 +2,7 @@ Release Notes
 -------------
 **Future Releases**
     * Enhancements
+        * Added ability to log how long each batch and pipeline take in automl.search() :pr:`3577`
     * Fixes
     * Changes
     * Documentation Changes

evalml/automl/automl_search.py

@@ -62,6 +62,7 @@
 from evalml.utils.gen_utils import contains_all_ts_parameters
 from evalml.utils.logger import (
     get_logger,
+    log_batch_times,
     log_subtitle,
     log_title,
     time_elapsed,
@@ -857,16 +858,34 @@ def _handle_keyboard_interrupt(self):
             else:
                 leading_char = ""
 
-    def search(self, show_iteration_plot=True):
+    def search(self, show_iteration_plot=True, timing=None):
         """Find the best pipeline for the data set.
 
         Args:
             show_iteration_plot (boolean, True): Shows an iteration vs. score plot in Jupyter notebook.
                 Disabled by default in non-Jupyter enviroments.
+            timing (str, None): Shows timing of the batches and the individual timings of each pipeline.
+                Default: None
+                log=prints out batch/pipeline timing to console.
 
         Raises:
             AutoMLSearchException: If all pipelines in the current AutoML batch produced a score of np.nan on the primary objective.
+            ValueError: If timing is not set to a correct value
+
+        Returns:
+                Dict[int, Dict[str, Timestamp]]: Returns dict.
+                Key=batch #, value=Dict[key=pipeline name, value=timestamp of pipeline].
+                Inner dict has key called "Total time of batch" with value=total time of batch.
         """
+        batch_times = {}
+        if timing is not None:
+            timing = timing.lower()
+
+        if timing != "log" and timing is not None:
+            raise ValueError(
+                """Timing isn't set to a correct value! Please try again using "log"."""
+            )
+
         if self._searched:
             self.logger.error(
                 "AutoMLSearch.search() has already been run and will not run again on the same instance. Re-initialize AutoMLSearch to search again."
@@ -924,7 +943,10 @@ def search(self, show_iteration_plot=True):
         current_batch_pipeline_scores = []
         new_pipeline_ids = []
         loop_interrupted = False
+
         while self._should_continue():
+            pipeline_times = {}
+            start_batch_time = time.time()
             computations = []
             try:
                 if not loop_interrupted:
@@ -952,6 +974,7 @@ def search(self, show_iteration_plot=True):
                         current_computation_index
                     ]
                     if computation.done() and not has_been_processed:
+                        start_pipeline_time = time.time()
                         evaluation = computation.get_result()
                         data, cached_data, pipeline, job_log = (
                             evaluation.get("scores"),
@@ -962,6 +985,9 @@ def search(self, show_iteration_plot=True):
                         pipeline_id = self._post_evaluation_callback(
                             pipeline, data, cached_data, job_log
                         )
+                        pipeline_times[pipeline.name] = time_elapsed(
+                            start_pipeline_time
+                        )
                         new_pipeline_ids.append(pipeline_id)
                         computations[current_computation_index] = (computation, True)
                         computations_left_to_process -= 1
@@ -983,20 +1009,28 @@ def search(self, show_iteration_plot=True):
             current_batch_pipeline_scores = full_rankings[current_batch_idx][
                 "validation_score"
             ]
+
             if (
                 len(current_batch_pipeline_scores)
                 and current_batch_pipeline_scores.isna().all()
             ):
                 raise AutoMLSearchException(
                     f"All pipelines in the current AutoML batch produced a score of np.nan on the primary objective {self.objective}."
                 )
+            if len(pipeline_times) > 0:
+                pipeline_times["Total time of batch"] = time_elapsed(start_batch_time)
+                batch_times[self._get_batch_number()] = pipeline_times
 
         self.search_duration = time.time() - self._start
         elapsed_time = time_elapsed(self._start)
         desc = f"\nSearch finished after {elapsed_time}"
         desc = desc.ljust(self._MAX_NAME_LEN)
         self.logger.info(desc)
 
+        if timing == "log":
+            log_title(self.logger, "Batch Time Stats")
+            log_batch_times(self.logger, batch_times)
+
         self._find_best_pipeline()
         if self._best_pipeline is not None:
             best_pipeline = self.rankings.iloc[0]
@@ -1006,6 +1040,7 @@ def search(self, show_iteration_plot=True):
                 f"Best pipeline {self.objective.name}: {best_pipeline['validation_score']:3f}"
             )
         self._searched = True
+        return batch_times
 
     def _find_best_pipeline(self):
         """Finds the best pipeline in the rankings If self._best_pipeline already exists, check to make sure it is different from the current best pipeline before training and thresholding."""

evalml/tests/automl_tests/test_automl.py

@@ -216,6 +216,61 @@ def test_search_results(X_y_regression, X_y_binary, X_y_multi, automl_type, obje
     )
 
 
+def test_search_batch_times(caplog, X_y_binary, AutoMLTestEnv):
+    caplog.clear()
+    X, y = X_y_binary
+    automl = AutoMLSearch(
+        X_train=X,
+        y_train=y,
+        problem_type="binary",
+        max_iterations=None,
+        optimize_thresholds=False,
+        max_batches=3,
+        verbose=True,
+    )
+    batch_times = None
+    env = AutoMLTestEnv("binary")
+    with env.test_context(score_return_value={"Log Loss Binary": 0.3}):
+        batch_times = automl.search(timing="log")
+
+    out = caplog.text
+    assert isinstance(batch_times, dict)
+    assert isinstance(list(batch_times.keys())[0], int)
+    assert isinstance(batch_times[1], dict)
+    assert isinstance(list(batch_times[1].keys())[0], str)
+    assert isinstance(batch_times[1]["Total time of batch"], str)
+    assert isinstance(batch_times[2]["Total time of batch"], str)
+    assert isinstance(batch_times[3]["Total time of batch"], str)
+
+    assert len(batch_times) == 3
+    assert len(batch_times[1]) == 3
+    assert len(batch_times[2]) == 3
+    assert len(batch_times[3]) == 7
+
+    assert "Batch Time Stats" in out
+    assert "Batch 1 time stats" in out
+    assert "Batch 2 time stats" in out
+    assert "Batch 3 time stats" in out
+
+
+def test_search_batch_times_raise_valueerror(caplog, X_y_binary, AutoMLTestEnv):
+    caplog.clear()
+    X, y = X_y_binary
+    automl = AutoMLSearch(
+        X_train=X,
+        y_train=y,
+        problem_type="binary",
+        max_iterations=None,
+        optimize_thresholds=False,
+        max_batches=3,
+        verbose=True,
+    )
+    env = AutoMLTestEnv("binary")
+    with env.test_context(score_return_value={"Log Loss Binary": 0.3}):
+        with pytest.raises(ValueError):
+            automl.search(timing="test")
+
+
 @pytest.mark.parametrize(
     "automl_type",
     [ProblemTypes.BINARY, ProblemTypes.MULTICLASS, ProblemTypes.REGRESSION],

evalml/tests/utils_tests/test_logger.py

@@ -6,6 +6,7 @@
 from evalml import AutoMLSearch
 from evalml.utils.logger import (
     get_logger,
+    log_batch_times,
     log_subtitle,
     log_title,
     time_elapsed,
@@ -72,6 +73,20 @@ def test_logger_critical(caplog, logger_env_cleanup):
     assert "CRITICAL" in caplog.text
 
 
+def test_logger_batch_times(caplog, logger_env_cleanup):
+    logger = get_logger(TEST_LOGGER_NAME)
+    batch_times = {"1": {"test": "00:01", "tset": "10:00"}, "2": {"pipe": "00:02"}}
+    log_batch_times(logger, batch_times)
+    assert "Batch 1 time stats" in caplog.text
+    assert "test:" in caplog.text
+    assert "00:01" in caplog.text
+    assert "tset" in caplog.text
+    assert "10:00" in caplog.text
+    assert "Batch 2 time stats" in caplog.text
+    assert "pipe" in caplog.text
+    assert "00:02" in caplog.text
+
+
 @pytest.mark.parametrize(
     "time_passed,answer",
     [(101199, "28:06:39"), (3660, "1:01:00"), (65, "01:05"), (7, "00:07")],

evalml/utils/logger.py

@@ -55,3 +55,20 @@ def time_elapsed(start_time):
         return "{0:d}:{1:02d}:{2:02d}".format(h, m, s)
     else:
         return "{0:02d}:{1:02d}".format(m, s)
+
+
+def log_batch_times(logger, batch_times):
+    """Used to print out the batch times.
+
+    Args:
+        logger: the logger.
+        batch_times: dict with (batch number, {pipeline name, pipeline time}).
+    """
+    for batch_number in batch_times:
+        subtitle = "Batch " + str(batch_number) + " time stats:"
+        log_subtitle(logger, subtitle)
+        for pipeline_name in batch_times[batch_number]:
+            logger.info(
+                "\n" + pipeline_name + ": " + batch_times[batch_number][pipeline_name]
+            )
+        logger.info("")