Reduce logspew from backend simulator

ax/benchmark/benchmark.py

@@ -248,6 +248,11 @@ def benchmark_replication(
         seed: The seed to use for this replication.
         strip_runner_before_saving: Whether to strip the runner from the
             experiment before saving it. This enables serialization.
+        scheduler_logging_level: If >INFO, logs will only appear when unexpected
+            things happen. If INFO, logs will update when a trial is completed
+            and when an early stopping strategy, if present, decides whether or
+            not to continue a trial. If DEBUG, logs additionaly include
+            information from a `BackendSimulator`, if present.
 
     Return:
         ``BenchmarkResult`` object.
@@ -263,8 +268,7 @@ def benchmark_replication(
         logging_level=scheduler_logging_level,
     )
     runner = get_benchmark_runner(
-        problem=problem,
-        max_concurrency=scheduler_options.max_pending_trials,
+        problem=problem, max_concurrency=scheduler_options.max_pending_trials
     )
     experiment = Experiment(
         name=f"{problem.name}|{method.name}_{int(time())}",

ax/benchmark/benchmark_runner.py

@@ -184,6 +184,7 @@ def __post_init__(self) -> None:
                     internal_clock=0,
                     use_update_as_start_time=True,
                 ),
+                verbose_logging=False,
             )
             self.simulated_backend_runner = SimulatedBackendRunner(
                 simulator=simulator,

ax/benchmark/tests/test_benchmark.py

@@ -405,6 +405,37 @@ def test_replication_async(self) -> None:
         self._test_replication_async(map_data=False)
         self._test_replication_async(map_data=True)
 
+    def test_logging(self) -> None:
+        method = get_async_benchmark_method()
+        problem = get_async_benchmark_problem(
+            map_data=True,
+        )
+        logger = get_logger("utils.testing.backend_simulator")
+
+        with self.subTest("Logs produced if level is DEBUG"):
+            with self.assertLogs(level=logging.DEBUG, logger=logger):
+                result = benchmark_replication(
+                    problem=problem,
+                    method=method,
+                    seed=0,
+                    strip_runner_before_saving=False,
+                    scheduler_logging_level=logging.DEBUG,
+                )
+            experiment = none_throws(result.experiment)
+            runner = assert_is_instance(experiment.runner, BenchmarkRunner)
+            self.assertFalse(
+                none_throws(runner.simulated_backend_runner).simulator._verbose_logging
+            )
+
+        with self.subTest("Logs not produced by default"), self.assertNoLogs(
+            level=logging.INFO, logger=logger
+        ), self.assertNoLogs(logger=logger):
+            benchmark_replication(
+                problem=problem,
+                method=method,
+                seed=0,
+            )
+
     def test_early_stopping(self) -> None:
         """
         Test early stopping with a deterministic generation strategy and ESS

ax/utils/testing/backend_simulator.py

@@ -6,7 +6,6 @@
 
 # pyre-strict
 
-import logging
 import random
 import time
 from dataclasses import dataclass
@@ -140,9 +139,6 @@ def __init__(
                 (only used for testing particular initialization cases)
             verbose_logging: If False, sets the logging level to WARNING.
         """
-        if not verbose_logging:
-            logger.setLevel(logging.WARNING)
-
         self.options: BackendSimulatorOptions = (
             BackendSimulatorOptions() if options is None else options
         )
@@ -153,6 +149,13 @@ def __init__(
         self._verbose_logging = verbose_logging
         self._create_index_to_trial_map()
 
+    def log(self, msg: str) -> None:
+        """Log at INFO level if `verbose_logging`, otherwise DEBUG."""
+        if self._verbose_logging:
+            logger.info(msg)
+        else:
+            logger.debug(msg)
+
     @property
     def num_queued(self) -> int:
         """The number of queued trials (to run as soon as capacity is available)."""
@@ -216,8 +219,8 @@ def update(self) -> None:
             self.options.internal_clock = none_throws(self.options.internal_clock) + 1
         self._update(self.time)
         state = self.state()
-        logger.info(
-            "\n-----------\n"
+        self.log(
+            msg="\n-----------\n"
             f"Updated backend simulator state (time = {self.time}):\n"
             f"** Queued:\n{format(state.queued)}\n"
             f"** Running:\n{format(state.running)}\n"
@@ -308,15 +311,15 @@ def stop_trial(self, trial_index: int) -> None:
         """
         trial_status = self.lookup_trial_index_status(trial_index)
         if trial_status is not TrialStatus.RUNNING:
-            logger.info(
-                f"Trial {trial_index} is not currently running (has status "
+            self.log(
+                msg=f"Trial {trial_index} is not currently running (has status "
                 f"{trial_status}) and cannot be stopped."
             )
         else:
             trial = self._index_to_trial_map[trial_index]
             trial.sim_completed_time = self.time
-            logger.info(
-                f"Trial {trial_index} stopped at time {trial.sim_completed_time}."
+            self.log(
+                msg=f"Trial {trial_index} stopped at time {trial.sim_completed_time}."
             )
 
     def status(self) -> SimStatus:

ax/utils/testing/tests/test_backend_simulator.py

@@ -9,6 +9,7 @@
 from unittest.mock import Mock, patch
 
 from ax.core.trial_status import TrialStatus
+from ax.utils.common.logger import get_logger
 from ax.utils.common.testutils import TestCase
 from ax.utils.testing.backend_simulator import BackendSimulator, BackendSimulatorOptions
 from ax.utils.testing.utils_testing_stubs import get_backend_simulator_with_trials
@@ -73,6 +74,20 @@ def test_backend_simulator(self, time_mock: Mock) -> None:
         self.assertEqual(sim3.num_failed, 1)
         self.assertEqual(sim3.num_completed, 0)
 
+        with self.subTest("Test logging"):
+            with self.assertLogs(
+                logger=get_logger("utils.testing.backend_simulator"), level="INFO"
+            ):
+                sim3.update()
+
+            non_verbose_simulator = BackendSimulator(
+                options=options, verbose_logging=False
+            )
+            with self.assertLogs(
+                logger=get_logger("utils.testing.backend_simulator"), level="DEBUG"
+            ):
+                non_verbose_simulator.update()
+
     def test_backend_simulator_internal_clock(self) -> None:
         sim = get_backend_simulator_with_trials()
         self.assertEqual(len(sim.all_trials), 3)