libervia-backend: sat/core/xmpp.py comparison

comparison sat/core/xmpp.py @ 3999:f7fa3993df28

core: add debug trace to show plugins loading time

author	Goffi <goffi@goffi.org>
date	Sat, 04 Mar 2023 22:21:28 +0100
parents	993cc8e56aef
children	2d59974a8e3e

comparison

equal deleted inserted replaced

-:402d31527af4
+:f7fa3993df28
 from functools import partial
 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
 import shortuuid
 from twisted.internet import defer, error as internet_error
 def __repr__(self):
 return f"{super().__repr__()} - profile: {self.profile!r}"
 ## initialisation ##
-@defer.inlineCallbacks
+async def _callConnectionTriggers(self, connection_timer):
-def _callConnectionTriggers(self):
 """Call conneting trigger prepare connected trigger
 @param plugins(iterable): plugins to use
 @return (list[object, callable]): plugin to trigger tuples with:
 - plugin instance
 if plugin.is_handler:
 plugin.getHandler(self).setHandlerParent(self)
 # 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
 need to be implemented by subclasses
 """Called once connection is done
 may return a Deferred, to perform initialisation tasks
 """
 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"""
 # FIXME: reconnection doesn't seems to be handled correclty
 entity.identityHandler = SatIdentityHandler()
 entity.identityHandler.setHandlerParent(entity)
 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()
 await entity.conn_deferred
 await defer.maybeDeferred(entity.entityConnected)
 # 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):
 all_succeed = all([success for success, result in results])
 if not all_succeed:
 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
 )  # FIXME: we should have a timeout here, and a way to know if a plugin freeze
 # TODO: mesure launch time of each plugin

Mercurial > libervia-backend

comparison sat/core/xmpp.py @ 3999:f7fa3993df28