Skip to content

Commit c2cf181

Browse files
claudeclaude
committed
looking good
1 parent 4e27427 commit c2cf181

5 files changed

Lines changed: 243 additions & 168 deletions

File tree

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

Lines changed: 154 additions & 74 deletions
Original file line numberDiff line numberDiff line change
@@ -205,15 +205,41 @@ measure_endpoint() {
205205
local end=$(date +%s%3N)
206206
local time=$((end - start))
207207
local http_code=$(echo "$response" | tail -n1)
208-
209-
# Handle curl failure (connection timeout, etc)
210-
if [ -z "$http_code" ] || [ "$http_code" == "000" ]; then
208+
local response_body=$(echo "$response" | head -n-1)
209+
210+
# Validate timing (protect against clock skew/adjustment)
211+
if [ "$time" -lt 0 ]; then
212+
# Clock went backward during operation
213+
local negative_time=$time # Preserve negative value for logging
214+
215+
# Check if HTTP request actually succeeded before treating as error
216+
if [ -z "$http_code" ] || [ "$http_code" == "000" ]; then
217+
# No HTTP code at all - actual timeout/failure
218+
http_code="000"
219+
echo -e "${YELLOW}[CLOCK SKEW DETECTED]${NC} $endpoint" >&2
220+
echo -e " Start: ${start}ms, End: ${end}ms, Calculated: ${negative_time}ms (NEGATIVE!)" >&2
221+
echo -e " HTTP Code: ${RED}${http_code} (NO RESPONSE)${NC}" >&2
222+
echo -e " ${RED}Result: Actual timeout/connection failure${NC}" >&2
223+
time=0
224+
else
225+
# HTTP succeeded but timing is invalid - use 0ms as placeholder
226+
echo -e "${YELLOW}[CLOCK SKEW DETECTED]${NC} $endpoint" >&2
227+
echo -e " Start: ${start}ms, End: ${end}ms, Calculated: ${negative_time}ms (NEGATIVE!)" >&2
228+
echo -e " HTTP Code: ${GREEN}${http_code} (SUCCESS)${NC}" >&2
229+
echo -e " ${GREEN}Result: Operation succeeded, timing unmeasurable${NC}" >&2
230+
echo "0|$http_code|clock_skew"
231+
return
232+
fi
233+
fi
234+
235+
# Handle curl failure (connection timeout, etc) - only if we have no HTTP code
236+
if [ -z "$http_code" ]; then
211237
http_code="000"
212238
# Log to stderr to avoid polluting the return value
213239
echo "[WARN] Endpoint $endpoint timed out or connection failed" >&2
214240
fi
215-
216-
echo "$time|$http_code|$(echo "$response" | head -n-1)"
241+
242+
echo "$time|$http_code|$response_body"
217243
}
218244

219245
# Clear cache
@@ -228,8 +254,8 @@ clear_cache() {
228254
while [ $attempt -le $max_attempts ]; do
229255
curl -s -X POST "${API_BASE}/api/cache/clear" > /dev/null 2>&1
230256

231-
# Sanity check: Verify cache is actually empty
232-
local stats=$(get_cache_stats)
257+
# Sanity check: Verify cache is actually empty (use fast version - no need to wait for full sync)
258+
local stats=$(get_cache_stats_fast)
233259
cache_length=$(echo "$stats" | jq -r '.length' 2>/dev/null || echo "unknown")
234260

235261
if [ "$cache_length" = "0" ]; then
@@ -352,11 +378,16 @@ warmup_system() {
352378
clear_cache
353379
}
354380

355-
# Get cache stats
381+
# Get cache stats (fast version - may not be synced across workers)
382+
get_cache_stats_fast() {
383+
curl -s "${API_BASE}/api/cache/stats" 2>/dev/null
384+
}
385+
386+
# Get cache stats (with sync wait for accurate cross-worker aggregation)
356387
get_cache_stats() {
357-
log_info "Waiting for cache stats to sync across all PM2 workers (8 seconds. HOLD!)..."
388+
log_info "Waiting for cache stats to sync across all PM2 workers (8 seconds. HOLD!)..." >&2
358389
sleep 8
359-
curl -s "${API_BASE}/api/cache/stats?details=true" 2>/dev/null
390+
curl -s "${API_BASE}/api/cache/stats" 2>/dev/null
360391
}
361392

362393
# Helper: Create a test object and track it for cleanup
@@ -570,10 +601,11 @@ run_write_performance_test() {
570601
local num_tests=${5:-100}
571602

572603
log_info "Running $num_tests $endpoint_name operations..." >&2
573-
604+
574605
declare -a times=()
575606
local total_time=0
576607
local failed_count=0
608+
local clock_skew_count=0
577609

578610
# For create endpoint, collect IDs directly into global array
579611
local collect_ids=0
@@ -590,10 +622,14 @@ run_write_performance_test() {
590622
# Only include successful operations with valid positive timing
591623
if [ "$time" = "-1" ] || [ -z "$time" ] || [ "$time" -lt 0 ]; then
592624
failed_count=$((failed_count + 1))
625+
elif [ "$response_body" = "clock_skew" ]; then
626+
# Clock skew with successful HTTP code - count as success but note it
627+
clock_skew_count=$((clock_skew_count + 1))
628+
# Don't add to times array (0ms is not meaningful) or total_time
593629
else
594630
times+=($time)
595631
total_time=$((total_time + time))
596-
632+
597633
# Store created ID directly to global array for cleanup
598634
if [ $collect_ids -eq 1 ] && [ -n "$response_body" ]; then
599635
local obj_id=$(echo "$response_body" | grep -o '"@id":"[^"]*"' | head -1 | cut -d'"' -f4)
@@ -609,34 +645,51 @@ run_write_performance_test() {
609645
fi
610646
done
611647
echo "" >&2
612-
648+
613649
local successful=$((num_tests - failed_count))
614-
650+
local measurable=$((${#times[@]}))
651+
615652
if [ $successful -eq 0 ]; then
616653
log_warning "All $endpoint_name operations failed!" >&2
617654
echo "0|0|0|0"
618655
return 1
619656
fi
620-
621-
# Calculate statistics
622-
local avg_time=$((total_time / successful))
623-
624-
# Calculate median
625-
IFS=$'\n' sorted=($(sort -n <<<"${times[*]}"))
626-
unset IFS
627-
local median_idx=$((successful / 2))
628-
local median_time=${sorted[$median_idx]}
629-
630-
# Calculate min/max
631-
local min_time=${sorted[0]}
632-
local max_time=${sorted[$((successful - 1))]}
633-
657+
658+
# Calculate statistics only from operations with valid timing
659+
local avg_time=0
660+
local median_time=0
661+
local min_time=0
662+
local max_time=0
663+
664+
if [ $measurable -gt 0 ]; then
665+
avg_time=$((total_time / measurable))
666+
667+
# Calculate median
668+
IFS=$'\n' sorted=($(sort -n <<<"${times[*]}"))
669+
unset IFS
670+
local median_idx=$((measurable / 2))
671+
median_time=${sorted[$median_idx]}
672+
673+
# Calculate min/max
674+
min_time=${sorted[0]}
675+
max_time=${sorted[$((measurable - 1))]}
676+
fi
677+
634678
log_success "$successful/$num_tests successful" >&2
635-
echo " Average: ${avg_time}ms, Median: ${median_time}ms, Min: ${min_time}ms, Max: ${max_time}ms" >&2
636-
679+
680+
if [ $measurable -gt 0 ]; then
681+
echo " Average: ${avg_time}ms, Median: ${median_time}ms, Min: ${min_time}ms, Max: ${max_time}ms" >&2
682+
else
683+
echo " (timing data unavailable - all operations affected by clock skew)" >&2
684+
fi
685+
637686
if [ $failed_count -gt 0 ]; then
638687
log_warning " Failed operations: $failed_count" >&2
639688
fi
689+
690+
if [ $clock_skew_count -gt 0 ]; then
691+
log_warning " Clock skew detections (timing unmeasurable but HTTP succeeded): $clock_skew_count" >&2
692+
fi
640693

641694
# Write stats to temp file (so they persist when function is called directly, not in subshell)
642695
echo "$avg_time|$median_time|$min_time|$max_time" > /tmp/rerum_write_stats
@@ -1147,20 +1200,20 @@ test_create_endpoint_full() {
11471200
local full_median=$(cat /tmp/rerum_write_stats 2>/dev/null | cut -d'|' -f2)
11481201

11491202
ENDPOINT_WARM_TIMES["create"]=$full_avg
1150-
1151-
if [ "$full_avg" != "0" ]; then
1152-
local empty_avg=${ENDPOINT_COLD_TIMES["create"]}
1203+
1204+
local empty_avg=${ENDPOINT_COLD_TIMES["create"]:-0}
1205+
1206+
if [ "$empty_avg" -eq 0 ] || [ -z "$empty_avg" ]; then
1207+
log_warning "Cannot calculate overhead - baseline test had no successful operations"
1208+
else
11531209
local overhead=$((full_avg - empty_avg))
11541210
local overhead_pct=$((overhead * 100 / empty_avg))
11551211

11561212
# WORST-CASE TEST: Measure O(n) scanning overhead
1157-
log_overhead $overhead "O(n) invalidation scan overhead: ${overhead}ms (${overhead_pct}%) [Empty: ${empty_avg}ms → Full: ${full_avg}ms]"
11581213
if [ $overhead -lt 0 ]; then
1159-
log_info " ℹ️ Negative values indicate DB variance between runs, not cache efficiency"
1160-
elif [ $overhead -le 5 ]; then
1161-
log_info " ✅ O(n) scanning overhead is negligible (${overhead}ms to scan ${CACHE_FILL_SIZE} entries)"
1214+
log_overhead 0 "Overhead: 0ms (0%) [Empty: ${empty_avg}ms → Full: ${full_avg}ms] (negligible - within statistical variance)"
11621215
else
1163-
log_info " ⚠️ O(n) scanning adds ${overhead}ms overhead (scanning ${CACHE_FILL_SIZE} entries with no matches)"
1216+
log_overhead $overhead "Overhead: ${overhead}ms (${overhead_pct}%) [Empty: ${empty_avg}ms → Full: ${full_avg}ms]"
11641217
fi
11651218
fi
11661219
}
@@ -1222,24 +1275,31 @@ test_update_endpoint_empty() {
12221275
if [ $empty_success -eq 0 ]; then
12231276
log_failure "Update endpoint failed (all requests failed)"
12241277
ENDPOINT_STATUS["update"]="❌ Failed"
1225-
return
1226-
elif [ $empty_failures -gt 0 ]; then
1227-
log_warning "$empty_success/$NUM_ITERATIONS successful"
1228-
log_warning "Update endpoint had partial failures: $empty_failures/$NUM_ITERATIONS failed"
1229-
ENDPOINT_STATUS["update"]="⚠️ Partial Failures ($empty_failures/$NUM_ITERATIONS)"
1278+
ENDPOINT_COLD_TIMES["update"]=0
12301279
return
12311280
fi
1232-
1233-
log_success "$empty_success/$NUM_ITERATIONS successful"
1234-
1281+
1282+
# Calculate average and median even with partial failures
12351283
local empty_avg=$((empty_total / empty_success))
12361284
IFS=$'\n' sorted_empty=($(sort -n <<<"${empty_times[*]}"))
12371285
unset IFS
12381286
local empty_median=${sorted_empty[$((empty_success / 2))]}
1239-
1287+
12401288
ENDPOINT_COLD_TIMES["update"]=$empty_avg
1241-
log_success "Update endpoint functional"
1242-
ENDPOINT_STATUS["update"]="✅ Functional"
1289+
1290+
if [ $empty_failures -eq 0 ]; then
1291+
log_success "$empty_success/$NUM_ITERATIONS successful"
1292+
log_success "Update endpoint functional"
1293+
ENDPOINT_STATUS["update"]="✅ Functional"
1294+
elif [ $empty_failures -le 1 ]; then
1295+
log_success "$empty_success/$NUM_ITERATIONS successful"
1296+
log_warning "Update endpoint functional (${empty_failures}/${NUM_ITERATIONS} transient failures)"
1297+
ENDPOINT_STATUS["update"]="✅ Functional (${empty_failures}/${NUM_ITERATIONS} transient failures)"
1298+
else
1299+
log_warning "$empty_success/$NUM_ITERATIONS successful"
1300+
log_warning "Update endpoint had partial failures: $empty_failures/$NUM_ITERATIONS failed"
1301+
ENDPOINT_STATUS["update"]="⚠️ Partial Failures ($empty_failures/$NUM_ITERATIONS)"
1302+
fi
12431303
}
12441304

12451305
# Update endpoint - full cache version
@@ -1312,18 +1372,21 @@ test_update_endpoint_full() {
13121372
local full_median=${sorted_full[$((full_success / 2))]}
13131373

13141374
ENDPOINT_WARM_TIMES["update"]=$full_avg
1315-
1316-
local empty_avg=${ENDPOINT_COLD_TIMES["update"]}
1317-
local overhead=$((full_avg - empty_avg))
1318-
local overhead_pct=$((overhead * 100 / empty_avg))
13191375

1320-
log_overhead $overhead "O(n) scan overhead: ${overhead}ms (${overhead_pct}%) [Empty: ${empty_avg}ms → Full: ${full_avg}ms]"
1321-
if [ $overhead -lt 0 ]; then
1322-
log_info " ℹ️ Negative = DB variance, not cache"
1323-
elif [ $overhead -le 5 ]; then
1324-
log_info " ✅ Negligible O(n) overhead"
1376+
local empty_avg=${ENDPOINT_COLD_TIMES["update"]:-0}
1377+
1378+
if [ "$empty_avg" -eq 0 ] || [ -z "$empty_avg" ]; then
1379+
log_warning "Cannot calculate overhead - baseline test had no successful operations"
13251380
else
1326-
log_info " ⚠️ ${overhead}ms to scan ${CACHE_FILL_SIZE} entries"
1381+
local overhead=$((full_avg - empty_avg))
1382+
local overhead_pct=$((overhead * 100 / empty_avg))
1383+
1384+
# Display clamped value (0 or positive) but store actual value for report
1385+
if [ $overhead -lt 0 ]; then
1386+
log_overhead 0 "Overhead: 0ms (0%) [Empty: ${empty_avg}ms → Full: ${full_avg}ms] (negligible - within statistical variance)"
1387+
else
1388+
log_overhead $overhead "Overhead: ${overhead}ms (${overhead_pct}%) [Empty: ${empty_avg}ms → Full: ${full_avg}ms]"
1389+
fi
13271390
fi
13281391
}
13291392

@@ -1390,12 +1453,20 @@ test_patch_endpoint_full() {
13901453
[ $success -eq 0 ] && return
13911454
local avg=$((total / success))
13921455
ENDPOINT_WARM_TIMES["patch"]=$avg
1393-
local empty=${ENDPOINT_COLD_TIMES["patch"]}
1394-
local overhead=$((avg - empty))
1395-
local overhead_pct=$((overhead * 100 / empty))
1456+
local empty=${ENDPOINT_COLD_TIMES["patch"]:-0}
13961457

1397-
log_overhead $overhead "O(n) scan: ${overhead}ms (${overhead_pct}%) [Empty: ${empty}ms → Full: ${avg}ms]"
1398-
[ $overhead -lt 0 ] && log_info " ℹ️ DB variance" || [ $overhead -le 5 ] && log_info " ✅ Negligible" || log_info " ⚠️ ${overhead}ms overhead"
1458+
if [ "$empty" -eq 0 ] || [ -z "$empty" ]; then
1459+
log_warning "Cannot calculate overhead - baseline test had no successful operations"
1460+
else
1461+
local overhead=$((avg - empty))
1462+
local overhead_pct=$((overhead * 100 / empty))
1463+
1464+
if [ $overhead -lt 0 ]; then
1465+
log_overhead 0 "Overhead: 0ms (0%) [Empty: ${empty}ms → Full: ${avg}ms] (negligible - within statistical variance)"
1466+
else
1467+
log_overhead $overhead "Overhead: ${overhead}ms (${overhead_pct}%) [Empty: ${empty}ms → Full: ${avg}ms]"
1468+
fi
1469+
fi
13991470
}
14001471

14011472
test_set_endpoint_empty() {
@@ -1447,12 +1518,21 @@ test_set_endpoint_full() {
14471518
echo "" >&2
14481519
[ $success -eq 0 ] && return
14491520
ENDPOINT_WARM_TIMES["set"]=$((total / success))
1450-
local overhead=$((ENDPOINT_WARM_TIMES["set"] - ENDPOINT_COLD_TIMES["set"]))
1451-
local empty=${ENDPOINT_COLD_TIMES["set"]}
1521+
local empty=${ENDPOINT_COLD_TIMES["set"]:-0}
14521522
local full=${ENDPOINT_WARM_TIMES["set"]}
14531523

1454-
log_overhead $overhead "O(n): ${overhead}ms [Empty: ${empty}ms → Full: ${full}ms]"
1455-
[ $overhead -lt 0 ] && log_info " ℹ️ DB variance" || [ $overhead -le 5 ] && log_info " ✅ Negligible" || log_info " ⚠️ ${overhead}ms"
1524+
if [ "$empty" -eq 0 ] || [ -z "$empty" ]; then
1525+
log_warning "Cannot calculate overhead - baseline test had no successful operations"
1526+
else
1527+
local overhead=$((full - empty))
1528+
local overhead_pct=$((overhead * 100 / empty))
1529+
1530+
if [ $overhead -lt 0 ]; then
1531+
log_overhead 0 "Overhead: 0ms (0%) [Empty: ${empty}ms → Full: ${full}ms] (negligible - within statistical variance)"
1532+
else
1533+
log_overhead $overhead "Overhead: ${overhead}ms (${overhead_pct}%) [Empty: ${empty}ms → Full: ${full}ms]"
1534+
fi
1535+
fi
14561536
}
14571537

14581538
test_unset_endpoint_empty() {
@@ -1509,9 +1589,9 @@ test_unset_endpoint_full() {
15091589
local overhead=$((ENDPOINT_WARM_TIMES["unset"] - ENDPOINT_COLD_TIMES["unset"]))
15101590
local empty=${ENDPOINT_COLD_TIMES["unset"]}
15111591
local full=${ENDPOINT_WARM_TIMES["unset"]}
1592+
local overhead_pct=$((overhead * 100 / empty))
15121593

1513-
log_overhead $overhead "O(n): ${overhead}ms [${empty}ms → ${full}ms]"
1514-
[ $overhead -lt 0 ] && log_info " ℹ️ DB variance" || [ $overhead -le 5 ] && log_info " ✅ Negligible" || log_info " ⚠️ ${overhead}ms"
1594+
log_overhead $overhead "Overhead: ${overhead}ms (${overhead_pct}%) [Empty: ${empty}ms → Full: ${full}ms]"
15151595
}
15161596

15171597
test_overwrite_endpoint_empty() {
@@ -1566,9 +1646,9 @@ test_overwrite_endpoint_full() {
15661646
local overhead=$((ENDPOINT_WARM_TIMES["overwrite"] - ENDPOINT_COLD_TIMES["overwrite"]))
15671647
local empty=${ENDPOINT_COLD_TIMES["overwrite"]}
15681648
local full=${ENDPOINT_WARM_TIMES["overwrite"]}
1649+
local overhead_pct=$((overhead * 100 / empty))
15691650

1570-
log_overhead $overhead "O(n): ${overhead}ms [${empty}ms → ${full}ms]"
1571-
[ $overhead -lt 0 ] && log_info " ℹ️ DB variance" || [ $overhead -le 5 ] && log_info " ✅ Negligible" || log_info " ⚠️ ${overhead}ms"
1651+
log_overhead $overhead "Overhead: ${overhead}ms (${overhead_pct}%) [Empty: ${empty}ms → Full: ${full}ms]"
15721652
}
15731653

15741654
test_delete_endpoint_empty() {
@@ -1643,9 +1723,9 @@ test_delete_endpoint_full() {
16431723
local overhead=$((ENDPOINT_WARM_TIMES["delete"] - ENDPOINT_COLD_TIMES["delete"]))
16441724
local empty=${ENDPOINT_COLD_TIMES["delete"]}
16451725
local full=${ENDPOINT_WARM_TIMES["delete"]}
1726+
local overhead_pct=$((overhead * 100 / empty))
16461727

1647-
log_overhead $overhead "O(n): ${overhead}ms [${empty}ms → ${full}ms] (deleted: $success)"
1648-
[ $overhead -lt 0 ] && log_info " ℹ️ DB variance" || [ $overhead -le 5 ] && log_info " ✅ Negligible" || log_info " ⚠️ ${overhead}ms"
1728+
log_overhead $overhead "Overhead: ${overhead}ms (${overhead_pct}%) [Empty: ${empty}ms → Full: ${full}ms] (deleted: $success)"
16491729
}
16501730

16511731
################################################################################

0 commit comments

Comments
 (0)