From 96e5813a0b67b08ef8a37d8597fab1d1bff63f95 Mon Sep 17 00:00:00 2001 From: udo Date: Fri, 17 Jul 2026 00:45:46 +0000 Subject: [PATCH] Profile workspace thread CPU time --- site/tests/io.uce | 3 ++- src/wasm/worker.cpp | 25 +++++++++++++++++++++++-- 2 files changed, 25 insertions(+), 3 deletions(-) diff --git a/site/tests/io.uce b/site/tests/io.uce index fe553c5..ccb8d94 100644 --- a/site/tests/io.uce +++ b/site/tests/io.uce @@ -157,6 +157,7 @@ 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 operation_hostcalls = 0; u64 operation_hostcall_us = 0; u64 operation_kinds = 0; @@ -170,7 +171,7 @@ RENDER(Request& context) }); 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())); - bool perf_stable = transport_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 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_components = perf["component_resolve_count"].to_u64(); diff --git a/src/wasm/worker.cpp b/src/wasm/worker.cpp index 97a0f12..bd8c9d0 100644 --- a/src/wasm/worker.cpp +++ b/src/wasm/worker.cpp @@ -228,6 +228,14 @@ static u64 wasm_monotonic_ms() return((u64)ts.tv_sec * 1000ull + (u64)ts.tv_nsec / 1000000ull); } +static f64 wasm_thread_cpu_time() +{ + struct timespec ts; + if(clock_gettime(CLOCK_THREAD_CPUTIME_ID, &ts) != 0) + return(0); + return((f64)ts.tv_sec + (f64)ts.tv_nsec / 1000000000.0); +} + static int wasm_open_locked_file(const String& file_name, int flags, int lock_type, bool truncate_after_lock) { int fd = open(file_name.c_str(), flags, 0644); @@ -1202,6 +1210,8 @@ public: f64 time_params = 0; f64 time_input = 0; f64 time_start = 0; + f64 workspace_wall_start = 0; + f64 workspace_cpu_start = 0; bool active = false; } request_perf; @@ -1210,7 +1220,8 @@ public: } void set_perf_snapshot(u64 worker_pid, u64 parent_pid, u64 request_count, - f64 time_init, f64 time_params, f64 time_input, f64 time_start) + f64 time_init, f64 time_params, f64 time_input, f64 time_start, + f64 workspace_wall_start, f64 workspace_cpu_start) { request_perf.worker_pid = worker_pid; request_perf.parent_pid = parent_pid; @@ -1219,6 +1230,8 @@ public: request_perf.time_params = time_params; request_perf.time_input = time_input; request_perf.time_start = time_start; + request_perf.workspace_wall_start = workspace_wall_start; + request_perf.workspace_cpu_start = workspace_cpu_start; request_perf.active = true; } @@ -2263,6 +2276,7 @@ private: if(self->request_perf.active) { f64 now = time_precise(); + f64 cpu_now = wasm_thread_cpu_time(); 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; @@ -2278,6 +2292,11 @@ private: response["running_us"] = (f64)((now - self->request_perf.time_start) * 1000000.0); if(self->request_perf.time_init > 0) response["total_us"] = (f64)((now - self->request_perf.time_init) * 1000000.0); + u64 workspace_wall_us = self->request_perf.workspace_wall_start > 0 ? (u64)((now - self->request_perf.workspace_wall_start) * 1000000.0) : 0; + u64 workspace_cpu_us = self->request_perf.workspace_cpu_start > 0 && cpu_now > 0 ? (u64)((cpu_now - self->request_perf.workspace_cpu_start) * 1000000.0) : 0; + response["workspace_wall_us"] = (f64)workspace_wall_us; + response["workspace_cpu_us"] = (f64)workspace_cpu_us; + 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_birth_us"] = (f64)self->workspace_birth_us; @@ -3428,6 +3447,7 @@ 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(); WasmWorkspace workspace(worker); workspace.workspace_setup_us = (u64)std::chrono::duration_cast( @@ -3435,7 +3455,8 @@ inline WasmResponse wasm_worker_serve(WasmWorker& worker, const DValue& context_ if(request) { 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); + request->stats.time_init, request->stats.time_params, request->stats.time_input, request->stats.time_start, + serve_started, cpu_started); if(request->stats.time_start > 0 && serve_started > request->stats.time_start) workspace.dispatch_us = (u64)((serve_started - request->stats.time_start) * 1000000.0); }