Mercurial > libervia-backend
changeset 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 | 402d31527af4 |
children | 2d59974a8e3e |
files | sat/core/xmpp.py |
diffstat | 1 files changed, 74 insertions(+), 15 deletions(-) [+] |
line wrap: on
line diff
--- a/sat/core/xmpp.py Sat Mar 04 18:30:47 2023 +0100 +++ b/sat/core/xmpp.py Sat Mar 04 22:21:28 2023 +0100 @@ -23,7 +23,7 @@ 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 @@ ## initialisation ## - @defer.inlineCallbacks - def _callConnectionTriggers(self): + async def _callConnectionTriggers(self, connection_timer): """Call conneting trigger prepare connected trigger @param plugins(iterable): plugins to use @@ -146,17 +145,23 @@ # 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 @@ """ 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 @@ 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 @@ # Call profileConnected callback for all plugins, # and print error message if any of them fails conn_cb_list = [] - for __, callback in plugin_conn_cb: - conn_cb_list.append(utils.asDeferred(callback, entity)) + for plugin, callback in plugin_conn_cb: + 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 @@ log.error(_("Plugins initialisation error")) for idx, (success, result) in enumerate(results): if not success: - log.error( - "error (plugin %(name)s): %(failure)s" - % { - "name": plugin_conn_cb[idx][0]._info["import_name"], - "failure": result, - } - ) + plugin_name = plugin_conn_cb[idx][0]._info["import_name"] + log.error(f"error (plugin {plugin_name}): {result}") + plugins_by_timer = sorted( + connection_timer, + 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