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

Profile hostcall thread CPU

Browse Source
This commit is contained in:
root 2026-07-17 02:09:16 +00:00
parent 1ad05475e8
commit 672e5b66ef
3 changed files with 17 additions and 4 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

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

@ -11,7 +11,7 @@ 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. `accept_us` is divided into `transport_params_us` (FastCGI begin through the end of parameters), `transport_input_us` (parameters through the end of input), and `handler_queue_us` (input close through handler entry). This distinguishes upstream request delivery from work inside the UCE handler.
Hostcall totals include component resolution; MySQL, memcache, and component resolution also expose their own count and microsecond fields. Workspace setup, birth, and context application expose matching wall and thread-CPU microseconds. `execution_cpu_us` is the remaining workspace thread CPU through the snapshot after those three phases. `unit_module_operations` is a source-root-relative list of up to 32 unit loads. Each item attributes module lookup/read/parse/build/classification plus allocation, import construction, symbol resolution, instantiation, and initialization; no caller-supplied paths are exposed. `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.
Hostcall totals include component resolution; `hostcall_cpu_us` separates thread CPU from hostcall wall time, and each bounded `hostcall_operations` item includes the same `cpu_us` attribution. MySQL, memcache, and component resolution also expose their own count and microsecond fields. Workspace setup, birth, and context application expose matching wall and thread-CPU microseconds. `execution_cpu_us` is the remaining workspace thread CPU through the snapshot after those three phases. `unit_module_operations` is a source-root-relative list of up to 32 unit loads. Each item attributes module lookup/read/parse/build/classification plus allocation, import construction, symbol resolution, instantiation, and initialization; no caller-supplied paths are exposed. `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.

9
site/tests/io.uce
View File

@ -165,6 +165,7 @@ RENDER(Request& context)
bool workspace_cpu_profile_valid = perf["workspace_wall_us"].to_u64() > 0 && perf["workspace_cpu_us"].to_u64() > 0 && perf["workspace_cpu_us"].to_u64() <= perf["workspace_wall_us"].to_u64() + 2 && (perf["workspace_cpu_us"].to_u64() >= perf["workspace_wall_us"].to_u64() ? perf["workspace_wait_us"].to_u64() == 0 : perf["workspace_wait_us"].to_u64() + perf["workspace_cpu_us"].to_u64() == perf["workspace_wall_us"].to_u64()) && perf["workspace_setup_cpu_us"].to_u64() <= perf["workspace_setup_us"].to_u64() + 2 && perf["workspace_birth_cpu_us"].to_u64() <= perf["workspace_birth_us"].to_u64() + 2 && perf["context_apply_cpu_us"].to_u64() <= perf["context_apply_us"].to_u64() + 2 && phase_cpu_us + perf["execution_cpu_us"].to_u64() == perf["workspace_cpu_us"].to_u64();
u64 operation_hostcalls = 0;
u64 operation_hostcall_us = 0;
u64 operation_hostcall_cpu_us = 0;
u64 operation_kinds = 0;
bool hostcall_operation_profile_valid = true;
perf["hostcall_operations"].each([&](DValue operation, String key) {
@ -172,13 +173,15 @@ RENDER(Request& context)
operation_kinds++;
operation_hostcalls += operation["count"].to_u64();
operation_hostcall_us += operation["us"].to_u64();
hostcall_operation_profile_valid = hostcall_operation_profile_valid && name != "" && !contains(name, "uce_host_") && !contains(name, "/") && operation["count"].to_u64() > 0;
operation_hostcall_cpu_us += operation["cpu_us"].to_u64();
hostcall_operation_profile_valid = hostcall_operation_profile_valid && name != "" && !contains(name, "uce_host_") && !contains(name, "/") && operation["count"].to_u64() > 0 && operation["cpu_us"].to_u64() <= operation["us"].to_u64() + 2;
});
u64 dropped_hostcall_operations = perf["hostcall_operations_dropped"].to_u64();
hostcall_operation_profile_valid = hostcall_operation_profile_valid && 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()) || (dropped_hostcall_operations > 0 && operation_kinds == 32 && operation_hostcalls < perf["hostcall_count"].to_u64() && operation_hostcall_us <= perf["hostcall_us"].to_u64()));
hostcall_operation_profile_valid = hostcall_operation_profile_valid && 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 perf_stable = transport_profile_valid && workspace_cpu_profile_valid && unit_module_profile_valid && hostcall_operation_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_hostcall_cpu_us = perf["hostcall_cpu_us"].to_u64();
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();
@ -197,7 +200,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["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_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["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_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));

10
src/wasm/worker.cpp
View File

@ -196,9 +196,11 @@ struct WasmRequestProfile
u64 unit_initialize_total_us = 0;
u64 hostcall_count = 0;
u64 hostcall_total_us = 0;
u64 hostcall_cpu_total_us = 0;
u64 hostcall_operation_slots = 0;
u64 hostcall_operation_counts[HOSTCALL_OPERATION_MAX] = {};
u64 hostcall_operation_us[HOSTCALL_OPERATION_MAX] = {};
u64 hostcall_operation_cpu_us[HOSTCALL_OPERATION_MAX] = {};
u64 mysql_hostcall_count = 0;
u64 mysql_hostcall_total_us = 0;
u64 mysql_operation_count = 0;
@ -2236,21 +2238,27 @@ private:
bool profile_memcache = name == "uce_host_memcache_command";
auto profiled = [self, callback, profile_index, profile_enabled, profile_mysql, profile_memcache](Caller caller, Span<const Val> args, Span<Val> results) mutable -> Result<std::monostate, Trap> {
auto started = std::chrono::steady_clock::now();
f64 cpu_started = profile_enabled ? wasm_thread_cpu_time() : 0;
auto result = callback(caller, args, results);
// Epoch interruption limits guest CPU, not time spent in native I/O,
// process management, hashing, or other host work. Re-arm at the one
// membrane every hostcall crosses so newly added blocking imports
// cannot silently consume the next guest segment's budget.
caller.context().set_epoch_deadline(self->worker.cfg.epoch_deadline_ticks);
f64 cpu_finished = profile_enabled ? wasm_thread_cpu_time() : 0;
if(profile_enabled)
{
u64 elapsed = (u64)std::chrono::duration_cast<std::chrono::microseconds>(std::chrono::steady_clock::now() - started).count();
u64 cpu_elapsed = cpu_started > 0 && cpu_finished > cpu_started ?
(u64)((cpu_finished - cpu_started) * 1000000.0) : 0;
self->hostcall_count++;
self->hostcall_total_us += elapsed;
self->hostcall_cpu_total_us += cpu_elapsed;
if(profile_index < WasmRequestProfile::HOSTCALL_OPERATION_MAX)
{
self->hostcall_operation_counts[profile_index]++;
self->hostcall_operation_us[profile_index] += elapsed;
self->hostcall_operation_cpu_us[profile_index] += cpu_elapsed;
}
if(profile_mysql)
{
@ -2340,6 +2348,7 @@ private:
response["execution_cpu_us"] = (f64)(workspace_cpu_us > phase_cpu_us ? workspace_cpu_us - phase_cpu_us : 0);
response["hostcall_count"] = (f64)self->hostcall_count;
response["hostcall_us"] = (f64)self->hostcall_total_us;
response["hostcall_cpu_us"] = (f64)self->hostcall_cpu_total_us;
std::vector<u64> invoked_hostcalls;
for(u64 i = 0; i < self->hostcall_operation_slots; i++)
if(self->hostcall_operation_counts[i] > 0)
@ -2359,6 +2368,7 @@ private:
item["name"] = operation_name.rfind("uce_host_", 0) == 0 ? operation_name.substr(9) : operation_name;
item["count"] = (f64)self->hostcall_operation_counts[operation_index];
item["us"] = (f64)self->hostcall_operation_us[operation_index];
item["cpu_us"] = (f64)self->hostcall_operation_cpu_us[operation_index];
response["hostcall_operations"].push(item);
}
response["mysql_hostcall_count"] = (f64)self->mysql_hostcall_count;