Mercurial > libervia-backend
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
3998:402d31527af4 | 3999:f7fa3993df28 |
---|---|
21 from functools import partial | 21 from functools import partial |
22 import mimetypes | 22 import mimetypes |
23 from pathlib import Path | 23 from pathlib import Path |
24 import sys | 24 import sys |
25 import time | 25 import time |
26 from typing import Tuple, Optional | 26 from typing import Callable, Dict, Tuple, Optional |
27 from urllib.parse import unquote, urlparse | 27 from urllib.parse import unquote, urlparse |
28 import uuid | 28 import uuid |
29 | 29 |
30 import shortuuid | 30 import shortuuid |
31 from twisted.internet import defer, error as internet_error | 31 from twisted.internet import defer, error as internet_error |
127 def __repr__(self): | 127 def __repr__(self): |
128 return f"{super().__repr__()} - profile: {self.profile!r}" | 128 return f"{super().__repr__()} - profile: {self.profile!r}" |
129 | 129 |
130 ## initialisation ## | 130 ## initialisation ## |
131 | 131 |
132 @defer.inlineCallbacks | 132 async def _callConnectionTriggers(self, connection_timer): |
133 def _callConnectionTriggers(self): | |
134 """Call conneting trigger prepare connected trigger | 133 """Call conneting trigger prepare connected trigger |
135 | 134 |
136 @param plugins(iterable): plugins to use | 135 @param plugins(iterable): plugins to use |
137 @return (list[object, callable]): plugin to trigger tuples with: | 136 @return (list[object, callable]): plugin to trigger tuples with: |
138 - plugin instance | 137 - plugin instance |
144 if plugin.is_handler: | 143 if plugin.is_handler: |
145 plugin.getHandler(self).setHandlerParent(self) | 144 plugin.getHandler(self).setHandlerParent(self) |
146 | 145 |
147 # profileConnecting/profileConnected methods handling | 146 # profileConnecting/profileConnected methods handling |
148 | 147 |
148 timer = connection_timer[plugin] = { | |
149 "total": 0 | |
150 } | |
149 # profile connecting is called right now (before actually starting client) | 151 # profile connecting is called right now (before actually starting client) |
150 connecting_cb = getattr(plugin, "profileConnecting", None) | 152 connecting_cb = getattr(plugin, "profileConnecting", None) |
151 if connecting_cb is not None: | 153 if connecting_cb is not None: |
152 yield utils.asDeferred(connecting_cb, self) | 154 connecting_start = time.time() |
155 await utils.asDeferred(connecting_cb, self) | |
156 timer["connecting"] = time.time() - connecting_start | |
157 timer["total"] += timer["connecting"] | |
153 | 158 |
154 # profile connected is called after client is ready and roster is got | 159 # profile connected is called after client is ready and roster is got |
155 connected_cb = getattr(plugin, "profileConnected", None) | 160 connected_cb = getattr(plugin, "profileConnected", None) |
156 if connected_cb is not None: | 161 if connected_cb is not None: |
157 plugin_conn_cb.append((plugin, connected_cb)) | 162 plugin_conn_cb.append((plugin, connected_cb)) |
158 | 163 |
159 defer.returnValue(plugin_conn_cb) | 164 return plugin_conn_cb |
160 | 165 |
161 def _getPluginsList(self): | 166 def _getPluginsList(self): |
162 """Return list of plugin to use | 167 """Return list of plugin to use |
163 | 168 |
164 need to be implemented by subclasses | 169 need to be implemented by subclasses |
174 """Called once connection is done | 179 """Called once connection is done |
175 | 180 |
176 may return a Deferred, to perform initialisation tasks | 181 may return a Deferred, to perform initialisation tasks |
177 """ | 182 """ |
178 return | 183 return |
184 | |
185 @staticmethod | |
186 async def _run_profile_connected( | |
187 callback: Callable, | |
188 entity: "SatXMPPEntity", | |
189 timer: Dict[str, float] | |
190 ) -> None: | |
191 connected_start = time.time() | |
192 await utils.asDeferred(callback, entity) | |
193 timer["connected"] = time.time() - connected_start | |
194 timer["total"] += timer["connected"] | |
179 | 195 |
180 @classmethod | 196 @classmethod |
181 async def startConnection(cls, host, profile, max_retries): | 197 async def startConnection(cls, host, profile, max_retries): |
182 """instantiate the entity and start the connection""" | 198 """instantiate the entity and start the connection""" |
183 # FIXME: reconnection doesn't seems to be handled correclty | 199 # FIXME: reconnection doesn't seems to be handled correclty |
256 entity.identityHandler = SatIdentityHandler() | 272 entity.identityHandler = SatIdentityHandler() |
257 entity.identityHandler.setHandlerParent(entity) | 273 entity.identityHandler.setHandlerParent(entity) |
258 | 274 |
259 log.debug(_("setting plugins parents")) | 275 log.debug(_("setting plugins parents")) |
260 | 276 |
261 plugin_conn_cb = await entity._callConnectionTriggers() | 277 connection_timer: Dict[str, Dict[str, float]] = {} |
278 plugin_conn_cb = await entity._callConnectionTriggers(connection_timer) | |
262 | 279 |
263 entity.startService() | 280 entity.startService() |
264 | 281 |
265 await entity.conn_deferred | 282 await entity.conn_deferred |
266 | 283 |
267 await defer.maybeDeferred(entity.entityConnected) | 284 await defer.maybeDeferred(entity.entityConnected) |
268 | 285 |
269 # Call profileConnected callback for all plugins, | 286 # Call profileConnected callback for all plugins, |
270 # and print error message if any of them fails | 287 # and print error message if any of them fails |
271 conn_cb_list = [] | 288 conn_cb_list = [] |
272 for __, callback in plugin_conn_cb: | 289 for plugin, callback in plugin_conn_cb: |
273 conn_cb_list.append(utils.asDeferred(callback, entity)) | 290 conn_cb_list.append( |
291 defer.ensureDeferred( | |
292 cls._run_profile_connected( | |
293 callback, entity, connection_timer[plugin] | |
294 ) | |
295 ) | |
296 ) | |
274 list_d = defer.DeferredList(conn_cb_list) | 297 list_d = defer.DeferredList(conn_cb_list) |
275 | 298 |
276 def logPluginResults(results): | 299 def logPluginResults(results): |
277 all_succeed = all([success for success, result in results]) | 300 all_succeed = all([success for success, result in results]) |
278 if not all_succeed: | 301 if not all_succeed: |
279 log.error(_("Plugins initialisation error")) | 302 log.error(_("Plugins initialisation error")) |
280 for idx, (success, result) in enumerate(results): | 303 for idx, (success, result) in enumerate(results): |
281 if not success: | 304 if not success: |
282 log.error( | 305 plugin_name = plugin_conn_cb[idx][0]._info["import_name"] |
283 "error (plugin %(name)s): %(failure)s" | 306 log.error(f"error (plugin {plugin_name}): {result}") |
284 % { | 307 plugins_by_timer = sorted( |
285 "name": plugin_conn_cb[idx][0]._info["import_name"], | 308 connection_timer, |
286 "failure": result, | 309 key=lambda p: connection_timer[p]["total"], |
287 } | 310 reverse=True |
288 ) | 311 ) |
312 log.debug(f"Plugin loading time for {profile!r} (longer to shorter):\n") | |
313 # total is the addition of all connecting and connected, doesn't really | |
314 # reflect the real loading time as connected are launched in a | |
315 # DeferredList | |
316 total_plugins = 0 | |
317 # total real sum all connecting (which happen sequentially) and the | |
318 # longuest connected (connected happen in parallel, thus the longuest is | |
319 # roughly the total time for connected) | |
320 total_real = 0 | |
321 total_real_first_connected = False | |
322 | |
323 for plugin in plugins_by_timer: | |
324 name = plugin._info["import_name"] | |
325 timer = connection_timer[plugin] | |
326 total_plugins += timer["total"] | |
327 try: | |
328 connecting = f"{timer['connecting']:.2f}s" | |
329 except KeyError: | |
330 connecting = "n/a" | |
331 else: | |
332 total_real += timer["connecting"] | |
333 try: | |
334 connected = f"{timer['connected']:.2f}s" | |
335 except KeyError: | |
336 connected = "n/a" | |
337 else: | |
338 if not total_real_first_connected: | |
339 total_real += timer['connected'] | |
340 total_real_first_connected = True | |
341 log.debug( | |
342 f" - {name}: total={timer['total']:.2f}s " | |
343 f"connecting={connecting} connected={connected}" | |
344 ) | |
345 log.debug( | |
346 f" Plugins total={total_plugins:.2f}s real={total_real:.2f}s\n" | |
347 ) | |
289 | 348 |
290 await list_d.addCallback( | 349 await list_d.addCallback( |
291 logPluginResults | 350 logPluginResults |
292 ) # FIXME: we should have a timeout here, and a way to know if a plugin freeze | 351 ) # FIXME: we should have a timeout here, and a way to know if a plugin freeze |
293 # TODO: mesure launch time of each plugin | 352 # TODO: mesure launch time of each plugin |