Real‐World Query Time Tracking Implementation

Real-World Query Time Tracking Implementation

This guide details the complete journey of implementing query time tracking in the MCP Memory Dashboard, from identifying the "always shows 0" problem to the final working solution.

Table of Contents

• Overview
• The Problem
• Investigation Process
• Root Cause Discovery
• The Solution
• Implementation Details
• Testing and Verification
• Lessons Learned

Overview

Query time tracking is essential for performance monitoring. This case study shows how a timing synchronization issue between frontend and backend was diagnosed and resolved.

The Problem

GitHub Issue #8

Title: "Average Query Time Always Shows 0" Symptoms:

• Dashboard always displayed 0ms for average query time
• Stats showed correct memory count and tags
• Query operations were clearly taking time but not being recorded

Initial Hypothesis

The query time tracking implementation was missing from the backend.

Investigation Process

Step 1: Backend Code Review

Examined the MCP server implementation:

# Found in server.py
async def handle_dashboard_retrieve_memory(self, query: str, n_results: int = 5):
    start_time = time.time()
    
    # Perform the search
    results = await self.storage.retrieve(query, n_results)
    
    # Record query time
    query_time = (time.time() - start_time) * 1000  # Convert to ms
    self._record_query_time(query_time)
    
    # Implementation was already there!

Discovery: Backend was correctly implementing query time tracking.

Step 2: Live Testing

Created a test script to verify MCP communication:

# test_query_time_live.py
import asyncio
import json
import subprocess
import time

async def test_mcp_query_times():
    # Start MCP server
    process = subprocess.Popen(
        ['uv', 'run', 'memory'],
        stdin=subprocess.PIPE,
        stdout=subprocess.PIPE,
        stderr=subprocess.PIPE,
        text=True
    )
    
    # Initialize connection
    init_request = {
        \"jsonrpc\": \"2.0\",
        \"id\": 1,
        \"method\": \"initialize\",
        \"params\": {\"protocolVersion\": \"2024-11-05\"}
    }
    
    process.stdin.write(json.dumps(init_request) + '\
')
    process.stdin.flush()
    
    # Test sequence
    # 1. Check initial stats
    stats_request = {
        \"jsonrpc\": \"2.0\",
        \"id\": 2,
        \"method\": \"tools/call\",
        \"params\": {
            \"name\": \"dashboard_get_stats\",
            \"arguments\": {}
        }
    }
    
    # 2. Perform a search
    search_request = {
        \"jsonrpc\": \"2.0\",
        \"id\": 3,
        \"method\": \"tools/call\",
        \"params\": {
            \"name\": \"dashboard_retrieve_memory\",
            \"arguments\": {\"query\": \"test\", \"n_results\": 5}
        }
    }
    
    # 3. Check stats again
    # Should show non-zero query time

Results:

• Before search: avg_query_time: 0
• After search: avg_query_time: 21.96

Discovery: Backend was working correctly!

Step 3: Frontend Investigation

The issue must be in the frontend. Examined MemoryDashboard.tsx:

const handleSearch = async () => {
    try {
        setSearching(true);
        
        // Perform search
        const response = await window.mcpTools.dashboard_retrieve_memory({
            query: searchQuery,
            n_results: 10
        });
        
        setSearchResults(response.memories || []);
        
        // Missing: loadStats() call!
    } catch (error) {
        console.error('Search failed:', error);
    } finally {
        setSearching(false);
    }
};

Discovery: Frontend wasn't refreshing stats after operations!

Root Cause Discovery

The Real Issue

The frontend was missing loadStats() calls after search and recall operations. Stats were only loaded on initial mount and after store/delete operations.

Version 1.2.3 Fix Attempt

Added immediate stats refresh:

const handleSearch = async () => {
    try {
        // ... search logic ...
        
        // Refresh stats to show updated query time
        await loadStats();
    } catch (error) {
        // ... error handling ...
    }
};

Result: Still showed 0ms!

Deeper Investigation

Created a timing test to understand the issue:

// test_timing_issue.js
console.log('1. Getting initial stats...');
let stats = await getStats();
console.log(`Initial avg_query_time: ${stats.avg_query_time}`);

console.log('2. Performing search...');
await search('test query');

console.log('3. Immediately getting stats...');
stats = await getStats();
console.log(`Immediate avg_query_time: ${stats.avg_query_time}`); // Still 0!

console.log('4. Waiting 100ms...');
await new Promise(resolve => setTimeout(resolve, 100));

console.log('5. Getting stats after delay...');
stats = await getStats();
console.log(`Delayed avg_query_time: ${stats.avg_query_time}`); // Now shows 68.36!

Discovery: The MCP server needed processing time between operations!

The Solution

Understanding the Timing Issue

The problem was a race condition:

1. Frontend sends search request
2. Backend processes search and records time
3. Frontend immediately requests stats
4. Backend hasn't finished updating stats yet
5. Frontend receives old stats (0ms)

Version 1.2.4 Final Solution

Add a small delay before refreshing stats:

const handleSearch = async () => {
    try {
        setSearching(true);
        
        const response = await window.mcpTools.dashboard_retrieve_memory({
            query: searchQuery,
            n_results: 10
        });
        
        setSearchResults(response.memories || []);
        
        // Give MCP server time to process and update stats
        await new Promise(resolve => setTimeout(resolve, 100));
        
        // Now refresh stats
        await loadStats();
    } catch (error) {
        console.error('Search failed:', error);
    } finally {
        setSearching(false);
    }
};

// Same pattern for handleRecall
const handleRecall = async () => {
    try {
        setRecalling(true);
        
        const response = await window.mcpTools.dashboard_recall_memory({
            query: recallQuery,
            n_results: 10
        });
        
        setRecallResults(response.memories || []);
        
        // Timing fix here too
        await new Promise(resolve => setTimeout(resolve, 100));
        await loadStats();
    } catch (error) {
        console.error('Recall failed:', error);
    } finally {
        setRecalling(false);
    }
};

Implementation Details

Backend Query Time Tracking

The backend maintains a rolling average of the last 100 query times:

from collections import deque

class MemoryServer:
    def __init__(self):
        self.query_times = deque(maxlen=100)
    
    def _record_query_time(self, time_ms: float):
        \"\"\"Record query execution time\"\"\"
        self.query_times.append(time_ms)
    
    def _get_average_query_time(self) -> float:
        \"\"\"Calculate average of recorded query times\"\"\"
        if not self.query_times:
            return 0.0
        return sum(self.query_times) / len(self.query_times)
    
    async def handle_dashboard_get_stats(self):
        \"\"\"Return stats including average query time\"\"\"
        return {
            \"total_memories\": self.storage.count(),
            \"unique_tags\": len(self.storage.get_all_tags()),
            \"avg_query_time\": round(self._get_average_query_time(), 2),
            \"health\": 100
        }

Frontend Stats Management

Efficient stats loading with caching:

const [stats, setStats] = useState({
    totalMemories: 0,
    uniqueTags: 0,
    avgQueryTime: 0,
    health: 100
});
const [lastStatsUpdate, setLastStatsUpdate] = useState(Date.now());

const loadStats = async () => {
    try {
        const response = await window.mcpTools.dashboard_get_stats();
        
        setStats({
            totalMemories: response.total_memories || 0,
            uniqueTags: response.unique_tags || 0,
            avgQueryTime: response.avg_query_time || 0,
            health: response.health || 100
        });
        
        setLastStatsUpdate(Date.now());
    } catch (error) {
        console.error('Failed to load stats:', error);
    }
};

// Stats age indicator
const statsAge = Math.floor((Date.now() - lastStatsUpdate) / 1000);
const isStale = statsAge > 30;

Testing and Verification

Test Script

Created comprehensive verification test:

// test_query_time_verification.js
async function verifyQueryTimeTracking() {
    console.log('=== Query Time Tracking Verification ===\
');
    
    // Test 1: Search operation
    console.log('Test 1: Search Operation');
    let stats = await getStats();
    console.log(`Before search: avg_query_time = ${stats.avg_query_time}ms`);
    
    await search('mcp memory test');
    await sleep(100); // Critical delay
    
    stats = await getStats();
    console.log(`After search: avg_query_time = ${stats.avg_query_time}ms`);
    console.log(`✓ Search query time recorded: ${stats.avg_query_time > 0}\
`);
    
    // Test 2: Recall operation
    console.log('Test 2: Recall Operation');
    const beforeRecall = stats.avg_query_time;
    
    await recall('yesterday');
    await sleep(100); // Critical delay
    
    stats = await getStats();
    console.log(`After recall: avg_query_time = ${stats.avg_query_time}ms`);
    console.log(`✓ Recall query time recorded: ${stats.avg_query_time !== beforeRecall}\
`);
    
    // Test 3: Multiple operations
    console.log('Test 3: Multiple Operations');
    const times = [];
    
    for (let i = 0; i < 5; i++) {
        await search(`test query ${i}`);
        await sleep(100);
        stats = await getStats();
        times.push(stats.avg_query_time);
    }
    
    console.log(`Query times over 5 operations: ${times.join(', ')}ms`);
    console.log(`✓ Rolling average working: ${new Set(times).size > 1}\
`);
    
    console.log('=== All Tests Passed ✓ ===');
}

Verification Results

Test 1: Search Operation
Before search: avg_query_time = 0ms
After search: avg_query_time = 68.36ms
✓ Search query time recorded: true

Test 2: Recall Operation
After recall: avg_query_time = 55.13ms
✓ Recall query time recorded: true

Test 3: Multiple Operations
Query times over 5 operations: 52.4, 49.8, 47.2, 45.9, 44.3ms
✓ Rolling average working: true

Lessons Learned

1. Always Test End-to-End

The backend implementation was perfect, but the integration failed due to missing frontend calls and timing issues.

2. Asynchronous Operations Need Time

Even with await/async, some operations need processing time:

// Bad: Immediate check
await operation();
checkResult(); // May get stale data

// Good: Allow processing time
await operation();
await sleep(100);
checkResult(); // Gets updated data

3. Systematic Debugging Approach

1. Check if feature is implemented (backend)
2. Verify with isolated tests (MCP protocol)
3. Test integration (frontend-backend)
4. Consider timing and race conditions

4. Version Documentation

Clear version progression helped track fixes:

• v1.2.2: Issue identified
• v1.2.3: First fix attempt (added loadStats calls)
• v1.2.4: Final fix (added timing delays)

5. User Experience Considerations

The 100ms delay is imperceptible to users but crucial for correct operation:

// User sees smooth flow:
// Click search → Results appear → Stats update
// The 100ms delay happens invisibly in the background

Conclusion

The query time tracking implementation journey demonstrates that:

1. Not all bugs are missing features - sometimes it's integration
2. Timing matters in distributed systems
3. Systematic testing reveals hidden issues
4. Small delays can solve race conditions
5. Version tracking helps document the fix process

The final solution was elegant: a simple 100ms delay that made the difference between a broken feature and a working one. This case study shows the importance of understanding the full system, not just individual components.