Instrument skill handlers and dialog rendering

docs/index.md

@@ -76,6 +76,7 @@ OVOSSkill                             ovos_workshop/skills/ovos.py
 | [intent-layers.md](intent-layers.md) | `IntentLayers` | Enable/disable intent sets at runtime |
 | [skill-launcher.md](skill-launcher.md) | `SkillLoader`, `PluginSkillLoader` | Loading skills as plugins or in standalone mode |
 | [permissions.md](permissions.md) | `ConverseMode`, `FallbackMode` | Converse and fallback permission modes |
+| [performance-metrics.md](performance-metrics.md) | runtime metrics | Skill-handler and dialog-rendering histogram boundaries |
 
 ---
 

docs/performance-metrics.md

@@ -0,0 +1,26 @@
+# Skill Runtime Performance Metrics
+
+`ovos-workshop` contributes two process-local histograms to a compatible
+`ovos-core` metrics endpoint through the `ovos.performance.metrics` entry-point
+group:
+
+| Metric | Boundary |
+|---|---|
+| `ovos_skill_handler_execution_seconds` | A registered skill handler with lifecycle metadata, including nested service calls and dialog work |
+| `ovos_dialog_render_seconds` | Mustache dialog rendering performed by `speak_dialog` or a `get_response` retry |
+
+Handler duration intentionally contains nested service-call and dialog-render
+duration. These histograms explain a request hierarchically and must not be
+summed as disjoint stages.
+
+Internal bus callbacks registered without handler lifecycle metadata are not
+counted as skill handlers. This keeps bus housekeeping from polluting the stage
+that operators use to explain user-visible reply latency.
+
+The histograms are fixed-cardinality and process-local. They do not contain
+skill IDs, session IDs, utterances, or other user-controlled labels. Prometheus
+should scrape each runtime process and aggregate the cumulative buckets before
+calculating p50 or p95.
+
+`ovos-workshop` does not open an HTTP port itself. Endpoint ownership remains in
+`ovos-core`, so standalone skills do not unexpectedly expose a listener.

ovos_workshop/_metrics.py

@@ -0,0 +1,89 @@
+"""Process-local latency histograms for skill execution and dialog rendering."""
+
+from __future__ import annotations
+
+import math
+import time
+from collections.abc import Iterable, Iterator, Mapping
+from contextlib import contextmanager
+from threading import Lock
+from typing import Any
+
+DEFAULT_BUCKETS_MS = (
+    1.0,
+    2.5,
+    5.0,
+    10.0,
+    25.0,
+    50.0,
+    100.0,
+    250.0,
+    500.0,
+    1_000.0,
+    2_500.0,
+    5_000.0,
+    10_000.0,
+    30_000.0,
+)
+
+
+class LatencyHistogram:
+    """Thread-safe cumulative latency histogram with fixed buckets."""
+
+    def __init__(self, name: str, *,
+                 buckets_ms: Iterable[float] = DEFAULT_BUCKETS_MS) -> None:
+        self.name = name
+        self._bounds = tuple(sorted(float(value) for value in buckets_ms))
+        self._buckets = [0] * len(self._bounds)
+        self._count = 0
+        self._sum_ms = 0.0
+        self._lock = Lock()
+
+    def observe_ms(self, elapsed_ms: float) -> None:
+        """Record one finite, non-negative duration in milliseconds."""
+        value = float(elapsed_ms)
+        if not math.isfinite(value):
+            raise ValueError("elapsed_ms must be finite")
+        value = max(0.0, value)
+        with self._lock:
+            self._count += 1
+            self._sum_ms += value
+            for index, bound in enumerate(self._bounds):
+                if value <= bound:
+                    self._buckets[index] += 1
+
+    @contextmanager
+    def measure(self) -> Iterator[None]:
+        """Observe the enclosed block, including exceptional exits."""
+        started = time.monotonic()
+        try:
+            yield
+        finally:
+            self.observe_ms((time.monotonic() - started) * 1_000)
+
+    def snapshot(self) -> Mapping[str, Any]:
+        """Return an immutable, JSON-friendly cumulative snapshot."""
+        with self._lock:
+            buckets = {
+                f"le_{bound:g}": count
+                for bound, count in zip(self._bounds, self._buckets)
+            }
+            buckets["inf"] = self._count
+            return {
+                "name": self.name,
+                "count": self._count,
+                "sum_ms": self._sum_ms,
+                "buckets": buckets,
+            }
+
+
+SKILL_HANDLER = LatencyHistogram("ovos_skill_handler_execution_ms")
+DIALOG_RENDER = LatencyHistogram("ovos_dialog_render_ms")
+
+
+def performance_histograms() -> Mapping[str, Mapping[str, Any]]:
+    """Return the process-local Workshop runtime histograms."""
+    return {
+        histogram.name: histogram.snapshot()
+        for histogram in (SKILL_HANDLER, DIALOG_RENDER)
+    }

ovos_workshop/skills/ovos.py

@@ -20,6 +20,7 @@
 import time
 import traceback
 from copy import copy
+from functools import wraps
 from hashlib import md5
 from inspect import signature
 from itertools import chain
@@ -61,6 +62,7 @@
 from ovos_yes_no import HeuristicYesNoEngine
 
 from ovos_workshop.decorators.killable import AbortEvent, killable_event, AbortQuestion
+from ovos_workshop._metrics import DIALOG_RENDER, SKILL_HANDLER
 from ovos_workshop.decorators.layers import IntentLayers
 from ovos_workshop.filesystem import FileSystemAccess
 from ovos_workshop.intents import IntentBuilder, Intent, IntentServiceInterface
@@ -1121,7 +1123,7 @@ def _handle_settings_file_change(self, path: str):
         @param path: Modified file path
         """
         if path != self._settings.path:
-            LOG.debug(f"Ignoring non-settings change")
+            LOG.debug("Ignoring non-settings change")
             return
         if self._settings:
             with self._settings_lock:
@@ -1682,7 +1684,8 @@ def speak_dialog(self, key: str, data: Optional[dict] = None,
         """
         if self.dialog_renderer:
             data = data or {}
-            utterance = self.dialog_renderer.render(key, data)
+            with DIALOG_RENDER.measure():
+                utterance = self.dialog_renderer.render(key, data)
             if render_callback is not None:
                 utterance = render_callback(utterance, self.lang)
             self.speak(
@@ -1839,11 +1842,13 @@ def on_fail_default(utterance):
             fail_data['utterance'] = utterance
             if on_fail:
                 if self.dialog_renderer:
-                    return self.dialog_renderer.render(on_fail, fail_data)
+                    with DIALOG_RENDER.measure():
+                        return self.dialog_renderer.render(on_fail, fail_data)
                 return on_fail
             else:
                 if self.dialog_renderer:
-                    return self.dialog_renderer.render(dialog, data)
+                    with DIALOG_RENDER.measure():
+                        return self.dialog_renderer.render(dialog, data)
                 return dialog
 
         def is_cancel(utterance):
@@ -2257,8 +2262,20 @@ def on_end(message):
             self._on_event_end(message, handler_info, skill_data,
                                is_intent=is_intent)
 
-        wrapper = create_wrapper(handler, self.skill_id, on_start, on_end,
-                                 on_error)
+        measured_handler = handler
+        if handler_info:
+            @wraps(handler)
+            def measured_handler(*args, **kwargs):
+                with SKILL_HANDLER.measure():
+                    return handler(*args, **kwargs)
+
+        wrapper = create_wrapper(
+            measured_handler,
+            self.skill_id,
+            on_start,
+            on_end,
+            on_error,
+        )
         return self.events.add(name, wrapper, once)
 
     def remove_event(self, name: str) -> bool:
@@ -2574,7 +2591,3 @@ def __init__(self, skill: OVOSSkill):
         ui_directories = get_ui_directories(skill.root_dir)
         GUIInterface.__init__(self, skill_id=skill_id, bus=bus, config=config,
                               ui_directories=ui_directories)
-
-
-
-

pyproject.toml

@@ -42,6 +42,9 @@ Repository = "https://github.com/OpenVoiceOS/OVOS-workshop"
 [project.scripts]
 ovos-skill-launcher = "ovos_workshop.skill_launcher:_launch_script"
 
+[project.entry-points."ovos.performance.metrics"]
+workshop = "ovos_workshop._metrics:performance_histograms"
+
 [tool.setuptools]
 include-package-data = true
 

test/unittests/test_runtime_metrics.py

@@ -0,0 +1,80 @@
+"""Runtime metric coverage for skill handlers and dialog rendering."""
+
+from unittest.mock import MagicMock, PropertyMock, patch
+
+from ovos_bus_client.message import Message
+from ovos_utils.events import EventContainer
+from ovos_utils.fakebus import FakeBus
+
+from ovos_workshop._metrics import DIALOG_RENDER, SKILL_HANDLER
+from ovos_workshop.skills.ovos import OVOSSkill
+
+
+def _skill() -> OVOSSkill:
+    skill = OVOSSkill.__new__(OVOSSkill)
+    skill.skill_id = "test.skill"
+    skill.bus = FakeBus()
+    skill.events = EventContainer(skill.bus)
+    skill.log = MagicMock()
+    skill._on_event_start = MagicMock()
+    skill._on_event_end = MagicMock()
+    skill._on_event_error = MagicMock()
+    return skill
+
+
+def test_handler_info_events_measure_handler_execution():
+    skill = _skill()
+    calls = MagicMock()
+
+    def handler(message):
+        calls(message)
+
+    before = SKILL_HANDLER.snapshot()["count"]
+    skill.add_event(
+        "test.intent",
+        handler,
+        handler_info="mycroft.skill.handler",
+        is_intent=True,
+    )
+
+    message = Message("test.intent")
+    skill.bus.emit(message)
+
+    calls.assert_called_once_with(message)
+    assert SKILL_HANDLER.snapshot()["count"] == before + 1
+
+
+def test_internal_events_do_not_pollute_skill_handler_metric():
+    skill = _skill()
+    before = SKILL_HANDLER.snapshot()["count"]
+
+    def handler(_message):
+        return None
+
+    skill.add_event("internal.event", handler)
+
+    skill.bus.emit(Message("internal.event"))
+
+    assert SKILL_HANDLER.snapshot()["count"] == before
+
+
+def test_speak_dialog_measures_only_renderer_work():
+    skill = _skill()
+    renderer = MagicMock()
+    renderer.render.return_value = "It is sunny."
+    skill.speak = MagicMock()
+    before = DIALOG_RENDER.snapshot()["count"]
+
+    with patch.object(
+        OVOSSkill,
+        "dialog_renderer",
+        new_callable=PropertyMock,
+        return_value=renderer,
+    ):
+        skill.speak_dialog("weather.answer", {"summary": "sunny"})
+
+    renderer.render.assert_called_once_with(
+        "weather.answer", {"summary": "sunny"}
+    )
+    skill.speak.assert_called_once()
+    assert DIALOG_RENDER.snapshot()["count"] == before + 1