From 197719ea23599bfdf68327073079e2367dd1f660 Mon Sep 17 00:00:00 2001 From: udo Date: Thu, 16 Jul 2026 18:01:31 +0000 Subject: [PATCH] Profile side module loading phases --- site/demo/index.uce | 1 + site/doc/pages/request_perf.txt | 2 ++ site/tests/io.uce | 10 ++++++++-- src/wasm/worker.cpp | 28 ++++++++++++++++++++++++++++ 4 files changed, 39 insertions(+), 2 deletions(-) diff --git a/site/demo/index.uce b/site/demo/index.uce index 88d544c..7ff2163 100644 --- a/site/demo/index.uce +++ b/site/demo/index.uce @@ -103,6 +103,7 @@ RENDER(Request& context) print("Memcache hostcalls: ", (u64)perf["memcache_hostcall_count"].to_u64(), " / ", (u64)perf["memcache_hostcall_us"].to_u64(), " us\n"); 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("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 40e2fb9..dcf7cf6 100644 --- a/site/doc/pages/request_perf.txt +++ b/site/doc/pages/request_perf.txt @@ -13,6 +13,8 @@ Returns a DValue with timing and process metadata such as worker pid, parent pid 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. +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. + 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. :example diff --git a/site/tests/io.uce b/site/tests/io.uce index 2796b55..861ad89 100644 --- a/site/tests/io.uce +++ b/site/tests/io.uce @@ -151,7 +151,7 @@ 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'; + 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_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(); @@ -159,11 +159,17 @@ RENDER(Request& context) u64 profiled_component_artifact = perf["component_artifact_us"].to_u64(); u64 profiled_component_load = perf["component_load_us"].to_u64(); u64 profiled_component_link = perf["component_link_us"].to_u64(); + u64 profiled_unit_loads = perf["unit_load_count"].to_u64(); + u64 profiled_unit_module = perf["unit_module_us"].to_u64(); + u64 profiled_unit_allocate = perf["unit_allocate_us"].to_u64(); + u64 profiled_unit_import = perf["unit_import_us"].to_u64(); + u64 profiled_unit_instantiate = perf["unit_instantiate_us"].to_u64(); + u64 profiled_unit_initialize = perf["unit_initialize_us"].to_u64(); String profiled_mysql_operations = json_encode(perf["mysql_operations"]); 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["guest_us"].to_f64() > 0 && perf["component_resolve_count"].to_u64() == profiled_components && 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 && json_encode(perf["mysql_operations"]) == profiled_mysql_operations; + 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["guest_us"].to_f64() > 0 && perf["component_resolve_count"].to_u64() == profiled_components && 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_instantiate_us"].to_u64() == profiled_unit_instantiate && perf["unit_initialize_us"].to_u64() == profiled_unit_initialize && json_encode(perf["mysql_operations"]) == profiled_mysql_operations; } check("request_perf() stages stable repeated snapshots", perf_stable, json_encode(perf)); diff --git a/src/wasm/worker.cpp b/src/wasm/worker.cpp index 828f85d..aa38e96 100644 --- a/src/wasm/worker.cpp +++ b/src/wasm/worker.cpp @@ -119,6 +119,12 @@ struct WasmRequestProfile u64 component_artifact_total_us = 0; u64 component_load_total_us = 0; u64 component_link_total_us = 0; + u64 unit_load_count = 0; + u64 unit_module_total_us = 0; + u64 unit_allocate_total_us = 0; + u64 unit_import_total_us = 0; + u64 unit_instantiate_total_us = 0; + u64 unit_initialize_total_us = 0; u64 hostcall_count = 0; u64 hostcall_total_us = 0; u64 mysql_hostcall_count = 0; @@ -1274,13 +1280,18 @@ private: return(""); } + unit_load_count++; String error; + auto module_start = std::chrono::steady_clock::now(); auto mod = worker.unit_module(source_path, error); + unit_module_total_us += (u64)std::chrono::duration_cast( + std::chrono::steady_clock::now() - module_start).count(); if(!mod) return(error); // Compiling/deserializing a cold module is host work. Refresh the guest // watchdog before the first core call so that wall time cannot make the // otherwise harmless malloc/reloc sequence trap immediately. + auto allocate_start = std::chrono::steady_clock::now(); ctx().set_epoch_deadline(worker.cfg.epoch_deadline_ticks); if(mod->abi.version != abi_version) return(mod->wasm_path + ": uce.abi version " + std::to_string(mod->abi.version) @@ -1302,8 +1313,11 @@ private: if(mod->dylink.table_size > table->size(cx) - table_next_free) return("funcref table headroom exhausted by " + source_path); table_next_free += mod->dylink.table_size; + unit_allocate_total_us += (u64)std::chrono::duration_cast( + std::chrono::steady_clock::now() - allocate_start).count(); // import resolution + auto import_start = std::chrono::steady_clock::now(); std::vector imports; std::vector> deferred_got; for(auto import_type : module.imports()) @@ -1390,8 +1404,13 @@ private: } return(source_path + ": import policy violation: " + mod_name + "." + name); } + unit_import_total_us += (u64)std::chrono::duration_cast( + std::chrono::steady_clock::now() - import_start).count(); + auto instantiate_start = std::chrono::steady_clock::now(); auto created = wasmtime::Instance::create(cx, module, imports); + unit_instantiate_total_us += (u64)std::chrono::duration_cast( + std::chrono::steady_clock::now() - instantiate_start).count(); if(!created) return(source_path + ": instantiation failed: " + trap_text(created.err())); @@ -1405,6 +1424,7 @@ private: unit_index_out = unit_index; // deferred GOT: the unit's own data exports are module-relative — + auto initialize_start = std::chrono::steady_clock::now(); // add this unit's memory base (Phase 0 FINDINGS erratum) for(auto& [name, got] : deferred_got) { @@ -1439,6 +1459,8 @@ private: if(worker.cfg.verbose) fprintf(stderr, "[wasm] loaded %s (mem_base=%u table_base=%u)\n", source_path.c_str(), memory_base, table_base); + unit_initialize_total_us += (u64)std::chrono::duration_cast( + std::chrono::steady_clock::now() - initialize_start).count(); // Exclude the rest of host-side loading as well. A genuine runaway loop // makes no loads, so it still trips the deadline. ctx().set_epoch_deadline(worker.cfg.epoch_deadline_ticks); @@ -1889,6 +1911,12 @@ private: response["component_artifact_us"] = (f64)self->component_artifact_total_us; response["component_load_us"] = (f64)self->component_load_total_us; 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_allocate_us"] = (f64)self->unit_allocate_total_us; + response["unit_import_us"] = (f64)self->unit_import_total_us; + response["unit_instantiate_us"] = (f64)self->unit_instantiate_total_us; + response["unit_initialize_us"] = (f64)self->unit_initialize_total_us; f64 running_us = response["running_us"].to_f64(); f64 accounted_us = (f64)(self->dispatch_us + self->workspace_setup_us + self->workspace_birth_us + self->context_apply_us + self->hostcall_total_us); response["guest_us"] = running_us > accounted_us ? running_us - accounted_us : 0.0;