Files
2026-07-13 12:24:33 +08:00

782 lines
24 KiB
Python

# SPDX-License-Identifier: Apache-2.0
"""Tests for MPServerTracingSubscriber."""
# Standard
from unittest.mock import patch
import time
# Third Party
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import SimpleSpanProcessor
from opentelemetry.sdk.trace.export.in_memory_span_exporter import InMemorySpanExporter
import pytest
# First Party
from lmcache.v1.mp_observability.event import Event, EventType
from lmcache.v1.mp_observability.event_bus import EventBus, EventBusConfig
from lmcache.v1.mp_observability.subscribers.tracing import (
MPServerTracingSubscriber,
)
from lmcache.v1.mp_observability.subscribers.tracing.span_registry import (
SpanRegistry,
)
import lmcache.v1.mp_observability.subscribers.tracing.mp_server as mp_server_module
@pytest.fixture
def bus():
return EventBus(EventBusConfig(enabled=True, max_queue_size=100))
@pytest.fixture
def registry():
return SpanRegistry()
@pytest.fixture
def subscriber(registry, bus):
sub = MPServerTracingSubscriber(registry)
bus.register_subscriber(sub)
return sub
class TestMPServerTracingSubscriber:
def test_subscriptions_cover_all_mp_server_events(self, subscriber):
subs = subscriber.get_subscriptions()
assert EventType.MP_REQUEST_START in subs
assert EventType.MP_STORE_SUBMITTED in subs
assert EventType.MP_RETRIEVE_SUBMITTED in subs
assert EventType.MP_REQUEST_END in subs
assert EventType.MP_STORE_START in subs
assert EventType.MP_STORE_END in subs
assert EventType.MP_RETRIEVE_START in subs
assert EventType.MP_RETRIEVE_END in subs
assert EventType.MP_LOOKUP_PREFETCH_START in subs
assert EventType.MP_LOOKUP_PREFETCH_END in subs
# ------------------------------------------------------------------
# Root span creation
# ------------------------------------------------------------------
def test_root_span_created_on_request_start(self, bus, registry, subscriber):
bus.start()
bus.publish(Event(event_type=EventType.MP_REQUEST_START, session_id="req-root"))
time.sleep(0.15)
assert registry.get("req-root", "request") is not None
bus.stop()
def test_no_root_span_before_any_event(self, registry):
assert registry.get("any-session", "request") is None
# ------------------------------------------------------------------
# Session-end closes root immediately when no stores in flight
# ------------------------------------------------------------------
def test_session_end_closes_root_immediately_when_no_store(
self, bus, registry, subscriber
):
bus.start()
now = time.time()
bus.publish(
Event(
event_type=EventType.MP_REQUEST_START,
session_id="req-lookup-only",
timestamp=now,
)
)
bus.publish(
Event(
event_type=EventType.MP_LOOKUP_PREFETCH_START,
session_id="req-lookup-only",
timestamp=now + 0.001,
)
)
bus.publish(
Event(
event_type=EventType.MP_LOOKUP_PREFETCH_END,
session_id="req-lookup-only",
timestamp=now + 0.010,
metadata={"found_count": 4},
)
)
bus.publish(
Event(
event_type=EventType.MP_REQUEST_END,
session_id="req-lookup-only",
timestamp=now + 0.020,
)
)
time.sleep(0.15)
bus.stop()
assert registry.get("req-lookup-only", "request") is None
assert "req-lookup-only" not in subscriber._pending_store_count
assert len(subscriber._pending) == 0
# ------------------------------------------------------------------
# Deferred close: SESSION_END races GPU store
# ------------------------------------------------------------------
def test_session_end_deferred_until_store_finishes(self, bus, registry, subscriber):
bus.start()
now = time.time()
sid = "req-deferred"
bus.publish(
Event(
event_type=EventType.MP_REQUEST_START,
session_id=sid,
timestamp=now,
)
)
bus.publish(
Event(
event_type=EventType.MP_STORE_SUBMITTED,
session_id=sid,
timestamp=now + 0.001,
)
)
# SESSION_END arrives before STORE_END
bus.publish(
Event(
event_type=EventType.MP_REQUEST_END,
session_id=sid,
timestamp=now + 0.005,
)
)
time.sleep(0.15)
# Root should still be open (store in flight)
assert registry.get(sid, "request") is not None
assert sid in subscriber._deferred_session_end_ts
# Now GPU store completes
bus.publish(
Event(
event_type=EventType.MP_STORE_START,
session_id=sid,
timestamp=now + 0.010,
metadata={"device": "cuda:0"},
)
)
bus.publish(
Event(
event_type=EventType.MP_STORE_END,
session_id=sid,
timestamp=now + 0.050,
metadata={"stored_count": 2, "device": "cuda:0"},
)
)
time.sleep(0.15)
bus.stop()
# Root should now be closed
assert registry.get(sid, "request") is None
assert sid not in subscriber._deferred_session_end_ts
assert sid not in subscriber._pending_store_count
# ------------------------------------------------------------------
# Multiple stores: root stays open until all complete
# ------------------------------------------------------------------
def test_multiple_stores_all_must_finish(self, bus, registry, subscriber):
bus.start()
now = time.time()
sid = "req-multi-store"
bus.publish(
Event(
event_type=EventType.MP_REQUEST_START,
session_id=sid,
timestamp=now,
)
)
bus.publish(
Event(
event_type=EventType.MP_STORE_SUBMITTED,
session_id=sid,
timestamp=now + 0.001,
)
)
bus.publish(
Event(
event_type=EventType.MP_STORE_SUBMITTED,
session_id=sid,
timestamp=now + 0.002,
)
)
bus.publish(
Event(
event_type=EventType.MP_REQUEST_END,
session_id=sid,
timestamp=now + 0.005,
)
)
time.sleep(0.15)
# count=2 — still open
assert registry.get(sid, "request") is not None
# First store ends — count=1, still open
bus.publish(
Event(
event_type=EventType.MP_STORE_START,
session_id=sid,
timestamp=now + 0.010,
metadata={"device": "cuda:0"},
)
)
bus.publish(
Event(
event_type=EventType.MP_STORE_END,
session_id=sid,
timestamp=now + 0.030,
metadata={"stored_count": 1, "device": "cuda:0"},
)
)
time.sleep(0.15)
assert registry.get(sid, "request") is not None
# Second store ends — count=0, closes now
bus.publish(
Event(
event_type=EventType.MP_STORE_START,
session_id=sid,
timestamp=now + 0.040,
metadata={"device": "cuda:0"},
)
)
bus.publish(
Event(
event_type=EventType.MP_STORE_END,
session_id=sid,
timestamp=now + 0.060,
metadata={"stored_count": 1, "device": "cuda:0"},
)
)
time.sleep(0.15)
bus.stop()
assert registry.get(sid, "request") is None
assert sid not in subscriber._pending_store_count
# ------------------------------------------------------------------
# Lazy root creation on store-only path (no lookup)
# ------------------------------------------------------------------
def test_lazy_root_on_store_only_path(self, bus, registry, subscriber):
bus.start()
now = time.time()
sid = "req-store-only"
# No MP_REQUEST_START — root created lazily on MP_STORE_START
bus.publish(
Event(
event_type=EventType.MP_STORE_SUBMITTED,
session_id=sid,
timestamp=now,
)
)
bus.publish(
Event(
event_type=EventType.MP_STORE_START,
session_id=sid,
timestamp=now + 0.001,
metadata={"device": "cuda:0"},
)
)
time.sleep(0.15)
assert registry.get(sid, "request") is not None
bus.publish(
Event(
event_type=EventType.MP_STORE_END,
session_id=sid,
timestamp=now + 0.020,
metadata={"stored_count": 3, "device": "cuda:0"},
)
)
bus.publish(
Event(
event_type=EventType.MP_REQUEST_END,
session_id=sid,
timestamp=now + 0.025,
)
)
time.sleep(0.15)
bus.stop()
assert registry.get(sid, "request") is None
# ------------------------------------------------------------------
# Retrieve deferral: SESSION_END races GPU retrieve
# ------------------------------------------------------------------
def test_session_end_deferred_until_retrieve_finishes(
self, bus, registry, subscriber
):
bus.start()
now = time.time()
sid = "req-deferred-retrieve"
bus.publish(
Event(
event_type=EventType.MP_REQUEST_START,
session_id=sid,
timestamp=now,
)
)
bus.publish(
Event(
event_type=EventType.MP_RETRIEVE_SUBMITTED,
session_id=sid,
timestamp=now + 0.001,
)
)
# SESSION_END arrives before RETRIEVE_END (the race condition)
bus.publish(
Event(
event_type=EventType.MP_REQUEST_END,
session_id=sid,
timestamp=now + 0.005,
)
)
time.sleep(0.15)
# Root should still be open (retrieve in flight)
assert registry.get(sid, "request") is not None
assert sid in subscriber._deferred_session_end_ts
# Now GPU retrieve completes
bus.publish(
Event(
event_type=EventType.MP_RETRIEVE_START,
session_id=sid,
timestamp=now + 0.010,
metadata={"device": "cuda:0"},
)
)
bus.publish(
Event(
event_type=EventType.MP_RETRIEVE_END,
session_id=sid,
timestamp=now + 0.050,
metadata={"retrieved_count": 4, "device": "cuda:0"},
)
)
time.sleep(0.15)
bus.stop()
# Root should now be closed
assert registry.get(sid, "request") is None
assert sid not in subscriber._deferred_session_end_ts
assert sid not in subscriber._pending_retrieve_count
def test_session_end_deferred_until_both_store_and_retrieve_finish(
self, bus, registry, subscriber
):
"""Root span stays open until both a store and a retrieve finish."""
bus.start()
now = time.time()
sid = "req-store-and-retrieve"
bus.publish(
Event(
event_type=EventType.MP_REQUEST_START,
session_id=sid,
timestamp=now,
)
)
bus.publish(
Event(
event_type=EventType.MP_STORE_SUBMITTED,
session_id=sid,
timestamp=now + 0.001,
)
)
bus.publish(
Event(
event_type=EventType.MP_RETRIEVE_SUBMITTED,
session_id=sid,
timestamp=now + 0.002,
)
)
bus.publish(
Event(
event_type=EventType.MP_REQUEST_END,
session_id=sid,
timestamp=now + 0.005,
)
)
time.sleep(0.15)
# Both in flight — root still open
assert registry.get(sid, "request") is not None
# Store finishes first — retrieve still pending, root stays open
bus.publish(
Event(
event_type=EventType.MP_STORE_START,
session_id=sid,
timestamp=now + 0.010,
metadata={"device": "cuda:0"},
)
)
bus.publish(
Event(
event_type=EventType.MP_STORE_END,
session_id=sid,
timestamp=now + 0.030,
metadata={"stored_count": 1, "device": "cuda:0"},
)
)
time.sleep(0.15)
assert registry.get(sid, "request") is not None
# Retrieve finishes — now both counters are zero → root closes
bus.publish(
Event(
event_type=EventType.MP_RETRIEVE_START,
session_id=sid,
timestamp=now + 0.040,
metadata={"device": "cuda:0"},
)
)
bus.publish(
Event(
event_type=EventType.MP_RETRIEVE_END,
session_id=sid,
timestamp=now + 0.060,
metadata={"retrieved_count": 2, "device": "cuda:0"},
)
)
time.sleep(0.15)
bus.stop()
assert registry.get(sid, "request") is None
assert sid not in subscriber._deferred_session_end_ts
# ------------------------------------------------------------------
# Child spans registered in shared registry for sub-span parenting
# ------------------------------------------------------------------
def test_retrieve_span_registered_in_registry_while_open(
self, bus, registry, subscriber
):
"""An open mp.retrieve span is accessible in the registry under
``span_name="retrieve"`` so that a future sub-span subscriber can
look it up as a parent."""
bus.start()
bus.publish(
Event(
event_type=EventType.MP_RETRIEVE_START,
session_id="req-reg",
metadata={"device": "cuda:0"},
)
)
time.sleep(0.15)
assert registry.get("req-reg", "retrieve") is not None
bus.stop()
def test_retrieve_span_deregistered_after_close(self, bus, registry, subscriber):
"""Registry entry is cleaned up when mp.retrieve ends so stale
contexts do not leak into subsequent requests."""
bus.start()
bus.publish(
Event(
event_type=EventType.MP_RETRIEVE_START,
session_id="req-reg2",
metadata={"device": "cuda:0"},
)
)
bus.publish(
Event(
event_type=EventType.MP_RETRIEVE_END,
session_id="req-reg2",
metadata={"device": "cuda:0", "retrieved_count": 1},
)
)
time.sleep(0.15)
bus.stop()
assert registry.get("req-reg2", "retrieve") is None
# ------------------------------------------------------------------
# Existing lifecycle tests (unchanged behaviour)
# ------------------------------------------------------------------
def test_store_span_lifecycle(self, bus, subscriber):
bus.start()
bus.publish(
Event(
event_type=EventType.MP_STORE_START,
session_id="req-1",
metadata={"device": "cuda:0"},
)
)
bus.publish(
Event(
event_type=EventType.MP_STORE_END,
session_id="req-1",
metadata={"device": "cuda:0", "stored_count": 5},
)
)
time.sleep(0.15)
bus.stop()
assert len(subscriber._pending) == 0
def test_retrieve_span_lifecycle(self, bus, subscriber):
bus.start()
bus.publish(
Event(
event_type=EventType.MP_RETRIEVE_START,
session_id="req-2",
metadata={"device": "cuda:1"},
)
)
bus.publish(
Event(
event_type=EventType.MP_RETRIEVE_END,
session_id="req-2",
metadata={"device": "cuda:1", "retrieved_count": 3},
)
)
time.sleep(0.15)
bus.stop()
assert len(subscriber._pending) == 0
def test_lookup_prefetch_span_lifecycle(self, bus, subscriber):
bus.start()
bus.publish(
Event(
event_type=EventType.MP_LOOKUP_PREFETCH_START,
session_id="req-3",
)
)
bus.publish(
Event(
event_type=EventType.MP_LOOKUP_PREFETCH_END,
session_id="req-3",
metadata={"found_count": 10},
)
)
time.sleep(0.15)
bus.stop()
assert len(subscriber._pending) == 0
def test_unmatched_end_does_not_crash(self, bus, subscriber):
bus.start()
bus.publish(
Event(
event_type=EventType.MP_STORE_END,
session_id="orphan",
metadata={"stored_count": 1, "device": "cuda:0"},
)
)
time.sleep(0.15)
bus.stop()
assert len(subscriber._pending) == 0
def test_unmatched_start_cleaned_on_shutdown(self, bus, subscriber):
bus.start()
bus.publish(
Event(
event_type=EventType.MP_STORE_START,
session_id="leaked",
metadata={"device": "cuda:0"},
)
)
time.sleep(0.15)
bus.stop()
subscriber.shutdown()
assert len(subscriber._pending) == 0
def test_multiple_concurrent_sessions(self, bus, subscriber):
bus.start()
for i in range(5):
bus.publish(
Event(
event_type=EventType.MP_STORE_START,
session_id=f"req-{i}",
metadata={"device": "cuda:0"},
)
)
for i in range(5):
bus.publish(
Event(
event_type=EventType.MP_STORE_END,
session_id=f"req-{i}",
metadata={"device": "cuda:0", "stored_count": i},
)
)
time.sleep(0.15)
bus.stop()
assert len(subscriber._pending) == 0
class TestHitRateAttributes:
"""Verify hit_tokens / requested_tokens / hit_rate are set on the root span.
Uses a real OTel TracerProvider backed by InMemorySpanExporter so that span
attributes are actually recorded. The module-level ``_tracer`` is patched
for the duration of each test; ``_HAS_OTEL`` is forced True so that the
handlers don't early-return.
"""
@pytest.fixture
def exporter(self):
"""Real OTel provider with in-memory exporter; patches module tracer."""
exp = InMemorySpanExporter()
provider = TracerProvider()
provider.add_span_processor(SimpleSpanProcessor(exp))
real_tracer = provider.get_tracer("lmcache_mp.server")
with (
patch.object(mp_server_module, "_tracer", real_tracer),
patch.object(mp_server_module, "_HAS_OTEL", True),
):
yield exp
exp.shutdown()
def _root_span(self, exporter: InMemorySpanExporter, sid: str):
"""Return the finished root span for *sid*, or None."""
for span in exporter.get_finished_spans():
if span.name == "request" and span.attributes.get("session_id") == sid:
return span
return None
def test_hit_rate_attrs_set_on_root_span(self, exporter):
"""LP_END with hit_tokens=512, requested_tokens=1024 → hit_rate=0.5."""
bus = EventBus(EventBusConfig(enabled=True, max_queue_size=100))
registry = SpanRegistry()
bus.register_subscriber(MPServerTracingSubscriber(registry))
bus.start()
now = time.time()
sid = "req-hr-normal"
bus.publish(
Event(event_type=EventType.MP_REQUEST_START, session_id=sid, timestamp=now)
)
bus.publish(
Event(
event_type=EventType.MP_LOOKUP_PREFETCH_START,
session_id=sid,
timestamp=now + 0.001,
)
)
bus.publish(
Event(
event_type=EventType.MP_LOOKUP_PREFETCH_END,
session_id=sid,
timestamp=now + 0.010,
metadata={
"hit_tokens": 512,
"requested_tokens": 1024,
"found_count": 2,
},
)
)
bus.publish(
Event(
event_type=EventType.MP_REQUEST_END,
session_id=sid,
timestamp=now + 0.020,
)
)
time.sleep(0.15)
bus.stop()
root = self._root_span(exporter, sid)
assert root is not None
assert root.attributes["hit_tokens"] == 512
assert root.attributes["requested_tokens"] == 1024
assert abs(root.attributes["hit_rate"] - 0.5) < 1e-9
def test_hit_rate_zero_when_requested_tokens_is_zero(self, exporter):
"""LP_END with requested_tokens=0 yields hit_rate=0.0 without error."""
bus = EventBus(EventBusConfig(enabled=True, max_queue_size=100))
registry = SpanRegistry()
bus.register_subscriber(MPServerTracingSubscriber(registry))
bus.start()
now = time.time()
sid = "req-hr-zero"
bus.publish(
Event(event_type=EventType.MP_REQUEST_START, session_id=sid, timestamp=now)
)
bus.publish(
Event(
event_type=EventType.MP_LOOKUP_PREFETCH_START,
session_id=sid,
timestamp=now + 0.001,
)
)
bus.publish(
Event(
event_type=EventType.MP_LOOKUP_PREFETCH_END,
session_id=sid,
timestamp=now + 0.010,
metadata={"hit_tokens": 0, "requested_tokens": 0, "found_count": 0},
)
)
bus.publish(
Event(
event_type=EventType.MP_REQUEST_END,
session_id=sid,
timestamp=now + 0.020,
)
)
time.sleep(0.15)
bus.stop()
root = self._root_span(exporter, sid)
assert root is not None
assert root.attributes["hit_tokens"] == 0
assert root.attributes["requested_tokens"] == 0
assert root.attributes["hit_rate"] == 0.0
def test_no_hit_rate_attrs_on_store_only_path(self, exporter):
"""Store-only request (no LP_END) leaves root span without hit rate attrs."""
bus = EventBus(EventBusConfig(enabled=True, max_queue_size=100))
registry = SpanRegistry()
bus.register_subscriber(MPServerTracingSubscriber(registry))
bus.start()
now = time.time()
sid = "req-hr-store-only"
bus.publish(
Event(
event_type=EventType.MP_STORE_SUBMITTED, session_id=sid, timestamp=now
)
)
bus.publish(
Event(
event_type=EventType.MP_STORE_START,
session_id=sid,
timestamp=now + 0.001,
metadata={"device": "cuda:0"},
)
)
bus.publish(
Event(
event_type=EventType.MP_STORE_END,
session_id=sid,
timestamp=now + 0.020,
metadata={"stored_count": 3, "device": "cuda:0"},
)
)
bus.publish(
Event(
event_type=EventType.MP_REQUEST_END,
session_id=sid,
timestamp=now + 0.025,
)
)
time.sleep(0.15)
bus.stop()
root = self._root_span(exporter, sid)
assert root is not None
assert "hit_tokens" not in root.attributes
assert "hit_rate" not in root.attributes