fix(cache): Apply OFFSET/LIMIT to cache hits and implement COUNT caching

libraz · libraz · commit eaaadefe9f9b · 2025-11-16T21:25:21.000+09:00
Fix critical pagination bug and implement comprehensive COUNT query caching
with metadata tracking for performance monitoring.

Bug Fixes:
- Fix SEARCH cache hits ignoring OFFSET/LIMIT parameters (search_handler.cpp:48-76)
  - Previously returned full cached results without pagination
  - Now applies ResultSorter::SortAndPaginate to cached results
  - Cache design: Store full results to support different OFFSET/LIMIT combinations
- Implement COUNT query caching (search_handler.cpp:298-434)
  - Add cache lookup/insert for COUNT queries
  - Same LRU eviction and invalidation as SEARCH queries
  - Separate cache entries for COUNT vs SEARCH

New Features:
- Add cache metadata tracking infrastructure
  - CacheLookupResult structure with query_cost_ms and created_at
  - QueryCache::LookupWithMetadata() for metadata retrieval
  - CacheManager::LookupWithMetadata() API
- Add cache performance metrics
  - cache_age_ms: Time since cache entry creation
  - cache_saved_ms: Query execution time saved by cache hit
  - Displayed in DEBUG mode for both SEARCH and COUNT
- Enhance COUNT debug info (response_formatter.cpp:126-147)
  - Add cache status to COUNT query debug output
  - Consistent format with SEARCH queries

Thread Safety:
- LookupWithMetadata uses correct lock ordering (shared → unique)
- Metadata copied under shared_lock before upgrade
- created_at verification prevents use-after-free
- No race conditions in cache hit path

Tests:
- Add integration_cache_pagination_test.cpp (12 tests)
  - Cache miss/hit with OFFSET/LIMIT
  - Multiple pagination combinations
  - Edge cases (offset beyond results, limit exceeding)
  - Cache management (clear, enable/disable)
  - Pagination consistency and metadata in debug mode
- Add integration_cache_count_test.cpp (6 tests)
  - COUNT cache miss/hit
  - Different search terms
  - COUNT and SEARCH coexistence
  - Cache clear and disable
  - COUNT metadata in debug mode
- All tests passing: 18/18 ✓

Changed Files:
- src/server/handlers/search_handler.cpp
- src/server/response_formatter.cpp
- src/cache/cache_manager.{h,cpp}
- src/cache/query_cache.{h,cpp}
- tests/server/integration_cache_pagination_test.cpp (new)
- tests/server/integration_cache_count_test.cpp (new)
- tests/server/CMakeLists.txt
diff --git a/src/cache/cache_manager.cpp b/src/cache/cache_manager.cpp
@@ -64,6 +64,40 @@ std::optional<std::vector<DocId>> CacheManager::Lookup(const query::Query& query
   return query_cache_->Lookup(key);
 }
 
+std::optional<CacheLookupResult> CacheManager::LookupWithMetadata(const query::Query& query) {
+  if (!enabled_ || !query_cache_) {
+    return std::nullopt;
+  }
+
+  // Only cache SEARCH and COUNT queries
+  if (query.type != query::QueryType::SEARCH && query.type != query::QueryType::COUNT) {
+    return std::nullopt;
+  }
+
+  // Normalize query and generate cache key
+  const std::string normalized = QueryNormalizer::Normalize(query);
+  if (normalized.empty()) {
+    return std::nullopt;
+  }
+
+  const CacheKey key = CacheKeyGenerator::Generate(normalized);
+
+  // Lookup in cache with metadata
+  QueryCache::LookupMetadata metadata;
+  auto result = query_cache_->LookupWithMetadata(key, metadata);
+  if (!result.has_value()) {
+    return std::nullopt;
+  }
+
+  // Package result with metadata
+  CacheLookupResult lookup_result;
+  lookup_result.results = std::move(result.value());
+  lookup_result.query_cost_ms = metadata.query_cost_ms;
+  lookup_result.created_at = metadata.created_at;
+
+  return lookup_result;
+}
+
 bool CacheManager::Insert(const query::Query& query, const std::vector<DocId>& result,
                           const std::set<std::string>& ngrams, double query_cost_ms) {
   if (!enabled_ || !query_cache_ || !invalidation_mgr_) {
diff --git a/src/cache/cache_manager.h b/src/cache/cache_manager.h
@@ -23,6 +23,15 @@ struct TableContext;
 
 namespace mygramdb::cache {
 
+/**
+ * @brief Cache lookup result with metadata
+ */
+struct CacheLookupResult {
+  std::vector<DocId> results;                        ///< Cached search results
+  double query_cost_ms = 0.0;                        ///< Original query execution time
+  std::chrono::steady_clock::time_point created_at;  ///< When cache entry was created
+};
+
 /**
  * @brief Unified cache manager
  *
@@ -62,6 +71,13 @@ class CacheManager {
    */
   [[nodiscard]] std::optional<std::vector<DocId>> Lookup(const query::Query& query);
 
+  /**
+   * @brief Lookup cached query result with metadata
+   * @param query Parsed query
+   * @return Cached result with metadata if found and valid, nullopt otherwise
+   */
+  [[nodiscard]] std::optional<CacheLookupResult> LookupWithMetadata(const query::Query& query);
+
   /**
    * @brief Insert query result into cache
    * @param query Parsed query
diff --git a/src/cache/query_cache.cpp b/src/cache/query_cache.cpp
@@ -105,6 +105,98 @@ std::optional<std::vector<DocId>> QueryCache::Lookup(const CacheKey& key) {
   return result;
 }
 
+std::optional<std::vector<DocId>> QueryCache::LookupWithMetadata(const CacheKey& key, LookupMetadata& metadata) {
+  // Start timing
+  auto start_time = std::chrono::high_resolution_clock::now();
+
+  // Shared lock for read
+  std::shared_lock lock(mutex_);
+
+  stats_.total_queries++;
+
+  auto iter = cache_map_.find(key);
+  if (iter == cache_map_.end()) {
+    stats_.cache_misses++;
+    stats_.cache_misses_not_found++;
+
+    // Record miss latency
+    auto end_time = std::chrono::high_resolution_clock::now();
+    double miss_time_ms = std::chrono::duration<double, std::milli>(end_time - start_time).count();
+    {
+      std::lock_guard<std::mutex> timing_lock(stats_.timing_mutex_);
+      stats_.total_cache_miss_time_ms += miss_time_ms;
+    }
+
+    return std::nullopt;
+  }
+
+  // Check invalidation flag
+  if (iter->second.first.invalidated.load()) {
+    stats_.cache_misses++;
+    stats_.cache_misses_invalidated++;
+
+    // Record miss latency
+    auto end_time = std::chrono::high_resolution_clock::now();
+    double miss_time_ms = std::chrono::duration<double, std::milli>(end_time - start_time).count();
+    {
+      std::lock_guard<std::mutex> timing_lock(stats_.timing_mutex_);
+      stats_.total_cache_miss_time_ms += miss_time_ms;
+    }
+
+    return std::nullopt;
+  }
+
+  // Cache hit
+  stats_.cache_hits++;
+
+  // Decompress result and copy metadata before releasing lock
+  const auto& entry = iter->second.first;
+  std::vector<DocId> result;
+  try {
+    result = ResultCompressor::Decompress(entry.compressed, entry.original_size);
+  } catch (const std::exception& e) {
+    // Decompression failed, treat as miss
+    stats_.cache_misses++;
+
+    // Record miss latency
+    auto end_time = std::chrono::high_resolution_clock::now();
+    double miss_time_ms = std::chrono::duration<double, std::milli>(end_time - start_time).count();
+    {
+      std::lock_guard<std::mutex> timing_lock(stats_.timing_mutex_);
+      stats_.total_cache_miss_time_ms += miss_time_ms;
+    }
+
+    return std::nullopt;
+  }
+
+  // Copy metadata before releasing lock to avoid use-after-free
+  metadata.query_cost_ms = entry.query_cost_ms;
+  metadata.created_at = entry.metadata.created_at;
+
+  // Update access time (need to upgrade to unique lock)
+  lock.unlock();
+  std::unique_lock write_lock(mutex_);
+
+  // Re-check existence and verify it's the same entry (not a new entry with same key)
+  iter = cache_map_.find(key);
+  if (iter != cache_map_.end() && iter->second.first.metadata.created_at == metadata.created_at) {
+    Touch(key);
+    iter->second.first.metadata.last_accessed = std::chrono::steady_clock::now();
+    iter->second.first.metadata.access_count++;
+
+    // Record hit latency and saved time
+    auto end_time = std::chrono::high_resolution_clock::now();
+    double hit_time_ms = std::chrono::duration<double, std::milli>(end_time - start_time).count();
+    {
+      std::lock_guard<std::mutex> timing_lock(stats_.timing_mutex_);
+      stats_.total_cache_hit_time_ms += hit_time_ms;
+      stats_.total_query_saved_time_ms += metadata.query_cost_ms;  // Time saved by not re-executing
+    }
+  }
+
+  return result;
+}
+
 bool QueryCache::Insert(const CacheKey& key, const std::vector<DocId>& result, const CacheMetadata& metadata,
                         double query_cost_ms) {
   // Check if query cost meets threshold
diff --git a/src/cache/query_cache.h b/src/cache/query_cache.h
@@ -138,13 +138,29 @@ class QueryCache {
   QueryCache(QueryCache&&) = delete;
   QueryCache& operator=(QueryCache&&) = delete;
 
+  /**
+   * @brief Cache lookup result with metadata
+   */
+  struct LookupMetadata {
+    double query_cost_ms = 0.0;                        ///< Original query execution time
+    std::chrono::steady_clock::time_point created_at;  ///< When cache entry was created
+  };
+
   /**
    * @brief Lookup cache entry
    * @param key Cache key
    * @return Decompressed result if found and not invalidated, nullopt otherwise
    */
   [[nodiscard]] std::optional<std::vector<DocId>> Lookup(const CacheKey& key);
 
+  /**
+   * @brief Lookup cache entry with metadata
+   * @param key Cache key
+   * @param[out] metadata Output parameter for cache metadata
+   * @return Decompressed result if found and not invalidated, nullopt otherwise
+   */
+  [[nodiscard]] std::optional<std::vector<DocId>> LookupWithMetadata(const CacheKey& key, LookupMetadata& metadata);
+
   /**
    * @brief Insert cache entry
    * @param key Cache key
diff --git a/src/server/handlers/search_handler.cpp b/src/server/handlers/search_handler.cpp
@@ -34,8 +34,8 @@ std::string SearchHandler::HandleSearch(const query::Query& query, ConnectionCon
   // Try cache lookup first
   auto cache_lookup_start = std::chrono::high_resolution_clock::now();
   if (ctx_.cache_manager != nullptr && ctx_.cache_manager->IsEnabled()) {
-    auto cached_result = ctx_.cache_manager->Lookup(query);
-    if (cached_result.has_value()) {
+    auto cached_lookup = ctx_.cache_manager->LookupWithMetadata(query);
+    if (cached_lookup.has_value()) {
       // Cache hit! Return cached result
       storage::DocumentStore* current_doc_store = nullptr;
       index::Index* dummy_index = nullptr;
@@ -50,22 +50,29 @@ std::string SearchHandler::HandleSearch(const query::Query& query, ConnectionCon
         double cache_lookup_time_ms =
             std::chrono::duration<double, std::milli>(cache_lookup_end - cache_lookup_start).count();
 
+        // Apply pagination to cached results
+        // Cache stores full results (before pagination) to allow different OFFSET/LIMIT on same query
+        auto full_results = cached_lookup.value().results;
+        size_t total_results = full_results.size();
+        auto paginated_results = query::ResultSorter::SortAndPaginate(full_results, *current_doc_store, query);
+
         if (conn_ctx.debug_mode) {
           query::DebugInfo debug_info;
           debug_info.query_time_ms = cache_lookup_time_ms;
-          debug_info.final_results = cached_result.value().size();
+          debug_info.final_results = paginated_results.size();
 
-          // Cache hit debug info
+          // Cache hit debug info with actual metadata
+          auto now = std::chrono::steady_clock::now();
           debug_info.cache_info.status = query::CacheDebugInfo::Status::HIT;
-          debug_info.cache_info.cache_age_ms = 0.0;    // TODO: Calculate from cache entry timestamp
-          debug_info.cache_info.cache_saved_ms = 0.0;  // TODO: Calculate from query cost in cache entry
+          debug_info.cache_info.cache_age_ms =
+              std::chrono::duration<double, std::milli>(now - cached_lookup.value().created_at).count();
+          debug_info.cache_info.cache_saved_ms = cached_lookup.value().query_cost_ms;
 
-          return ResponseFormatter::FormatSearchResponse(cached_result.value(), cached_result.value().size(),
-                                                         current_doc_store, &debug_info);
+          return ResponseFormatter::FormatSearchResponse(paginated_results, total_results, current_doc_store,
+                                                         &debug_info);
         }
 
-        return ResponseFormatter::FormatSearchResponse(cached_result.value(), cached_result.value().size(),
-                                                       current_doc_store);
+        return ResponseFormatter::FormatSearchResponse(paginated_results, total_results, current_doc_store);
       }
     }
   }
@@ -290,6 +297,35 @@ std::string SearchHandler::HandleCount(const query::Query& query, ConnectionCont
     return ResponseFormatter::FormatError("Server is loading, please try again later");
   }
 
+  // Try cache lookup first
+  auto cache_lookup_start = std::chrono::high_resolution_clock::now();
+  if (ctx_.cache_manager != nullptr && ctx_.cache_manager->IsEnabled()) {
+    auto cached_lookup = ctx_.cache_manager->LookupWithMetadata(query);
+    if (cached_lookup.has_value()) {
+      // Cache hit! Return count from cached result
+      auto cache_lookup_end = std::chrono::high_resolution_clock::now();
+      double cache_lookup_time_ms =
+          std::chrono::duration<double, std::milli>(cache_lookup_end - cache_lookup_start).count();
+
+      if (conn_ctx.debug_mode) {
+        query::DebugInfo debug_info;
+        debug_info.query_time_ms = cache_lookup_time_ms;
+        debug_info.final_results = cached_lookup.value().results.size();
+
+        // Cache hit debug info with actual metadata
+        auto now = std::chrono::steady_clock::now();
+        debug_info.cache_info.status = query::CacheDebugInfo::Status::HIT;
+        debug_info.cache_info.cache_age_ms =
+            std::chrono::duration<double, std::milli>(now - cached_lookup.value().created_at).count();
+        debug_info.cache_info.cache_saved_ms = cached_lookup.value().query_cost_ms;
+
+        return ResponseFormatter::FormatCountResponse(cached_lookup.value().results.size(), &debug_info);
+      }
+
+      return ResponseFormatter::FormatCountResponse(cached_lookup.value().results.size());
+    }
+  }
+
   // Get table context
   index::Index* current_index = nullptr;
   storage::DocumentStore* current_doc_store = nullptr;
@@ -364,11 +400,37 @@ std::string SearchHandler::HandleCount(const query::Query& query, ConnectionCont
     results = ApplyFilters(results, query.filters, current_doc_store);
   }
 
+  // Calculate query execution time
+  auto end_time = std::chrono::high_resolution_clock::now();
+  double query_time_ms = std::chrono::duration<double, std::milli>(end_time - start_time).count();
+
+  // Store in cache if enabled
+  if (ctx_.cache_manager != nullptr && ctx_.cache_manager->IsEnabled()) {
+    // Collect all ngrams from term_infos
+    std::set<std::string> all_ngrams;
+    for (const auto& term_info : term_infos) {
+      all_ngrams.insert(term_info.ngrams.begin(), term_info.ngrams.end());
+    }
+
+    // Insert result into cache (COUNT caches the full result set like SEARCH)
+    ctx_.cache_manager->Insert(query, results, all_ngrams, query_time_ms);
+  }
+
   // Calculate final debug info
   if (conn_ctx.debug_mode) {
-    auto end_time = std::chrono::high_resolution_clock::now();
-    debug_info.query_time_ms = std::chrono::duration<double, std::milli>(end_time - start_time).count();
+    debug_info.query_time_ms = query_time_ms;
     debug_info.index_time_ms = std::chrono::duration<double, std::milli>(end_time - index_start).count();
+
+    // Cache debug info
+    if (ctx_.cache_manager != nullptr && ctx_.cache_manager->IsEnabled()) {
+      // Cache was enabled but missed (either not found or invalidated)
+      debug_info.cache_info.status = query::CacheDebugInfo::Status::MISS_NOT_FOUND;
+      debug_info.cache_info.query_cost_ms = query_time_ms;
+    } else {
+      // Cache disabled
+      debug_info.cache_info.status = query::CacheDebugInfo::Status::MISS_DISABLED;
+    }
+
     return ResponseFormatter::FormatCountResponse(results.size(), &debug_info);
   }
 
diff --git a/src/server/response_formatter.cpp b/src/server/response_formatter.cpp
@@ -122,6 +122,29 @@ std::string ResponseFormatter::FormatCountResponse(uint64_t count, const query::
     oss << "index_time: " << debug_info->index_time_ms << "ms\r\n";
     oss << "terms: " << debug_info->search_terms.size() << "\r\n";
     oss << "ngrams: " << debug_info->ngrams_used.size() << "\r\n";
+
+    // Cache debug information
+    switch (debug_info->cache_info.status) {
+      case query::CacheDebugInfo::Status::HIT:
+        oss << "cache: hit\r\n";
+        oss << "cache_age_ms: " << std::fixed << std::setprecision(3) << debug_info->cache_info.cache_age_ms << "\r\n";
+        oss << "cache_saved_ms: " << std::fixed << std::setprecision(3) << debug_info->cache_info.cache_saved_ms
+            << "\r\n";
+        break;
+      case query::CacheDebugInfo::Status::MISS_NOT_FOUND:
+        oss << "cache: miss (not found)\r\n";
+        oss << "query_cost_ms: " << std::fixed << std::setprecision(3) << debug_info->cache_info.query_cost_ms
+            << "\r\n";
+        break;
+      case query::CacheDebugInfo::Status::MISS_INVALIDATED:
+        oss << "cache: miss (invalidated)\r\n";
+        break;
+      case query::CacheDebugInfo::Status::MISS_DISABLED:
+        oss << "cache: disabled\r\n";
+        break;
+      default:
+        break;
+    }
   }
 
   return oss.str();
diff --git a/tests/server/CMakeLists.txt b/tests/server/CMakeLists.txt
@@ -210,3 +210,37 @@ target_link_libraries(request_dispatcher_test
 gtest_discover_tests(request_dispatcher_test
   PROPERTIES RESOURCE_LOCK server_port
 )
+
+# Integration: Cache Pagination tests
+# Tests for SEARCH query caching with OFFSET/LIMIT
+
+add_executable(integration_cache_pagination_test
+  integration_cache_pagination_test.cpp
+)
+
+target_link_libraries(integration_cache_pagination_test
+  mygramdb_server
+  GTest::gtest_main
+)
+
+# RESOURCE_LOCK: Prevent parallel execution to avoid port binding and cache state conflicts
+gtest_discover_tests(integration_cache_pagination_test
+  PROPERTIES RESOURCE_LOCK server_port
+)
+
+# Integration: Cache COUNT tests
+# Tests for COUNT query caching
+
+add_executable(integration_cache_count_test
+  integration_cache_count_test.cpp
+)
+
+target_link_libraries(integration_cache_count_test
+  mygramdb_server
+  GTest::gtest_main
+)
+
+# RESOURCE_LOCK: Prevent parallel execution to avoid port binding and cache state conflicts
+gtest_discover_tests(integration_cache_count_test
+  PROPERTIES RESOURCE_LOCK server_port
+)
diff --git a/tests/server/integration_cache_count_test.cpp b/tests/server/integration_cache_count_test.cpp
diff --git a/tests/server/integration_cache_pagination_test.cpp b/tests/server/integration_cache_pagination_test.cpp
