Profile workspace thread CPU time

This commit is contained in:
udo
2026-07-17 00:45:46 +00:00
parent 03ffeeb0da
commit 96e5813a0b
2 changed files with 25 additions and 3 deletions
+2 -1
View File
@@ -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();
+23 -2
View File
@@ -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<std::chrono::microseconds>(
@@ -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);
}