Repository: pytorch/ignite

Issue:
Insert logged times into state
## 🚀 Feature

By default, Engine measures times for single epoch and total run. These times are logged with `engine.logger`:
https://github.com/pytorch/ignite/blob/efc45a79ee0a5bf8105c3caff194758439db2426/ignite/engine/engine.py#L793-L796
and
https://github.com/pytorch/ignite/blob/efc45a79ee0a5bf8105c3caff194758439db2426/ignite/engine/engine.py#L497-L500

 Idea is to put these times (at least `time_taken` for epoch and total time) into `engine.state` under a name (e.g. "times"). Such that we can also use this information without need to use `Timer` or setup logger.

Discussion:
vfdev-5: @erip I think we should keep previous behavious about logging h,m,s times.

About the tests, I think we can just check the presence of values.
erip: You want to log the h,m,s times in the engine, but store the timestamp?
vfdev-5: > You want to log the h,m,s times in the engine, but store the timestamp?

Yes, I want to keep previous engine's behaviour and in addition to store the timestamp.
vfdev-5: Looking into this code now:
```python
                time_taken = self._run_once_on_dataset()
                self.state.times[Events.EPOCH_COMPLETED.name] = time_taken
                hours, mins, secs = _to_hours_mins_secs(time_taken)
                self.logger.info("Epoch[%s] Complete. Time taken: %02d:%02d:%02d", self.state.epoch, hours, mins, secs)
                if self.should_terminate:
                    break
                self._fire_event(Events.EPOCH_COMPLETED)
```
In case if `should_terminate` is True, we log and set the time of a completed epoch, but we do not trigger the event... I need to think if this is OK or we need to trigger the event...
vfdev-5: > Excellent. This initialization happens in the State constructor, but I forgot to remove this from the test; that said, I think that's slightly different than wiring up the event handler.

> Is there some place where it makes sense to wire this or is engine.run good enough?

Good point, we need to check what happens if we run multiple times evaluator and whether times are still correct. Do we need to include that into state dict (maybe not) ?

vfdev-5: And @erip I think it is déjàvu, are these values good for a single process and for DDP multi-process ?
erip: >we need to check what happens if we run multiple times 

Ok, I'll add another test. :)

> Do we need to include that into state dict?

Currently no. It's unclear if these would be useful in the state info. If they were, I imagine it would just be simple enough to (de)serialize the values.
vfdev-5: @erip thanks for the updates! Could you please update the docstring of `Engine` and show the usage in `examples/mnist/mnist.py`.
erip: Absolutely
erip: @vfdev-5 thanks for catching the missed TODO comments. Please let me know if there's anything else you want me to polish
vfdev-5: @erip I thinks we are good with this one. Could you, please, take a look at this issue : https://github.com/pytorch/ignite/issues/784
 with `Frequency` you worked previously ? 
erip: Are the tests normally this flaky? The failure seems unrelated, but I've seen the same test fail a few times.
vfdev-5: @erip OK, I understand now why tests are failing. In FastaiLRFiner tests we check that there is no more attached handlers, by default `Engine` has no internally attached handlers
```
    def test_with_attach(lr_finder, to_save, dummy_engine, dataloader):

        with lr_finder.attach(dummy_engine, to_save=to_save) as trainer_with_finder:
            trainer_with_finder.run(dataloader)

        assert lr_finder.get_results() is not None
        for event in dummy_engine._event_handlers:
>           assert len(dummy_engine._event_handlers[event]) == 0
```
and here we added `_init_timers` on started. Maybe we can call this method inside `run` and keep previous behaviour.

Patch:
diff --git a/examples/mnist/mnist.py b/examples/mnist/mnist.py
index 4a23028d..93886113 100644
--- a/examples/mnist/mnist.py
+++ b/examples/mnist/mnist.py
@@ -99,6 +99,12 @@ def run(train_batch_size, val_batch_size, epochs, lr, momentum, log_interval):
 
         pbar.n = pbar.last_print_n = 0
 
+    @trainer.on(Events.EPOCH_COMPLETED | Events.COMPLETED)
+    def log_time(engine):
+        tqdm.write(
+            "{} took {} seconds".format(trainer.last_event_name.name, trainer.state.times[trainer.last_event_name.name])
+        )
+
     trainer.run(train_loader, max_epochs=epochs)
     pbar.close()
 
diff --git a/ignite/engine/engine.py b/ignite/engine/engine.py
index b8a457f9..b6decfeb 100644
--- a/ignite/engine/engine.py
+++ b/ignite/engine/engine.py
@@ -433,7 +433,7 @@ class Engine:
         )
         self.should_terminate_single_epoch = True
 
-    def _run_once_on_dataset(self) -> Tuple[int, int, int]:
+    def _run_once_on_dataset(self) -> float:
         start_time = time.time()
 
         # We need to setup iter_counter > 0 if we resume from an iteration
@@ -497,10 +497,7 @@ class Engine:
             self.logger.error("Current run is terminating due to exception: %s.", str(e))
             self._handle_exception(e)
 
-        time_taken = time.time() - start_time
-        hours, mins, secs = _to_hours_mins_secs(time_taken)
-
-        return hours, mins, secs
+        return time.time() - start_time
 
     def _handle_exception(self, e: Exception) -> None:
         if Events.EXCEPTION_RAISED in self._event_handlers:
@@ -619,7 +616,8 @@ class Engine:
 
         Engine has a state and the following logic is applied in this function:
 
-        - At the first call, new state is defined by `max_epochs`, `epoch_length`, `seed` if provided.
+        - At the first call, new state is defined by `max_epochs`, `epoch_length`, `seed` if provided. A timer for
+            total and per-epoch time is initialized when Events.STARTED is handled.
         - If state is already defined such that there are iterations to run until `max_epochs` and no input arguments
             provided, state is kept and used in the function.
         - If state is defined and engine is "done" (no iterations to run until `max_epochs`), a new state is defined.
@@ -690,6 +688,11 @@ class Engine:
         self.state.dataloader = data
         return self._internal_run()
 
+    @staticmethod
+    def _init_timers(state: State):
+        state.times[Events.EPOCH_COMPLETED.name] = 0.0
+        state.times[Events.COMPLETED.name] = 0.0
+
     def _setup_engine(self) -> None:
 
         try:
@@ -775,6 +778,7 @@ class Engine:
 
     def _internal_run(self) -> State:
         self.should_terminate = self.should_terminate_single_epoch = False
+        self._init_timers(self.state)
         try:
             start_time = time.time()
             self._fire_event(Events.STARTED)
@@ -785,16 +789,18 @@ class Engine:
                 if self._dataloader_iter is None:
                     self._setup_engine()
 
-                hours, mins, secs = self._run_once_on_dataset()
-
+                time_taken = self._run_once_on_dataset()
+                self.state.times[Events.EPOCH_COMPLETED.name] = time_taken
+                hours, mins, secs = _to_hours_mins_secs(time_taken)
                 self.logger.info("Epoch[%s] Complete. Time taken: %02d:%02d:%02d", self.state.epoch, hours, mins, secs)
                 if self.should_terminate:
                     break
                 self._fire_event(Events.EPOCH_COMPLETED)
 
-            self._fire_event(Events.COMPLETED)
             time_taken = time.time() - start_time
             hours, mins, secs = _to_hours_mins_secs(time_taken)
+            self.state.times[Events.COMPLETED.name] = time_taken
+            self._fire_event(Events.COMPLETED)
             self.logger.info("Engine run complete. Time taken %02d:%02d:%02d" % (hours, mins, secs))
 
         except BaseException as e:
diff --git a/ignite/engine/events.py b/ignite/engine/events.py
index 7ebab19c..1e3de579 100644
--- a/ignite/engine/events.py
+++ b/ignite/engine/events.py
@@ -246,6 +246,8 @@ class State:
         state.batch             # batch passed to `process_function`
         state.output            # output of `process_function` after a single iteration
         state.metrics           # dictionary with defined metrics if any
+        state.times             # dictionary with total and per-epoch times fetched on
+                                # keys: Events.EPOCH_COMPLETED.name and Events.COMPLETED.name
 
     """
 
@@ -270,6 +272,7 @@ class State:
         self.metrics = {}
         self.dataloader = None
         self.seed = None
+        self.times = {Events.EPOCH_COMPLETED.name: None, Events.COMPLETED.name: None}
 
         for k, v in kwargs.items():
             setattr(self, k, v)


Test patch:
diff --git a/tests/ignite/engine/test_engine.py b/tests/ignite/engine/test_engine.py
index bd66f6dc..1d49728c 100644
--- a/tests/ignite/engine/test_engine.py
+++ b/tests/ignite/engine/test_engine.py
@@ -1,4 +1,5 @@
 import os
+import time
 import pytest
 from unittest.mock import call, MagicMock, Mock
 
@@ -366,6 +367,27 @@ def test_state_get_event_attrib_value():
     assert state.get_event_attrib_value(e) == state.epoch
 
 
+def test_time_stored_in_state():
+    def _test(data, max_epochs, epoch_length):
+        sleep_time = 0.01
+        engine = Engine(lambda e, b: time.sleep(sleep_time))
+
+        def check_epoch_time(engine):
+            assert engine.state.times[Events.EPOCH_COMPLETED.name] >= sleep_time * epoch_length
+
+        def check_completed_time(engine):
+            assert engine.state.times[Events.COMPLETED.name] >= sleep_time * epoch_length * max_epochs
+
+        engine.add_event_handler(Events.EPOCH_COMPLETED, lambda e: check_epoch_time(e))
+        engine.add_event_handler(Events.COMPLETED, lambda e: check_completed_time(e))
+
+        engine.run(data, max_epochs=max_epochs, epoch_length=epoch_length)
+
+    _test(list(range(100)), max_epochs=2, epoch_length=100)
+    _test(list(range(200)), max_epochs=2, epoch_length=100)
+    _test(list(range(200)), max_epochs=5, epoch_length=100)
+
+
 def _test_run_check_triggered_events():
     def _test(data, max_epochs, epoch_length):
         engine = Engine(lambda e, b: 1)