From 7789385ef5d0654824dbb184dcfeb9863cf00e51 Mon Sep 17 00:00:00 2001 From: udo Date: Fri, 17 Jul 2026 00:01:19 +0000 Subject: [PATCH] Profile bounded hostcall operations --- site/tests/io.uce | 18 ++++++++++++++-- src/wasm/worker.cpp | 52 ++++++++++++++++++++++++++++++++++++++++----- 2 files changed, 63 insertions(+), 7 deletions(-) diff --git a/site/tests/io.uce b/site/tests/io.uce index 257db71..9190fe3 100644 --- a/site/tests/io.uce +++ b/site/tests/io.uce @@ -157,7 +157,20 @@ 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 perf_stable = transport_profile_valid && unit_module_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 operation_hostcalls = 0; + u64 operation_hostcall_us = 0; + u64 operation_kinds = 0; + bool hostcall_operation_profile_valid = true; + perf["hostcall_operations"].each([&](DValue operation, String key) { + String name = operation["name"].to_string(); + 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; + }); + 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'; 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(); @@ -174,10 +187,11 @@ RENDER(Request& context) u64 profiled_unit_instantiate = perf["unit_instantiate_us"].to_u64(); u64 profiled_unit_initialize = perf["unit_initialize_us"].to_u64(); String profiled_mysql_operations = json_encode(perf["mysql_operations"]); + String profiled_hostcall_operations = json_encode(perf["hostcall_operations"]); 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; + 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; } 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 5604ae6..97a0f12 100644 --- a/src/wasm/worker.cpp +++ b/src/wasm/worker.cpp @@ -154,6 +154,7 @@ struct WasmUnitModuleOperation struct WasmRequestProfile { + static const u64 HOSTCALL_OPERATION_MAX = 96; u64 dispatch_us = 0; u64 workspace_setup_us = 0; u64 workspace_birth_us = 0; @@ -186,6 +187,9 @@ struct WasmRequestProfile u64 unit_initialize_total_us = 0; u64 hostcall_count = 0; u64 hostcall_total_us = 0; + u64 hostcall_operation_slots = 0; + u64 hostcall_operation_counts[HOSTCALL_OPERATION_MAX] = {}; + u64 hostcall_operation_us[HOSTCALL_OPERATION_MAX] = {}; u64 mysql_hostcall_count = 0; u64 mysql_hostcall_total_us = 0; u64 mysql_operation_count = 0; @@ -1080,6 +1084,8 @@ public: } private: + friend class WasmWorkspace; + static String cached_wasm_path(const String& wasm_path) { if(wasm_path.size() >= 5 && wasm_path.rfind(".wasm", wasm_path.size() - 5) == wasm_path.size() - 5) @@ -1169,6 +1175,7 @@ private: } std::map> module_cache; + std::vector hostcall_operation_names; }; // ---- workspace (per request) ---------------------------------------------- @@ -2172,8 +2179,17 @@ private: WasmWorkspace* self = this; auto add = [&](auto&& callback) -> Extern { - String profile_name = name; - auto profiled = [self, callback, profile_name](Caller caller, Span args, Span results) mutable -> Result { + u64 profile_index = self->hostcall_operation_slots; + if(profile_index < WasmRequestProfile::HOSTCALL_OPERATION_MAX) + { + self->hostcall_operation_slots++; + if(self->worker.hostcall_operation_names.size() <= profile_index) + self->worker.hostcall_operation_names.push_back(name); + } + bool profile_enabled = name != "uce_host_request_perf"; + bool profile_mysql = name == "uce_host_mysql"; + 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(); auto result = callback(caller, args, results); // Epoch interruption limits guest CPU, not time spent in native I/O, @@ -2181,17 +2197,22 @@ private: // 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); - if(profile_name != "uce_host_request_perf") + if(profile_enabled) { u64 elapsed = (u64)std::chrono::duration_cast(std::chrono::steady_clock::now() - started).count(); self->hostcall_count++; self->hostcall_total_us += elapsed; - if(profile_name == "uce_host_mysql") + if(profile_index < WasmRequestProfile::HOSTCALL_OPERATION_MAX) + { + self->hostcall_operation_counts[profile_index]++; + self->hostcall_operation_us[profile_index] += elapsed; + } + if(profile_mysql) { self->mysql_hostcall_count++; self->mysql_hostcall_total_us += elapsed; } - else if(profile_name == "uce_host_memcache_command") + else if(profile_memcache) { self->memcache_hostcall_count++; self->memcache_hostcall_total_us += elapsed; @@ -2263,6 +2284,27 @@ private: response["context_apply_us"] = (f64)self->context_apply_us; response["hostcall_count"] = (f64)self->hostcall_count; response["hostcall_us"] = (f64)self->hostcall_total_us; + std::vector invoked_hostcalls; + for(u64 i = 0; i < self->hostcall_operation_slots; i++) + if(self->hostcall_operation_counts[i] > 0) + invoked_hostcalls.push_back(i); + std::sort(invoked_hostcalls.begin(), invoked_hostcalls.end(), [&](u64 a, u64 b) { + if(self->hostcall_operation_us[a] != self->hostcall_operation_us[b]) + return(self->hostcall_operation_us[a] > self->hostcall_operation_us[b]); + return(self->worker.hostcall_operation_names[a] < self->worker.hostcall_operation_names[b]); + }); + response["hostcall_operations_dropped"] = (f64)(invoked_hostcalls.size() > 32 ? invoked_hostcalls.size() - 32 : 0); + response["hostcall_operations"].set_array(); + for(u64 i = 0; i < invoked_hostcalls.size() && i < 32; i++) + { + u64 operation_index = invoked_hostcalls[i]; + String& operation_name = self->worker.hostcall_operation_names[operation_index]; + DValue item; + 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]; + response["hostcall_operations"].push(item); + } response["mysql_hostcall_count"] = (f64)self->mysql_hostcall_count; response["mysql_hostcall_us"] = (f64)self->mysql_hostcall_total_us; response["mysql_operation_count"] = (f64)self->mysql_operation_count;