From 73e8a68002db06794d8bf312e8ad18f1f78a0e9f Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ga=C3=ABtan=20Trellu?= Date: Wed, 5 Aug 2026 19:23:08 -0400 Subject: [PATCH 1/4] perf: instrument skill handlers and dialog rendering --- docs/index.md | 1 + docs/performance-metrics.md | 26 ++++++++ ovos_workshop/_metrics.py | 89 ++++++++++++++++++++++++++ ovos_workshop/skills/ovos.py | 32 ++++++--- pyproject.toml | 3 + test/unittests/test_runtime_metrics.py | 80 +++++++++++++++++++++++ 6 files changed, 222 insertions(+), 9 deletions(-) create mode 100644 docs/performance-metrics.md create mode 100644 ovos_workshop/_metrics.py create mode 100644 test/unittests/test_runtime_metrics.py 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..02af8a5c 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: @@ -2575,6 +2592,3 @@ def __init__(self, skill: OVOSSkill): 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 From 93a6f44f9564eb56795a691341364757188953f1 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ga=C3=ABtan=20Trellu?= Date: Sun, 9 Aug 2026 07:26:40 -0400 Subject: [PATCH 2/4] feat: trace skill reply emission --- docs/performance-metrics.md | 7 ++ ovos_workshop/_performance_trace.py | 90 ++++++++++++++++++++++++++ ovos_workshop/skills/ovos.py | 41 +++++++----- test/unittests/test_runtime_metrics.py | 67 +++++++++++++++++++ 4 files changed, 188 insertions(+), 17 deletions(-) create mode 100644 ovos_workshop/_performance_trace.py diff --git a/docs/performance-metrics.md b/docs/performance-metrics.md index e3344666..69400d58 100644 --- a/docs/performance-metrics.md +++ b/docs/performance-metrics.md @@ -24,3 +24,10 @@ 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. + +For controlled benchmarks, `OVOS_PERFORMANCE_TRACE=true` also emits the +`skill_reply_emit` wall-clock boundary immediately before a correlated `speak` +message is placed on the bus. The structured event contains only `stage`, the +opaque request ID, and `at_unix_ns`. It is a log event rather than a metric, so +request IDs never become Prometheus labels. Tracing is disabled by default and +does not mutate the reply context. diff --git a/ovos_workshop/_performance_trace.py b/ovos_workshop/_performance_trace.py new file mode 100644 index 00000000..3f6c85f0 --- /dev/null +++ b/ovos_workshop/_performance_trace.py @@ -0,0 +1,90 @@ +"""Opt-in request-correlated skill trace events. + +Request identifiers are intentionally written only to structured trace logs; +they never become Prometheus labels or metric names. +""" + +from __future__ import annotations + +import json +import logging +import os +import time +from collections import deque +from typing import Any + +_LOG = logging.getLogger("ovos.performance.trace") +_TRUE_VALUES = {"1", "true", "yes", "on"} +_DIRECT_ID_KEYS = ("query_id", "request_id", "qa_query_id") +_NESTED_KEYS = ("context", "data", "metadata", "payload") +_MAX_REQUEST_ID_LENGTH = 256 +_MAX_SEARCH_NODES = 24 + + +def performance_trace_enabled() -> bool: + """Return whether request-correlated trace logging is enabled.""" + return os.environ.get( + "OVOS_PERFORMANCE_TRACE", "" + ).strip().lower() in _TRUE_VALUES + + +def message_request_id(message: Any) -> str | None: + """Extract one bounded explicit request ID from an OVOS message.""" + pending = deque([message]) + visited: set[int] = set() + searched = 0 + while pending and searched < _MAX_SEARCH_NODES: + candidate = pending.popleft() + if candidate is None: + continue + identity = id(candidate) + if identity in visited: + continue + visited.add(identity) + searched += 1 + + if isinstance(candidate, dict): + for key in _DIRECT_ID_KEYS: + value = candidate.get(key) + if isinstance(value, str) and value: + return value[:_MAX_REQUEST_ID_LENGTH] + pending.extend( + candidate.get(key) for key in _NESTED_KEYS + if key in candidate + ) + continue + + for key in _DIRECT_ID_KEYS: + value = getattr(candidate, key, None) + if isinstance(value, str) and value: + return value[:_MAX_REQUEST_ID_LENGTH] + pending.extend( + getattr(candidate, key, None) for key in _NESTED_KEYS + if hasattr(candidate, key) + ) + return None + + +def trace_performance_stage( + stage: str, + *, + message: Any = None, + request_id: str | None = None, + at_unix_ns: int | None = None, +) -> None: + """Log one timestamped stage for an explicitly correlated request.""" + if not performance_trace_enabled(): + return + identifier = request_id or message_request_id(message) + if not identifier: + return + event = { + "at_unix_ns": int(at_unix_ns if at_unix_ns is not None + else time.time_ns()), + "request_id": identifier[:_MAX_REQUEST_ID_LENGTH], + "stage": str(stage), + } + _LOG.info( + "performance_trace %s", + json.dumps(event, sort_keys=True, separators=(",", ":")), + ) diff --git a/ovos_workshop/skills/ovos.py b/ovos_workshop/skills/ovos.py index 02af8a5c..01829bb7 100644 --- a/ovos_workshop/skills/ovos.py +++ b/ovos_workshop/skills/ovos.py @@ -24,49 +24,56 @@ from hashlib import md5 from inspect import signature from itertools import chain -from os.path import join, abspath, dirname, basename, isfile +from os.path import abspath, basename, dirname, isfile, join from pathlib import Path from threading import Event, RLock -from typing import Dict, Callable, List, Optional, Union +from typing import Callable, Dict, List, Optional, Union from json_database import JsonStorage from ovos_bus_client import MessageBusClient -from ovos_gui_api_client import EnclosureAPI from ovos_bus_client.apis.events import EventSchedulerInterface from ovos_bus_client.apis.gui import GUIInterface from ovos_bus_client.apis.ocp import OCPInterface from ovos_bus_client.handler import HandlerLifecycle from ovos_bus_client.message import Message, dig_for_message -from ovos_bus_client.session import SessionManager, Session +from ovos_bus_client.session import Session, SessionManager from ovos_bus_client.util import get_message_lang -from ovos_spec_tools import SpecMessage, standardize_lang -from ovos_spec_tools.resources import read_resource_file from ovos_config.config import Configuration -from ovos_config.locations import get_xdg_cache_save_path -from ovos_config.locations import get_xdg_config_save_path +from ovos_config.locations import get_xdg_cache_save_path, get_xdg_config_save_path +from ovos_gui_api_client import EnclosureAPI from ovos_number_parser import pronounce_number from ovos_option_matcher_fuzzy import FuzzyOptionMatcherPlugin -from ovos_plugin_manager.agents import load_yesno_plugin, load_option_matcher_plugin -from ovos_plugin_manager.language import OVOSLangTranslationFactory, OVOSLangDetectionFactory -from ovos_plugin_manager.templates.agents import YesNoEngine, OptionMatcherEngine +from ovos_plugin_manager.agents import load_option_matcher_plugin, load_yesno_plugin +from ovos_plugin_manager.language import ( + OVOSLangDetectionFactory, + OVOSLangTranslationFactory, +) +from ovos_plugin_manager.templates.agents import OptionMatcherEngine, YesNoEngine +from ovos_spec_tools import SpecMessage, standardize_lang +from ovos_spec_tools.resources import read_resource_file from ovos_utils import camel_case_split, classproperty from ovos_utils.dialog import MustacheDialogRenderer -from ovos_utils.events import EventContainer, get_handler_name, create_wrapper +from ovos_utils.events import EventContainer, create_wrapper, get_handler_name from ovos_utils.file_utils import FileWatcher from ovos_utils.gui import get_ui_directories from ovos_utils.json_helper import merge_dict from ovos_utils.log import LOG -from ovos_utils.process_utils import ProcessStatus, StatusCallbackMap, RuntimeRequirements +from ovos_utils.process_utils import ( + ProcessStatus, + RuntimeRequirements, + StatusCallbackMap, +) from ovos_utils.skills import get_non_properties from ovos_utils.text_utils import remove_accents_and_punct 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._performance_trace import trace_performance_stage +from ovos_workshop.decorators.killable import AbortEvent, AbortQuestion, killable_event from ovos_workshop.decorators.layers import IntentLayers from ovos_workshop.filesystem import FileSystemAccess -from ovos_workshop.intents import IntentBuilder, Intent, IntentServiceInterface -from ovos_workshop.resource_files import ResourceFile, find_resource, SkillResources +from ovos_workshop.intents import Intent, IntentBuilder, IntentServiceInterface +from ovos_workshop.resource_files import ResourceFile, SkillResources, find_resource from ovos_workshop.settings import PrivateSettings from ovos_workshop.skills.util import join_word_list, simple_trace @@ -1644,6 +1651,7 @@ def speak(self, utterance: str, expect_response: bool = False, meta["translation_data"]) m.context["translation_data"] = tx_data + trace_performance_stage("skill_reply_emit", message=m) self.bus.emit(m) if wait: @@ -2591,4 +2599,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/test/unittests/test_runtime_metrics.py b/test/unittests/test_runtime_metrics.py index f1d58934..cc1b79c8 100644 --- a/test/unittests/test_runtime_metrics.py +++ b/test/unittests/test_runtime_metrics.py @@ -7,6 +7,11 @@ from ovos_utils.fakebus import FakeBus from ovos_workshop._metrics import DIALOG_RENDER, SKILL_HANDLER +from ovos_workshop._performance_trace import ( + message_request_id, + trace_performance_stage, +) +from ovos_workshop.skills import ovos as ovos_skill_module from ovos_workshop.skills.ovos import OVOSSkill @@ -78,3 +83,65 @@ def test_speak_dialog_measures_only_renderer_work(): ) skill.speak.assert_called_once() assert DIALOG_RENDER.snapshot()["count"] == before + 1 + + +def test_trace_extracts_nested_query_id(): + message = Message( + "speak", + {}, + {"metadata": {"qa_query_id": "request-skill"}}, + ) + + assert message_request_id(message) == "request-skill" + + +def test_speak_emits_correlated_stage_without_changing_message( + monkeypatch): + skill = _skill() + trigger = Message( + "test.intent", + {}, + {"query_id": "request-skill"}, + ) + traces = [] + emitted = [] + skill.bus.on("speak", emitted.append) + monkeypatch.setattr( + ovos_skill_module, + "dig_for_message", + lambda: trigger, + ) + monkeypatch.setattr( + ovos_skill_module, + "trace_performance_stage", + lambda stage, **values: traces.append(( + stage, + values["message"].context.get("query_id"), + set(values["message"].data), + )), + ) + + with patch.object( + OVOSSkill, + "lang", + new_callable=PropertyMock, + return_value="en-US", + ): + skill.speak("It is sunny.") + + assert len(emitted) == 1 + assert emitted[0].context["query_id"] == "request-skill" + assert traces == [( + "skill_reply_emit", + "request-skill", + {"utterance", "expect_response", "meta", "lang"}, + )] + + +def test_skill_trace_is_silent_without_opt_in(monkeypatch, caplog): + monkeypatch.delenv("OVOS_PERFORMANCE_TRACE", raising=False) + caplog.set_level("INFO", logger="ovos.performance.trace") + + trace_performance_stage("skill_reply_emit", request_id="request-silent") + + assert "request-silent" not in caplog.text From f6b016e74f3c9f0b3b2802623881fa01bf3e0312 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ga=C3=ABtan=20Trellu?= Date: Sun, 9 Aug 2026 07:58:41 -0400 Subject: [PATCH 3/4] fix: emit traces through service logger --- ovos_workshop/_performance_trace.py | 5 +++-- test/unittests/test_runtime_metrics.py | 11 +++++++---- 2 files changed, 10 insertions(+), 6 deletions(-) diff --git a/ovos_workshop/_performance_trace.py b/ovos_workshop/_performance_trace.py index 3f6c85f0..6fead86d 100644 --- a/ovos_workshop/_performance_trace.py +++ b/ovos_workshop/_performance_trace.py @@ -7,13 +7,14 @@ from __future__ import annotations import json -import logging import os import time from collections import deque from typing import Any -_LOG = logging.getLogger("ovos.performance.trace") +from ovos_utils.log import LOG + +_LOG = LOG _TRUE_VALUES = {"1", "true", "yes", "on"} _DIRECT_ID_KEYS = ("query_id", "request_id", "qa_query_id") _NESTED_KEYS = ("context", "data", "metadata", "payload") diff --git a/test/unittests/test_runtime_metrics.py b/test/unittests/test_runtime_metrics.py index cc1b79c8..995f9ab6 100644 --- a/test/unittests/test_runtime_metrics.py +++ b/test/unittests/test_runtime_metrics.py @@ -138,10 +138,13 @@ def test_speak_emits_correlated_stage_without_changing_message( )] -def test_skill_trace_is_silent_without_opt_in(monkeypatch, caplog): +def test_skill_trace_is_silent_without_opt_in(monkeypatch): monkeypatch.delenv("OVOS_PERFORMANCE_TRACE", raising=False) - caplog.set_level("INFO", logger="ovos.performance.trace") + log_info = MagicMock() + monkeypatch.setattr( + "ovos_workshop._performance_trace._LOG.info", + log_info, + ) trace_performance_stage("skill_reply_emit", request_id="request-silent") - - assert "request-silent" not in caplog.text + log_info.assert_not_called() From 9efd827ee6b3f29d31407f950f74019a46ca66a8 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ga=C3=ABtan=20Trellu?= Date: Sun, 9 Aug 2026 08:21:03 -0400 Subject: [PATCH 4/4] refactor: move reply tracing to bus boundary --- docs/performance-metrics.md | 7 -- ovos_workshop/_performance_trace.py | 91 -------------------------- ovos_workshop/skills/ovos.py | 40 +++++------ test/unittests/test_runtime_metrics.py | 70 -------------------- 4 files changed, 16 insertions(+), 192 deletions(-) delete mode 100644 ovos_workshop/_performance_trace.py diff --git a/docs/performance-metrics.md b/docs/performance-metrics.md index 69400d58..e3344666 100644 --- a/docs/performance-metrics.md +++ b/docs/performance-metrics.md @@ -24,10 +24,3 @@ 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. - -For controlled benchmarks, `OVOS_PERFORMANCE_TRACE=true` also emits the -`skill_reply_emit` wall-clock boundary immediately before a correlated `speak` -message is placed on the bus. The structured event contains only `stage`, the -opaque request ID, and `at_unix_ns`. It is a log event rather than a metric, so -request IDs never become Prometheus labels. Tracing is disabled by default and -does not mutate the reply context. diff --git a/ovos_workshop/_performance_trace.py b/ovos_workshop/_performance_trace.py deleted file mode 100644 index 6fead86d..00000000 --- a/ovos_workshop/_performance_trace.py +++ /dev/null @@ -1,91 +0,0 @@ -"""Opt-in request-correlated skill trace events. - -Request identifiers are intentionally written only to structured trace logs; -they never become Prometheus labels or metric names. -""" - -from __future__ import annotations - -import json -import os -import time -from collections import deque -from typing import Any - -from ovos_utils.log import LOG - -_LOG = LOG -_TRUE_VALUES = {"1", "true", "yes", "on"} -_DIRECT_ID_KEYS = ("query_id", "request_id", "qa_query_id") -_NESTED_KEYS = ("context", "data", "metadata", "payload") -_MAX_REQUEST_ID_LENGTH = 256 -_MAX_SEARCH_NODES = 24 - - -def performance_trace_enabled() -> bool: - """Return whether request-correlated trace logging is enabled.""" - return os.environ.get( - "OVOS_PERFORMANCE_TRACE", "" - ).strip().lower() in _TRUE_VALUES - - -def message_request_id(message: Any) -> str | None: - """Extract one bounded explicit request ID from an OVOS message.""" - pending = deque([message]) - visited: set[int] = set() - searched = 0 - while pending and searched < _MAX_SEARCH_NODES: - candidate = pending.popleft() - if candidate is None: - continue - identity = id(candidate) - if identity in visited: - continue - visited.add(identity) - searched += 1 - - if isinstance(candidate, dict): - for key in _DIRECT_ID_KEYS: - value = candidate.get(key) - if isinstance(value, str) and value: - return value[:_MAX_REQUEST_ID_LENGTH] - pending.extend( - candidate.get(key) for key in _NESTED_KEYS - if key in candidate - ) - continue - - for key in _DIRECT_ID_KEYS: - value = getattr(candidate, key, None) - if isinstance(value, str) and value: - return value[:_MAX_REQUEST_ID_LENGTH] - pending.extend( - getattr(candidate, key, None) for key in _NESTED_KEYS - if hasattr(candidate, key) - ) - return None - - -def trace_performance_stage( - stage: str, - *, - message: Any = None, - request_id: str | None = None, - at_unix_ns: int | None = None, -) -> None: - """Log one timestamped stage for an explicitly correlated request.""" - if not performance_trace_enabled(): - return - identifier = request_id or message_request_id(message) - if not identifier: - return - event = { - "at_unix_ns": int(at_unix_ns if at_unix_ns is not None - else time.time_ns()), - "request_id": identifier[:_MAX_REQUEST_ID_LENGTH], - "stage": str(stage), - } - _LOG.info( - "performance_trace %s", - json.dumps(event, sort_keys=True, separators=(",", ":")), - ) diff --git a/ovos_workshop/skills/ovos.py b/ovos_workshop/skills/ovos.py index 01829bb7..f57d1b5f 100644 --- a/ovos_workshop/skills/ovos.py +++ b/ovos_workshop/skills/ovos.py @@ -24,56 +24,49 @@ from hashlib import md5 from inspect import signature from itertools import chain -from os.path import abspath, basename, dirname, isfile, join +from os.path import join, abspath, dirname, basename, isfile from pathlib import Path from threading import Event, RLock -from typing import Callable, Dict, List, Optional, Union +from typing import Dict, Callable, List, Optional, Union from json_database import JsonStorage from ovos_bus_client import MessageBusClient +from ovos_gui_api_client import EnclosureAPI from ovos_bus_client.apis.events import EventSchedulerInterface from ovos_bus_client.apis.gui import GUIInterface from ovos_bus_client.apis.ocp import OCPInterface from ovos_bus_client.handler import HandlerLifecycle from ovos_bus_client.message import Message, dig_for_message -from ovos_bus_client.session import Session, SessionManager +from ovos_bus_client.session import SessionManager, Session from ovos_bus_client.util import get_message_lang +from ovos_spec_tools import SpecMessage, standardize_lang +from ovos_spec_tools.resources import read_resource_file from ovos_config.config import Configuration -from ovos_config.locations import get_xdg_cache_save_path, get_xdg_config_save_path -from ovos_gui_api_client import EnclosureAPI +from ovos_config.locations import get_xdg_cache_save_path +from ovos_config.locations import get_xdg_config_save_path from ovos_number_parser import pronounce_number from ovos_option_matcher_fuzzy import FuzzyOptionMatcherPlugin -from ovos_plugin_manager.agents import load_option_matcher_plugin, load_yesno_plugin -from ovos_plugin_manager.language import ( - OVOSLangDetectionFactory, - OVOSLangTranslationFactory, -) -from ovos_plugin_manager.templates.agents import OptionMatcherEngine, YesNoEngine -from ovos_spec_tools import SpecMessage, standardize_lang -from ovos_spec_tools.resources import read_resource_file +from ovos_plugin_manager.agents import load_yesno_plugin, load_option_matcher_plugin +from ovos_plugin_manager.language import OVOSLangTranslationFactory, OVOSLangDetectionFactory +from ovos_plugin_manager.templates.agents import YesNoEngine, OptionMatcherEngine from ovos_utils import camel_case_split, classproperty from ovos_utils.dialog import MustacheDialogRenderer -from ovos_utils.events import EventContainer, create_wrapper, get_handler_name +from ovos_utils.events import EventContainer, get_handler_name, create_wrapper from ovos_utils.file_utils import FileWatcher from ovos_utils.gui import get_ui_directories from ovos_utils.json_helper import merge_dict from ovos_utils.log import LOG -from ovos_utils.process_utils import ( - ProcessStatus, - RuntimeRequirements, - StatusCallbackMap, -) +from ovos_utils.process_utils import ProcessStatus, StatusCallbackMap, RuntimeRequirements from ovos_utils.skills import get_non_properties from ovos_utils.text_utils import remove_accents_and_punct 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._performance_trace import trace_performance_stage -from ovos_workshop.decorators.killable import AbortEvent, AbortQuestion, killable_event from ovos_workshop.decorators.layers import IntentLayers from ovos_workshop.filesystem import FileSystemAccess -from ovos_workshop.intents import Intent, IntentBuilder, IntentServiceInterface -from ovos_workshop.resource_files import ResourceFile, SkillResources, find_resource +from ovos_workshop.intents import IntentBuilder, Intent, IntentServiceInterface +from ovos_workshop.resource_files import ResourceFile, find_resource, SkillResources from ovos_workshop.settings import PrivateSettings from ovos_workshop.skills.util import join_word_list, simple_trace @@ -1651,7 +1644,6 @@ def speak(self, utterance: str, expect_response: bool = False, meta["translation_data"]) m.context["translation_data"] = tx_data - trace_performance_stage("skill_reply_emit", message=m) self.bus.emit(m) if wait: diff --git a/test/unittests/test_runtime_metrics.py b/test/unittests/test_runtime_metrics.py index 995f9ab6..f1d58934 100644 --- a/test/unittests/test_runtime_metrics.py +++ b/test/unittests/test_runtime_metrics.py @@ -7,11 +7,6 @@ from ovos_utils.fakebus import FakeBus from ovos_workshop._metrics import DIALOG_RENDER, SKILL_HANDLER -from ovos_workshop._performance_trace import ( - message_request_id, - trace_performance_stage, -) -from ovos_workshop.skills import ovos as ovos_skill_module from ovos_workshop.skills.ovos import OVOSSkill @@ -83,68 +78,3 @@ def test_speak_dialog_measures_only_renderer_work(): ) skill.speak.assert_called_once() assert DIALOG_RENDER.snapshot()["count"] == before + 1 - - -def test_trace_extracts_nested_query_id(): - message = Message( - "speak", - {}, - {"metadata": {"qa_query_id": "request-skill"}}, - ) - - assert message_request_id(message) == "request-skill" - - -def test_speak_emits_correlated_stage_without_changing_message( - monkeypatch): - skill = _skill() - trigger = Message( - "test.intent", - {}, - {"query_id": "request-skill"}, - ) - traces = [] - emitted = [] - skill.bus.on("speak", emitted.append) - monkeypatch.setattr( - ovos_skill_module, - "dig_for_message", - lambda: trigger, - ) - monkeypatch.setattr( - ovos_skill_module, - "trace_performance_stage", - lambda stage, **values: traces.append(( - stage, - values["message"].context.get("query_id"), - set(values["message"].data), - )), - ) - - with patch.object( - OVOSSkill, - "lang", - new_callable=PropertyMock, - return_value="en-US", - ): - skill.speak("It is sunny.") - - assert len(emitted) == 1 - assert emitted[0].context["query_id"] == "request-skill" - assert traces == [( - "skill_reply_emit", - "request-skill", - {"utterance", "expect_response", "meta", "lang"}, - )] - - -def test_skill_trace_is_silent_without_opt_in(monkeypatch): - monkeypatch.delenv("OVOS_PERFORMANCE_TRACE", raising=False) - log_info = MagicMock() - monkeypatch.setattr( - "ovos_workshop._performance_trace._LOG.info", - log_info, - ) - - trace_performance_stage("skill_reply_emit", request_id="request-silent") - log_info.assert_not_called()