Updates for better timing metrics (#574)

Co-authored-by: Daniel McKnight <[email protected]>

neon_core/skills/intent_service.py

@@ -170,40 +170,44 @@ def handle_utterance(self, message):
         Arguments:
             message (Message): message associated with user request
         """
+        utt_received = time.time()
 
         # Notify emitting module that skills is handling this utterance
         self.bus.emit(message.response())
 
+        # Add or init timing data
+        message.context.setdefault("timing", dict())
+        message.context["timing"]["handle_utterance"] = utt_received
+        if message.context["timing"].get("client_sent") and \
+                not message.context["timing"].get("client_to_core"):
+            message.context["timing"]["client_to_core"] = \
+                utt_received - message.context["timing"]["client_sent"]
+
         try:
-            requested_lang = message.data.get('lang')
             # Get language of the utterance
+            requested_lang = message.data.get('lang')
             lang = get_full_lang_code(
                 message.data.get('lang') or self.language_config["user"])
             if requested_lang and \
                     requested_lang.split('-')[0] != lang.split('-')[0]:
                 lang = get_full_lang_code(requested_lang.split('-')[0])
                 LOG.warning(f"requested={requested_lang}|resolved={lang}")
-
             message.data["lang"] = lang
             LOG.debug(f"message_lang={lang}")
-            # Add or init timing data
-            message.context = message.context or {}
-            if not message.context.get("timing"):
-                LOG.debug("No timing data available at intent service")
-                message.context["timing"] = {}
-            message.context["timing"]["handle_utterance"] = time.time()
+        except Exception as e:
+            LOG.exception(e)
+            if '-' not in message.data.get("lang", ""):
+                raise RuntimeError(f"Full `lang` code not in message.data: "
+                                   f"{message.data}")
+            lang = message.data["lang"]
 
+        try:
             # Ensure user profile data is present
             if "user_profiles" not in message.context:
                 message.context["user_profiles"] = [self._default_user.content]
                 message.context["username"] = \
                     self._default_user.content["user"]["username"]
 
-            # Make sure there is a `transcribed` timestamp
-            if not message.context["timing"].get("transcribed"):
-                message.context["timing"]["transcribed"] = \
-                    message.context["timing"]["handle_utterance"]
-
             stopwatch = Stopwatch()
 
             # TODO: Consider saving transcriptions after text parsers cleanup
@@ -217,7 +221,9 @@ def handle_utterance(self, message):
             # Get text parser context
             with stopwatch:
                 message = self._get_parsers_service_context(message, lang)
+            # TODO: `text_parsers` timing context left for backwards-compat.
             message.context["timing"]["text_parsers"] = stopwatch.time
+            message.context["timing"]["transform_utterance"] = stopwatch.time
 
             # Normalize all utterances for intent engines
             message.data['utterances'] = [u.lower().strip() for u in
@@ -226,17 +232,15 @@ def handle_utterance(self, message):
 
             # Catch empty utterances after parser service
             if len(message.data['utterances']) == 0:
-                LOG.debug("Received empty utterance!!")
-                reply = \
-                    message.reply('intent_aborted',
-                                  {'utterances': message.data.get('utterances',
-                                                                  []),
-                                   'lang': lang})
+                LOG.info("Received empty utterance!")
+                reply = message.reply('intent_aborted',
+                                      {'utterances': message.data['utterances'],
+                                       'lang': lang})
                 self.bus.emit(reply)
                 return
 
-            if message.data["lang"].split('-')[0] in self.supported_languages:
-                LOG.debug(f'Native language support ({message.data["lang"]})')
+            if lang.split('-')[0] in self.supported_languages:
+                LOG.debug(f'Native language support ({lang})')
                 if message.context.get("translation_data") and \
                     message.context.get("translation_data")[0].get(
                         "was_translated"):

requirements/core_modules.txt

@@ -1,6 +1,6 @@
 # neon core modules
-neon_messagebus~=1.1
+neon_messagebus~=1.1,>=1.1.1a5
 neon_enclosure~=1.6
-neon_speech~=4.2
+neon_speech~=4.2,>=4.2.1a3
 neon_gui~=1.2,>=1.2.2
 neon_audio~=1.4

requirements/requirements.txt

@@ -6,8 +6,7 @@ ovos-plugin-common-play~=0.0.5
 # utils
 neon-utils[network]~=1.7
 ovos-utils~=0.0.35
-ovos-bus-client==0.0.5
-# TODO: Above pinned to reduce logs from ovos-core 0.0.7 with ovos-bus-client 0.0.6
+ovos-bus-client~=0.0.5
 neon-transformers~=0.2
 ovos-config~=0.0.11
 ovos-plugin-manager~=0.0.24
@@ -24,7 +23,7 @@ mock~=5.0
 # default plugins
 neon-lang-plugin-libretranslate~=0.2
 neon-utterance-translator-plugin~=0.1,>=0.1.2a2
-neon-utterance-normalizer-plugin~=0.0.2
+neon-utterance-normalizer-plugin~=0.0.2,>=0.0.3a4
 
 # TODO: Patching test failures https://github.com/NeonGeckoCom/NeonCore/actions/runs/4888865255/jobs/8727164992?pr=422
 requests < 2.30.0