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

Attribute per-unit load phases accurately

Browse Source
This commit is contained in:
root 2026-07-17 01:41:33 +00:00
parent 51cbb19f7d
commit aeab8df208
3 changed files with 51 additions and 12 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. `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. `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.

6
site/tests/io.uce
View File

@ -155,7 +155,11 @@ RENDER(Request& context)
u64 serialized_hits = perf["unit_module_serialized_cache_hit_count"].to_u64();
u64 module_read_bytes = perf["unit_module_read_bytes"].to_u64();
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 unit_operation_profile_valid = true;
perf["unit_module_operations"].each([&](DValue operation, String key) {
unit_operation_profile_valid = unit_operation_profile_valid && operation["unit"].to_string() != "" && operation["allocate_us"].type != 'S' && operation["import_us"].type != 'S' && operation["symbol_resolve_count"].type != 'S' && operation["symbol_resolve_us"].type != 'S' && operation["instantiate_us"].type != 'S' && operation["initialize_us"].type != 'S';
});
bool unit_module_profile_valid = serialized_reads_bounded && unit_operation_profile_valid && 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();
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();

55
src/wasm/worker.cpp
View File

@ -150,6 +150,12 @@ struct WasmUnitModuleOperation
u64 parse_us = 0;
u64 build_us = 0;
u64 classify_us = 0;
u64 allocate_us = 0;
u64 import_us = 0;
u64 symbol_resolve_count = 0;
u64 symbol_resolve_us = 0;
u64 instantiate_us = 0;
u64 initialize_us = 0;
};
struct WasmRequestProfile
@ -1642,7 +1648,8 @@ private:
unit_module_parse_total_us += module_profile.parse_us;
unit_module_compile_total_us += module_profile.compile_us;
unit_module_classify_total_us += module_profile.classify_us;
if(unit_module_operations.size() < 32)
size_t module_operation_index = unit_module_operations.size();
if(module_operation_index < 32)
{
String unit_name = source_path;
String site_prefix = worker.cfg.site_root;
@ -1665,7 +1672,10 @@ private:
unit_module_operations.push_back(operation);
}
else
{
module_operation_index = 32;
unit_module_operations_dropped++;
}
if(!mod)
return(error);
// Compiling/deserializing a cold module is host work. Refresh the guest
@ -1693,11 +1703,16 @@ 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>(
u64 allocate_us = (u64)std::chrono::duration_cast<std::chrono::microseconds>(
std::chrono::steady_clock::now() - allocate_start).count();
unit_allocate_total_us += allocate_us;
if(module_operation_index < unit_module_operations.size())
unit_module_operations[module_operation_index].allocate_us = allocate_us;
// import resolution
auto import_start = std::chrono::steady_clock::now();
u64 symbol_resolve_count_start = unit_symbol_resolve_count;
u64 symbol_resolve_us_start = unit_symbol_resolve_total_us;
std::vector<wasmtime::Extern> imports;
imports.reserve(mod->imports.size());
std::vector<std::pair<String, wasmtime::Global>> deferred_got;
@ -1793,13 +1808,24 @@ private:
continue;
}
}
unit_import_total_us += (u64)std::chrono::duration_cast<std::chrono::microseconds>(
u64 import_us = (u64)std::chrono::duration_cast<std::chrono::microseconds>(
std::chrono::steady_clock::now() - import_start).count();
unit_import_total_us += import_us;
if(module_operation_index < unit_module_operations.size())
{
auto& operation = unit_module_operations[module_operation_index];
operation.import_us = import_us;
operation.symbol_resolve_count = unit_symbol_resolve_count - symbol_resolve_count_start;
operation.symbol_resolve_us = unit_symbol_resolve_total_us - symbol_resolve_us_start;
}
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>(
u64 instantiate_us = (u64)std::chrono::duration_cast<std::chrono::microseconds>(
std::chrono::steady_clock::now() - instantiate_start).count();
unit_instantiate_total_us += instantiate_us;
if(module_operation_index < unit_module_operations.size())
unit_module_operations[module_operation_index].instantiate_us = instantiate_us;
if(!created)
return(source_path + ": instantiation failed: " + trap_text(created.err()));
@ -1848,8 +1874,11 @@ 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>(
u64 initialize_us = (u64)std::chrono::duration_cast<std::chrono::microseconds>(
std::chrono::steady_clock::now() - initialize_start).count();
unit_initialize_total_us += initialize_us;
if(module_operation_index < unit_module_operations.size())
unit_module_operations[module_operation_index].initialize_us = initialize_us;
// 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);
@ -2278,8 +2307,8 @@ private:
DValue response;
if(self->request_perf.active)
{
f64 now = time_precise();
f64 cpu_now = wasm_thread_cpu_time();
f64 now = time_precise();
response["worker_pid"] = (f64)self->request_perf.worker_pid;
response["parent_pid"] = (f64)self->request_perf.parent_pid;
response["request_count"] = (f64)self->request_perf.request_count;
@ -2383,6 +2412,12 @@ private:
item["parse_us"] = (f64)operation.parse_us;
item["build_us"] = (f64)operation.build_us;
item["classify_us"] = (f64)operation.classify_us;
item["allocate_us"] = (f64)operation.allocate_us;
item["import_us"] = (f64)operation.import_us;
item["symbol_resolve_count"] = (f64)operation.symbol_resolve_count;
item["symbol_resolve_us"] = (f64)operation.symbol_resolve_us;
item["instantiate_us"] = (f64)operation.instantiate_us;
item["initialize_us"] = (f64)operation.initialize_us;
response["unit_module_operations"].push(item);
}
response["unit_allocate_us"] = (f64)self->unit_allocate_total_us;
@ -3455,12 +3490,12 @@ inline WasmResponse wasm_worker_serve(WasmWorker& worker, const DValue& context_
{
WasmResponse response;
f64 serve_started = time_precise();
f64 cpu_started = wasm_thread_cpu_time();
auto workspace_start = std::chrono::steady_clock::now();
f64 cpu_started = wasm_thread_cpu_time();
WasmWorkspace workspace(worker);
f64 setup_cpu_finished = wasm_thread_cpu_time();
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)
@ -3474,9 +3509,9 @@ inline WasmResponse wasm_worker_serve(WasmWorker& worker, const DValue& context_
auto birth_start = std::chrono::steady_clock::now();
f64 birth_cpu_start = wasm_thread_cpu_time();
String error = workspace.birth();
f64 birth_cpu_finished = wasm_thread_cpu_time();
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 == "")
@ -3484,9 +3519,9 @@ inline WasmResponse wasm_worker_serve(WasmWorker& worker, const DValue& context_
auto context_start = std::chrono::steady_clock::now();
f64 context_cpu_start = wasm_thread_cpu_time();
error = workspace.apply_context(context_tree);
f64 context_cpu_finished = wasm_thread_cpu_time();
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;
}