From bdf50b72879bc6caad30bbbb934ee58c4dc1c318 Mon Sep 17 00:00:00 2001 From: Daniel McKnight Date: Mon, 13 Nov 2023 11:56:39 -0800 Subject: [PATCH] More timing metrics and logging --- neon_iris/client.py | 9 +++++++-- neon_iris/web_client.py | 12 +++++++++--- 2 files changed, 16 insertions(+), 5 deletions(-) diff --git a/neon_iris/client.py b/neon_iris/client.py index ec34fbb..7e70b05 100644 --- a/neon_iris/client.py +++ b/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}") diff --git a/neon_iris/web_client.py b/neon_iris/web_client.py index 68a63e6..62339e4 100644 --- a/neon_iris/web_client.py +++ b/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}")