@@ -100,6 +100,26 @@ log_overhead() {
100100 fi
101101}
102102
103+ check_wsl2_time_sync () {
104+ # Check if running on WSL2
105+ if grep -qEi " (Microsoft|WSL)" & > /dev/null; then
106+ log_info " WSL2 detected - checking system time synchronization..."
107+
108+ # Try to sync hardware clock to system time (requires sudo)
109+ if command -v hwclock & > /dev/null; then
110+ if sudo -n hwclock -s & > /dev/null 2>&1 ; then
111+ log_success " System time synchronized with hardware clock"
112+ else
113+ log_warning " Could not sync hardware clock (sudo required)"
114+ log_info " To fix clock skew issues, run: sudo hwclock -s"
115+ log_info " Continuing anyway - some timing measurements may show warnings"
116+ fi
117+ else
118+ log_info " hwclock not available - skipping time sync"
119+ fi
120+ fi
121+ }
122+
103123check_server () {
104124 log_info " Checking server connectivity at ${BASE_URL} ..."
105125 if ! curl -s -f " ${BASE_URL} " > /dev/null 2>&1 ; then
@@ -528,9 +548,10 @@ fill_cache() {
528548 # We need to wait long enough to ensure the NEXT sync cycle completes AFTER all requests finish
529549 # Worst case: sync happened 0.1s ago, next sync in 4.9s, need to wait >4.9s for that sync,
530550 # plus a buffer for the sync operation itself to complete
551+ # Updated to 12s to ensure atomic stat increments are fully synced across all workers
531552 log_info " Waiting for cache operations to complete and stats to sync across all PM2 workers..."
532- log_info " Stats sync every 5 seconds - waiting 8 seconds to ensure at least one sync after requests ..."
533- sleep 8
553+ log_info " Stats sync every 5 seconds - waiting 12 seconds to ensure at least two sync cycles complete ..."
554+ sleep 12
534555
535556 # Sanity check: Verify cache actually contains entries
536557 log_info " Sanity check - Verifying cache size after fill..."
@@ -1471,24 +1492,27 @@ test_update_endpoint_empty() {
14711492 if [ $empty_success -eq 0 ]; then
14721493 log_failure " Update endpoint failed (all requests failed)"
14731494 ENDPOINT_STATUS[" update" " ❌ Failed"
1474- return
1475- elif [ $empty_failures -gt 0 ]; then
1476- log_warning " $empty_success /$NUM_ITERATIONS successful"
1477- log_warning " Update endpoint had partial failures: $empty_failures /$NUM_ITERATIONS failed"
1478- ENDPOINT_STATUS[" update" " ⚠️ Partial Failures ($empty_failures /$NUM_ITERATIONS )"
1495+ ENDPOINT_COLD_TIMES[" update"
14791496 return
14801497 fi
1481-
1482- log_success " $empty_success /$NUM_ITERATIONS successful"
1483-
1498+
1499+ # Calculate average and median even with partial failures
14841500 local empty_avg=$(( empty_total / empty_success))
14851501 IFS=$' \n ' $( sort -n <<< " ${empty_times[*]}" )
14861502 unset IFS
14871503 local empty_median=${sorted_empty[$((empty_success / 2))]}
1488-
1504+
14891505 ENDPOINT_COLD_TIMES[" update" $empty_avg
1490- log_success " Update endpoint functional"
1491- ENDPOINT_STATUS[" update" " ✅ Functional"
1506+
1507+ if [ $empty_failures -gt 0 ]; then
1508+ log_warning " $empty_success /$NUM_ITERATIONS successful"
1509+ log_warning " Update endpoint had partial failures: $empty_failures /$NUM_ITERATIONS failed"
1510+ ENDPOINT_STATUS[" update" " ⚠️ Partial Failures ($empty_failures /$NUM_ITERATIONS )"
1511+ else
1512+ log_success " $empty_success /$NUM_ITERATIONS successful"
1513+ log_success " Update endpoint functional"
1514+ ENDPOINT_STATUS[" update" " ✅ Functional"
1515+ fi
14921516}
14931517
14941518# Update endpoint - full cache version
@@ -1560,16 +1584,21 @@ test_update_endpoint_full() {
15601584 local full_median=${sorted_full[$((full_success / 2))]}
15611585
15621586 ENDPOINT_WARM_TIMES[" update" $full_avg
1563-
1564- local empty_avg=${ENDPOINT_COLD_TIMES["update"]}
1565- local overhead=$(( full_avg - empty_avg))
1566- local overhead_pct=$(( overhead * 100 / empty_avg))
1567-
1568- # Display clamped value (0 or positive) but store actual value for report
1569- if [ $overhead -lt 0 ]; then
1570- log_overhead 0 " Cache invalidation overhead: 0ms (negligible - within statistical variance)"
1587+
1588+ local empty_avg=${ENDPOINT_COLD_TIMES["update"]:- 0}
1589+
1590+ if [ " $empty_avg " -eq 0 ] || [ -z " $empty_avg " ; then
1591+ log_warning " Cannot calculate overhead - baseline test had no successful operations"
15711592 else
1572- log_overhead $overhead " Cache invalidation overhead: ${overhead} ms (${overhead_pct} %)"
1593+ local overhead=$(( full_avg - empty_avg))
1594+ local overhead_pct=$(( overhead * 100 / empty_avg))
1595+
1596+ # Display clamped value (0 or positive) but store actual value for report
1597+ if [ $overhead -lt 0 ]; then
1598+ log_overhead 0 " Cache invalidation overhead: 0ms (negligible - within statistical variance)"
1599+ else
1600+ log_overhead $overhead " Cache invalidation overhead: ${overhead} ms (${overhead_pct} %)"
1601+ fi
15731602 fi
15741603}
15751604
@@ -2026,8 +2055,9 @@ main() {
20262055 echo " 4B. Test read endpoints with CACHE MISSES (measure overhead + evictions)"
20272056 echo " 5. Test write endpoints with FULL cache (measure invalidation overhead vs baseline)"
20282057 echo " "
2029-
2058+
20302059 # Setup
2060+ check_wsl2_time_sync
20312061 check_server
20322062 get_auth_token
20332063 warmup_system
@@ -2336,9 +2366,10 @@ main() {
23362366 # Wait for cache to sync across all workers before checking final stats
23372367 # Background stats sync happens every 5 seconds starting from server boot
23382368 # We need to wait long enough to ensure the NEXT sync cycle completes AFTER all writes finish
2369+ # Updated to 12s to ensure atomic stat increments are fully synced across all workers
23392370 log_info " Waiting for cache invalidations and stats to sync across all PM2 workers..."
2340- log_info " Stats sync every 5 seconds - waiting 8 seconds to ensure at least one sync after writes ..."
2341- sleep 8
2371+ log_info " Stats sync every 5 seconds - waiting 12 seconds to ensure at least two sync cycles complete ..."
2372+ sleep 12
23422373
23432374 # Get cache stats after Phase 5 writes
23442375 local stats_after_phase5=$( get_cache_stats)
@@ -2422,6 +2453,14 @@ main() {
24222453 log_info " ℹ️ Invalidation count: $total_invalidations (expected ~$expected_total_invalidations )"
24232454 log_info " Note: Variance can occur if some objects were cached via /id/:id endpoint"
24242455 fi
2456+
2457+ # Additional check for suspiciously low invalidation counts (stats sync issue)
2458+ if [ $total_invalidations -lt 25 ]; then
2459+ log_warning " ⚠️ Invalidation count ($total_invalidations ) is lower than expected minimum (~25)"
2460+ log_info " This is likely due to PM2 cluster stats aggregation timing"
2461+ log_info " Cache behavior is correct (${actual_entries_removed} entries removed), but stats under-reported"
2462+ log_info " Note: Stats sync wait time is 12s - if this warning persists, check atomic increment implementation"
2463+ fi
24252464
24262465 # Verify the relationship: actual_entries_removed >= total_invalidations
24272466 # (removals include invalidations + evictions + non-existent keys)
0 commit comments