Timing metrics and ovos-audio compat (#141)

* Update playback queue for improved ovos-audio compat.

* Add `get_tts` timing context

* Add `get_tts` timing context in `execute`

* Troubleshoot TTS stopwatch

* Add `get_tts` signature compatibility check

* Add log around compat. handling

* More helpful logging in legacy signature check

* Updated logging

---------

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

neon_audio/service.py

@@ -33,6 +33,7 @@
 from ovos_utils.log import LOG
 from neon_audio.tts import TTSFactory
 from neon_utils.messagebus_utils import get_messagebus
+from neon_utils.metrics_utils import Stopwatch
 from ovos_audio.service import PlaybackService
 
 ovos_audio.tts.TTSFactory = TTSFactory
@@ -60,6 +61,8 @@ def on_started():
 
 
 class NeonPlaybackService(PlaybackService):
+    _stopwatch = Stopwatch("get_tts")
+
     def __init__(self, ready_hook=on_ready, error_hook=on_error,
                  stopping_hook=on_stopping, alive_hook=on_alive,
                  started_hook=on_started, watchdog=lambda: None,
@@ -143,7 +146,10 @@ def handle_get_tts(self, message):
                     ident, data={"error": f"text is not a str: {text}"}))
                 return
             try:
-                responses = self.tts.get_multiple_tts(message)
+                with self._stopwatch:
+                    responses = self.tts.get_multiple_tts(message)
+                message.context.setdefault('timing', dict())
+                message.context['timing']['get_tts'] = self._stopwatch.time
                 LOG.debug(f"Emitting response: {responses}")
                 self.bus.emit(message.reply(ident, data=responses))
             except Exception as e:

neon_audio/tts/neon.py

@@ -40,9 +40,10 @@
 
 from neon_utils.file_utils import encode_file_to_base64_string
 from neon_utils.message_utils import resolve_message
+from neon_utils.metrics_utils import Stopwatch
 from neon_utils.signal_utils import create_signal, check_for_signal,\
     init_signal_bus
-from ovos_utils.log import LOG
+from ovos_utils.log import LOG, log_deprecation
 
 from ovos_config.config import Configuration
 
@@ -73,7 +74,7 @@ def get_requested_tts_languages(msg) -> list:
 
         # If multiple profiles attached to message, get TTS for all
         elif profiles:
-            LOG.info(f"Got profiles: {profiles}")
+            LOG.debug(f"Got profiles: {profiles}")
             for profile in profiles:
                 username = profile.get("user", {}).get("username")
                 lang_prefs = profile.get("speech") or dict()
@@ -105,9 +106,8 @@ def get_requested_tts_languages(msg) -> list:
 
         # General non-server response, use yml configuration
         else:
-            # TODO: Deprecate this clause
+            log_deprecation("speaker data or profile context required", "2.0.0")
             from neon_utils.configuration_utils import get_neon_user_config
-            LOG.error("No profile information with request")
             user_config = get_neon_user_config()["speech"]
             tts_reqs.append({"speaker": tts_name,
                              "language": user_config["tts_language"],
@@ -160,6 +160,7 @@ def _play(self):
 
 class WrappedTTS(TTS):
     def __new__(cls, base_engine, *args, **kwargs):
+        base_engine._stopwatch = Stopwatch("get_tts")
         base_engine.execute = cls.execute
         base_engine.get_multiple_tts = cls.get_multiple_tts
         # TODO: Below method is only to bridge compatibility
@@ -212,9 +213,10 @@ def _init_playback(self):
         TTS.playback.start()
 
     def _get_tts(self, sentence: str, request: dict = None, **kwargs):
+        # TODO: Signature should be made to match ovos-audio
         if any([x in inspect.signature(self.get_tts).parameters
                 for x in {"speaker", "wav_file"}]):
-            LOG.info("Legacy Neon TTS signature found")
+            LOG.info(f"Legacy Neon TTS signature found ({self.__class__.__name__})")
             key = str(hashlib.md5(
                 sentence.encode('utf-8', 'ignore')).hexdigest())
             file = kwargs.get("wav_file") or \
@@ -311,7 +313,10 @@ def execute(self, sentence: str, ident: str = None, listen: bool = False,
                 create_signal("isSpeaking")
             # TODO: Should sentence and ident be added to message context? DM
             message.data["text"] = sentence
-            responses = self.get_multiple_tts(message, **kwargs)
+            with self._stopwatch:
+                responses = self.get_multiple_tts(message, **kwargs)
+            message.context.setdefault('timing', dict())
+            message.context['timing']['get_tts'] = self._stopwatch.time
             LOG.debug(f"responses={responses}")
 
             ident = message.data.get('speak_ident') or ident
@@ -334,8 +339,7 @@ def execute(self, sentence: str, ident: str = None, listen: bool = False,
                         vis = self.viseme(r["phonemes"]) if r["phonemes"] \
                             else None
                         # queue for playback
-                        self.queue.put((self.audio_ext, wav_file, vis, ident,
-                                        listen))
+                        self.queue.put((wav_file, vis, listen, ident, message))
                         self.handle_metric({"metric_type": "tts.queued"})
         else:
             LOG.warning(f'no Message associated with TTS request: {ident}')