Mercurial > libervia-backend
comparison sat/core/xmpp.py @ 4000:2d59974a8e3e
core (xmpp): improve pluging timing log by using highest `profileConnected` time:
previously the first `profileConnected` time was used, however it may not be the highest
(if `profileConnecting` is high but not `profileConnected`).
| author | Goffi <goffi@goffi.org> |
|---|---|
| date | Fri, 10 Mar 2023 17:01:09 +0100 |
| parents | f7fa3993df28 |
| children | 412b99c29d83 |
comparison
equal
deleted
inserted
replaced
| 3999:f7fa3993df28 | 4000:2d59974a8e3e |
|---|---|
| 295 ) | 295 ) |
| 296 ) | 296 ) |
| 297 list_d = defer.DeferredList(conn_cb_list) | 297 list_d = defer.DeferredList(conn_cb_list) |
| 298 | 298 |
| 299 def logPluginResults(results): | 299 def logPluginResults(results): |
| 300 if not results: | |
| 301 log.info("no plugin loaded") | |
| 302 return | |
| 300 all_succeed = all([success for success, result in results]) | 303 all_succeed = all([success for success, result in results]) |
| 301 if not all_succeed: | 304 if not all_succeed: |
| 302 log.error(_("Plugins initialisation error")) | 305 log.error(_("Plugins initialisation error")) |
| 303 for idx, (success, result) in enumerate(results): | 306 for idx, (success, result) in enumerate(results): |
| 304 if not success: | 307 if not success: |
| 305 plugin_name = plugin_conn_cb[idx][0]._info["import_name"] | 308 plugin_name = plugin_conn_cb[idx][0]._info["import_name"] |
| 306 log.error(f"error (plugin {plugin_name}): {result}") | 309 log.error(f"error (plugin {plugin_name}): {result}") |
| 310 | |
| 311 log.debug(f"Plugin loading time for {profile!r} (longer to shorter):\n") | |
| 307 plugins_by_timer = sorted( | 312 plugins_by_timer = sorted( |
| 308 connection_timer, | 313 connection_timer, |
| 309 key=lambda p: connection_timer[p]["total"], | 314 key=lambda p: connection_timer[p]["total"], |
| 310 reverse=True | 315 reverse=True |
| 311 ) | 316 ) |
| 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 | 317 # total is the addition of all connecting and connected, doesn't really |
| 314 # reflect the real loading time as connected are launched in a | 318 # reflect the real loading time as connected are launched in a |
| 315 # DeferredList | 319 # DeferredList |
| 316 total_plugins = 0 | 320 total_plugins = 0 |
| 317 # total real sum all connecting (which happen sequentially) and the | 321 # total real sum all connecting (which happen sequentially) and the |
| 318 # longuest connected (connected happen in parallel, thus the longuest is | 322 # longuest connected (connected happen in parallel, thus the longuest is |
| 319 # roughly the total time for connected) | 323 # roughly the total time for connected) |
| 320 total_real = 0 | 324 total_real = 0 |
| 321 total_real_first_connected = False | 325 total_real = max(t.get("connected", 0) for t in connection_timer.values()) |
| 322 | 326 |
| 323 for plugin in plugins_by_timer: | 327 for plugin in plugins_by_timer: |
| 324 name = plugin._info["import_name"] | 328 name = plugin._info["import_name"] |
| 325 timer = connection_timer[plugin] | 329 timer = connection_timer[plugin] |
| 326 total_plugins += timer["total"] | 330 total_plugins += timer["total"] |
| 332 total_real += timer["connecting"] | 336 total_real += timer["connecting"] |
| 333 try: | 337 try: |
| 334 connected = f"{timer['connected']:.2f}s" | 338 connected = f"{timer['connected']:.2f}s" |
| 335 except KeyError: | 339 except KeyError: |
| 336 connected = "n/a" | 340 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( | 341 log.debug( |
| 342 f" - {name}: total={timer['total']:.2f}s " | 342 f" - {name}: total={timer['total']:.2f}s " |
| 343 f"connecting={connecting} connected={connected}" | 343 f"connecting={connecting} connected={connected}" |
| 344 ) | 344 ) |
| 345 log.debug( | 345 log.debug( |