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

Profile component resolution subphases

Browse Source
This commit is contained in:
udo
2026-07-16 17:34:46 +00:00
parent 6a02c07bcb
commit fd276f8343
4 changed files with 36 additions and 2 deletions
Download Patch File Download Diff File Expand all files Collapse all files
site/demo/index.uce
+1
View File
@@ -102,6 +102,7 @@ RENDER(Request& context)
print("MySQL connections: ", (u64)perf["mysql_connection_open_count"].to_u64(), " new / ", (u64)perf["mysql_connection_reuse_count"].to_u64(), " worker reuse / ", (u64)perf["mysql_request_pool_hit_count"].to_u64(), " request reuse\n");
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("Output buffer size: ", context.ob->str().length(), "\n");
?></pre>
</div>
site/doc/pages/request_perf.txt
+2
View File
@@ -11,6 +11,8 @@ return value : performance snapshot for the active request/workspace
:content
Returns a DValue with timing and process metadata such as worker pid, parent pid, request count, request start times, native dispatch, workspace setup and birth, context application, guest execution, and hostcall timing. Hostcall totals include component resolution; MySQL, memcache, and component resolution also expose their own count and microsecond fields. `mysql_operations` is an ordered, query-text-free list of up to 64 logical MySQL operations and their microsecond durations. A connect operation also identifies its source as `new`, cross-request `worker`, or same-request `request`; the corresponding `mysql_connection_open_count`, `mysql_connection_reuse_count`, and `mysql_request_pool_hit_count` fields provide totals. `mysql_operations_dropped` reports any overflow. The profiling hostcall itself is excluded from those totals so repeated snapshots remain comparable.
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.
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
site/tests/io.uce
+6 -2
View File
@@ -151,15 +151,19 @@ 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';
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';
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();
u64 profiled_component_path = perf["component_path_us"].to_u64();
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();
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 && 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 && json_encode(perf["mysql_operations"]) == profiled_mysql_operations;
}
check("request_perf() stages stable repeated snapshots", perf_stable, json_encode(perf));
src/wasm/worker.cpp
+27
View File
@@ -115,6 +115,10 @@ struct WasmRequestProfile
u64 context_apply_us = 0;
u64 component_resolve_count = 0;
u64 component_resolve_total_us = 0;
u64 component_path_total_us = 0;
u64 component_artifact_total_us = 0;
u64 component_load_total_us = 0;
u64 component_link_total_us = 0;
u64 hostcall_count = 0;
u64 hostcall_total_us = 0;
u64 mysql_hostcall_count = 0;
@@ -1678,11 +1682,15 @@ private:
file_name = current_unit;
if(file_name == "")
{
component_path_total_us += (u64)std::chrono::duration_cast<std::chrono::microseconds>(
std::chrono::steady_clock::now() - probe_start).count();
record_probe();
return(0);
}
String resolved = resolve_source_path(file_name, current_unit);
component_path_total_us += (u64)std::chrono::duration_cast<std::chrono::microseconds>(
std::chrono::steady_clock::now() - probe_start).count();
if(resolved == "")
{
record_probe();
@@ -1695,6 +1703,7 @@ private:
return(1);
}
auto artifact_start = std::chrono::steady_clock::now();
bool artifact_exists = file_exists_host(worker.unit_wasm_path(resolved));
bool can_serve_stale = compiler_request_can_serve_stale_artifact(context);
// The proactive compiler owns freshness while stale HTTP artifacts may be
@@ -1703,20 +1712,31 @@ private:
bool stale = !can_serve_stale && artifact_exists && compiler_unit_needs_recompile(context, resolved, 0);
if(!artifact_exists || stale)
get_shared_unit(context, resolved);
component_artifact_total_us += (u64)std::chrono::duration_cast<std::chrono::microseconds>(
std::chrono::steady_clock::now() - artifact_start).count();
auto load_start = std::chrono::steady_clock::now();
size_t unit_index = 0;
String error = load_unit(resolved, unit_index);
component_load_total_us += (u64)std::chrono::duration_cast<std::chrono::microseconds>(
std::chrono::steady_clock::now() - load_start).count();
if(error != "")
{
fprintf(stderr, "[wasm] component load failed: %s\n", error.c_str());
record_probe();
return(0);
}
auto link_start = std::chrono::steady_clock::now();
auto record_link = [&]() {
component_link_total_us += (u64)std::chrono::duration_cast<std::chrono::microseconds>(
std::chrono::steady_clock::now() - link_start).count();
};
String symbol = handler_export_symbol(handler);
String slot_key = resolved + ":" + symbol;
auto cached = handler_slots.find(slot_key);
if(cached != handler_slots.end())
{
record_link();
record_probe();
return((int32_t)cached->second);
}
@@ -1726,6 +1746,7 @@ private:
// ONCE is optional per unit; a missing __uce_once is not an error
if(handler != "once")
fprintf(stderr, "[wasm] %s does not export %s\n", resolved.c_str(), symbol.c_str());
record_link();
record_probe();
return(0);
}
@@ -1734,10 +1755,12 @@ private:
if(error != "")
{
fprintf(stderr, "[wasm] %s\n", error.c_str());
record_link();
record_probe();
return(0);
}
handler_slots[slot_key] = slot;
record_link();
record_probe();
return((int32_t)slot);
}
@@ -1862,6 +1885,10 @@ private:
response["memcache_hostcall_us"] = (f64)self->memcache_hostcall_total_us;
response["component_resolve_count"] = (f64)self->component_resolve_count;
response["component_resolve_us"] = (f64)self->component_resolve_total_us;
response["component_path_us"] = (f64)self->component_path_total_us;
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;
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;