diff --git a/docs/index.md b/docs/index.md index df6268b5..8a0ef7b1 100644 --- a/docs/index.md +++ b/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 | --- diff --git a/docs/performance-metrics.md b/docs/performance-metrics.md new file mode 100644 index 00000000..e3344666 --- /dev/null +++ b/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. diff --git a/ovos_workshop/_metrics.py b/ovos_workshop/_metrics.py new file mode 100644 index 00000000..dcdc19cc --- /dev/null +++ b/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) + } diff --git a/ovos_workshop/skills/ovos.py b/ovos_workshop/skills/ovos.py index f3610bc7..f57d1b5f 100644 --- a/ovos_workshop/skills/ovos.py +++ b/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) - - - - diff --git a/pyproject.toml b/pyproject.toml index 2c585932..e4d0c2f0 100644 --- a/pyproject.toml +++ b/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 diff --git a/test/unittests/test_runtime_metrics.py b/test/unittests/test_runtime_metrics.py new file mode 100644 index 00000000..f1d58934 --- /dev/null +++ b/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