Getting ready for dev

Author: claude

cache/__tests__/cache-metrics-worst-case.sh

@@ -1077,12 +1077,11 @@ cleanup_test_objects() {
 
 generate_report() {
     log_header "Generating Report"
-    
+
     local cache_stats=$(get_cache_stats)
     local cache_hits=$(echo "$cache_stats" | grep -o '"hits":[0-9]*' | cut -d: -f2)
     local cache_misses=$(echo "$cache_stats" | grep -o '"misses":[0-9]*' | cut -d: -f2)
     local cache_size=$(echo "$cache_stats" | grep -o '"length":[0-9]*' | cut -d: -f2)
-    local cache_invalidations=$(echo "$cache_stats" | grep -o '"invalidations":[0-9]*' | cut -d: -f2)
 
     cat > "$REPORT_FILE" << EOF
 # RERUM Cache Metrics & Functionality Report
@@ -1105,7 +1104,6 @@ generate_report() {
 | Cache Misses | ${cache_misses:-0} |
 | Hit Rate | $(echo "$cache_stats" | grep -o '"hitRate":"[^"]*"' | cut -d'"' -f4) |
 | Cache Size | ${cache_size:-0} entries |
-| Invalidations | ${cache_invalidations:-0} |
 
 ---
 
@@ -1315,7 +1313,7 @@ The cache layer provides:
 In production, monitor:
 - **Hit rate**: Target 60-80% for optimal benefit
 - **Evictions**: Should be minimal; increase cache size if frequent
-- **Invalidation count**: Should correlate with write operations
+- **Cache size changes**: Track cache size over time to understand invalidation patterns
 - **Response times**: Track p50, p95, p99 for all endpoints
 
 ### ⚙️ Configuration Tuning
@@ -2237,28 +2235,48 @@ main() {
     # Get starting state at beginning of Phase 5
     local stats_before_phase5=$(get_cache_stats)
     local starting_cache_size=$(echo "$stats_before_phase5" | grep -o '"length":[0-9]*' | sed 's/"length"://')
-    local invalidations_before_phase5=$(echo "$stats_before_phase5" | grep -o '"invalidations":[0-9]*' | sed 's/"invalidations"://')
-    
+    local starting_evictions=$(echo "$stats_before_phase5" | grep -o '"evictions":[0-9]*' | sed 's/"evictions"://')
+
+    # Track invalidations ourselves (app doesn't track them)
+    # Invalidations = cache size decrease from write operations
+    local total_invalidations=0
+
     log_info "=== PHASE 5 STARTING STATE ==="
     log_info "Starting cache size: $starting_cache_size entries"
-    log_info "Invalidations before Phase 5: $invalidations_before_phase5"
     log_info "Phase 3 filled cache with queries matching Phase 5 write operation types"
     log_info "Each write operation should invalidate multiple cache entries"
+    log_info "Test will calculate invalidations as cache size decrease per write operation"
 
     echo "[INFO] Running write endpoint tests..."
 
     # Cache is already full from Phase 3 - reuse it without refilling
 
-    # Helper function to log cache changes
+    # Helper function to log cache changes and calculate invalidations
+    # Write operations don't add cache entries, so size decrease = invalidations
+    local size_before=$starting_cache_size
+
     track_cache_change() {
         local operation=$1
         local stats=$(get_cache_stats)
-        local size=$(echo "$stats" | grep -o '"length":[0-9]*' | sed 's/"length"://')
-        local invalidations=$(echo "$stats" | grep -o '"invalidations":[0-9]*' | sed 's/"invalidations"://')
+        local size_after=$(echo "$stats" | grep -o '"length":[0-9]*' | sed 's/"length"://')
         local evictions=$(echo "$stats" | grep -o '"evictions":[0-9]*' | sed 's/"evictions"://')
-        local sets=$(echo "$stats" | grep -o '"sets":[0-9]*' | sed 's/"sets"://')
-        
-        echo "[CACHE TRACK] After $operation: size=$size, invalidations=$invalidations (Δ+$((invalidations - invalidations_before_phase5))), evictions=$evictions, sets=$sets" >&2
+
+        # Calculate invalidations for this operation
+        # Write operations don't add cache entries, so size decrease = invalidations only
+        local operation_invalidations=$((size_before - size_after))
+
+        # Ensure non-negative
+        if [ $operation_invalidations -lt 0 ]; then
+            operation_invalidations=0
+        fi
+
+        # Accumulate total
+        total_invalidations=$((total_invalidations + operation_invalidations))
+
+        echo "[CACHE TRACK] After $operation: size=$size_after (Δ-$operation_invalidations invalidations), evictions=$evictions, total_invalidations=$total_invalidations" >&2
+
+        # Update size for next operation
+        size_before=$size_after
     }
 
     # DEBUG: Log cache state before each write test
@@ -2286,34 +2304,41 @@ main() {
 
     test_delete_endpoint_full
 
-    log_info "Waiting for cache invalidations and stats to sync across all PM2 workers..."
+    log_info "Waiting for cache stats to sync across all PM2 workers..."
     log_info "Stats sync every 5 seconds - waiting 12 seconds to ensure at least two sync cycles complete..."
     sleep 12
-    
+
     local stats_after_phase5=$(get_cache_stats)
     local final_cache_size=$(echo "$stats_after_phase5" | grep -o '"length":[0-9]*' | sed 's/"length"://')
-    local invalidations_after_phase5=$(echo "$stats_after_phase5" | grep -o '"invalidations":[0-9]*' | sed 's/"invalidations"://')
-    
-    local total_invalidations=$((invalidations_after_phase5 - invalidations_before_phase5))
-    local actual_entries_removed=$((starting_cache_size - final_cache_size))
-    
-    local total_invalidations=$((invalidations_after_phase5 - invalidations_before_phase5))
+    local final_evictions=$(echo "$stats_after_phase5" | grep -o '"evictions":[0-9]*' | sed 's/"evictions"://')
+
     local actual_entries_removed=$((starting_cache_size - final_cache_size))
+    local total_evictions=$((final_evictions - starting_evictions))
+
+    # total_invalidations was calculated incrementally by track_cache_change()
+    # Verify it matches our overall size reduction (should be close, minor differences due to timing)
+    if [ $total_invalidations -ne $actual_entries_removed ]; then
+        local diff=$((actual_entries_removed - total_invalidations))
+        if [ ${diff#-} -gt 2 ]; then  # Allow ±2 difference for timing
+            log_warning "Invalidation count variance: incremental=$total_invalidations, overall_removed=$actual_entries_removed (diff: $diff)"
+        fi
+    fi
 
     echo ""
     log_info "=== PHASE 5 FINAL RESULTS ==="
     log_info "Starting cache size: $starting_cache_size entries (after adding 5 test queries)"
     log_info "Final cache size: $final_cache_size entries"
-    log_info "Actual entries removed: $actual_entries_removed entries"
+    log_info "Total cache size reduction: $actual_entries_removed entries"
+    log_info "Calculated invalidations: $total_invalidations entries (from write operations)"
+    log_info "LRU evictions during phase: $total_evictions (separate from invalidations)"
     log_info ""
     log_info "=== PHASE 5 CACHE ACCOUNTING ==="
     log_info "Initial state: ${starting_cache_size} entries"
     log_info "  - Cache filled to 1000 in Phase 3"
     log_info "  - Added 5 query entries for write tests (matched test object types)"
-    log_info "  - Starting invalidations: ${invalidations_before_phase5}"
     log_info ""
     log_info "Write operations performed:"
-    log_info "  - create: 100 operations (no existing data, minimal invalidation)"
+    log_info "  - create: 100 operations (minimal invalidation - no existing data)"
     log_info "  - update: 50 operations (invalidates id:*, history:*, since:*, matching queries)"
     log_info "  - patch: 50 operations (invalidates id:*, history:*, since:*, matching queries)"
     log_info "  - set: 50 operations (invalidates id:*, history:*, since:*, matching queries)"
@@ -2322,28 +2347,21 @@ main() {
     log_info "  - delete: 50 operations (invalidates id:*, history:*, since:* for each)"
     log_info ""
     log_info "Final state: ${final_cache_size} entries"
-    log_info "  - Entries removed: ${actual_entries_removed}"
-    log_info "  - Invalidations recorded: ${total_invalidations}"
-    log_info "  - Final invalidations: ${invalidations_after_phase5}"
+    log_info "  - Invalidations from writes: ${total_invalidations}"
+    log_info "  - LRU evictions (separate): ${total_evictions}"
+    log_info "  - Total size reduction: ${actual_entries_removed}"
     echo ""
 
-    # Validate that invalidations and removals are in the expected range
+    # Validate that calculated invalidations are in the expected range
     if [ -n "$final_cache_size" ] && [ -n "$total_invalidations" ]; then
-        # Calculate difference between invalidations and actual removals
-        local invalidation_diff=$((total_invalidations - actual_entries_removed))
-        local invalidation_diff_abs=${invalidation_diff#-}  # Absolute value
-        
-        # Important: invalidations count entries actually deleted from cache
-        # actual_entries_removed may be larger because it includes:
-        # - Invalidations (entries deleted)
-        # - LRU evictions (entries removed due to cache limits)
-        # - Entries that didn't exist (e.g., id:* keys never cached)
-        #
+        # total_invalidations = cumulative cache size decrease from each write operation
+        # This represents entries removed by invalidation logic during writes
+
         # For DELETE operations:
         # - Each DELETE tries to invalidate 3 keys: id:*, history:*, since:*
         # - But id:* only exists if /id/:id was called for that object
-        # - history:* and since:* always exist (created during reads)
-        # - So we expect ~2 invalidations per DELETE (not 3)
+        # - history:* and since:* are created during read operations
+        # - So we expect ~2 invalidations per DELETE on average (not 3)
 
         # Calculate expected invalidations based on test operations
         local num_deletes=50
@@ -2366,22 +2384,25 @@ main() {
             log_info "Note: Variance can occur if some objects were cached via /id/:id endpoint"
         fi
 
-        # Additional check for suspiciously low invalidation counts (stats sync issue)
+        # Additional check for suspiciously low invalidation counts
         if [ $total_invalidations -lt 25 ]; then
             log_warning "⚠️  Invalidation count ($total_invalidations) is lower than expected minimum (~25)"
-            log_info "This is likely due to PM2 cluster stats aggregation timing"
-            log_info "Cache behavior is correct (${actual_entries_removed} entries removed), but stats under-reported"
-            log_info "Note: Stats sync wait time is 12s - if this warning persists, check atomic increment implementation"
+            log_info "Possible causes:"
+            log_info "  - Write operations may not have matched many cached queries"
+            log_info "  - Phase 3 cache fill may not have created many matching entries"
+            log_info "  - Total size reduction: ${actual_entries_removed}, Invalidations tracked: ${total_invalidations}"
         fi
-        
-        # Verify the relationship: actual_entries_removed >= total_invalidations
-        # (removals include invalidations + evictions + non-existent keys)
-        if [ $actual_entries_removed -ge $total_invalidations ]; then
-            log_success "✅ Cache behavior correct: $actual_entries_removed entries removed ≥ $total_invalidations invalidations"
-            log_info "Difference ($invalidation_diff_abs) includes: LRU evictions, non-existent keys, or cluster sync timing"
+
+        # Verify invalidations are reasonable (should be most of the size reduction)
+        # Note: Evictions happen asynchronously during reads, not during writes
+        # So invalidations should be close to total size reduction
+        if [ $total_invalidations -eq $actual_entries_removed ]; then
+            log_success "✅ All cache size reduction from invalidations: $total_invalidations entries"
+        elif [ $((actual_entries_removed - total_invalidations)) -le 5 ]; then
+            log_success "✅ Most cache reduction from invalidations: $total_invalidations of $actual_entries_removed entries"
         else
-            log_warning "⚠️  Unexpected: fewer entries removed ($actual_entries_removed) than invalidations ($total_invalidations)"
-            log_info "This may indicate an issue with invalidation tracking"
+            log_info "ℹ️  Cache reduction: $total_invalidations invalidations, $actual_entries_removed total removed"
+            log_info "Difference may be due to concurrent operations or timing between measurements"
         fi
 
         # Report cache size reduction