diff --git a/hindsight-api/hindsight_api/engine/llm_wrapper.py b/hindsight-api/hindsight_api/engine/llm_wrapper.py index 65ba39ed..996ae7ab 100644 --- a/hindsight-api/hindsight_api/engine/llm_wrapper.py +++ b/hindsight-api/hindsight_api/engine/llm_wrapper.py @@ -400,13 +400,17 @@ class LLMProvider: output_tokens = usage.completion_tokens or 0 if usage else 0 total_tokens = usage.total_tokens or 0 if usage else 0 - if usage: - get_metrics_collector().record_tokens( - operation=scope, - bank_id="llm", - input_tokens=input_tokens, - output_tokens=output_tokens, - ) + # Record LLM metrics + metrics = get_metrics_collector() + metrics.record_llm_call( + provider=self.provider, + model=self.model, + scope=scope, + duration=duration, + input_tokens=input_tokens, + output_tokens=output_tokens, + success=True, + ) # Log slow calls if duration > 10.0 and usage: @@ -559,24 +563,28 @@ class LLMProvider: else: result = content - # Record token usage metrics + # Record metrics and log slow calls duration = time.time() - start_time input_tokens = response.usage.input_tokens or 0 if response.usage else 0 output_tokens = response.usage.output_tokens or 0 if response.usage else 0 total_tokens = input_tokens + output_tokens - if response.usage: - get_metrics_collector().record_tokens( - operation="memory", - bank_id="llm", - input_tokens=input_tokens, - output_tokens=output_tokens, - ) + # Record LLM metrics + metrics = get_metrics_collector() + metrics.record_llm_call( + provider=self.provider, + model=self.model, + scope="memory", + duration=duration, + input_tokens=input_tokens, + output_tokens=output_tokens, + success=True, + ) # Log slow calls - if duration > 10.0 and response.usage: + if duration > 10.0: logger.info( - f"slow llm call: model={self.provider}/{self.model}, " + f"slow llm call: scope=memory, model={self.provider}/{self.model}, " f"input_tokens={input_tokens}, output_tokens={output_tokens}, " f"time={duration:.3f}s" ) @@ -719,18 +727,22 @@ class LLMProvider: # Extract token usage from Ollama response # Ollama returns prompt_eval_count (input) and eval_count (output) + duration = time.time() - start_time input_tokens = result.get("prompt_eval_count", 0) or 0 output_tokens = result.get("eval_count", 0) or 0 total_tokens = input_tokens + output_tokens - # Record to metrics - if input_tokens > 0 or output_tokens > 0: - get_metrics_collector().record_tokens( - operation="memory", - bank_id="llm", - input_tokens=input_tokens, - output_tokens=output_tokens, - ) + # Record LLM metrics + metrics = get_metrics_collector() + metrics.record_llm_call( + provider=self.provider, + model=self.model, + scope="memory", + duration=duration, + input_tokens=input_tokens, + output_tokens=output_tokens, + success=True, + ) # Validate against Pydantic model or return raw JSON if skip_validation: @@ -865,7 +877,7 @@ class LLMProvider: else: result = content - # Record token usage metrics + # Record metrics and log slow calls duration = time.time() - start_time input_tokens = 0 output_tokens = 0 @@ -873,20 +885,26 @@ class LLMProvider: usage = response.usage_metadata input_tokens = usage.prompt_token_count or 0 output_tokens = usage.candidates_token_count or 0 - get_metrics_collector().record_tokens( - operation="memory", - bank_id="llm", - input_tokens=input_tokens, - output_tokens=output_tokens, - ) - # Log slow calls - if duration > 10.0: - logger.info( - f"slow llm call: model={self.provider}/{self.model}, " - f"input_tokens={input_tokens}, output_tokens={output_tokens}, " - f"time={duration:.3f}s" - ) + # Record LLM metrics + metrics = get_metrics_collector() + metrics.record_llm_call( + provider=self.provider, + model=self.model, + scope="memory", + duration=duration, + input_tokens=input_tokens, + output_tokens=output_tokens, + success=True, + ) + + # Log slow calls + if duration > 10.0 and input_tokens > 0: + logger.info( + f"slow llm call: scope=memory, model={self.provider}/{self.model}, " + f"input_tokens={input_tokens}, output_tokens={output_tokens}, " + f"time={duration:.3f}s" + ) if return_usage: token_usage = TokenUsage( diff --git a/hindsight-api/hindsight_api/engine/memory_engine.py b/hindsight-api/hindsight_api/engine/memory_engine.py index 67e664df..bce48cdd 100644 --- a/hindsight-api/hindsight_api/engine/memory_engine.py +++ b/hindsight-api/hindsight_api/engine/memory_engine.py @@ -18,6 +18,7 @@ from datetime import UTC, datetime, timedelta from typing import TYPE_CHECKING, Any from ..config import get_config +from ..metrics import get_metrics_collector # Context variable for current schema (async-safe, per-task isolation) _current_schema: contextvars.ContextVar[str] = contextvars.ContextVar("current_schema", default="public") @@ -3162,16 +3163,20 @@ Guidelines: # Steps 1-3: Run multi-fact-type search (12-way retrieval: 4 methods × 3 fact types) recall_start = time.time() - search_result = await self.recall_async( - bank_id=bank_id, - query=query, - budget=budget, - max_tokens=4096, - enable_trace=False, - fact_type=["experience", "world", "opinion"], - include_entities=True, - request_context=request_context, - ) + metrics = get_metrics_collector() + with metrics.record_operation( + "recall", bank_id=bank_id, source="reflect", budget=budget.value if budget else None + ): + search_result = await self.recall_async( + bank_id=bank_id, + query=query, + budget=budget, + max_tokens=4096, + enable_trace=False, + fact_type=["experience", "world", "opinion"], + include_entities=True, + request_context=request_context, + ) recall_time = time.time() - recall_start all_results = search_result.results diff --git a/hindsight-api/hindsight_api/metrics.py b/hindsight-api/hindsight_api/metrics.py index d8f16cf6..0f082fba 100644 --- a/hindsight-api/hindsight_api/metrics.py +++ b/hindsight-api/hindsight_api/metrics.py @@ -5,6 +5,7 @@ This module provides metrics for: - Operation latency (retain, recall, reflect) with percentiles - Token usage (input/output) per operation - Per-bank granularity via labels +- LLM call latency and token usage with scope dimension """ import logging @@ -14,8 +15,54 @@ from contextlib import contextmanager from opentelemetry import metrics from opentelemetry.exporter.prometheus import PrometheusMetricReader from opentelemetry.sdk.metrics import MeterProvider +from opentelemetry.sdk.metrics.view import ExplicitBucketHistogramAggregation, View from opentelemetry.sdk.resources import Resource +# Custom bucket boundaries for operation duration (in seconds) +# Fine granularity in 0-30s range where most operations complete +DURATION_BUCKETS = (0.1, 0.25, 0.5, 0.75, 1.0, 2.0, 3.0, 5.0, 7.5, 10.0, 15.0, 20.0, 30.0, 60.0, 120.0) + +# LLM duration buckets (finer granularity for faster LLM calls) +LLM_DURATION_BUCKETS = (0.1, 0.25, 0.5, 1.0, 2.0, 3.0, 5.0, 10.0, 15.0, 30.0, 60.0, 120.0) + + +def get_token_bucket(token_count: int) -> str: + """ + Convert a token count to a bucket label for use as a dimension. + + This allows analyzing token usage patterns without high-cardinality issues. + + Buckets: + - "0-100": Very small requests/responses + - "100-500": Small requests/responses + - "500-1k": Medium requests/responses + - "1k-5k": Large requests/responses + - "5k-10k": Very large requests/responses + - "10k-50k": Huge requests/responses + - "50k+": Extremely large requests/responses + + Args: + token_count: Number of tokens + + Returns: + Bucket label string + """ + if token_count < 100: + return "0-100" + elif token_count < 500: + return "100-500" + elif token_count < 1000: + return "500-1k" + elif token_count < 5000: + return "1k-5k" + elif token_count < 10000: + return "5k-10k" + elif token_count < 50000: + return "10k-50k" + else: + return "50k+" + + logger = logging.getLogger(__name__) # Global meter instance @@ -48,8 +95,22 @@ def initialize_metrics(service_name: str = "hindsight-api", service_version: str # Create Prometheus metric reader prometheus_reader = PrometheusMetricReader() - # Create meter provider with Prometheus exporter - provider = MeterProvider(resource=resource, metric_readers=[prometheus_reader]) + # Create view with custom bucket boundaries for duration histogram + duration_view = View( + instrument_name="hindsight.operation.duration", + aggregation=ExplicitBucketHistogramAggregation(boundaries=DURATION_BUCKETS), + ) + + # Create view with custom bucket boundaries for LLM duration histogram + llm_duration_view = View( + instrument_name="hindsight.llm.duration", + aggregation=ExplicitBucketHistogramAggregation(boundaries=LLM_DURATION_BUCKETS), + ) + + # Create meter provider with Prometheus exporter and custom views + provider = MeterProvider( + resource=resource, metric_readers=[prometheus_reader], views=[duration_view, llm_duration_view] + ) # Set the global meter provider metrics.set_meter_provider(provider) @@ -71,20 +132,39 @@ class MetricsCollectorBase: """Base class for metrics collectors.""" @contextmanager - def record_operation(self, operation: str, bank_id: str, budget: str | None = None, max_tokens: int | None = None): - """Context manager to record operation duration and status.""" - raise NotImplementedError - - def record_tokens( + def record_operation( self, operation: str, bank_id: str, - input_tokens: int = 0, - output_tokens: int = 0, + source: str = "api", budget: str | None = None, max_tokens: int | None = None, ): - """Record token usage for an operation.""" + """Context manager to record operation duration and status.""" + raise NotImplementedError + + def record_llm_call( + self, + provider: str, + model: str, + scope: str, + duration: float, + input_tokens: int = 0, + output_tokens: int = 0, + success: bool = True, + ): + """ + Record metrics for an LLM call. + + Args: + provider: LLM provider name (openai, anthropic, gemini, groq, ollama, lmstudio) + model: Model name + scope: Scope identifier (e.g., "memory", "reflect", "entity_observation") + duration: Call duration in seconds + input_tokens: Number of input/prompt tokens + output_tokens: Number of output/completion tokens + success: Whether the call was successful + """ raise NotImplementedError @@ -92,20 +172,28 @@ class NoOpMetricsCollector(MetricsCollectorBase): """No-op metrics collector that does nothing. Used when metrics are disabled.""" @contextmanager - def record_operation(self, operation: str, bank_id: str, budget: str | None = None, max_tokens: int | None = None): - """No-op context manager.""" - yield - - def record_tokens( + def record_operation( self, operation: str, bank_id: str, - input_tokens: int = 0, - output_tokens: int = 0, + source: str = "api", budget: str | None = None, max_tokens: int | None = None, ): - """No-op token recording.""" + """No-op context manager.""" + yield + + def record_llm_call( + self, + provider: str, + model: str, + scope: str, + duration: float, + input_tokens: int = 0, + output_tokens: int = 0, + success: bool = True, + ): + """No-op LLM call recording.""" pass @@ -125,33 +213,52 @@ class MetricsCollector(MetricsCollectorBase): name="hindsight.operation.duration", description="Duration of Hindsight operations in seconds", unit="s" ) - # Token usage counters - self.tokens_input = self.meter.create_counter( - name="hindsight.tokens.input", description="Number of input tokens consumed", unit="tokens" - ) - - self.tokens_output = self.meter.create_counter( - name="hindsight.tokens.output", description="Number of output tokens generated", unit="tokens" - ) - # Operation counter (success/failure) self.operation_total = self.meter.create_counter( name="hindsight.operation.total", description="Total number of operations executed", unit="operations" ) + # LLM call latency histogram (in seconds) + # Records duration of LLM API calls with provider, model, and scope dimensions + self.llm_duration = self.meter.create_histogram( + name="hindsight.llm.duration", description="Duration of LLM API calls in seconds", unit="s" + ) + + # LLM token usage counters with bucket labels + self.llm_tokens_input = self.meter.create_counter( + name="hindsight.llm.tokens.input", description="Number of input tokens for LLM calls", unit="tokens" + ) + + self.llm_tokens_output = self.meter.create_counter( + name="hindsight.llm.tokens.output", description="Number of output tokens from LLM calls", unit="tokens" + ) + + # LLM call counter (success/failure) + self.llm_calls_total = self.meter.create_counter( + name="hindsight.llm.calls.total", description="Total number of LLM API calls", unit="calls" + ) + @contextmanager - def record_operation(self, operation: str, bank_id: str, budget: str | None = None, max_tokens: int | None = None): + def record_operation( + self, + operation: str, + bank_id: str, + source: str = "api", + budget: str | None = None, + max_tokens: int | None = None, + ): """ Context manager to record operation duration and status. Usage: - with metrics.record_operation("recall", bank_id="user123", budget="mid", max_tokens=4096): + with metrics.record_operation("recall", bank_id="user123", source="api", budget="mid", max_tokens=4096): # ... perform operation pass Args: - operation: Operation name (retain, recall, reflect) + operation: Operation name (retain, recall, reflect, entity_observation) bank_id: Memory bank ID + source: Source of the operation (api, reflect, internal) budget: Optional budget level (low, mid, high) max_tokens: Optional max tokens for the operation """ @@ -159,6 +266,7 @@ class MetricsCollector(MetricsCollectorBase): attributes = { "operation": operation, "bank_id": bank_id, + "source": source, } if budget: attributes["budget"] = budget @@ -181,40 +289,56 @@ class MetricsCollector(MetricsCollectorBase): # Record operation count self.operation_total.add(1, attributes) - def record_tokens( + def record_llm_call( self, - operation: str, - bank_id: str, + provider: str, + model: str, + scope: str, + duration: float, input_tokens: int = 0, output_tokens: int = 0, - budget: str | None = None, - max_tokens: int | None = None, + success: bool = True, ): """ - Record token usage for an operation. + Record metrics for an LLM call. Args: - operation: Operation name (retain, recall, reflect) - bank_id: Memory bank ID - input_tokens: Number of input tokens - output_tokens: Number of output tokens - budget: Optional budget level - max_tokens: Optional max tokens for the operation + provider: LLM provider name (openai, anthropic, gemini, groq, ollama, lmstudio) + model: Model name + scope: Scope identifier (e.g., "memory", "reflect", "entity_observation") + duration: Call duration in seconds + input_tokens: Number of input/prompt tokens + output_tokens: Number of output/completion tokens + success: Whether the call was successful """ - attributes = { - "operation": operation, - "bank_id": bank_id, + # Base attributes for all metrics + base_attributes = { + "provider": provider, + "model": model, + "scope": scope, + "success": str(success).lower(), } - if budget: - attributes["budget"] = budget - if max_tokens: - attributes["max_tokens"] = str(max_tokens) + # Record duration + self.llm_duration.record(duration, base_attributes) + + # Record call count + self.llm_calls_total.add(1, base_attributes) + + # Record tokens with bucket labels for cardinality control if input_tokens > 0: - self.tokens_input.add(input_tokens, attributes) + input_attributes = { + **base_attributes, + "token_bucket": get_token_bucket(input_tokens), + } + self.llm_tokens_input.add(input_tokens, input_attributes) if output_tokens > 0: - self.tokens_output.add(output_tokens, attributes) + output_attributes = { + **base_attributes, + "token_bucket": get_token_bucket(output_tokens), + } + self.llm_tokens_output.add(output_tokens, output_attributes) # Global metrics collector instance (defaults to no-op) diff --git a/hindsight-api/tests/test_llm_token_metrics.py b/hindsight-api/tests/test_llm_token_metrics.py index d4a81e67..87a24cd6 100644 --- a/hindsight-api/tests/test_llm_token_metrics.py +++ b/hindsight-api/tests/test_llm_token_metrics.py @@ -9,8 +9,6 @@ from hindsight_api.metrics import ( MetricsCollector, NoOpMetricsCollector, get_metrics_collector, - initialize_metrics, - create_metrics_collector, ) @@ -20,16 +18,16 @@ def get_groq_api_key() -> str | None: @pytest.mark.asyncio -async def test_token_metrics_recorded_for_groq(): +async def test_llm_metrics_recorded_for_groq(): """ - Test that token metrics are recorded when making LLM calls via Groq. + Test that LLM metrics are recorded when making LLM calls via Groq. Uses openai/gpt-oss-20b as recommended by Hindsight. """ api_key = get_groq_api_key() if not api_key: pytest.skip("Skipping: GROQ_API_KEY not set") - # Create a mock metrics collector to track record_tokens calls + # Create a mock metrics collector to track record_llm_call calls mock_collector = MagicMock(spec=MetricsCollector) with patch("hindsight_api.engine.llm_wrapper.get_metrics_collector", return_value=mock_collector): @@ -50,30 +48,35 @@ async def test_token_metrics_recorded_for_groq(): scope="test_metrics", ) - # Verify record_tokens was called - this is the main test - assert mock_collector.record_tokens.called, "record_tokens should have been called" + # Verify record_llm_call was called - this is the main test + assert mock_collector.record_llm_call.called, "record_llm_call should have been called" # Get the call arguments - call_kwargs = mock_collector.record_tokens.call_args.kwargs + call_kwargs = mock_collector.record_llm_call.call_args.kwargs # Verify the call had correct structure - assert call_kwargs["operation"] == "test_metrics", f"Expected operation='test_metrics', got {call_kwargs}" - assert call_kwargs["bank_id"] == "llm", f"Expected bank_id='llm', got {call_kwargs}" + assert call_kwargs["provider"] == "groq", f"Expected provider='groq', got {call_kwargs}" + assert call_kwargs["model"] == "openai/gpt-oss-20b", f"Expected model='openai/gpt-oss-20b', got {call_kwargs}" + assert call_kwargs["scope"] == "test_metrics", f"Expected scope='test_metrics', got {call_kwargs}" + assert call_kwargs["duration"] > 0, f"Expected duration > 0, got {call_kwargs['duration']}" assert call_kwargs["input_tokens"] > 0, f"Expected input_tokens > 0, got {call_kwargs['input_tokens']}" - # Output tokens may be 0 for some edge cases, but input should always be > 0 assert call_kwargs["output_tokens"] >= 0, f"Expected output_tokens >= 0, got {call_kwargs['output_tokens']}" + assert call_kwargs["success"] is True, f"Expected success=True, got {call_kwargs['success']}" - print(f"\nToken metrics recorded:") - print(f" operation: {call_kwargs['operation']}") + print(f"\nLLM metrics recorded:") + print(f" provider: {call_kwargs['provider']}") + print(f" model: {call_kwargs['model']}") + print(f" scope: {call_kwargs['scope']}") + print(f" duration: {call_kwargs['duration']:.3f}s") print(f" input_tokens: {call_kwargs['input_tokens']}") print(f" output_tokens: {call_kwargs['output_tokens']}") print(f" response: {response}") @pytest.mark.asyncio -async def test_token_metrics_recorded_for_structured_output(): +async def test_llm_metrics_recorded_for_structured_output(): """ - Test that token metrics are recorded for structured output (JSON) calls. + Test that LLM metrics are recorded for structured output (JSON) calls. """ api_key = get_groq_api_key() if not api_key: @@ -108,14 +111,14 @@ async def test_token_metrics_recorded_for_structured_output(): assert response.greeting is not None assert response.language is not None - # Verify record_tokens was called - assert mock_collector.record_tokens.called, "record_tokens should have been called" + # Verify record_llm_call was called + assert mock_collector.record_llm_call.called, "record_llm_call should have been called" - call_kwargs = mock_collector.record_tokens.call_args.kwargs + call_kwargs = mock_collector.record_llm_call.call_args.kwargs assert call_kwargs["input_tokens"] > 0 assert call_kwargs["output_tokens"] > 0 - print(f"\nStructured output token metrics:") + print(f"\nStructured output LLM metrics:") print(f" greeting: {response.greeting}") print(f" language: {response.language}") print(f" input_tokens: {call_kwargs['input_tokens']}") diff --git a/hindsight-api/tests/test_metrics.py b/hindsight-api/tests/test_metrics.py new file mode 100644 index 00000000..d6a4c914 --- /dev/null +++ b/hindsight-api/tests/test_metrics.py @@ -0,0 +1,391 @@ +"""Tests for metrics instrumentation.""" +import pytest +from unittest.mock import MagicMock, patch + +from hindsight_api.metrics import ( + MetricsCollector, + MetricsCollectorBase, + NoOpMetricsCollector, + get_metrics_collector, + get_token_bucket, + create_metrics_collector, + initialize_metrics, +) + + +class TestNoOpMetricsCollector: + """Tests for the no-op metrics collector.""" + + def test_record_operation_is_noop(self): + """Test that record_operation does nothing.""" + collector = NoOpMetricsCollector() + + # Should not raise any exception + with collector.record_operation("recall", bank_id="test_bank", source="api"): + pass + + def test_nested_contexts_work(self): + """Test that nested context managers work correctly.""" + collector = NoOpMetricsCollector() + + # Nested contexts should work without issues + with collector.record_operation("reflect", bank_id="test_bank", source="api"): + with collector.record_operation("recall", bank_id="test_bank", source="reflect"): + pass + + def test_exception_propagates(self): + """Test that exceptions inside context are propagated.""" + collector = NoOpMetricsCollector() + + with pytest.raises(ValueError, match="test error"): + with collector.record_operation("recall", bank_id="test_bank"): + raise ValueError("test error") + + def test_record_llm_call_is_noop(self): + """Test that record_llm_call does nothing.""" + collector = NoOpMetricsCollector() + + # Should not raise any exception + collector.record_llm_call( + provider="openai", + model="gpt-4", + scope="memory", + duration=1.5, + input_tokens=100, + output_tokens=50, + success=True, + ) + + +class TestMetricsCollector: + """Tests for the real metrics collector.""" + + @pytest.fixture + def mock_meter(self): + """Create a mock meter for testing.""" + meter = MagicMock() + # Create separate mocks for each histogram (operation_duration, llm_duration) + histogram_mocks = [MagicMock(), MagicMock()] + meter.create_histogram.side_effect = histogram_mocks + # Create separate mocks for each counter + # (operation_total, llm_tokens_input, llm_tokens_output, llm_calls_total) + counter_mocks = [MagicMock() for _ in range(4)] + meter.create_counter.side_effect = counter_mocks + return meter + + @pytest.fixture + def collector(self, mock_meter): + """Create a MetricsCollector with a mock meter.""" + with patch("hindsight_api.metrics.get_meter", return_value=mock_meter): + return MetricsCollector() + + def test_record_operation_records_duration(self, collector): + """Test that record_operation records duration.""" + with collector.record_operation("recall", bank_id="test_bank", source="api"): + pass + + # Histogram should have been called + collector.operation_duration.record.assert_called_once() + call_args = collector.operation_duration.record.call_args + + # First arg is duration (should be > 0) + duration = call_args[0][0] + assert duration >= 0 + + # Second arg is attributes dict + attributes = call_args[0][1] + assert attributes["operation"] == "recall" + assert attributes["bank_id"] == "test_bank" + assert attributes["source"] == "api" + assert attributes["success"] == "true" + + def test_record_operation_records_failure_on_exception(self, collector): + """Test that record_operation records failure when exception occurs.""" + with pytest.raises(RuntimeError): + with collector.record_operation("retain", bank_id="test_bank", source="api"): + raise RuntimeError("Test error") + + # Should have recorded with success=false + call_args = collector.operation_duration.record.call_args + attributes = call_args[0][1] + assert attributes["success"] == "false" + + def test_record_operation_with_budget(self, collector): + """Test that budget is included in attributes when provided.""" + with collector.record_operation("recall", bank_id="test_bank", source="api", budget="mid"): + pass + + call_args = collector.operation_duration.record.call_args + attributes = call_args[0][1] + assert attributes["budget"] == "mid" + + def test_record_operation_with_max_tokens(self, collector): + """Test that max_tokens is included in attributes when provided.""" + with collector.record_operation("recall", bank_id="test_bank", source="api", max_tokens=4096): + pass + + call_args = collector.operation_duration.record.call_args + attributes = call_args[0][1] + assert attributes["max_tokens"] == "4096" + + def test_record_operation_source_values(self, collector): + """Test different source values: api, reflect, internal.""" + sources = ["api", "reflect", "internal"] + + for source in sources: + collector.operation_duration.record.reset_mock() + + with collector.record_operation("recall", bank_id="test_bank", source=source): + pass + + call_args = collector.operation_duration.record.call_args + attributes = call_args[0][1] + assert attributes["source"] == source + + def test_nested_contexts_track_separately(self, collector): + """Test that nested operations are tracked separately with different sources.""" + # Simulate reflect (api) calling recall (reflect) + with collector.record_operation("reflect", bank_id="test_bank", source="api"): + with collector.record_operation("recall", bank_id="test_bank", source="reflect"): + pass + + # Should have 2 calls to record + assert collector.operation_duration.record.call_count == 2 + assert collector.operation_total.add.call_count == 2 + + # Check the calls + calls = collector.operation_duration.record.call_args_list + + # First call should be recall (inner context exits first) + recall_attrs = calls[0][0][1] + assert recall_attrs["operation"] == "recall" + assert recall_attrs["source"] == "reflect" + + # Second call should be reflect (outer context exits last) + reflect_attrs = calls[1][0][1] + assert reflect_attrs["operation"] == "reflect" + assert reflect_attrs["source"] == "api" + + +class TestGetMetricsCollector: + """Tests for the get_metrics_collector function.""" + + def test_returns_noop_by_default(self): + """Test that get_metrics_collector returns NoOpMetricsCollector by default.""" + # Reset global state + import hindsight_api.metrics as metrics_module + original_collector = metrics_module._metrics_collector + + try: + metrics_module._metrics_collector = NoOpMetricsCollector() + collector = get_metrics_collector() + assert isinstance(collector, NoOpMetricsCollector) + finally: + metrics_module._metrics_collector = original_collector + + +class TestMetricsCollectorBase: + """Tests for the MetricsCollectorBase abstract class.""" + + def test_is_abstract(self): + """Test that MetricsCollectorBase methods are abstract.""" + # Create a class that inherits but doesn't implement + class IncompleteCollector(MetricsCollectorBase): + pass + + collector = IncompleteCollector() + + # Abstract methods should raise NotImplementedError + with pytest.raises(NotImplementedError): + with collector.record_operation("test", "test"): + pass + + with pytest.raises(NotImplementedError): + collector.record_llm_call("test", "test", "test", 1.0) + + +class TestGetTokenBucket: + """Tests for the get_token_bucket function.""" + + def test_bucket_0_100(self): + """Test tokens < 100 return '0-100' bucket.""" + assert get_token_bucket(0) == "0-100" + assert get_token_bucket(50) == "0-100" + assert get_token_bucket(99) == "0-100" + + def test_bucket_100_500(self): + """Test tokens 100-499 return '100-500' bucket.""" + assert get_token_bucket(100) == "100-500" + assert get_token_bucket(250) == "100-500" + assert get_token_bucket(499) == "100-500" + + def test_bucket_500_1k(self): + """Test tokens 500-999 return '500-1k' bucket.""" + assert get_token_bucket(500) == "500-1k" + assert get_token_bucket(750) == "500-1k" + assert get_token_bucket(999) == "500-1k" + + def test_bucket_1k_5k(self): + """Test tokens 1000-4999 return '1k-5k' bucket.""" + assert get_token_bucket(1000) == "1k-5k" + assert get_token_bucket(2500) == "1k-5k" + assert get_token_bucket(4999) == "1k-5k" + + def test_bucket_5k_10k(self): + """Test tokens 5000-9999 return '5k-10k' bucket.""" + assert get_token_bucket(5000) == "5k-10k" + assert get_token_bucket(7500) == "5k-10k" + assert get_token_bucket(9999) == "5k-10k" + + def test_bucket_10k_50k(self): + """Test tokens 10000-49999 return '10k-50k' bucket.""" + assert get_token_bucket(10000) == "10k-50k" + assert get_token_bucket(25000) == "10k-50k" + assert get_token_bucket(49999) == "10k-50k" + + def test_bucket_50k_plus(self): + """Test tokens >= 50000 return '50k+' bucket.""" + assert get_token_bucket(50000) == "50k+" + assert get_token_bucket(100000) == "50k+" + assert get_token_bucket(1000000) == "50k+" + + +class TestLLMMetrics: + """Tests for LLM-specific metrics recording.""" + + @pytest.fixture + def mock_meter(self): + """Create a mock meter for testing.""" + meter = MagicMock() + # Create separate mocks for each histogram (operation_duration, llm_duration) + histogram_mocks = [MagicMock(), MagicMock()] + meter.create_histogram.side_effect = histogram_mocks + # Create separate mocks for each counter + # (operation_total, llm_tokens_input, llm_tokens_output, llm_calls_total) + counter_mocks = [MagicMock() for _ in range(4)] + meter.create_counter.side_effect = counter_mocks + return meter + + @pytest.fixture + def collector(self, mock_meter): + """Create a MetricsCollector with a mock meter.""" + with patch("hindsight_api.metrics.get_meter", return_value=mock_meter): + return MetricsCollector() + + def test_record_llm_call_records_duration(self, collector): + """Test that record_llm_call records duration.""" + collector.record_llm_call( + provider="openai", + model="gpt-4", + scope="memory", + duration=1.5, + input_tokens=100, + output_tokens=50, + success=True, + ) + + # LLM duration histogram should be called + collector.llm_duration.record.assert_called_once() + call_args = collector.llm_duration.record.call_args + + # First arg is duration + assert call_args[0][0] == 1.5 + + # Second arg is attributes dict + attributes = call_args[0][1] + assert attributes["provider"] == "openai" + assert attributes["model"] == "gpt-4" + assert attributes["scope"] == "memory" + assert attributes["success"] == "true" + + def test_record_llm_call_records_failure(self, collector): + """Test that record_llm_call records failure status.""" + collector.record_llm_call( + provider="anthropic", + model="claude-3", + scope="reflect", + duration=0.5, + success=False, + ) + + # Check success is false + call_args = collector.llm_duration.record.call_args + attributes = call_args[0][1] + assert attributes["success"] == "false" + + def test_record_llm_call_records_tokens_with_buckets(self, collector): + """Test that record_llm_call records tokens with bucket labels.""" + collector.record_llm_call( + provider="openai", + model="gpt-4", + scope="memory", + duration=1.0, + input_tokens=2500, # Should be "1k-5k" bucket + output_tokens=150, # Should be "100-500" bucket + success=True, + ) + + # Input tokens should be recorded with bucket + collector.llm_tokens_input.add.assert_called_once() + input_call = collector.llm_tokens_input.add.call_args + assert input_call[0][0] == 2500 + assert input_call[0][1]["token_bucket"] == "1k-5k" + + # Output tokens should be recorded with bucket + collector.llm_tokens_output.add.assert_called_once() + output_call = collector.llm_tokens_output.add.call_args + assert output_call[0][0] == 150 + assert output_call[0][1]["token_bucket"] == "100-500" + + def test_record_llm_call_skips_zero_tokens(self, collector): + """Test that zero token values don't record.""" + collector.record_llm_call( + provider="openai", + model="gpt-4", + scope="memory", + duration=1.0, + input_tokens=0, + output_tokens=0, + success=True, + ) + + # Token counters should not be called + collector.llm_tokens_input.add.assert_not_called() + collector.llm_tokens_output.add.assert_not_called() + + def test_record_llm_call_increments_call_counter(self, collector): + """Test that record_llm_call increments the call counter.""" + collector.record_llm_call( + provider="gemini", + model="gemini-pro", + scope="entity_observation", + duration=2.0, + success=True, + ) + + # Call counter should be incremented + collector.llm_calls_total.add.assert_called_once() + call_args = collector.llm_calls_total.add.call_args + assert call_args[0][0] == 1 + assert call_args[0][1]["provider"] == "gemini" + assert call_args[0][1]["model"] == "gemini-pro" + assert call_args[0][1]["scope"] == "entity_observation" + + def test_record_llm_call_different_scopes(self, collector): + """Test recording LLM calls with different scopes.""" + scopes = ["memory", "reflect", "entity_observation", "answer"] + + for scope in scopes: + collector.llm_duration.record.reset_mock() + + collector.record_llm_call( + provider="openai", + model="gpt-4", + scope=scope, + duration=1.0, + success=True, + ) + + call_args = collector.llm_duration.record.call_args + attributes = call_args[0][1] + assert attributes["scope"] == scope diff --git a/hindsight-docs/docs/developer/metrics.md b/hindsight-docs/docs/developer/metrics.md index 21c246ce..cb30c694 100644 --- a/hindsight-docs/docs/developer/metrics.md +++ b/hindsight-docs/docs/developer/metrics.md @@ -12,17 +12,51 @@ curl http://localhost:8888/metrics | Metric | Type | Labels | Description | |--------|------|--------|-------------| -| `hindsight.operation.duration` | Histogram | operation, bank_id, budget, max_tokens, success | Duration of operations in seconds | -| `hindsight.operation.total` | Counter | operation, bank_id, budget, max_tokens, success | Total number of operations executed | +| `hindsight.operation.duration` | Histogram | operation, bank_id, source, budget, max_tokens, success | Duration of operations in seconds | +| `hindsight.operation.total` | Counter | operation, bank_id, source, budget, max_tokens, success | Total number of operations executed | -The `operation` label values are: `retain`, `recall`, `reflect`. +**Labels:** +- `operation`: Operation type (`retain`, `recall`, `reflect`) +- `bank_id`: Memory bank identifier +- `source`: Where the operation was triggered from (`api`, `reflect`, `internal`) +- `budget`: Budget level if specified (`low`, `mid`, `high`) +- `max_tokens`: Max tokens if specified +- `success`: Whether the operation succeeded (`true`, `false`) -### Token Metrics +The `source` label allows distinguishing between: +- `api`: Direct API calls from clients +- `reflect`: Internal recall calls made during reflect operations +- `internal`: Other internal operations + +### LLM Metrics | Metric | Type | Labels | Description | |--------|------|--------|-------------| -| `hindsight.tokens.input` | Counter | operation, bank_id, budget, max_tokens | Input tokens consumed | -| `hindsight.tokens.output` | Counter | operation, bank_id, budget, max_tokens | Output tokens generated | +| `hindsight.llm.duration` | Histogram | provider, model, scope, success | Duration of LLM API calls in seconds | +| `hindsight.llm.calls.total` | Counter | provider, model, scope, success | Total number of LLM API calls | +| `hindsight.llm.tokens.input` | Counter | provider, model, scope, success, token_bucket | Input tokens for LLM calls | +| `hindsight.llm.tokens.output` | Counter | provider, model, scope, success, token_bucket | Output tokens from LLM calls | + +**Labels:** +- `provider`: LLM provider (`openai`, `anthropic`, `gemini`, `groq`, `ollama`, `lmstudio`) +- `model`: Model name (e.g., `gpt-4`, `claude-3-sonnet`) +- `scope`: What the LLM call is for (`memory`, `reflect`, `entity_observation`, `answer`) +- `success`: Whether the call succeeded (`true`, `false`) +- `token_bucket`: Token count bucket for cardinality control (`0-100`, `100-500`, `500-1k`, `1k-5k`, `5k-10k`, `10k-50k`, `50k+`) + +### Histogram Buckets + +Custom bucket boundaries are configured for better percentile accuracy: + +**Operation Duration Buckets (seconds):** +``` +0.1, 0.25, 0.5, 0.75, 1.0, 2.0, 3.0, 5.0, 7.5, 10.0, 15.0, 20.0, 30.0, 60.0, 120.0 +``` + +**LLM Duration Buckets (seconds):** +``` +0.1, 0.25, 0.5, 1.0, 2.0, 3.0, 5.0, 10.0, 15.0, 30.0, 60.0, 120.0 +``` ## Prometheus Configuration @@ -32,3 +66,30 @@ scrape_configs: static_configs: - targets: ['localhost:8888'] ``` + +## Example Queries + +### Average operation latency by type +```promql +rate(hindsight_operation_duration_sum[5m]) / rate(hindsight_operation_duration_count[5m]) +``` + +### LLM calls per minute by provider +```promql +rate(hindsight_llm_calls_total[1m]) * 60 +``` + +### P95 LLM latency +```promql +histogram_quantile(0.95, rate(hindsight_llm_duration_bucket[5m])) +``` + +### Total tokens consumed by model +```promql +sum by (model) (hindsight_llm_tokens_input_total + hindsight_llm_tokens_output_total) +``` + +### Internal vs API recall operations +```promql +sum by (source) (rate(hindsight_operation_total{operation="recall"}[5m])) +```