diff --git a/site/doc/pages/request_perf.txt b/site/doc/pages/request_perf.txt index caf33ae..06afe16 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. `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; 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 4338dc4..abfa0f0 100644 --- a/site/tests/io.uce +++ b/site/tests/io.uce @@ -155,7 +155,11 @@ RENDER(Request& context) u64 serialized_hits = perf["unit_module_serialized_cache_hit_count"].to_u64(); u64 module_read_bytes = perf["unit_module_read_bytes"].to_u64(); 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 unit_operation_profile_valid = true; + perf["unit_module_operations"].each([&](DValue operation, String key) { + unit_operation_profile_valid = unit_operation_profile_valid && operation["unit"].to_string() != "" && operation["allocate_us"].type != 'S' && operation["import_us"].type != 'S' && operation["symbol_resolve_count"].type != 'S' && operation["symbol_resolve_us"].type != 'S' && operation["instantiate_us"].type != 'S' && operation["initialize_us"].type != 'S'; + }); + bool unit_module_profile_valid = serialized_reads_bounded && unit_operation_profile_valid && 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(); u64 phase_cpu_us = perf["workspace_setup_cpu_us"].to_u64() + perf["workspace_birth_cpu_us"].to_u64() + perf["context_apply_cpu_us"].to_u64(); 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(); diff --git a/src/wasm/worker.cpp b/src/wasm/worker.cpp index 0307c4f..e9d5d57 100644 --- a/src/wasm/worker.cpp +++ b/src/wasm/worker.cpp @@ -150,6 +150,12 @@ struct WasmUnitModuleOperation u64 parse_us = 0; u64 build_us = 0; u64 classify_us = 0; + u64 allocate_us = 0; + u64 import_us = 0; + u64 symbol_resolve_count = 0; + u64 symbol_resolve_us = 0; + u64 instantiate_us = 0; + u64 initialize_us = 0; }; struct WasmRequestProfile @@ -1642,7 +1648,8 @@ private: unit_module_parse_total_us += module_profile.parse_us; unit_module_compile_total_us += module_profile.compile_us; unit_module_classify_total_us += module_profile.classify_us; - if(unit_module_operations.size() < 32) + size_t module_operation_index = unit_module_operations.size(); + if(module_operation_index < 32) { String unit_name = source_path; String site_prefix = worker.cfg.site_root; @@ -1665,7 +1672,10 @@ private: unit_module_operations.push_back(operation); } else + { + module_operation_index = 32; unit_module_operations_dropped++; + } if(!mod) return(error); // Compiling/deserializing a cold module is host work. Refresh the guest @@ -1693,11 +1703,16 @@ private: if(mod->dylink.table_size > table->size(cx) - table_next_free) return("funcref table headroom exhausted by " + source_path); table_next_free += mod->dylink.table_size; - unit_allocate_total_us += (u64)std::chrono::duration_cast( + u64 allocate_us = (u64)std::chrono::duration_cast( std::chrono::steady_clock::now() - allocate_start).count(); + unit_allocate_total_us += allocate_us; + if(module_operation_index < unit_module_operations.size()) + unit_module_operations[module_operation_index].allocate_us = allocate_us; // import resolution auto import_start = std::chrono::steady_clock::now(); + u64 symbol_resolve_count_start = unit_symbol_resolve_count; + u64 symbol_resolve_us_start = unit_symbol_resolve_total_us; std::vector imports; imports.reserve(mod->imports.size()); std::vector> deferred_got; @@ -1793,13 +1808,24 @@ private: continue; } } - unit_import_total_us += (u64)std::chrono::duration_cast( + u64 import_us = (u64)std::chrono::duration_cast( std::chrono::steady_clock::now() - import_start).count(); + unit_import_total_us += import_us; + if(module_operation_index < unit_module_operations.size()) + { + auto& operation = unit_module_operations[module_operation_index]; + operation.import_us = import_us; + operation.symbol_resolve_count = unit_symbol_resolve_count - symbol_resolve_count_start; + operation.symbol_resolve_us = unit_symbol_resolve_total_us - symbol_resolve_us_start; + } auto instantiate_start = std::chrono::steady_clock::now(); auto created = wasmtime::Instance::create(cx, module, imports); - unit_instantiate_total_us += (u64)std::chrono::duration_cast( + u64 instantiate_us = (u64)std::chrono::duration_cast( std::chrono::steady_clock::now() - instantiate_start).count(); + unit_instantiate_total_us += instantiate_us; + if(module_operation_index < unit_module_operations.size()) + unit_module_operations[module_operation_index].instantiate_us = instantiate_us; if(!created) return(source_path + ": instantiation failed: " + trap_text(created.err())); @@ -1848,8 +1874,11 @@ private: if(worker.cfg.verbose) fprintf(stderr, "[wasm] loaded %s (mem_base=%u table_base=%u)\n", source_path.c_str(), memory_base, table_base); - unit_initialize_total_us += (u64)std::chrono::duration_cast( + u64 initialize_us = (u64)std::chrono::duration_cast( std::chrono::steady_clock::now() - initialize_start).count(); + unit_initialize_total_us += initialize_us; + if(module_operation_index < unit_module_operations.size()) + unit_module_operations[module_operation_index].initialize_us = initialize_us; // Exclude the rest of host-side loading as well. A genuine runaway loop // makes no loads, so it still trips the deadline. ctx().set_epoch_deadline(worker.cfg.epoch_deadline_ticks); @@ -2278,8 +2307,8 @@ private: DValue response; if(self->request_perf.active) { - f64 now = time_precise(); f64 cpu_now = wasm_thread_cpu_time(); + f64 now = time_precise(); 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; @@ -2383,6 +2412,12 @@ private: item["parse_us"] = (f64)operation.parse_us; item["build_us"] = (f64)operation.build_us; item["classify_us"] = (f64)operation.classify_us; + item["allocate_us"] = (f64)operation.allocate_us; + item["import_us"] = (f64)operation.import_us; + item["symbol_resolve_count"] = (f64)operation.symbol_resolve_count; + item["symbol_resolve_us"] = (f64)operation.symbol_resolve_us; + item["instantiate_us"] = (f64)operation.instantiate_us; + item["initialize_us"] = (f64)operation.initialize_us; response["unit_module_operations"].push(item); } response["unit_allocate_us"] = (f64)self->unit_allocate_total_us; @@ -3455,12 +3490,12 @@ 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(); + f64 cpu_started = wasm_thread_cpu_time(); WasmWorkspace workspace(worker); + f64 setup_cpu_finished = wasm_thread_cpu_time(); workspace.workspace_setup_us = (u64)std::chrono::duration_cast( std::chrono::steady_clock::now() - workspace_start).count(); - f64 setup_cpu_finished = wasm_thread_cpu_time(); workspace.workspace_setup_cpu_us = cpu_started > 0 && setup_cpu_finished > cpu_started ? (u64)((setup_cpu_finished - cpu_started) * 1000000.0) : 0; if(request) @@ -3474,9 +3509,9 @@ inline WasmResponse wasm_worker_serve(WasmWorker& worker, const DValue& context_ auto birth_start = std::chrono::steady_clock::now(); f64 birth_cpu_start = wasm_thread_cpu_time(); String error = workspace.birth(); + f64 birth_cpu_finished = wasm_thread_cpu_time(); workspace.workspace_birth_us = (u64)std::chrono::duration_cast( std::chrono::steady_clock::now() - birth_start).count(); - f64 birth_cpu_finished = wasm_thread_cpu_time(); workspace.workspace_birth_cpu_us = birth_cpu_start > 0 && birth_cpu_finished > birth_cpu_start ? (u64)((birth_cpu_finished - birth_cpu_start) * 1000000.0) : 0; if(error == "") @@ -3484,9 +3519,9 @@ inline WasmResponse wasm_worker_serve(WasmWorker& worker, const DValue& context_ auto context_start = std::chrono::steady_clock::now(); f64 context_cpu_start = wasm_thread_cpu_time(); error = workspace.apply_context(context_tree); + f64 context_cpu_finished = wasm_thread_cpu_time(); workspace.context_apply_us = (u64)std::chrono::duration_cast( std::chrono::steady_clock::now() - context_start).count(); - f64 context_cpu_finished = wasm_thread_cpu_time(); workspace.context_apply_cpu_us = context_cpu_start > 0 && context_cpu_finished > context_cpu_start ? (u64)((context_cpu_finished - context_cpu_start) * 1000000.0) : 0; }