Add timing for model loading and log duration

Author: sergioave

mlserver/server.py

@@ -1,6 +1,7 @@
 import asyncio
 import signal
 import logging
+import time
 
 from typing import Optional, List
 
@@ -122,12 +123,12 @@ async def start(self, models_settings: List[ModelSettings] = []):
         servers_task = asyncio.gather(*servers)
 
         try:
+            total_start: float = time.perf_counter()
             await asyncio.gather(
-                *[
-                    self._model_registry.load(model_settings)
-                    for model_settings in models_settings
-                ]
+                *[ self._timed_load(model_settings) for model_settings in models_settings ]
             )
+            total_duration: float = time.perf_counter() - total_start
+            logger.debug(f"Loaded {len(models_settings)} models in {total_duration:3f}s")
         except Exception:
             # If one of the models failed to load during startup, shutdown the
             # server gracefully
@@ -188,3 +189,14 @@ async def stop(self, sig: Optional[int] = None):
 
         if self._metrics_server:
             await self._metrics_server.stop(sig)
+
+    async def _timed_load(self, model_settings: ModelSettings) -> MLModel:
+        """
+            Load a model while measuring the elapsed time.
+        """
+        t0: float = time.perf_counter()
+        try:
+            return await self._model_registry.load(model_settings)
+        finally:
+            elapsed: float = time.perf_counter() - t0
+            logger.debug(F"Model {getattr(model_settings, 'name', '<unknown>')} loaded in {elapsed:3f}s")