Encapsulate time-related operations into training profiler

Author: jindrahelcl

neuralmonkey/learning_utils.py

@@ -12,14 +12,15 @@
 from termcolor import colored
 from typeguard import check_argument_types
 
-from neuralmonkey.logging import log, log_print, warn, notice
+from neuralmonkey.logging import log, log_print, warn
 from neuralmonkey.dataset import Dataset, BatchingScheme
 from neuralmonkey.tf_manager import TensorFlowManager
 from neuralmonkey.runners.base_runner import (
     BaseRunner, ExecutionResult, reduce_execution_results)
 from neuralmonkey.trainers.generic_trainer import GenericTrainer
 from neuralmonkey.trainers.multitask_trainer import MultitaskTrainer
 from neuralmonkey.trainers.delayed_update_trainer import DelayedUpdateTrainer
+from neuralmonkey.training_profiler import TrainingProfiler
 
 # pylint: disable=invalid-name
 Evaluation = Dict[str, float]
@@ -133,14 +134,12 @@ def training_loop(tf_manager: TensorFlowManager,
         log("TensorBoard writer initialized.")
 
     log("Starting training")
-    last_log_time = time.process_time()
-    last_val_time = time.process_time()
+    profiler = TrainingProfiler()
+    profiler.training_start()
+
     interrupt = None
     try:
         for epoch_n in range(1, epochs + 1):
-            log_print("")
-            log("Epoch {} begins".format(epoch_n), color="red")
-
             train_batches = train_dataset.batches(batching_scheme)
 
             if epoch_n == 1 and train_start_offset:
@@ -150,11 +149,15 @@ def training_loop(tf_manager: TensorFlowManager,
                 else:
                     _skip_lines(train_start_offset, train_batches)
 
+            log_print("")
+            log("Epoch {} begins".format(epoch_n), color="red")
+            profiler.epoch_start()
+
             for batch_n, batch in enumerate(train_batches):
                 step += 1
                 seen_instances += len(batch)
 
-                if log_timer(step, last_log_time):
+                if log_timer(step, profiler.last_log_time):
                     trainer_result = tf_manager.execute(
                         batch, feedables, trainers, train=True, summaries=True)
                     train_results, train_outputs = run_on_dataset(
@@ -172,14 +175,18 @@ def training_loop(tf_manager: TensorFlowManager,
                         tb_writer, main_metric, train_evaluation,
                         seen_instances, epoch_n, epochs, trainer_result,
                         train=True)
-                    last_log_time = time.process_time()
+
+                    profiler.log_done()
+
                 else:
                     tf_manager.execute(batch, feedables, trainers, train=True,
                                        summaries=False)
 
-                if val_timer(step, last_val_time):
+                if val_timer(step, profiler.last_val_time):
+
                     log_print("")
-                    val_duration_start = time.process_time()
+                    profiler.validation_start()
+
                     val_examples = 0
                     for val_id, valset in enumerate(val_datasets):
                         val_examples += len(valset)
@@ -243,24 +250,12 @@ def training_loop(tf_manager: TensorFlowManager,
                             seen_instances, epoch_n, epochs, val_results,
                             train=False, dataset_name=v_name)
 
-                    # how long was the training between validations
-                    training_duration = val_duration_start - last_val_time
-                    val_duration = time.process_time() - val_duration_start
-
-                    # the training should take at least twice the time of val.
-                    steptime = (training_duration
-                                / (seen_instances - last_seen_instances))
-                    valtime = val_duration / val_examples
+                    profiler.validation_done()
+                    profiler.log_after_validation(
+                        val_examples, seen_instances - last_seen_instances)
                     last_seen_instances = seen_instances
-                    log("Validation time: {:.2f}s, inter-validation: {:.2f}s, "
-                        "per-instance (train): {:.2f}s, per-instance (val): "
-                        "{:.2f}s".format(val_duration, training_duration,
-                                         steptime, valtime), color="blue")
-                    if training_duration < 2 * val_duration:
-                        notice("Validation period setting is inefficient.")
 
                     log_print("")
-                    last_val_time = time.process_time()
 
     except KeyboardInterrupt as ex:
         interrupt = ex

neuralmonkey/training_profiler.py

@@ -0,0 +1,81 @@
+# pylint: disable=unused-import
+from typing import List, Optional
+# pylint: enable=unused-import
+import time
+
+from neuralmonkey.logging import log, notice
+
+
+class TrainingProfiler:
+
+    def __init__(self) -> None:
+        self._start_time = None  # type: Optional[float]
+        self._epoch_starts = []  # type: List[float]
+
+        self._last_val_time = None  # type: Optional[float]
+        self._last_log_time = None  # type: Optional[float]
+        self._current_validation_start = None  # type: Optional[float]
+
+        self.inter_val_times = []  # type: List[float]
+        self.validation_times = []  # type: List[float]
+
+        self.time = time.process_time
+
+    @property
+    def start_time(self) -> float:
+        if self._start_time is None:
+            raise RuntimeError("Training did not start yet")
+        return self._start_time
+
+    @property
+    def last_log_time(self) -> float:
+        if self._last_log_time is None:
+            return self.start_time
+        return self._last_log_time
+
+    @property
+    def last_val_time(self) -> float:
+        if self._last_val_time is None:
+            return self.start_time
+        return self._last_val_time
+
+    def training_start(self) -> None:
+        self._start_time = self.time()
+
+    def epoch_start(self) -> None:
+        self._epoch_starts.append(self.time())
+
+    def log_done(self) -> None:
+        self._last_log_time = self.time()
+
+    def validation_start(self) -> None:
+        assert self._current_validation_start is None
+        self._current_validation_start = self.time()
+        self.inter_val_times.append(
+            self._current_validation_start - self.last_val_time)
+
+    def validation_done(self) -> None:
+        assert self._current_validation_start is not None
+        self._last_val_time = self.time()
+
+        self.validation_times.append(
+            self.last_val_time - self._current_validation_start)
+
+        self._current_validation_start = None
+
+    def log_after_validation(
+            self, val_examples: int, train_examples: int) -> None:
+
+        train_duration = self.inter_val_times[-1]
+        val_duration = self.validation_times[-1]
+
+        train_speed = train_examples / train_duration
+        val_speed = val_examples / val_duration
+
+        log("Validation time: {:.2f}s ({:.1f} instances/sec), "
+            "inter-validation: {:.2f}s, ({:.1f} instances/sec)"
+            .format(val_duration, val_speed, train_duration, train_speed),
+            color="blue")
+
+        if self.inter_val_times[-1] < 2 * self.validation_times[-1]:
+            notice("Validation period setting is inefficient.")