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

Profile request thread runtime on demand

Browse Source
This commit is contained in:
udo 2026-07-17 03:05:37 +00:00
parent 5a5450caa8
commit 8dbff881a1
6 changed files with 37 additions and 2 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

1
etc/uce/settings.cfg
View File

@ -39,6 +39,7 @@ WASM_COMPILE_SCRIPT=scripts/compile_wasm_unit
# WASM RUNTIME SETTINGS. Unit execution is always routed through wasm.
WASM_BACKEND_VERBOSE=0
WASM_PROFILE_HOSTCALL_CPU=0
WASM_PROFILE_THREAD_RUNTIME=0
WASM_CORE_PATH=bin/wasm/core.wasm
WASM_MEMORY_LIMIT_BYTES=536870912
WASM_EPOCH_DEADLINE_TICKS=200

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. When `WASM_PROFILE_HOSTCALL_CPU=1`, `hostcall_cpu_us` separates thread CPU from hostcall wall time and each bounded `hostcall_operations` item includes the same `cpu_us` attribution. This diagnostic is off by default because sampling thread CPU around every hostcall adds hot-path cost; `hostcall_cpu_profiled` identifies whether the current request used it, and disabled counters remain zero. 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. When `WASM_PROFILE_HOSTCALL_CPU=1`, `hostcall_cpu_us` separates thread CPU from hostcall wall time and each bounded `hostcall_operations` item includes the same `cpu_us` attribution. This diagnostic is off by default because sampling thread CPU around every hostcall adds hot-path cost; `hostcall_cpu_profiled` identifies whether the current request used it, and disabled counters remain zero. `WASM_PROFILE_THREAD_RUNTIME=1` adds one bounded kernel thread snapshot per request: user/system CPU, voluntary/involuntary context switches, minor/major faults, and start/end logical CPU plus migration state. `thread_runtime_profiled` identifies the opt-in diagnostic; its counters are absent when disabled. 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.

3
site/tests/io.uce
View File

@ -178,7 +178,8 @@ RENDER(Request& context)
});
u64 dropped_hostcall_operations = perf["hostcall_operations_dropped"].to_u64();
hostcall_operation_profile_valid = hostcall_operation_profile_valid && perf["hostcall_cpu_profiled"].type == 'B' && 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';
bool thread_runtime_profile_valid = perf["thread_runtime_profiled"].type == 'B' && (!perf["thread_runtime_profiled"].to_bool() || (perf["thread_cpu_start"].to_f64() >= 0 && perf["thread_cpu_end"].to_f64() >= 0 && perf["thread_cpu_migrated"].type == 'B' && perf["thread_user_cpu_us"].to_u64() + perf["thread_system_cpu_us"].to_u64() <= perf["workspace_wall_us"].to_u64() + 5 && perf["thread_voluntary_context_switches"].type != 'S' && perf["thread_involuntary_context_switches"].type != 'S' && perf["thread_minor_faults"].type != 'S' && perf["thread_major_faults"].type != 'S'));
bool perf_stable = transport_profile_valid && workspace_cpu_profile_valid && unit_module_profile_valid && hostcall_operation_profile_valid && thread_runtime_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();

1
src/lib/sys.cpp
View File

@ -1677,6 +1677,7 @@ StringMap make_server_settings()
cfg["WASM_COMPILE_SCRIPT"] = "scripts/compile_wasm_unit";
cfg["WASM_BACKEND_VERBOSE"] = "0";
cfg["WASM_PROFILE_HOSTCALL_CPU"] = "0";
cfg["WASM_PROFILE_THREAD_RUNTIME"] = "0";
cfg["WASM_CORE_PATH"] = "";
cfg["WASM_MEMORY_LIMIT_BYTES"] = std::to_string(512ull * 1024 * 1024);
cfg["WASM_EPOCH_DEADLINE_TICKS"] = "200";

1
src/wasm/backend.cpp
View File

@ -54,6 +54,7 @@ static String wasm_backend_ensure_started(Request* context)
wc.epoch_deadline_ticks = to_u64(cfg["WASM_EPOCH_DEADLINE_TICKS"], 200);
wc.mysql_persistent_pool_size = std::min<u64>(to_u64(cfg["MYSQL_PERSISTENT_POOL_SIZE"], 8), 64);
wc.profile_hostcall_cpu = to_bool(cfg["WASM_PROFILE_HOSTCALL_CPU"], false);
wc.profile_thread_runtime = to_bool(cfg["WASM_PROFILE_THREAD_RUNTIME"], false);
wc.verbose = to_bool(cfg["WASM_BACKEND_VERBOSE"], false);
// UCE_HOSTCALL_BLOCKLIST: comma-separated uce_host_* names (with or without
// the "uce_host_" prefix) the sysadmin disables; each blocked call traps into

31
src/wasm/worker.cpp
View File

@ -47,6 +47,8 @@
#include <limits.h>
#include <unistd.h>
#include <sys/time.h>
#include <sys/resource.h>
#include <sched.h>
#include <vector>
#include <algorithm>
#include <dirent.h>
@ -126,6 +128,7 @@ struct WasmWorkerConfig
u64 epoch_deadline_ticks = 200; // ticker period × ticks = CPU budget
u64 mysql_persistent_pool_size = 8;
bool profile_hostcall_cpu = false;
bool profile_thread_runtime = false;
bool verbose = false;
// uce_host_* names (bare, without the "uce_host_" prefix) the sysadmin has
// disabled via UCE_HOSTCALL_BLOCKLIST. A blocked hostcall resolves to a trap
@ -1224,6 +1227,9 @@ public:
f64 time_start = 0;
f64 workspace_wall_start = 0;
f64 workspace_cpu_start = 0;
struct rusage thread_runtime_start = {};
int thread_cpu_start = -1;
bool thread_runtime_profiled = false;
bool active = false;
} request_perf;
@ -2351,6 +2357,25 @@ private:
response["hostcall_us"] = (f64)self->hostcall_total_us;
response["hostcall_cpu_profiled"].set_bool(self->worker.cfg.profile_hostcall_cpu);
response["hostcall_cpu_us"] = (f64)self->hostcall_cpu_total_us;
struct rusage runtime_now = {};
bool thread_runtime_profiled = self->request_perf.thread_runtime_profiled && getrusage(RUSAGE_THREAD, &runtime_now) == 0;
response["thread_runtime_profiled"].set_bool(thread_runtime_profiled);
if(thread_runtime_profiled)
{
auto timeval_us = [](const struct timeval& value) -> int64_t {
return((int64_t)value.tv_sec * 1000000 + value.tv_usec);
};
int cpu_now = sched_getcpu();
response["thread_user_cpu_us"] = (f64)std::max<int64_t>(0, timeval_us(runtime_now.ru_utime) - timeval_us(self->request_perf.thread_runtime_start.ru_utime));
response["thread_system_cpu_us"] = (f64)std::max<int64_t>(0, timeval_us(runtime_now.ru_stime) - timeval_us(self->request_perf.thread_runtime_start.ru_stime));
response["thread_voluntary_context_switches"] = (f64)std::max<int64_t>(0, runtime_now.ru_nvcsw - self->request_perf.thread_runtime_start.ru_nvcsw);
response["thread_involuntary_context_switches"] = (f64)std::max<int64_t>(0, runtime_now.ru_nivcsw - self->request_perf.thread_runtime_start.ru_nivcsw);
response["thread_minor_faults"] = (f64)std::max<int64_t>(0, runtime_now.ru_minflt - self->request_perf.thread_runtime_start.ru_minflt);
response["thread_major_faults"] = (f64)std::max<int64_t>(0, runtime_now.ru_majflt - self->request_perf.thread_runtime_start.ru_majflt);
response["thread_cpu_start"] = (f64)self->request_perf.thread_cpu_start;
response["thread_cpu_end"] = (f64)cpu_now;
response["thread_cpu_migrated"].set_bool(self->request_perf.thread_cpu_start >= 0 && cpu_now >= 0 && self->request_perf.thread_cpu_start != cpu_now);
}
std::vector<u64> invoked_hostcalls;
for(u64 i = 0; i < self->hostcall_operation_slots; i++)
if(self->hostcall_operation_counts[i] > 0)
@ -3504,6 +3529,9 @@ inline WasmResponse wasm_worker_serve(WasmWorker& worker, const DValue& context_
f64 serve_started = time_precise();
auto workspace_start = std::chrono::steady_clock::now();
f64 cpu_started = wasm_thread_cpu_time();
struct rusage thread_runtime_start = {};
bool thread_runtime_profiled = request && worker.cfg.profile_thread_runtime && getrusage(RUSAGE_THREAD, &thread_runtime_start) == 0;
int thread_cpu_start = thread_runtime_profiled ? sched_getcpu() : -1;
WasmWorkspace workspace(worker);
f64 setup_cpu_finished = wasm_thread_cpu_time();
workspace.workspace_setup_us = (u64)std::chrono::duration_cast<std::chrono::microseconds>(
@ -3515,6 +3543,9 @@ inline WasmResponse wasm_worker_serve(WasmWorker& worker, const DValue& context_
workspace.set_perf_snapshot(my_pid, (u64)parent_pid, request->server ? request->server->request_count : 0,
request->stats.time_init, request->stats.time_params, request->stats.time_input, request->stats.time_start,
serve_started, cpu_started);
workspace.request_perf.thread_runtime_start = thread_runtime_start;
workspace.request_perf.thread_cpu_start = thread_cpu_start;
workspace.request_perf.thread_runtime_profiled = thread_runtime_profiled;
if(request->stats.time_start > 0 && serve_started > request->stats.time_start)
workspace.dispatch_us = (u64)((serve_started - request->stats.time_start) * 1000000.0);
}