diff --git a/docs/wasm-runtime-architecture.md b/docs/wasm-runtime-architecture.md index 6143bae..abf7149 100644 --- a/docs/wasm-runtime-architecture.md +++ b/docs/wasm-runtime-architecture.md @@ -137,6 +137,10 @@ own import vector, memory/table-base globals, GOT globals and function-table slots, then runs relocations, constructors, and request-pointer binding. This removes repeated Wasmtime import-type traversal without sharing request state or changing core-first, unit-load-order symbol resolution. +`request_perf()` reports worker module-cache hits and misses and divides a miss +into artifact lookup, wasm read, custom-section parse, serialized-module +deserialization or wasm compilation, and immutable import classification. This +keeps cold-worker module latency distinguishable without exposing source paths. Cold module compilation and deserialization are host work, so `load_unit()` refreshes the epoch deadline before its first guest call. Otherwise a component whose compilation outlasted the guest CPU budget would immediately trap in the diff --git a/site/demo/index.uce b/site/demo/index.uce index dfe81e7..379d551 100644 --- a/site/demo/index.uce +++ b/site/demo/index.uce @@ -104,6 +104,8 @@ RENDER(Request& context) print("Component resolves: ", (u64)perf["component_resolve_count"].to_u64(), " / ", (u64)perf["component_resolve_us"].to_u64(), " us\n"); print("Component phases: path ", (u64)perf["component_path_us"].to_u64(), " / artifact ", (u64)perf["component_artifact_us"].to_u64(), " / load ", (u64)perf["component_load_us"].to_u64(), " / link ", (u64)perf["component_link_us"].to_u64(), " us\n"); print("Unit loads: ", (u64)perf["unit_load_count"].to_u64(), " / module ", (u64)perf["unit_module_us"].to_u64(), " / allocate ", (u64)perf["unit_allocate_us"].to_u64(), " / imports ", (u64)perf["unit_import_us"].to_u64(), " / instantiate ", (u64)perf["unit_instantiate_us"].to_u64(), " / initialize ", (u64)perf["unit_initialize_us"].to_u64(), " us\n"); + print("Unit module cache: ", (u64)perf["unit_module_cache_hit_count"].to_u64(), " worker hits / ", (u64)perf["unit_module_cache_miss_count"].to_u64(), " misses / ", (u64)perf["unit_module_serialized_cache_hit_count"].to_u64(), " serialized hits / ", (u64)perf["unit_module_compile_count"].to_u64(), " wasm compiles\n"); + print("Unit module phases: lookup ", (u64)perf["unit_module_lookup_us"].to_u64(), " / read ", (u64)perf["unit_module_read_us"].to_u64(), " / parse ", (u64)perf["unit_module_parse_us"].to_u64(), " / deserialize/compile ", (u64)perf["unit_module_compile_us"].to_u64(), " / classify ", (u64)perf["unit_module_classify_us"].to_u64(), " us\n"); print("Unit symbol resolves: ", (u64)perf["unit_symbol_resolve_count"].to_u64(), " / ", (u64)perf["unit_symbol_resolve_us"].to_u64(), " us\n"); print("Output buffer size: ", context.ob->str().length(), "\n"); ?> diff --git a/site/doc/pages/request_perf.txt b/site/doc/pages/request_perf.txt index 892c66e..e1c743c 100644 --- a/site/doc/pages/request_perf.txt +++ b/site/doc/pages/request_perf.txt @@ -15,6 +15,8 @@ Component resolution is divided into `component_path_us`, `component_artifact_us 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. 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_parse_us`, `unit_module_compile_us`, and `unit_module_classify_us` divide `unit_module_us` into artifact stat/cache lookup, wasm read, custom-section parse, deserialize-or-compile, and immutable import classification. The phase sum can be below the total because allocation and cache publication overhead remain in the aggregate. + `unit_symbol_resolve_count` and `unit_symbol_resolve_us` isolate function and data symbol lookup within `unit_import_us`. The remainder of import time covers import-vector construction, Wasmtime Globals, GOT function table placement, and related bindings. Wasm FastCGI workers retain up to `MYSQL_PERSISTENT_POOL_SIZE` credential-keyed MySQL connections (default `8`; set `0` to disable). UCE calls the client library's connection-reset operation before another request receives a cached connection, clearing transactions, temporary tables, session variables, and selected databases while avoiding a new authentication handshake. Same-request leases continue to share state until request cleanup. diff --git a/site/tests/io.uce b/site/tests/io.uce index 091009c..f1af42d 100644 --- a/site/tests/io.uce +++ b/site/tests/io.uce @@ -151,7 +151,8 @@ RENDER(Request& context) check("to_u64() / to_s64() / to_f64() / to_bool()", to_u64(cfg["u64"], 7) == 42 && to_u64(cfg["bad"], 7) == 7 && to_s64(cfg["s64"], 5) == -12 && to_s64(cfg["bad"], 5) == 5 && to_f64(cfg["f64"], 1.0) > 3.49 && to_f64(cfg["bad"], 1.25) == 1.25 && to_bool(cfg["yes"], false) && !to_bool(cfg["no"], true) && !to_bool("unknown", false), var_dump(cfg)); DValue perf = request_perf(); - bool 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() > 0 && perf["hostcall_us"].type != 'S' && perf["guest_us"].to_f64() > 0 && perf["component_resolve_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 unit_module_profile_valid = perf["unit_module_cache_hit_count"].to_u64() + perf["unit_module_cache_miss_count"].to_u64() == perf["unit_load_count"].to_u64() && perf["unit_module_serialized_cache_hit_count"].to_u64() + perf["unit_module_compile_count"].to_u64() == perf["unit_module_cache_miss_count"].to_u64() && perf["unit_module_lookup_us"].type != 'S' && perf["unit_module_read_us"].type != 'S' && perf["unit_module_parse_us"].type != 'S' && perf["unit_module_compile_us"].type != 'S' && perf["unit_module_classify_us"].type != 'S'; + bool perf_stable = unit_module_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_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_hostcalls = perf["hostcall_count"].to_u64(); f64 profiled_hostcall_us = perf["hostcall_us"].to_f64(); u64 profiled_components = perf["component_resolve_count"].to_u64(); diff --git a/src/wasm/worker.cpp b/src/wasm/worker.cpp index 8db7b4c..1327830 100644 --- a/src/wasm/worker.cpp +++ b/src/wasm/worker.cpp @@ -103,6 +103,17 @@ struct WasmUnitModule size_t got_memory_imports = 0; }; +struct WasmUnitModuleLoadProfile +{ + bool cache_hit = false; + bool serialized_cache_hit = false; + u64 lookup_us = 0; + u64 read_us = 0; + u64 parse_us = 0; + u64 compile_us = 0; + u64 classify_us = 0; +}; + struct WasmWorkerConfig { String core_wasm_path = "bin/wasm/core.wasm"; @@ -141,6 +152,15 @@ struct WasmRequestProfile u64 component_link_total_us = 0; u64 unit_load_count = 0; u64 unit_module_total_us = 0; + u64 unit_module_cache_hit_count = 0; + u64 unit_module_cache_miss_count = 0; + u64 unit_module_serialized_cache_hit_count = 0; + u64 unit_module_compile_count = 0; + u64 unit_module_lookup_total_us = 0; + u64 unit_module_read_total_us = 0; + u64 unit_module_parse_total_us = 0; + u64 unit_module_compile_total_us = 0; + u64 unit_module_classify_total_us = 0; u64 unit_allocate_total_us = 0; u64 unit_import_total_us = 0; u64 unit_symbol_resolve_count = 0; @@ -730,7 +750,8 @@ public: String core_cached_path = cached_wasm_path(cfg.core_wasm_path); String compile_error; - auto compiled_or_cached = load_or_compile_cached_module(engine, core_cached_path, cfg.core_wasm_path, bytes, compile_error); + bool serialized_cache_hit = false; + auto compiled_or_cached = load_or_compile_cached_module(engine, core_cached_path, cfg.core_wasm_path, bytes, compile_error, serialized_cache_hit); if(!compiled_or_cached) return("core module compile failed: " + compile_error); core_module.emplace(std::move(*compiled_or_cached)); @@ -747,20 +768,28 @@ public: return(cfg.cache_root + source_path + ".wasm"); } - std::shared_ptr unit_module(const String& source_path, String& error) + std::shared_ptr unit_module(const String& source_path, String& error, WasmUnitModuleLoadProfile& profile) { + auto lookup_start = std::chrono::steady_clock::now(); String wasm_path = unit_wasm_path(source_path); struct stat st; if(stat(wasm_path.c_str(), &st) != 0) { + profile.lookup_us = (u64)std::chrono::duration_cast( + std::chrono::steady_clock::now() - lookup_start).count(); error = "no wasm artifact for " + source_path + " (expected " + wasm_path + ")"; return(nullptr); } auto cached = module_cache.find(wasm_path); u64 modified_ns = (u64)st.st_mtim.tv_sec * 1000000000ull + (u64)st.st_mtim.tv_nsec; u64 changed_ns = (u64)st.st_ctim.tv_sec * 1000000000ull + (u64)st.st_ctim.tv_nsec; + profile.lookup_us = (u64)std::chrono::duration_cast( + std::chrono::steady_clock::now() - lookup_start).count(); if(cached != module_cache.end() && cached->second->modified_ns == modified_ns && cached->second->changed_ns == changed_ns && cached->second->size == (u64)st.st_size) + { + profile.cache_hit = true; return(cached->second); + } auto unit = std::make_shared(); unit->source_path = source_path; @@ -769,16 +798,26 @@ public: unit->changed_ns = changed_ns; unit->size = (u64)st.st_size; std::vector bytes; + auto read_start = std::chrono::steady_clock::now(); if(!wasm_read_file(wasm_path, bytes)) { + profile.read_us = (u64)std::chrono::duration_cast( + std::chrono::steady_clock::now() - read_start).count(); error = "cannot read " + wasm_path; return(nullptr); } + profile.read_us = (u64)std::chrono::duration_cast( + std::chrono::steady_clock::now() - read_start).count(); + auto parse_start = std::chrono::steady_clock::now(); if(!wasm_parse_sections(bytes, unit->dylink, unit->abi, error)) { + profile.parse_us = (u64)std::chrono::duration_cast( + std::chrono::steady_clock::now() - parse_start).count(); error = wasm_path + ": " + error; return(nullptr); } + profile.parse_us = (u64)std::chrono::duration_cast( + std::chrono::steady_clock::now() - parse_start).count(); if(!unit->dylink.found) { error = wasm_path + ": missing dylink.0 mem_info (not a PIC side module)"; @@ -791,13 +830,17 @@ public: } String unit_cached_path = cached_wasm_path(wasm_path); String compile_error; - auto compiled_or_cached = load_or_compile_cached_module(engine, unit_cached_path, wasm_path, bytes, compile_error); + auto compile_start = std::chrono::steady_clock::now(); + auto compiled_or_cached = load_or_compile_cached_module(engine, unit_cached_path, wasm_path, bytes, compile_error, profile.serialized_cache_hit); + profile.compile_us = (u64)std::chrono::duration_cast( + std::chrono::steady_clock::now() - compile_start).count(); if(!compiled_or_cached) { error = wasm_path + ": compile failed: " + compile_error; return(nullptr); } unit->module.emplace(std::move(*compiled_or_cached)); + auto classify_start = std::chrono::steady_clock::now(); for(auto import_type : unit->module->imports()) { String mod_name(import_type.module()); @@ -831,6 +874,8 @@ public: } unit->imports.push_back({ kind, std::move(name) }); } + profile.classify_us = (u64)std::chrono::duration_cast( + std::chrono::steady_clock::now() - classify_start).count(); module_cache[wasm_path] = unit; return(unit); } @@ -844,8 +889,9 @@ private: } static std::optional load_or_compile_cached_module(wasmtime::Engine& engine, const String& cached_path, const String& wasm_path, - std::vector& bytes, String& compile_error) + std::vector& bytes, String& compile_error, bool& serialized_cache_hit) { + serialized_cache_hit = false; struct stat wasm_stat; struct stat cached_stat; if(stat(cached_path.c_str(), &cached_stat) == 0 && stat(wasm_path.c_str(), &wasm_stat) == 0) @@ -855,7 +901,10 @@ private: { auto deserialized = wasmtime::Module::deserialize_file(engine, cached_path); if(deserialized) + { + serialized_cache_hit = true; return(deserialized.ok()); + } } } @@ -1338,9 +1387,19 @@ private: unit_load_count++; String error; auto module_start = std::chrono::steady_clock::now(); - auto mod = worker.unit_module(source_path, error); + WasmUnitModuleLoadProfile module_profile; + auto mod = worker.unit_module(source_path, error, module_profile); unit_module_total_us += (u64)std::chrono::duration_cast( std::chrono::steady_clock::now() - module_start).count(); + unit_module_cache_hit_count += module_profile.cache_hit ? 1 : 0; + unit_module_cache_miss_count += module_profile.cache_hit ? 0 : 1; + unit_module_serialized_cache_hit_count += module_profile.serialized_cache_hit ? 1 : 0; + unit_module_compile_count += !module_profile.cache_hit && !module_profile.serialized_cache_hit ? 1 : 0; + unit_module_lookup_total_us += module_profile.lookup_us; + unit_module_read_total_us += module_profile.read_us; + unit_module_parse_total_us += module_profile.parse_us; + unit_module_compile_total_us += module_profile.compile_us; + unit_module_classify_total_us += module_profile.classify_us; if(!mod) return(error); // Compiling/deserializing a cold module is host work. Refresh the guest @@ -1977,6 +2036,15 @@ private: response["component_link_us"] = (f64)self->component_link_total_us; response["unit_load_count"] = (f64)self->unit_load_count; response["unit_module_us"] = (f64)self->unit_module_total_us; + response["unit_module_cache_hit_count"] = (f64)self->unit_module_cache_hit_count; + response["unit_module_cache_miss_count"] = (f64)self->unit_module_cache_miss_count; + response["unit_module_serialized_cache_hit_count"] = (f64)self->unit_module_serialized_cache_hit_count; + response["unit_module_compile_count"] = (f64)self->unit_module_compile_count; + response["unit_module_lookup_us"] = (f64)self->unit_module_lookup_total_us; + response["unit_module_read_us"] = (f64)self->unit_module_read_total_us; + response["unit_module_parse_us"] = (f64)self->unit_module_parse_total_us; + response["unit_module_compile_us"] = (f64)self->unit_module_compile_total_us; + response["unit_module_classify_us"] = (f64)self->unit_module_classify_total_us; response["unit_allocate_us"] = (f64)self->unit_allocate_total_us; response["unit_import_us"] = (f64)self->unit_import_total_us; response["unit_symbol_resolve_count"] = (f64)self->unit_symbol_resolve_count;