More timing metrics and logging

neon_iris/client.py

@@ -41,6 +41,7 @@
 from ovos_utils.json_helper import merge_dict
 from pika.exceptions import StreamLostError
 from neon_utils.configuration_utils import get_neon_user_config
+from neon_utils.metrics_utils import Stopwatch
 from neon_utils.mq_utils import NeonMQHandler
 from neon_utils.socket_utils import b64_to_dict
 from neon_utils.file_utils import decode_base64_string_to_file, \
@@ -49,6 +50,8 @@
 from ovos_utils.xdg_utils import xdg_config_home, xdg_cache_home
 from ovos_config.config import Configuration
 
+_stopwatch = Stopwatch()
+
 
 class NeonAIClient:
     def __init__(self, mq_config: dict = None, config_dir: str = None):
@@ -129,7 +132,9 @@ def handle_neon_response(self, channel, method, _, body):
         """
         channel.basic_ack(delivery_tag=method.delivery_tag)
         recv_time = time()
-        response = b64_to_dict(body)
+        with _stopwatch:
+            response = b64_to_dict(body)
+        LOG.debug(f"Message deserialized in {_stopwatch.time}s")
         message = Message(response.get('msg_type'), response.get('data'),
                           response.get('context'))
 
@@ -139,7 +144,7 @@ def handle_neon_response(self, channel, method, _, body):
         if recv_time != resp_time:
             transit_time = recv_time - resp_time
             message.context['timing']['mq_from_core'] = transit_time
-            LOG.debug(f"Response MQ time={transit_time}")
+            LOG.debug(f"Response MQ transit time={transit_time}")
         handling_time = recv_time - message.context['timing'].get('client_sent',
                                                                   recv_time)
         LOG.info(f"{message.msg_type} handled in {handling_time}")

neon_iris/web_client.py

@@ -27,7 +27,7 @@
 from os import makedirs
 from os.path import isfile, join, isdir
 from time import time
-from typing import List, Optional, Dict
+from typing import List, Dict
 from uuid import uuid4
 
 import gradio
@@ -124,10 +124,12 @@ def on_user_input(self, utterance: str, *args, **kwargs) -> str:
         @param utterance: String utterance submitted by the user
         @returns: String response from Neon (or "ERROR")
         """
+        input_time = time()
         LOG.debug(f"Input received")
         if not self._await_response.wait(30):
             LOG.error("Previous response not completed after 30 seconds")
         LOG.debug(f"args={args}|kwargs={kwargs}")
+        in_queue = time() - input_time
         self._await_response.clear()
         self._response = None
         gradio_id = args[2]
@@ -136,12 +138,16 @@ def on_user_input(self, utterance: str, *args, **kwargs) -> str:
             LOG.info(f"Sending utterance: {utterance} with lang: {lang}")
             self.send_utterance(utterance, lang, username=gradio_id,
                                 user_profiles=[self._profiles[gradio_id]],
-                                context={"gradio": {"session": gradio_id}})
+                                context={"gradio": {"session": gradio_id},
+                                         "timing": {"wait_in_queue": in_queue,
+                                                    "gradio_sent": time()}})
         else:
             LOG.info(f"Sending audio: {args[1]} with lang: {lang}")
             self.send_audio(args[1], lang, username=gradio_id,
                             user_profiles=[self._profiles[gradio_id]],
-                            context={"gradio": {"session": gradio_id}})
+                            context={"gradio": {"session": gradio_id},
+                                     "timing": {"wait_in_queue": in_queue,
+                                                "gradio_sent": time()}})
         self._await_response.wait(30)
         self._response = self._response or "ERROR"
         LOG.info(f"Got response={self._response}")