From 556025a77969d8aaab8d5c72cf97847227e941be Mon Sep 17 00:00:00 2001 From: udo Date: Sat, 18 Jul 2026 05:43:36 +0000 Subject: [PATCH] Profile pre-dispatch WASM readiness --- docs/wasm-runtime-architecture.md | 4 ++++ site/tests/io.uce | 10 ++++++++-- src/lib/types.h | 6 ++++++ src/linux_fastcgi.cpp | 4 ++++ src/wasm/backend.cpp | 14 +++++++++++++- src/wasm/worker.cpp | 23 +++++++++++++++++++++++ 6 files changed, 58 insertions(+), 3 deletions(-) diff --git a/docs/wasm-runtime-architecture.md b/docs/wasm-runtime-architecture.md index 914670e..05edefd 100644 --- a/docs/wasm-runtime-architecture.md +++ b/docs/wasm-runtime-architecture.md @@ -205,6 +205,10 @@ source, bytes, and phase durations so a cold outlier identifies its exact unit 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. When a current serialized module exists, the worker scans wasm section headers and reads only `dylink.0` and `uce.abi`; it does not fault the multi-megabyte code and data bodies into every new worker. A missing/stale/invalid serialized module diff --git a/site/tests/io.uce b/site/tests/io.uce index cdb9bb5..45cd819 100644 --- a/site/tests/io.uce +++ b/site/tests/io.uce @@ -181,7 +181,13 @@ 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["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_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_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(); f64 profiled_hostcall_us = perf["hostcall_us"].to_f64(); u64 profiled_hostcall_cpu_us = perf["hostcall_cpu_us"].to_u64(); @@ -204,7 +210,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["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_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 c388b8a..0a76d2b 100644 --- a/src/lib/types.h +++ b/src/lib/types.h @@ -316,6 +316,12 @@ struct Request { u64 wasm_workspace_complete_us = 0; u64 wasm_entry_invoke_us = 0; u64 wasm_output_collect_us = 0; + u64 wasm_ready_normalize_us = 0; + u64 wasm_ready_mutation_check_us = 0; + u64 wasm_ready_artifact_stat_us = 0; + u64 wasm_ready_freshness_us = 0; + u64 wasm_ready_worker_us = 0; + u32 wasm_ready_check_count = 0; u64 mem_high = 0; u64 mem_alloc = 0; u32 invoke_count = 0; diff --git a/src/linux_fastcgi.cpp b/src/linux_fastcgi.cpp index 4154cbc..9c2d090 100644 --- a/src/linux_fastcgi.cpp +++ b/src/linux_fastcgi.cpp @@ -581,10 +581,14 @@ int handle_complete(FastCGIRequest& request) { } }; + f64 ready_phase_started = time_precise(); String entry_unit = compiler_normalize_unit_path(&request, request.params["SCRIPT_FILENAME"]); + request.stats.wasm_ready_normalize_us += (u64)((time_precise() - ready_phase_started) * 1000000.0); String request_method = to_upper(trim(request.params["REQUEST_METHOD"])); bool read_request = request_method == "GET" || request_method == "HEAD" || request_method == "OPTIONS"; + ready_phase_started = time_precise(); bool stale_mutation = !request.resources.is_cli && !read_request && compiler_unit_needs_recompile(&request, entry_unit); + request.stats.wasm_ready_mutation_check_us += (u64)((time_precise() - ready_phase_started) * 1000000.0); if(stale_mutation) { compiler_prioritize_unit(&request, entry_unit); diff --git a/src/wasm/backend.cpp b/src/wasm/backend.cpp index 5eb0b2d..38b3eaf 100644 --- a/src/wasm/backend.cpp +++ b/src/wasm/backend.cpp @@ -116,17 +116,26 @@ static bool wasm_artifact_exists(Request* context, const String& entry_unit) return(false); String wasm_path = context->server->config["BIN_DIRECTORY"] + entry_unit + ".wasm"; struct stat wasm_st; + f64 phase_started = time_precise(); + context->stats.wasm_ready_check_count++; if(stat(wasm_path.c_str(), &wasm_st) != 0 || !S_ISREG(wasm_st.st_mode)) + { + context->stats.wasm_ready_artifact_stat_us += (u64)((time_precise() - phase_started) * 1000000.0); return(false); + } + context->stats.wasm_ready_artifact_stat_us += (u64)((time_precise() - phase_started) * 1000000.0); // 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. bool source_missing = false; + phase_started = time_precise(); if(compiler_unit_needs_recompile(context, entry_unit, &source_missing)) { + context->stats.wasm_ready_freshness_us += (u64)((time_precise() - phase_started) * 1000000.0); compiler_prioritize_unit(context, entry_unit); return(compiler_request_can_serve_stale_artifact(context)); } + context->stats.wasm_ready_freshness_us += (u64)((time_precise() - phase_started) * 1000000.0); if(source_missing) return(false); return(true); @@ -141,7 +150,10 @@ bool wasm_backend_should_handle(Request& request, const String& entry_unit) return(false); if(!wasm_artifact_exists(&request, entry_unit)) return(false); - if(wasm_backend_ensure_started(&request) != "") + f64 phase_started = time_precise(); + String start_error = wasm_backend_ensure_started(&request); + request.stats.wasm_ready_worker_us += (u64)((time_precise() - phase_started) * 1000000.0); + if(start_error != "") return(false); return(true); } diff --git a/src/wasm/worker.cpp b/src/wasm/worker.cpp index d529315..8446835 100644 --- a/src/wasm/worker.cpp +++ b/src/wasm/worker.cpp @@ -1343,6 +1343,12 @@ public: f64 time_params = 0; f64 time_input = 0; f64 time_start = 0; + u64 ready_normalize_us = 0; + u64 ready_mutation_check_us = 0; + u64 ready_artifact_stat_us = 0; + u64 ready_freshness_us = 0; + u64 ready_worker_us = 0; + u32 ready_check_count = 0; f64 workspace_wall_start = 0; f64 workspace_cpu_start = 0; struct rusage thread_runtime_start = {}; @@ -1358,6 +1364,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, f64 workspace_wall_start, f64 workspace_cpu_start) { request_perf.worker_pid = worker_pid; @@ -1367,6 +1375,12 @@ public: request_perf.time_params = time_params; request_perf.time_input = time_input; request_perf.time_start = time_start; + request_perf.ready_normalize_us = ready_normalize_us; + 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_worker_us = ready_worker_us; + request_perf.ready_check_count = ready_check_count; request_perf.workspace_wall_start = workspace_wall_start; request_perf.workspace_cpu_start = workspace_cpu_start; request_perf.active = true; @@ -2645,6 +2659,12 @@ private: response["worker_pid"] = (f64)self->request_perf.worker_pid; response["parent_pid"] = (f64)self->request_perf.parent_pid; response["request_count"] = (f64)self->request_perf.request_count; + response["ready_normalize_us"] = (f64)self->request_perf.ready_normalize_us; + 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_worker_us"] = (f64)self->request_perf.ready_worker_us; + response["ready_check_count"] = (f64)self->request_perf.ready_check_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) @@ -3883,6 +3903,9 @@ inline WasmResponse wasm_worker_serve(WasmWorker& worker, const Request& request (u64)((setup_cpu_finished - cpu_started) * 1000000.0) : 0; workspace.set_perf_snapshot(my_pid, (u64)parent_pid, request.server ? request.server->request_count : 0, 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_worker_us, request.stats.wasm_ready_check_count, serve_started, cpu_started); workspace.request_perf.thread_runtime_start = thread_runtime_start; workspace.request_perf.thread_cpu_start = thread_cpu_start;