core: add debug trace to show plugins loading time

sat/core/xmpp.py

@@ -23,7 +23,7 @@ import mimetypes
 from pathlib import Path
 import sys
 import time
-from typing import Tuple, Optional
+from typing import Callable, Dict, Tuple, Optional
 from urllib.parse import unquote, urlparse
 import uuid
 
@@ -129,8 +129,7 @@ class SatXMPPEntity(core_types.SatXMPPEntity):
 
     ## initialisation ##
 
-    @defer.inlineCallbacks
+    async def _callConnectionTriggers(self, connection_timer):
-    def _callConnectionTriggers(self):
         """Call conneting trigger prepare connected trigger
 
         @param plugins(iterable): plugins to use
@@ -146,17 +145,23 @@ class SatXMPPEntity(core_types.SatXMPPEntity):
 
             # profileConnecting/profileConnected methods handling
 
+            timer = connection_timer[plugin] = {
+                "total": 0
+            }
             # profile connecting is called right now (before actually starting client)
             connecting_cb = getattr(plugin, "profileConnecting", None)
             if connecting_cb is not None:
-                yield utils.asDeferred(connecting_cb, self)
+                connecting_start = time.time()
+                await utils.asDeferred(connecting_cb, self)
+                timer["connecting"] = time.time() - connecting_start
+                timer["total"] += timer["connecting"]
 
             # profile connected is called after client is ready and roster is got
             connected_cb = getattr(plugin, "profileConnected", None)
             if connected_cb is not None:
                 plugin_conn_cb.append((plugin, connected_cb))
 
-        defer.returnValue(plugin_conn_cb)
+        return plugin_conn_cb
 
     def _getPluginsList(self):
         """Return list of plugin to use
@@ -177,6 +182,17 @@ class SatXMPPEntity(core_types.SatXMPPEntity):
         """
         return
 
+    @staticmethod
+    async def _run_profile_connected(
+        callback: Callable,
+        entity: "SatXMPPEntity",
+        timer: Dict[str, float]
+    ) -> None:
+        connected_start = time.time()
+        await utils.asDeferred(callback, entity)
+        timer["connected"] = time.time() - connected_start
+        timer["total"] += timer["connected"]
+
     @classmethod
     async def startConnection(cls, host, profile, max_retries):
         """instantiate the entity and start the connection"""
@@ -258,7 +274,8 @@ class SatXMPPEntity(core_types.SatXMPPEntity):
 
             log.debug(_("setting plugins parents"))
 
-            plugin_conn_cb = await entity._callConnectionTriggers()
+            connection_timer: Dict[str, Dict[str, float]] = {}
+            plugin_conn_cb = await entity._callConnectionTriggers(connection_timer)
 
             entity.startService()
 
@@ -269,8 +286,14 @@ class SatXMPPEntity(core_types.SatXMPPEntity):
             # Call profileConnected callback for all plugins,
             # and print error message if any of them fails
             conn_cb_list = []
-            for __, callback in plugin_conn_cb:
+            for plugin, callback in plugin_conn_cb:
-                conn_cb_list.append(utils.asDeferred(callback, entity))
+                conn_cb_list.append(
+                    defer.ensureDeferred(
+                        cls._run_profile_connected(
+                            callback, entity, connection_timer[plugin]
+                        )
+                    )
+                )
             list_d = defer.DeferredList(conn_cb_list)
 
             def logPluginResults(results):
@@ -279,13 +302,49 @@ class SatXMPPEntity(core_types.SatXMPPEntity):
                     log.error(_("Plugins initialisation error"))
                     for idx, (success, result) in enumerate(results):
                         if not success:
-                            log.error(
+                            plugin_name = plugin_conn_cb[idx][0]._info["import_name"]
-                                "error (plugin %(name)s): %(failure)s"
+                            log.error(f"error (plugin {plugin_name}): {result}")
-                                % {
+                plugins_by_timer = sorted(
-                                    "name": plugin_conn_cb[idx][0]._info["import_name"],
+                    connection_timer,
-                                    "failure": result,
+                    key=lambda p: connection_timer[p]["total"],
-                                }
+                    reverse=True
-                            )
+                )
+                log.debug(f"Plugin loading time for {profile!r} (longer to shorter):\n")
+                # total is the addition of all connecting and connected, doesn't really
+                # reflect the real loading time as connected are launched in a
+                # DeferredList
+                total_plugins = 0
+                # total real sum all connecting (which happen sequentially) and the
+                # longuest connected (connected happen in parallel, thus the longuest is
+                # roughly the total time for connected)
+                total_real = 0
+                total_real_first_connected = False
+
+                for plugin in plugins_by_timer:
+                    name = plugin._info["import_name"]
+                    timer = connection_timer[plugin]
+                    total_plugins += timer["total"]
+                    try:
+                        connecting = f"{timer['connecting']:.2f}s"
+                    except KeyError:
+                        connecting = "n/a"
+                    else:
+                        total_real += timer["connecting"]
+                    try:
+                        connected = f"{timer['connected']:.2f}s"
+                    except KeyError:
+                        connected = "n/a"
+                    else:
+                        if not total_real_first_connected:
+                            total_real += timer['connected']
+                            total_real_first_connected = True
+                    log.debug(
+                        f"  - {name}: total={timer['total']:.2f}s "
+                        f"connecting={connecting} connected={connected}"
+                    )
+                log.debug(
+                    f"  Plugins total={total_plugins:.2f}s real={total_real:.2f}s\n"
+                )
 
             await list_d.addCallback(
                 logPluginResults