udo/uce
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Profile side module loading phases

Browse Source
This commit is contained in:
udo 2026-07-16 18:01:31 +00:00
parent fd276f8343
commit 197719ea23
4 changed files with 39 additions and 2 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

1
site/demo/index.uce
View File

@ -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");
?></pre>
</div>

2
site/doc/pages/request_perf.txt
View File

@ -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

10
site/tests/io.uce
View File

@ -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));

28
src/wasm/worker.cpp
View File

@ -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::microseconds>(
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::microseconds>(
std::chrono::steady_clock::now() - allocate_start).count();
// import resolution
auto import_start = std::chrono::steady_clock::now();
std::vector<wasmtime::Extern> imports;
std::vector<std::pair<String, wasmtime::Global>> 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::microseconds>(
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::microseconds>(
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::microseconds>(
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;