From 4f010d37a0ae2c018cfd397be5a69bc01bec563c Mon Sep 17 00:00:00 2001 From: udo Date: Sun, 19 Jul 2026 04:24:45 +0000 Subject: [PATCH] Cache positive entry freshness checks --- docs/wasm-runtime-architecture.md | 19 ++- scripts/run_cli_tests.sh | 1 + scripts/test_entry_freshness_ttl.sh | 175 ++++++++++++++++++++++++++++ site/doc/pages/request_perf.txt | 2 + site/tests/io.uce | 7 +- src/lib/types.h | 3 + src/wasm/backend.cpp | 122 ++++++++++++++++++- src/wasm/worker.cpp | 14 ++- 8 files changed, 332 insertions(+), 11 deletions(-) create mode 100755 scripts/test_entry_freshness_ttl.sh diff --git a/docs/wasm-runtime-architecture.md b/docs/wasm-runtime-architecture.md index a468a51..630b395 100644 --- a/docs/wasm-runtime-architecture.md +++ b/docs/wasm-runtime-architecture.md @@ -229,12 +229,19 @@ and whether it used worker memory, serialized code, compilation, or failed. Absolute source paths and source contents are not exposed. This keeps cold-worker module latency distinguishable without exposing source paths. The same snapshot divides pre-dispatch WASM readiness into entry normalization, -mutation freshness, artifact stat, complete dependency freshness, and worker -availability. `ready_check_count` distinguishes the warm one-check path from an -on-demand compile and recheck; repeated snapshot reads retain the initial values. -Freshness still stats every distinct source on every entry check. Exact repeated -load paths are deduplicated before canonicalization, while distinct aliases are -resolved independently so symlink retargets remain immediately visible. +mutation freshness, artifact stat, source-generation lookup, dependency +freshness, and worker availability. `ready_freshness_full_check_us` and +`ready_freshness_cache_hit_count` distinguish full graph validation from a +positive worker-local hit; `ready_freshness_us` remains inclusive. +`ready_check_count` distinguishes the warm one-check path from an on-demand +compile and recheck; repeated snapshot reads retain the initial values. +Read-only HTTP entry checks may reuse a positive result for at most ten seconds +when the source generation and exact Wasm, metadata, and setup-template +identities are unchanged. CLI and mutation requests always validate the complete +graph. Misses, expiry, missing tokens, and changed identities also run the full +check. Exact repeated load paths are then deduplicated before canonicalization, +while distinct aliases are resolved independently so symlink retargets remain +visible by the next hard validation. When a current serialized module exists, the worker scans wasm section headers and reads only `dylink.0`, `uce.abi`, and the tiny `uce.module` identity; it does not fault the code and data bodies into every new worker. A missing/stale/invalid serialized module diff --git a/scripts/run_cli_tests.sh b/scripts/run_cli_tests.sh index c78ebb7..1ce5364 100755 --- a/scripts/run_cli_tests.sh +++ b/scripts/run_cli_tests.sh @@ -82,6 +82,7 @@ if [[ "$action" == "run" ]]; then scripts/test_log_timeliness.sh scripts/test_raw_http_request_log.sh scripts/test_component_resolution_ttl.sh + timeout --signal=TERM --kill-after=5s 120s scripts/test_entry_freshness_ttl.sh scripts/test_unit_export_surface.sh scripts/test_wasm_source_locations.sh scripts/test_socket_activation.sh diff --git a/scripts/test_entry_freshness_ttl.sh b/scripts/test_entry_freshness_ttl.sh new file mode 100755 index 0000000..76fbe3f --- /dev/null +++ b/scripts/test_entry_freshness_ttl.sh @@ -0,0 +1,175 @@ +#!/usr/bin/env bash +set -euo pipefail +cd "$(dirname "$0")/.." + +test_name="entry-freshness-ttl-test-$$" +site_directory="${UCE_TEST_SITE_DIRECTORY:-site}" +worker_count="${UCE_TEST_WORKER_COUNT:-4}" +bin_directory="${BIN_DIRECTORY:-/tmp/uce/work}" +http_host="${UCE_TEST_HTTP_HOST:-uce.openfu.com}" +if [[ -r /etc/uce/settings.cfg ]]; then + configured_site_directory=$(awk -F= '/^[[:space:]]*SITE_DIRECTORY[[:space:]]*=/ {gsub(/^[[:space:]]+|[[:space:]]+$/, "", $2); print $2; exit}' /etc/uce/settings.cfg) + configured_worker_count=$(awk -F= '/^[[:space:]]*WORKER_COUNT[[:space:]]*=/ {gsub(/^[[:space:]]+|[[:space:]]+$/, "", $2); print $2; exit}' /etc/uce/settings.cfg) + configured_bin_directory=$(awk -F= '/^[[:space:]]*BIN_DIRECTORY[[:space:]]*=/ {gsub(/^[[:space:]]+|[[:space:]]+$/, "", $2); print $2; exit}' /etc/uce/settings.cfg) + [[ -n "${UCE_TEST_SITE_DIRECTORY:-}" || -z "$configured_site_directory" ]] || site_directory="$configured_site_directory" + [[ -n "${UCE_TEST_WORKER_COUNT:-}" || -z "$configured_worker_count" ]] || worker_count="$configured_worker_count" + [[ -n "${BIN_DIRECTORY:-}" || -z "$configured_bin_directory" ]] || bin_directory="$configured_bin_directory" +fi +source_dir="$site_directory/$test_name" +cache_dir="" +mutation_file="/tmp/$test_name-mutation" +post_body="/tmp/$test_name-post-body" +post_headers="/tmp/$test_name-post-headers" +generation_file="" + +cleanup() { + if [[ -n "$generation_file" ]]; then + exec 7>"$generation_file.lock" + flock 7 + printf 'test-cleanup:%s\n' "$(date +%s%N)" >"$generation_file" + flock -u 7 + exec 7>&- + fi + rm -rf "$source_dir" + [[ -z "$cache_dir" ]] || rm -rf "$cache_dir" + rm -f "$mutation_file" "$post_body" "$post_headers" +} +trap cleanup EXIT +mkdir -p "$source_dir" +cache_dir="$(scripts/unit_cache_directory "$bin_directory")$(realpath "$source_dir")" +generation_file="$(scripts/unit_cache_directory "$bin_directory")/source-generation.txt" + +printf '%s\n' 'String entry_freshness_marker() { return("marker-a"); }' >"$source_dir/child.uce" +printf '%s\n' \ + '#load "child.uce"' \ + "void entry_freshness_output(Request& context) { DValue perf = request_perf(); if(context.params[\"REQUEST_METHOD\"] == \"POST\") file_put_contents(\"$mutation_file\", \"executed\"); print(entry_freshness_marker(), \":\", perf[\"worker_pid\"].to_string(), \":\", perf[\"ready_freshness_cache_hit_count\"].to_string(), \":\", perf[\"ready_freshness_full_check_us\"].to_string()); }" \ + 'RENDER(Request& context) { entry_freshness_output(context); }' \ + 'CLI(Request& context) { entry_freshness_output(context); }' >"$source_dir/parent.uce" + +http_probe() { + curl -fsS --max-time 5 -H "Host: $http_host" "http://127.0.0.1/$test_name/parent.uce" +} + +declare -A seen +collect_all_workers() { + local require_hit="$1" + local expected_marker="$2" + local deadline=$((SECONDS + 35)) + seen=() + while (( SECONDS < deadline && ${#seen[@]} < worker_count )); do + local output marker pid hit full + output=$(http_probe) + IFS=: read -r marker pid hit full <<<"$output" + pid=${pid%%.*}; hit=${hit%%.*}; full=${full%%.*} + if [[ "$marker" != "$expected_marker" || -z "$pid" ]]; then + echo "entry freshness probe returned unexpected output: $output" >&2 + exit 1 + fi + if [[ "$require_hit" == "1" && ( "$hit" == "0" || "$full" != "0" ) ]]; then + continue + fi + seen["$pid"]=1 + done + if (( ${#seen[@]} != worker_count )); then + echo "entry freshness probe reached ${#seen[@]}/$worker_count workers (hit=$require_hit)" >&2 + exit 1 + fi +} + +collect_all_workers 0 marker-a +collect_all_workers 1 marker-a + +parent_wasm="$cache_dir/parent.uce.wasm" +exec 8>"$parent_wasm.lock" +flock 8 +sed -i 's/marker-a/marker-b/' "$source_dir/child.uce" +rm -f "$mutation_file" +post_status=$(curl -sS --max-time 5 -o "$post_body" -D "$post_headers" -w '%{http_code}' -X POST -H "Host: $http_host" "http://127.0.0.1/$test_name/parent.uce") +if [[ "$post_status" != "503" || -e "$mutation_file" ]] || ! grep -qi '^Retry-After: 1' "$post_headers"; then + echo "stale mutation did not fail closed: status=$post_status body=$(cat "$post_body")" >&2 + exit 1 +fi + +sleep 10.2 +expired_output=$(http_probe) +IFS=: read -r expired_marker expired_pid expired_hit expired_full <<<"$expired_output" +expired_hit=${expired_hit%%.*}; expired_full=${expired_full%%.*} +if [[ "$expired_marker" != "marker-a" || "$expired_hit" != "0" || "$expired_full" == "0" ]]; then + echo "expired positive entry did not perform a full safe check: $expired_output" >&2 + exit 1 +fi +flock -u 8 +exec 8>&- + +deadline=$((SECONDS + 25)) +output="" +while (( SECONDS < deadline )); do + output=$(http_probe) + [[ "$output" == marker-b:* ]] && break + sleep 0.2 +done +if [[ "$output" != marker-b:* ]]; then + echo "entry did not converge after dependency rebuild: $output" >&2 + exit 1 +fi +collect_all_workers 1 marker-b + +exec 9>"$generation_file.lock" +flock 9 +printf 'test:%s\n' "$(date +%s%N)" >"$generation_file" +flock -u 9 +exec 9>&- +generation_output=$(http_probe) +IFS=: read -r generation_marker generation_pid generation_hit generation_full <<<"$generation_output" +generation_hit=${generation_hit%%.*}; generation_full=${generation_full%%.*} +if [[ "$generation_marker" != "marker-b" || "$generation_hit" != "0" || "$generation_full" == "0" ]]; then + echo "source generation change did not invalidate immediately: $generation_output" >&2 + exit 1 +fi + +collect_all_workers 1 marker-b +touch "$parent_wasm" +identity_output=$(http_probe) +IFS=: read -r identity_marker identity_pid identity_hit identity_full <<<"$identity_output" +identity_hit=${identity_hit%%.*}; identity_full=${identity_full%%.*} +if [[ "$identity_marker" != "marker-b" || "$identity_hit" != "0" || "$identity_full" == "0" ]]; then + echo "wasm identity change did not invalidate immediately: $identity_output" >&2 + exit 1 +fi + +collect_all_workers 1 marker-b +touch "$cache_dir/parent.uce.meta.txt" +metadata_output=$(http_probe) +IFS=: read -r metadata_marker metadata_pid metadata_hit metadata_full <<<"$metadata_output" +metadata_hit=${metadata_hit%%.*}; metadata_full=${metadata_full%%.*} +if [[ "$metadata_marker" != "marker-b" || "$metadata_hit" != "0" || "$metadata_full" == "0" ]]; then + echo "metadata identity change did not invalidate immediately: $metadata_output" >&2 + exit 1 +fi + +collect_all_workers 1 marker-b +exec 9>"$generation_file.lock" +flock 9 +rm -f "$generation_file" +flock -u 9 +missing_generation_output=$(http_probe) +IFS=: read -r missing_generation_marker missing_generation_pid missing_generation_hit missing_generation_full <<<"$missing_generation_output" +missing_generation_hit=${missing_generation_hit%%.*}; missing_generation_full=${missing_generation_full%%.*} +if [[ "$missing_generation_marker" != "marker-b" || "$missing_generation_hit" != "0" || "$missing_generation_full" == "0" ]]; then + echo "missing generation token did not force a full check: $missing_generation_output" >&2 + exit 1 +fi +flock 9 +printf 'test:%s\n' "$(date +%s%N)" >"$generation_file" +flock -u 9 +exec 9>&- + +cli_output=$(timeout --signal=TERM --kill-after=3s 20s scripts/uce-cli "/$test_name/parent.uce") +IFS=: read -r cli_marker cli_pid cli_hit cli_full <<<"$cli_output" +cli_hit=${cli_hit%%.*}; cli_full=${cli_full%%.*} +if [[ "$cli_marker" != "marker-b" || "$cli_hit" != "0" || "$cli_full" == "0" ]]; then + echo "CLI unexpectedly reused the HTTP freshness cache: $cli_output" >&2 + exit 1 +fi + +echo "entry freshness TTL passed" diff --git a/site/doc/pages/request_perf.txt b/site/doc/pages/request_perf.txt index 8a96825..cb18601 100644 --- a/site/doc/pages/request_perf.txt +++ b/site/doc/pages/request_perf.txt @@ -15,6 +15,8 @@ Hostcall totals include component resolution. When `WASM_PROFILE_HOSTCALL_CPU=1` Component resolution is divided into `component_path_us`, `component_artifact_us`, `component_load_us`, and `component_link_us`. These aggregate path resolution, artifact readiness/freshness, Wasmtime side-module loading, and exported-handler lookup/table placement without exposing source paths. +Entry readiness reports inclusive `ready_freshness_us` plus `ready_source_generation_us`, `ready_freshness_full_check_us`, and `ready_freshness_cache_hit_count`. Read-only HTTP requests can reuse a positive result for at most ten seconds only while source generation and exact artifact identities remain unchanged. CLI, mutation, miss, expiry, and uncertain states perform the complete dependency check. + Successful first loads within the request are counted by `unit_load_count` and divided into `unit_module_us`, `unit_allocate_us`, `unit_import_us`, `unit_instantiate_us`, and `unit_initialize_us`. These cover compiled-module lookup, guest memory/table allocation, import construction, Wasmtime instantiation, and relocations/constructors/request binding. `entry_unit_load_count` and `entry_unit_materialize_us` isolate the initial page/CLI unit; `dynamic_include_load_count` and `dynamic_include_materialize_us` isolate side units first requested through `component()`. The per-unit bounded list adds `kind` (`entry` or `component`) and `materialize_us`, the inclusive host-side time from module acquisition through request binding. Repeated handlers from an already loaded unit are excluded. `unit_module_cache_hit_count` and `unit_module_cache_miss_count` divide module loads by the worker's compiled-module cache. A miss is further identified by `unit_module_serialized_cache_hit_count` when Wasmtime deserializes the current `.cwasm`; `unit_module_compile_count` means it fell back to compiling the `.wasm`. `unit_module_lookup_us`, `unit_module_read_us`, `unit_module_read_bytes`, `unit_module_parse_us`, `unit_module_compile_us`, and `unit_module_classify_us` divide `unit_module_us` into artifact stat/cache lookup, wasm metadata/full-artifact read volume, custom-section parse, deserialize-or-compile, and immutable import classification. A current serialized-module hit scans only section headers and the `dylink.0`/`uce.abi` payloads; compilation fallback reads the complete wasm. The phase sum can be below the total because allocation and cache publication overhead remain in the aggregate. diff --git a/site/tests/io.uce b/site/tests/io.uce index ed67269..335b418 100644 --- a/site/tests/io.uce +++ b/site/tests/io.uce @@ -185,11 +185,14 @@ RENDER(Request& context) u64 dropped_hostcall_operations = perf["hostcall_operations_dropped"].to_u64(); hostcall_operation_profile_valid = hostcall_operation_profile_valid && perf["hostcall_cpu_profiled"].type == 'B' && perf["hostcall_cpu_us"].to_u64() <= perf["hostcall_us"].to_u64() + 2 && operation_kinds > 0 && operation_kinds <= 32 && ((dropped_hostcall_operations == 0 && operation_hostcalls == perf["hostcall_count"].to_u64() && operation_hostcall_us == perf["hostcall_us"].to_u64() && operation_hostcall_cpu_us == perf["hostcall_cpu_us"].to_u64()) || (dropped_hostcall_operations > 0 && operation_kinds == 32 && operation_hostcalls < perf["hostcall_count"].to_u64() && operation_hostcall_us <= perf["hostcall_us"].to_u64() && operation_hostcall_cpu_us <= perf["hostcall_cpu_us"].to_u64())); bool thread_runtime_profile_valid = perf["thread_runtime_profiled"].type == 'B' && (!perf["thread_runtime_profiled"].to_bool() || (perf["thread_cpu_start"].to_f64() >= 0 && perf["thread_cpu_end"].to_f64() >= 0 && perf["thread_cpu_migrated"].type == 'B' && perf["thread_user_cpu_us"].to_u64() + perf["thread_system_cpu_us"].to_u64() <= perf["workspace_wall_us"].to_u64() + 5 && perf["thread_voluntary_context_switches"].type != 'S' && perf["thread_involuntary_context_switches"].type != 'S' && perf["thread_minor_faults"].type != 'S' && perf["thread_major_faults"].type != 'S')); - bool perf_stable = transport_profile_valid && workspace_cpu_profile_valid && unit_module_profile_valid && hostcall_operation_profile_valid && thread_runtime_profile_valid && perf["worker_pid"].to_u64() > 0 && perf["running_us"].to_f64() > 0 && perf["ready_normalize_us"].type != 'S' && perf["ready_mutation_check_us"].type != 'S' && perf["ready_artifact_stat_us"].type != 'S' && perf["ready_freshness_us"].type != 'S' && perf["ready_worker_us"].type != 'S' && perf["ready_check_count"].to_u64() > 0 && perf["dispatch_us"].type != 'S' && perf["workspace_setup_us"].type != 'S' && perf["workspace_birth_us"].type != 'S' && perf["context_apply_us"].type != 'S' && perf["hostcall_count"].to_u64() > 0 && perf["hostcall_us"].type != 'S' && perf["guest_us"].to_f64() > 0 && perf["component_resolve_count"].type != 'S' && perf["component_loaded_reuse_count"].type != 'S' && perf["component_path_us"].type != 'S' && perf["component_artifact_us"].type != 'S' && perf["component_load_us"].type != 'S' && perf["component_link_us"].type != 'S' && perf["unit_load_count"].to_u64() > 0 && perf["unit_module_us"].type != 'S' && perf["unit_allocate_us"].type != 'S' && perf["unit_import_us"].type != 'S' && perf["unit_symbol_resolve_count"].type != 'S' && perf["unit_symbol_resolve_us"].type != 'S' && perf["unit_instantiate_us"].type != 'S' && perf["unit_initialize_us"].type != 'S'; + bool perf_stable = transport_profile_valid && workspace_cpu_profile_valid && unit_module_profile_valid && hostcall_operation_profile_valid && thread_runtime_profile_valid && perf["worker_pid"].to_u64() > 0 && perf["running_us"].to_f64() > 0 && perf["ready_normalize_us"].type != 'S' && perf["ready_mutation_check_us"].type != 'S' && perf["ready_artifact_stat_us"].type != 'S' && perf["ready_freshness_us"].type != 'S' && perf["ready_source_generation_us"].type != 'S' && perf["ready_freshness_full_check_us"].type != 'S' && perf["ready_freshness_cache_hit_count"].type != 'S' && perf["ready_worker_us"].type != 'S' && perf["ready_check_count"].to_u64() > 0 && perf["dispatch_us"].type != 'S' && perf["workspace_setup_us"].type != 'S' && perf["workspace_birth_us"].type != 'S' && perf["context_apply_us"].type != 'S' && perf["hostcall_count"].to_u64() > 0 && perf["hostcall_us"].type != 'S' && perf["guest_us"].to_f64() > 0 && perf["component_resolve_count"].type != 'S' && perf["component_loaded_reuse_count"].type != 'S' && perf["component_path_us"].type != 'S' && perf["component_artifact_us"].type != 'S' && perf["component_load_us"].type != 'S' && perf["component_link_us"].type != 'S' && perf["unit_load_count"].to_u64() > 0 && perf["unit_module_us"].type != 'S' && perf["unit_allocate_us"].type != 'S' && perf["unit_import_us"].type != 'S' && perf["unit_symbol_resolve_count"].type != 'S' && perf["unit_symbol_resolve_us"].type != 'S' && perf["unit_instantiate_us"].type != 'S' && perf["unit_initialize_us"].type != 'S'; u64 profiled_ready_normalize = perf["ready_normalize_us"].to_u64(); u64 profiled_ready_mutation_check = perf["ready_mutation_check_us"].to_u64(); u64 profiled_ready_artifact_stat = perf["ready_artifact_stat_us"].to_u64(); u64 profiled_ready_freshness = perf["ready_freshness_us"].to_u64(); + u64 profiled_ready_source_generation = perf["ready_source_generation_us"].to_u64(); + u64 profiled_ready_freshness_full_check = perf["ready_freshness_full_check_us"].to_u64(); + u64 profiled_ready_freshness_cache_hit_count = perf["ready_freshness_cache_hit_count"].to_u64(); u64 profiled_ready_worker = perf["ready_worker_us"].to_u64(); u64 profiled_ready_checks = perf["ready_check_count"].to_u64(); u64 profiled_hostcalls = perf["hostcall_count"].to_u64(); @@ -214,7 +217,7 @@ RENDER(Request& context) for(u64 i = 0; i < 512 && perf_stable; i++) { perf = request_perf(); - perf_stable = perf["worker_pid"].to_u64() > 0 && perf["running_us"].to_f64() > 0 && perf["ready_normalize_us"].to_u64() == profiled_ready_normalize && perf["ready_mutation_check_us"].to_u64() == profiled_ready_mutation_check && perf["ready_artifact_stat_us"].to_u64() == profiled_ready_artifact_stat && perf["ready_freshness_us"].to_u64() == profiled_ready_freshness && perf["ready_worker_us"].to_u64() == profiled_ready_worker && perf["ready_check_count"].to_u64() == profiled_ready_checks && perf["dispatch_us"].type != 'S' && perf["workspace_setup_us"].type != 'S' && perf["workspace_birth_us"].type != 'S' && perf["context_apply_us"].type != 'S' && perf["hostcall_count"].to_u64() == profiled_hostcalls && perf["hostcall_us"].to_f64() == profiled_hostcall_us && perf["hostcall_cpu_us"].to_u64() == profiled_hostcall_cpu_us && perf["guest_us"].to_f64() > 0 && perf["component_resolve_count"].to_u64() == profiled_components && perf["component_loaded_reuse_count"].to_u64() == profiled_component_loaded_reuses && perf["component_path_us"].to_u64() == profiled_component_path && perf["component_artifact_us"].to_u64() == profiled_component_artifact && perf["component_load_us"].to_u64() == profiled_component_load && perf["component_link_us"].to_u64() == profiled_component_link && perf["unit_load_count"].to_u64() == profiled_unit_loads && perf["unit_module_us"].to_u64() == profiled_unit_module && perf["unit_allocate_us"].to_u64() == profiled_unit_allocate && perf["unit_import_us"].to_u64() == profiled_unit_import && perf["unit_symbol_resolve_count"].to_u64() == profiled_unit_symbol_resolve_count && perf["unit_symbol_resolve_us"].to_u64() == profiled_unit_symbol_resolve && perf["unit_instantiate_us"].to_u64() == profiled_unit_instantiate && perf["unit_initialize_us"].to_u64() == profiled_unit_initialize && json_encode(perf["mysql_operations"]) == profiled_mysql_operations && json_encode(perf["hostcall_operations"]) == profiled_hostcall_operations; + perf_stable = perf["worker_pid"].to_u64() > 0 && perf["running_us"].to_f64() > 0 && perf["ready_normalize_us"].to_u64() == profiled_ready_normalize && perf["ready_mutation_check_us"].to_u64() == profiled_ready_mutation_check && perf["ready_artifact_stat_us"].to_u64() == profiled_ready_artifact_stat && perf["ready_freshness_us"].to_u64() == profiled_ready_freshness && perf["ready_source_generation_us"].to_u64() == profiled_ready_source_generation && perf["ready_freshness_full_check_us"].to_u64() == profiled_ready_freshness_full_check && perf["ready_freshness_cache_hit_count"].to_u64() == profiled_ready_freshness_cache_hit_count && perf["ready_worker_us"].to_u64() == profiled_ready_worker && perf["ready_check_count"].to_u64() == profiled_ready_checks && perf["dispatch_us"].type != 'S' && perf["workspace_setup_us"].type != 'S' && perf["workspace_birth_us"].type != 'S' && perf["context_apply_us"].type != 'S' && perf["hostcall_count"].to_u64() == profiled_hostcalls && perf["hostcall_us"].to_f64() == profiled_hostcall_us && perf["hostcall_cpu_us"].to_u64() == profiled_hostcall_cpu_us && perf["guest_us"].to_f64() > 0 && perf["component_resolve_count"].to_u64() == profiled_components && perf["component_loaded_reuse_count"].to_u64() == profiled_component_loaded_reuses && perf["component_path_us"].to_u64() == profiled_component_path && perf["component_artifact_us"].to_u64() == profiled_component_artifact && perf["component_load_us"].to_u64() == profiled_component_load && perf["component_link_us"].to_u64() == profiled_component_link && perf["unit_load_count"].to_u64() == profiled_unit_loads && perf["unit_module_us"].to_u64() == profiled_unit_module && perf["unit_allocate_us"].to_u64() == profiled_unit_allocate && perf["unit_import_us"].to_u64() == profiled_unit_import && perf["unit_symbol_resolve_count"].to_u64() == profiled_unit_symbol_resolve_count && perf["unit_symbol_resolve_us"].to_u64() == profiled_unit_symbol_resolve && perf["unit_instantiate_us"].to_u64() == profiled_unit_instantiate && perf["unit_initialize_us"].to_u64() == profiled_unit_initialize && json_encode(perf["mysql_operations"]) == profiled_mysql_operations && json_encode(perf["hostcall_operations"]) == profiled_hostcall_operations; } check("request_perf() stages stable repeated snapshots", perf_stable, json_encode(perf)); diff --git a/src/lib/types.h b/src/lib/types.h index 0a76d2b..de2cc56 100644 --- a/src/lib/types.h +++ b/src/lib/types.h @@ -320,8 +320,11 @@ struct Request { u64 wasm_ready_mutation_check_us = 0; u64 wasm_ready_artifact_stat_us = 0; u64 wasm_ready_freshness_us = 0; + u64 wasm_ready_source_generation_us = 0; + u64 wasm_ready_freshness_full_check_us = 0; u64 wasm_ready_worker_us = 0; u32 wasm_ready_check_count = 0; + u32 wasm_ready_freshness_cache_hit_count = 0; u64 mem_high = 0; u64 mem_alloc = 0; u32 invoke_count = 0; diff --git a/src/wasm/backend.cpp b/src/wasm/backend.cpp index 8000efd..f651d3a 100644 --- a/src/wasm/backend.cpp +++ b/src/wasm/backend.cpp @@ -24,6 +24,58 @@ static std::atomic g_wasm_epoch_running(false); static String g_wasm_init_error; static bool g_wasm_init_attempted = false; +struct WasmEntryArtifactIdentity +{ + dev_t device = 0; + ino_t inode = 0; + mode_t mode = 0; + off_t size = 0; + timespec modified = {}; + timespec changed = {}; +}; + +struct WasmEntryFreshnessState +{ + std::chrono::steady_clock::time_point checked_at; + String source_generation; + WasmEntryArtifactIdentity wasm; + WasmEntryArtifactIdentity metadata; + WasmEntryArtifactIdentity setup_template; +}; + +static std::mutex g_wasm_entry_freshness_mutex; +static std::map g_wasm_entry_freshness; +static constexpr u64 WASM_ENTRY_FRESHNESS_CACHE_MAX = 4096; +static constexpr auto WASM_ENTRY_FRESHNESS_TTL = std::chrono::seconds(10); + +static WasmEntryArtifactIdentity wasm_entry_artifact_identity(const struct stat& info) +{ + return(WasmEntryArtifactIdentity{ info.st_dev, info.st_ino, info.st_mode, info.st_size, info.st_mtim, info.st_ctim }); +} + +static bool wasm_entry_artifact_identity_matches(const WasmEntryArtifactIdentity& expected, const struct stat& actual) +{ + return( + expected.device == actual.st_dev && expected.inode == actual.st_ino && expected.mode == actual.st_mode && expected.size == actual.st_size && + expected.modified.tv_sec == actual.st_mtim.tv_sec && expected.modified.tv_nsec == actual.st_mtim.tv_nsec && + expected.changed.tv_sec == actual.st_ctim.tv_sec && expected.changed.tv_nsec == actual.st_ctim.tv_nsec + ); +} + +static bool wasm_entry_cache_allowed(Request* context) +{ + if(!compiler_request_can_serve_stale_artifact(context)) + return(false); + String method = to_upper(trim(context->params["REQUEST_METHOD"])); + return(method == "GET" || method == "HEAD" || method == "OPTIONS"); +} + +static void wasm_entry_freshness_forget(const String& entry_unit) +{ + std::lock_guard lock(g_wasm_entry_freshness_mutex); + g_wasm_entry_freshness.erase(entry_unit); +} + bool wasm_backend_configured(Request* context) { return(context && context->server); @@ -144,6 +196,41 @@ static bool wasm_artifact_exists(Request* context, const String& entry_unit) return(false); } context->stats.wasm_ready_artifact_stat_us += (u64)((time_precise() - phase_started) * 1000000.0); + f64 freshness_started = time_precise(); + bool cache_allowed = wasm_entry_cache_allowed(context); + String metadata_path = compiler_unit_bin_directory(context) + entry_unit + ".meta.txt"; + String setup_template_path = path_join(context->server->config["COMPILER_SYS_PATH"], context->server->config["SETUP_TEMPLATE"]); + String source_generation; + struct stat metadata_st; + struct stat setup_template_st; + bool metadata_exists = false; + bool setup_template_exists = false; + auto now = std::chrono::steady_clock::now(); + if(cache_allowed) + { + phase_started = time_precise(); + source_generation = compiler_source_generation(context); + context->stats.wasm_ready_source_generation_us += (u64)((time_precise() - phase_started) * 1000000.0); + metadata_exists = stat(metadata_path.c_str(), &metadata_st) == 0 && S_ISREG(metadata_st.st_mode); + setup_template_exists = stat(setup_template_path.c_str(), &setup_template_st) == 0 && S_ISREG(setup_template_st.st_mode); + if(source_generation != "" && metadata_exists && setup_template_exists) + { + std::lock_guard lock(g_wasm_entry_freshness_mutex); + auto cached = g_wasm_entry_freshness.find(entry_unit); + if(cached != g_wasm_entry_freshness.end() && now - cached->second.checked_at < WASM_ENTRY_FRESHNESS_TTL && + cached->second.source_generation == source_generation && + wasm_entry_artifact_identity_matches(cached->second.wasm, wasm_st) && + wasm_entry_artifact_identity_matches(cached->second.metadata, metadata_st) && + wasm_entry_artifact_identity_matches(cached->second.setup_template, setup_template_st)) + { + context->stats.wasm_ready_freshness_cache_hit_count++; + context->stats.wasm_ready_freshness_us += (u64)((time_precise() - freshness_started) * 1000000.0); + return(true); + } + if(cached != g_wasm_entry_freshness.end()) + g_wasm_entry_freshness.erase(cached); + } + } // Require the artifact to satisfy the full compiler freshness check. Source // mtime alone misses runtime/unit ABI changes, setup-template changes, and // metadata mismatches, which can leave stale wasm with old imports. @@ -151,13 +238,44 @@ static bool wasm_artifact_exists(Request* context, const String& entry_unit) phase_started = time_precise(); if(compiler_unit_needs_recompile(context, entry_unit, &source_missing, false, true)) { - context->stats.wasm_ready_freshness_us += (u64)((time_precise() - phase_started) * 1000000.0); + u64 full_freshness_us = (u64)((time_precise() - phase_started) * 1000000.0); + context->stats.wasm_ready_freshness_us += (u64)((time_precise() - freshness_started) * 1000000.0); + context->stats.wasm_ready_freshness_full_check_us += full_freshness_us; + wasm_entry_freshness_forget(entry_unit); compiler_prioritize_unit(context, entry_unit); return(compiler_unit_can_serve_stale_artifact(context, entry_unit)); } - context->stats.wasm_ready_freshness_us += (u64)((time_precise() - phase_started) * 1000000.0); + u64 full_freshness_us = (u64)((time_precise() - phase_started) * 1000000.0); + context->stats.wasm_ready_freshness_full_check_us += full_freshness_us; if(source_missing) + { + context->stats.wasm_ready_freshness_us += (u64)((time_precise() - freshness_started) * 1000000.0); + wasm_entry_freshness_forget(entry_unit); return(false); + } + if(cache_allowed && source_generation != "") + { + struct stat final_wasm_st; + struct stat final_metadata_st; + struct stat final_setup_template_st; + phase_started = time_precise(); + String final_generation = compiler_source_generation(context); + context->stats.wasm_ready_source_generation_us += (u64)((time_precise() - phase_started) * 1000000.0); + if(final_generation == source_generation && stat(wasm_path.c_str(), &final_wasm_st) == 0 && S_ISREG(final_wasm_st.st_mode) && + stat(metadata_path.c_str(), &final_metadata_st) == 0 && S_ISREG(final_metadata_st.st_mode) && + stat(setup_template_path.c_str(), &final_setup_template_st) == 0 && S_ISREG(final_setup_template_st.st_mode)) + { + std::lock_guard lock(g_wasm_entry_freshness_mutex); + if(g_wasm_entry_freshness.size() >= WASM_ENTRY_FRESHNESS_CACHE_MAX) + g_wasm_entry_freshness.clear(); + g_wasm_entry_freshness[entry_unit] = { + std::chrono::steady_clock::now(), final_generation, + wasm_entry_artifact_identity(final_wasm_st), wasm_entry_artifact_identity(final_metadata_st), + wasm_entry_artifact_identity(final_setup_template_st) + }; + } + } + context->stats.wasm_ready_freshness_us += (u64)((time_precise() - freshness_started) * 1000000.0); return(true); } diff --git a/src/wasm/worker.cpp b/src/wasm/worker.cpp index 2ea30e8..f4241fc 100644 --- a/src/wasm/worker.cpp +++ b/src/wasm/worker.cpp @@ -1499,8 +1499,11 @@ public: u64 ready_mutation_check_us = 0; u64 ready_artifact_stat_us = 0; u64 ready_freshness_us = 0; + u64 ready_source_generation_us = 0; + u64 ready_freshness_full_check_us = 0; u64 ready_worker_us = 0; u32 ready_check_count = 0; + u32 ready_freshness_cache_hit_count = 0; f64 workspace_wall_start = 0; f64 workspace_cpu_start = 0; struct rusage thread_runtime_start = {}; @@ -1608,7 +1611,8 @@ public: void set_perf_snapshot(u64 worker_pid, u64 parent_pid, u64 request_count, f64 time_init, f64 time_params, f64 time_input, f64 time_start, u64 ready_normalize_us, u64 ready_mutation_check_us, u64 ready_artifact_stat_us, - u64 ready_freshness_us, u64 ready_worker_us, u32 ready_check_count, + u64 ready_freshness_us, u64 ready_source_generation_us, u64 ready_freshness_full_check_us, + u64 ready_worker_us, u32 ready_check_count, u32 ready_freshness_cache_hit_count, f64 workspace_wall_start, f64 workspace_cpu_start) { request_perf.worker_pid = worker_pid; @@ -1622,8 +1626,11 @@ public: request_perf.ready_mutation_check_us = ready_mutation_check_us; request_perf.ready_artifact_stat_us = ready_artifact_stat_us; request_perf.ready_freshness_us = ready_freshness_us; + request_perf.ready_source_generation_us = ready_source_generation_us; + request_perf.ready_freshness_full_check_us = ready_freshness_full_check_us; request_perf.ready_worker_us = ready_worker_us; request_perf.ready_check_count = ready_check_count; + request_perf.ready_freshness_cache_hit_count = ready_freshness_cache_hit_count; request_perf.workspace_wall_start = workspace_wall_start; request_perf.workspace_cpu_start = workspace_cpu_start; request_perf.active = true; @@ -3042,8 +3049,11 @@ private: response["ready_mutation_check_us"] = (f64)self->request_perf.ready_mutation_check_us; response["ready_artifact_stat_us"] = (f64)self->request_perf.ready_artifact_stat_us; response["ready_freshness_us"] = (f64)self->request_perf.ready_freshness_us; + response["ready_source_generation_us"] = (f64)self->request_perf.ready_source_generation_us; + response["ready_freshness_full_check_us"] = (f64)self->request_perf.ready_freshness_full_check_us; response["ready_worker_us"] = (f64)self->request_perf.ready_worker_us; response["ready_check_count"] = (f64)self->request_perf.ready_check_count; + response["ready_freshness_cache_hit_count"] = (f64)self->request_perf.ready_freshness_cache_hit_count; if(self->request_perf.time_start > 0 && self->request_perf.time_init > 0) response["accept_us"] = (f64)((self->request_perf.time_start - self->request_perf.time_init) * 1000000.0); if(self->request_perf.time_params > 0 && self->request_perf.time_init > 0) @@ -4308,7 +4318,9 @@ inline WasmResponse wasm_worker_serve(WasmWorker& worker, const Request& request request.stats.time_init, request.stats.time_params, request.stats.time_input, request.stats.time_start, request.stats.wasm_ready_normalize_us, request.stats.wasm_ready_mutation_check_us, request.stats.wasm_ready_artifact_stat_us, request.stats.wasm_ready_freshness_us, + request.stats.wasm_ready_source_generation_us, request.stats.wasm_ready_freshness_full_check_us, request.stats.wasm_ready_worker_us, request.stats.wasm_ready_check_count, + request.stats.wasm_ready_freshness_cache_hit_count, serve_started, cpu_started); workspace.request_perf.thread_runtime_start = thread_runtime_start; workspace.request_perf.thread_cpu_start = thread_cpu_start;