Log loading time of models and topklexicon at inference (#373)

sockeye/inference.py

@@ -18,6 +18,7 @@
 import json
 import logging
 import os
+import time
 from collections import defaultdict
 from functools import lru_cache, partial
 from typing import Callable, Dict, Generator, List, NamedTuple, Optional, Tuple, Union, Set
@@ -372,6 +373,8 @@ def load_models(context: mx.context.Context,
                                    restrict lexicon).
     :return: List of models, source vocabulary, target vocabulary, source factor vocabularies.
     """
+    logger.info("Loading %d model(s) from %s ...", len(model_folders), model_folders)
+    load_time_start = time.time()
     models = []  # type: List[InferenceModel]
     source_vocabs = []  # type: List[List[vocab.Vocab]]
     target_vocabs = []  # type: List[vocab.Vocab]
@@ -422,6 +425,8 @@ def load_models(context: mx.context.Context,
     for inference_model in models:
         inference_model.initialize(max_input_len, get_max_output_length)
 
+    load_time = time.time() - load_time_start
+    logger.info("%d model(s) loaded in %.4fs", len(models), load_time)
     return models, source_vocabs[0], target_vocabs[0]
 
 

sockeye/lexicon.py

@@ -16,6 +16,7 @@
 import operator
 import os
 import sys
+import time
 from typing import Dict, Generator, Tuple, Optional
 
 import mxnet as mx
@@ -244,6 +245,7 @@ def load(self, path: str, k: Optional[int] = None):
         :param path: Path to Numpy array file.
         :param k: Optionally load less items than stored in path.
         """
+        load_time_start = time.time()
         with open(path, 'rb') as inp:
             _lex = np.load(inp)
         loaded_k = _lex.shape[1]
@@ -257,7 +259,8 @@ def load(self, path: str, k: Optional[int] = None):
         self.lex = np.zeros((len(self.vocab_source), top_k), dtype=_lex.dtype)
         for src_id, trg_ids in enumerate(_lex):
             self.lex[src_id, :] = np.sort(trg_ids[:top_k])
-        logger.info("Loaded top-%d lexicon from \"%s\".", top_k, path)
+        load_time = time.time() - load_time_start
+        logger.info("Loaded top-%d lexicon from \"%s\" in %.4fs.", top_k, path, load_time)
 
     def get_trg_ids(self, src_ids: np.ndarray) -> np.ndarray:
         """