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

Profile workspace CPU phases

Browse Source
This commit is contained in:
root 2026-07-17 01:12:55 +00:00
parent 0e43a89636
commit 51cbb19f7d
3 changed files with 22 additions and 2 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. `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; 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. `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.

3
site/tests/io.uce
View File

@ -157,7 +157,8 @@ RENDER(Request& context)
bool serialized_reads_bounded = module_misses == 0 || serialized_hits != module_misses || (module_read_bytes > 0 && module_read_bytes < module_misses * 1024 * 1024);
bool unit_module_profile_valid = serialized_reads_bounded && perf["unit_module_cache_hit_count"].to_u64() + module_misses == perf["unit_load_count"].to_u64() && serialized_hits + perf["unit_module_compile_count"].to_u64() == module_misses && perf["unit_module_lookup_us"].type != 'S' && perf["unit_module_read_us"].type != 'S' && perf["unit_module_read_bytes"].type != 'S' && perf["unit_module_parse_us"].type != 'S' && perf["unit_module_compile_us"].type != 'S' && perf["unit_module_classify_us"].type != 'S';
bool transport_profile_valid = perf["transport_params_us"].type != 'S' && perf["transport_input_us"].type != 'S' && perf["handler_queue_us"].type != 'S' && perf["accept_us"].to_f64() + 2 >= perf["transport_params_us"].to_f64() + perf["transport_input_us"].to_f64() + perf["handler_queue_us"].to_f64();
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());
u64 phase_cpu_us = perf["workspace_setup_cpu_us"].to_u64() + perf["workspace_birth_cpu_us"].to_u64() + perf["context_apply_cpu_us"].to_u64();
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_kinds = 0;

19
src/wasm/worker.cpp
View File

@ -157,8 +157,11 @@ struct WasmRequestProfile
static const u64 HOSTCALL_OPERATION_MAX = 96;
u64 dispatch_us = 0;
u64 workspace_setup_us = 0;
u64 workspace_setup_cpu_us = 0;
u64 workspace_birth_us = 0;
u64 workspace_birth_cpu_us = 0;
u64 context_apply_us = 0;
u64 context_apply_cpu_us = 0;
u64 component_resolve_count = 0;
u64 component_resolve_total_us = 0;
u64 component_path_total_us = 0;
@ -2299,8 +2302,13 @@ private:
response["workspace_wait_us"] = (f64)(workspace_wall_us > workspace_cpu_us ? workspace_wall_us - workspace_cpu_us : 0);
response["dispatch_us"] = (f64)self->dispatch_us;
response["workspace_setup_us"] = (f64)self->workspace_setup_us;
response["workspace_setup_cpu_us"] = (f64)self->workspace_setup_cpu_us;
response["workspace_birth_us"] = (f64)self->workspace_birth_us;
response["workspace_birth_cpu_us"] = (f64)self->workspace_birth_cpu_us;
response["context_apply_us"] = (f64)self->context_apply_us;
response["context_apply_cpu_us"] = (f64)self->context_apply_cpu_us;
u64 phase_cpu_us = self->workspace_setup_cpu_us + self->workspace_birth_cpu_us + self->context_apply_cpu_us;
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;
std::vector<u64> invoked_hostcalls;
@ -3452,6 +3460,9 @@ inline WasmResponse wasm_worker_serve(WasmWorker& worker, const DValue& context_
WasmWorkspace workspace(worker);
workspace.workspace_setup_us = (u64)std::chrono::duration_cast<std::chrono::microseconds>(
std::chrono::steady_clock::now() - workspace_start).count();
f64 setup_cpu_finished = wasm_thread_cpu_time();
workspace.workspace_setup_cpu_us = cpu_started > 0 && setup_cpu_finished > cpu_started ?
(u64)((setup_cpu_finished - cpu_started) * 1000000.0) : 0;
if(request)
{
workspace.set_perf_snapshot(my_pid, (u64)parent_pid, request->server ? request->server->request_count : 0,
@ -3461,15 +3472,23 @@ inline WasmResponse wasm_worker_serve(WasmWorker& worker, const DValue& context_
workspace.dispatch_us = (u64)((serve_started - request->stats.time_start) * 1000000.0);
}
auto birth_start = std::chrono::steady_clock::now();
f64 birth_cpu_start = wasm_thread_cpu_time();
String error = workspace.birth();
workspace.workspace_birth_us = (u64)std::chrono::duration_cast<std::chrono::microseconds>(
std::chrono::steady_clock::now() - birth_start).count();
f64 birth_cpu_finished = wasm_thread_cpu_time();
workspace.workspace_birth_cpu_us = birth_cpu_start > 0 && birth_cpu_finished > birth_cpu_start ?
(u64)((birth_cpu_finished - birth_cpu_start) * 1000000.0) : 0;
if(error == "")
{
auto context_start = std::chrono::steady_clock::now();
f64 context_cpu_start = wasm_thread_cpu_time();
error = workspace.apply_context(context_tree);
workspace.context_apply_us = (u64)std::chrono::duration_cast<std::chrono::microseconds>(
std::chrono::steady_clock::now() - context_start).count();
f64 context_cpu_finished = wasm_thread_cpu_time();
workspace.context_apply_cpu_us = context_cpu_start > 0 && context_cpu_finished > context_cpu_start ?
(u64)((context_cpu_finished - context_cpu_start) * 1000000.0) : 0;
}
if(error == "")
error = workspace.invoke_entry(entry_source_path, handler, &response.handler_present);