Revamp logging (#478)

Summary:
This is a bunch of changes to make our training logs more meaningful and
easier to understand. We print the task config in the beginning of training,
make it clear what values are approximate or final, supress verbose logs
by default and format floats accordingly.

Before this diff: P128995674
After this diff: P128995244
Pull Request resolved: #478

Reviewed By: mannatsingh

Differential Revision: D21022171

Pulled By: vreis

fbshipit-source-id: d63d5ac9b4b3b3cc9abb359914141bf6821dc14a

Author: vreis

classy_vision/hooks/loss_lr_meter_logging_hook.py

@@ -18,7 +18,6 @@ class LossLrMeterLoggingHook(ClassyHook):
     Logs the loss, optimizer LR, and meters. Logs at the end of a phase.
     """
 
-    on_start = ClassyHook._noop
     on_phase_start = ClassyHook._noop
     on_end = ClassyHook._noop
 
@@ -35,6 +34,9 @@ def __init__(self, log_freq: Optional[int] = None) -> None:
         ), "log_freq must be an int or None"
         self.log_freq: Optional[int] = log_freq
 
+    def on_start(self, task) -> None:
+        logging.info(f"Starting training. Task: {task}")
+
     def on_phase_end(self, task) -> None:
         """
         Log the loss, optimizer LR, and meters for the phase.
@@ -45,10 +47,7 @@ def on_phase_end(self, task) -> None:
             # do not explicitly state this since it is possible for a
             # trainer to implement an unsynced end of phase meter or
             # for meters to not provide a sync function.
-            logging.info("End of phase metric values:")
-            self._log_loss_meters(task)
-            if task.train:
-                self._log_lr(task)
+            self._log_loss_meters(task, prefix="Synced meters: ")
 
     def on_step(self, task) -> None:
         """
@@ -58,18 +57,9 @@ def on_step(self, task) -> None:
             return
         batches = len(task.losses)
         if batches and batches % self.log_freq == 0:
-            self._log_lr(task)
-            logging.info("Local unsynced metric values:")
-            self._log_loss_meters(task)
-
-    def _log_lr(self, task) -> None:
-        """
-        Compute and log the optimizer LR.
-        """
-        optimizer_lr = task.optimizer.parameters.lr
-        logging.info("Learning Rate: {}\n".format(optimizer_lr))
+            self._log_loss_meters(task, prefix="Approximate meters: ")
 
-    def _log_loss_meters(self, task) -> None:
+    def _log_loss_meters(self, task, prefix="") -> None:
         """
         Compute and log the loss and meters.
         """
@@ -80,14 +70,9 @@ def _log_loss_meters(self, task) -> None:
 
         # Loss for the phase
         loss = sum(task.losses) / (batches * task.get_batchsize_per_replica())
+        phase_pct = batches / task.num_batches_per_phase
 
-        log_strs = [
-            "Rank: {}, {} phase: {}, processed batches: {}".format(
-                get_rank(), phase_type, phase_type_idx, batches
-            ),
-            "{} loss: {}".format(phase_type, loss),
-            "Meters:",
-        ]
-        for meter in task.meters:
-            log_strs.append("{}".format(meter))
-        logging.info("\n".join(log_strs))
+        logging.info(
+            f"{prefix}[{get_rank()}] {phase_type} phase {phase_type_idx} "
+            f"({phase_pct*100:.2f}% done), loss: {loss:.4f}, meters: {task.meters}"
+        )

classy_vision/hooks/model_complexity_hook.py

@@ -53,10 +53,10 @@ def on_start(self, task) -> None:
                     )
             except NotImplementedError:
                 logging.warning(
-                    """Model contains unsupported modules:
-                Could not compute FLOPs for model forward pass. Exception:""",
-                    exc_info=True,
+                    "Model contains unsupported modules, "
+                    "could not compute FLOPs for model forward pass."
                 )
+                logging.debug("Exception:", exc_info=True)
             try:
                 self.num_activations = compute_activations(
                     task.base_model,

classy_vision/meters/accuracy_meter.py

@@ -126,9 +126,6 @@ def set_classy_state(self, state):
         self._curr_correct_predictions_k = state["curr_correct_predictions_k"].clone()
         self._curr_sample_count = state["curr_sample_count"].clone()
 
-    def __repr__(self):
-        return repr({"name": self.name, "value": self.value})
-
     def update(self, model_output, target, **kwargs):
         """
         args:

classy_vision/meters/classy_meter.py

@@ -114,3 +114,16 @@ def set_classy_state(self, state: Dict[str, Any]) -> None:
         This is used to load the state of the meter from a checkpoint.
         """
         raise NotImplementedError
+
+    def __repr__(self):
+        """Returns a string representation of the meter, used for logging.
+
+        The default implementation assumes value is a dict. value is not
+        required to be a dict, and in that case you should override this
+        method."""
+
+        if not isinstance(self.value, dict):
+            return super().__repr__()
+
+        values = ",".join([f"{key}={value:.6f}" for key, value in self.value.items()])
+        return f"{self.name}_meter({values})"

classy_vision/meters/precision_meter.py

@@ -127,9 +127,6 @@ def set_classy_state(self, state):
         self._curr_correct_predictions_k = state["curr_correct_predictions_k"].clone()
         self._curr_sample_count = state["curr_sample_count"].clone()
 
-    def __repr__(self):
-        return repr({"name": self.name, "value": self.value})
-
     def update(self, model_output, target, **kwargs):
         """
         args:

classy_vision/meters/recall_meter.py

@@ -126,9 +126,6 @@ def set_classy_state(self, state):
         self._curr_correct_predictions_k = state["curr_correct_predictions_k"].clone()
         self._curr_correct_targets = state["curr_correct_targets"].clone()
 
-    def __repr__(self):
-        return repr({"name": self.name, "value": self.value})
-
     def update(self, model_output, target, **kwargs):
         """
         args:

classy_vision/meters/video_meter.py

@@ -76,9 +76,6 @@ def set_classy_state(self, state):
         self.reset()
         self.meter.set_classy_state(state["meter_state"])
 
-    def __repr__(self):
-        return repr({"name": self.name, "value": self.value})
-
     def update(self, model_output, target, is_train, **kwargs):
         """Updates any internal state of meter with new model output and target.
 

classy_vision/tasks/classification_task.py

@@ -6,6 +6,7 @@
 
 import copy
 import enum
+import json
 import logging
 import math
 import time
@@ -413,6 +414,10 @@ def from_config(cls, config: Dict[str, Any]) -> "ClassificationTask":
         for phase_type in phase_types:
             task.set_dataset(datasets[phase_type], phase_type)
 
+        # NOTE: this is a private member and only meant to be used for
+        # logging/debugging purposes. See __repr__ implementation
+        task._config = config
+
         return task
 
     @property
@@ -854,7 +859,7 @@ def advance_phase(self):
         resets counters, shuffles dataset, rebuilds iterators, and
         sets the train / test state for phase.
         """
-        logging.info("Advancing phase")
+        logging.debug("Advancing phase")
         # Reset meters for next phase / epoch
         for meter in self.meters:
             meter.reset()
@@ -893,7 +898,7 @@ def _recreate_data_loader_from_dataset(self, phase_type=None):
         if phase_type is None:
             phase_type = self.phase_type
 
-        logging.info("Recreating data loader for new phase")
+        logging.debug("Recreating data loader for new phase")
         num_workers = 0
         if hasattr(self.dataloaders[phase_type], "num_workers"):
             num_workers = self.dataloaders[phase_type].num_workers
@@ -979,10 +984,10 @@ def on_phase_start(self):
     def on_phase_end(self):
         self.log_phase_end("train")
 
-        logging.info("Syncing meters on phase end...")
+        logging.debug("Syncing meters on phase end...")
         for meter in self.meters:
             meter.sync_state()
-        logging.info("...meters synced")
+        logging.debug("...meters synced")
         barrier()
 
         for hook in self.hooks:
@@ -1016,3 +1021,10 @@ def log_phase_end(self, tag):
                 "im_per_sec": im_per_sec,
             }
         )
+
+    def __repr__(self):
+        if hasattr(self, "_config"):
+            config = json.dumps(self._config, indent=4)
+            return f"{super().__repr__()} initialized with config:\n{config}"
+
+        return super().__repr__()

test/hooks_loss_lr_meter_logging_hook_test.py

@@ -11,7 +11,7 @@
 from test.generic.config_utils import get_test_mlp_task_config, get_test_task_config
 from test.generic.hook_test_utils import HookTestBase
 
-from classy_vision.hooks import LossLrMeterLoggingHook
+from classy_vision.hooks import ClassyHook, LossLrMeterLoggingHook
 from classy_vision.optim.param_scheduler import UpdateInterval
 from classy_vision.tasks import ClassyTask, build_task
 from classy_vision.trainer import LocalTrainer
@@ -48,6 +48,8 @@ def test_logging(self, mock_get_rank: mock.MagicMock) -> None:
         config["dataset"]["test"]["batchsize_per_replica"] = 5
         task = build_task(config)
         task.prepare()
+        task.on_start()
+        task.on_phase_start()
 
         losses = [1.2, 2.3, 3.4, 4.5]
 
@@ -62,32 +64,25 @@ def test_logging(self, mock_get_rank: mock.MagicMock) -> None:
             # and _log_lr() is called after on_step() every log_freq batches
             # and after on_phase_end()
             with mock.patch.object(loss_lr_meter_hook, "_log_loss_meters") as mock_fn:
-                with mock.patch.object(loss_lr_meter_hook, "_log_lr") as mock_lr_fn:
-                    num_batches = 20
-
-                    for i in range(num_batches):
-                        task.losses = list(range(i))
-                        loss_lr_meter_hook.on_step(task)
-                        if log_freq is not None and i and i % log_freq == 0:
-                            mock_fn.assert_called_with(task)
-                            mock_fn.reset_mock()
-                            mock_lr_fn.assert_called_with(task)
-                            mock_lr_fn.reset_mock()
-                            continue
-                        mock_fn.assert_not_called()
-                        mock_lr_fn.assert_not_called()
-
-                    loss_lr_meter_hook.on_phase_end(task)
-                    mock_fn.assert_called_with(task)
-                    if task.train:
-                        mock_lr_fn.assert_called_with(task)
+                num_batches = 20
+
+                for i in range(num_batches):
+                    task.losses = list(range(i))
+                    loss_lr_meter_hook.on_step(task)
+                    if log_freq is not None and i and i % log_freq == 0:
+                        mock_fn.assert_called()
+                        mock_fn.reset_mock()
+                        continue
+                    mock_fn.assert_not_called()
+
+                loss_lr_meter_hook.on_phase_end(task)
+                mock_fn.assert_called()
 
             # test _log_loss_lr_meters()
             task.losses = losses
 
             with self.assertLogs():
                 loss_lr_meter_hook._log_loss_meters(task)
-                loss_lr_meter_hook._log_lr(task)
 
             task.phase_idx += 1
 
@@ -106,18 +101,21 @@ def scheduler_mock(where):
         task.optimizer.param_schedulers["lr"] = mock_lr_scheduler
         trainer = LocalTrainer()
 
-        # 2 LR updates per epoch
-        # At end of each epoch for train, LR is logged an additional time
-        lr_order = [0.0, 1 / 6, 1 / 6, 2 / 6, 3 / 6, 3 / 6, 4 / 6, 5 / 6, 5 / 6]
+        # 2 LR updates per epoch = 6
+        lr_order = [0.0, 1 / 6, 2 / 6, 3 / 6, 4 / 6, 5 / 6]
         lr_list = []
 
-        def mock_log_lr(task: ClassyTask) -> None:
-            lr_list.append(task.optimizer.parameters.lr)
+        class LRLoggingHook(ClassyHook):
+            on_end = ClassyHook._noop
+            on_phase_end = ClassyHook._noop
+            on_phase_start = ClassyHook._noop
+            on_start = ClassyHook._noop
+
+            def on_step(self, task):
+                if task.train:
+                    lr_list.append(task.optimizer.parameters.lr)
 
-        with mock.patch.object(
-            LossLrMeterLoggingHook, "_log_lr", side_effect=mock_log_lr
-        ):
-            hook = LossLrMeterLoggingHook(1)
-            task.set_hooks([hook])
-            trainer.train(task)
-            self.assertEqual(lr_list, lr_order)
+        hook = LRLoggingHook()
+        task.set_hooks([hook])
+        trainer.train(task)
+        self.assertEqual(lr_list, lr_order)