From 672e5b66ef8491dc36706fa4684cc99b2c5da8eb Mon Sep 17 00:00:00 2001 From: root Date: Fri, 17 Jul 2026 02:09:16 +0000 Subject: [PATCH] Profile hostcall thread CPU --- site/doc/pages/request_perf.txt | 2 +- site/tests/io.uce | 9 ++++++--- src/wasm/worker.cpp | 10 ++++++++++ 3 files changed, 17 insertions(+), 4 deletions(-) diff --git a/site/doc/pages/request_perf.txt b/site/doc/pages/request_perf.txt index 06afe16..abb31eb 100644 --- a/site/doc/pages/request_perf.txt +++ b/site/doc/pages/request_perf.txt @@ -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. diff --git a/site/tests/io.uce b/site/tests/io.uce index abfa0f0..7954d19 100644 --- a/site/tests/io.uce +++ b/site/tests/io.uce @@ -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)); diff --git a/src/wasm/worker.cpp b/src/wasm/worker.cpp index e9d5d57..2ebb651 100644 --- a/src/wasm/worker.cpp +++ b/src/wasm/worker.cpp @@ -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 args, Span results) mutable -> Result { 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::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 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;